🐛 Adding logs to figure out what is going wrong (#649)

* adding rule id in more places * adding konveyor log from LS logs for java provider Signed-off-by: Shawn Hurley <[email protected]>
konveyor · Jul 12, 2024 · 66df777 · 66df777
1 parent 57a736a
commit 66df777
Show file tree

Hide file tree

Showing 9 changed files with 74 additions and 24 deletions.
diff --git a/engine/engine.go b/engine/engine.go
@@ -127,8 +127,9 @@ func processRuleWorker(ctx context.Context, ruleMessages chan ruleMessage, logge
 		select {
 		case m := <-ruleMessages:
 			logger.V(5).Info("taking rule", "ruleset", m.ruleSetName, "rule", m.rule.RuleID)
+			newLogger := logger.WithValues("ruleID", m.rule.RuleID)
 			m.ctx.Template = make(map[string]ChainTemplate)
-			bo, err := processRule(ctx, m.rule, m.ctx, logger)
+			bo, err := processRule(ctx, m.rule, m.ctx, newLogger)
 			logger.V(5).Info("finished rule", "found", len(bo.Incidents), "error", err, "rule", m.rule.RuleID)
 			m.returnChan <- response{
 				ConditionResponse: bo,
@@ -183,7 +184,7 @@ func (r *ruleEngine) RunRules(ctx context.Context, ruleSets []RuleSet, selectors
 			select {
 			case response := <-ret:
 				func() {
-					r.logger.Info("rule returned", "rule", response.Rule.RuleID)
+					r.logger.Info("rule returned", "ruleID", response.Rule.RuleID)
 					defer wg.Done()
 					if response.Err != nil {
 						atomic.AddInt32(&failedRules, 1)
@@ -198,7 +199,7 @@ func (r *ruleEngine) RunRules(ctx context.Context, ruleSets []RuleSet, selectors
 							r.logger.Error(err, "unable to create violation from response", "ruleID", response.Rule.RuleID)
 						}
 						if len(violation.Incidents) == 0 {
-							r.logger.V(5).Info("rule was evaluated and incidents were filtered out to make it unmatched", "rule", response.Rule.RuleID)
+							r.logger.V(5).Info("rule was evaluated and incidents were filtered out to make it unmatched", "ruleID", response.Rule.RuleID)
 							atomic.AddInt32(&unmatchedRules, 1)
 							if rs, ok := mapRuleSets[response.RuleSetName]; ok {
 								rs.Unmatched = append(rs.Unmatched, response.Rule.RuleID)
@@ -220,7 +221,7 @@ func (r *ruleEngine) RunRules(ctx context.Context, ruleSets []RuleSet, selectors
 					} else {
 						atomic.AddInt32(&unmatchedRules, 1)
 						// Log that rule did not pass
-						r.logger.V(5).Info("rule was evaluated, and we did not find a violation", "rule", response.Rule.RuleID)
+						r.logger.V(5).Info("rule was evaluated, and we did not find a violation", "ruleID", response.Rule.RuleID)
 
 						if rs, ok := mapRuleSets[response.RuleSetName]; ok {
 							rs.Unmatched = append(rs.Unmatched, response.Rule.RuleID)

diff --git a/external-providers/java-external-provider/go.mod b/external-providers/java-external-provider/go.mod
@@ -13,13 +13,16 @@ require (
 )
 
 require (
+	github.com/nxadm/tail v1.4.8
 	github.com/sirupsen/logrus v1.9.0
 	github.com/vifraa/gopom v1.0.0
 )
 
 require (
+	github.com/fsnotify/fsnotify v1.7.0 // indirect
 	github.com/golang-jwt/jwt/v5 v5.2.1 // indirect
 	google.golang.org/genproto/googleapis/rpc v0.0.0-20240123012728-ef4313101c80 // indirect
+	gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 // indirect
 )
 
 require (
@@ -37,7 +40,9 @@ require (
 	go.opentelemetry.io/otel/sdk v1.11.2 // indirect
 	go.opentelemetry.io/otel/trace v1.11.2 // indirect
 	golang.org/x/net v0.24.0 // indirect
-	golang.org/x/sys v0.19.0 // indirect
+	golang.org/x/sys v0.22.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	google.golang.org/protobuf v1.33.1-0.20240408130810-98873a205002 // indirect
 )
+
+replace github.com/konveyor/analyzer-lsp => ../../
diff --git a/external-providers/java-external-provider/go.sum b/external-providers/java-external-provider/go.sum
@@ -11,6 +11,9 @@ github.com/cbroglie/mustache v1.3.0/go.mod h1:w58RIHjw/L7DPyRX2CcCTduNmcP1dvztaH
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/fsnotify/fsnotify v1.4.9/go.mod h1:znqG4EE+3YCdAaPaxE2ZRY/06pZUdp0tY4IgpuI1SZQ=
+github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA=
+github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM=
 github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/logr v1.4.1 h1:pKouT5E8xu9zeFC39JXRDukb6JFQPXM5p5I91188VAQ=
 github.com/go-logr/logr v1.4.1/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY=
@@ -25,12 +28,12 @@ github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI=
 github.com/hashicorp/go-version v1.6.0 h1:feTTfFNnjP967rlCxM/I9g701jU+RN74YKx2mOkIeek=
 github.com/hashicorp/go-version v1.6.0/go.mod h1:fltr4n8CU8Ke44wwGCBoEymUuxUHl09ZGVZPK5anwXA=
 github.com/iancoleman/orderedmap v0.3.0 h1:5cbR2grmZR/DiVt+VJopEhtVs9YGInGIxAoMJn+Ichc=
-github.com/konveyor/analyzer-lsp v0.4.0-alpha.1.0.20240520232004-8af6f5c84a59 h1:ybaunU+d9G4yMU2rhYVmO624QupG5JjiOA1rNCMh38o=
-github.com/konveyor/analyzer-lsp v0.4.0-alpha.1.0.20240520232004-8af6f5c84a59/go.mod h1:GXkSykQ84oE1SyMvFko9s9wRn/FMdl4efLLWSjMX2nU=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/nxadm/tail v1.4.8 h1:nPr65rt6Y5JFSKQO7qToXr7pePgD6Gwiw05lkbyAQTE=
+github.com/nxadm/tail v1.4.8/go.mod h1:+ncqLTQzXmGhMZNUePPaPqPvBxHAIsmXswZKocGu+AU=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/sergi/go-diff v1.3.1 h1:xkr+Oxo4BOQKmkn/B9eMK0g5Kg/983T9DqqPHwYqD+8=
@@ -66,9 +69,10 @@ go.opentelemetry.io/otel/trace v1.11.2 h1:Xf7hWSF2Glv0DE3MH7fBHvtpSBsjcBUe5MYAmZ
 go.opentelemetry.io/otel/trace v1.11.2/go.mod h1:4N+yC7QEz7TTsG9BSRLNAa63eg5E06ObSbKPmxQ/pKA=
 golang.org/x/net v0.24.0 h1:1PcaxkF854Fu3+lvBIx5SYn9wRlBzzcnHZSiaFFAb0w=
 golang.org/x/net v0.24.0/go.mod h1:2Q7sJY5mzlzWjKtYUEXSlBWCdyaioyXzRB2RtU8KVE8=
+golang.org/x/sys v0.0.0-20191005200804-aed5e4c7ecf9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.19.0 h1:q5f1RH2jigJ1MoAWp2KTp3gm5zAGFUTarQZ5U386+4o=
-golang.org/x/sys v0.19.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.22.0 h1:RI27ohtqKCnwULzJLqkv897zojh5/DwS/ENaMzUOaWI=
+golang.org/x/sys v0.22.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
 golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
@@ -80,6 +84,8 @@ google.golang.org/protobuf v1.33.1-0.20240408130810-98873a205002 h1:V7Da7qt0MkY3
 google.golang.org/protobuf v1.33.1-0.20240408130810-98873a205002/go.mod h1:c6P6GXX6sHbq/GpV6MGZEdwhWPcYBgnhAHhKbcUYpos=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
+gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7 h1:uRGJdciOHaEIrze2W8Q3AKkepLTh2hOroT7a+7czfdQ=
+gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw=
 gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY=
 gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

diff --git a/external-providers/java-external-provider/pkg/java_external_provider/provider.go b/external-providers/java-external-provider/pkg/java_external_provider/provider.go
@@ -22,6 +22,7 @@ import (
 	"github.com/konveyor/analyzer-lsp/output/v1/konveyor"
 	"github.com/konveyor/analyzer-lsp/provider"
 	"github.com/konveyor/analyzer-lsp/tracing"
+	"github.com/nxadm/tail"
 	"github.com/swaggest/openapi-go/openapi3"
 )
 
@@ -45,7 +46,7 @@ const (
 // Rule Location to location that the bundle understands
 var locationToCode = map[string]int{
 	//Type is the default.
-	"":                 0,
+	"":                 10,
 	"inheritance":      1,
 	"method_call":      2,
 	"constructor_call": 3,
@@ -72,6 +73,8 @@ type javaProvider struct {
 	hasMaven          bool
 	depsMutex         sync.RWMutex
 	depsLocationCache map[string]int
+
+	logFollow sync.Once
 }
 
 var _ provider.BaseClient = &javaProvider{}
@@ -98,6 +101,7 @@ func NewJavaProvider(log logr.Logger, lspServerName string, contextLines int) *j
 		lspServerName:     lspServerName,
 		depsLocationCache: make(map[string]int),
 		contextLines:      contextLines,
+		logFollow:         sync.Once{},
 	}
 }
 
@@ -374,6 +378,28 @@ func (p *javaProvider) Init(ctx context.Context, log logr.Logger, config provide
 	if err != nil {
 		return nil, err
 	}
+	// Will only set up log follow one time
+	// Will work in container image and hub, will not work
+	// When running for long period of time.
+	p.logFollow.Do(func() {
+		go func() {
+			t, err := tail.TailFile(".metadata/.log", tail.Config{
+				ReOpen:    true,
+				MustExist: false,
+				Follow:    true,
+			})
+			if err != nil {
+				log.Error(err, "unable to set up follower")
+				return
+			}
+
+			for line := range t.Lines {
+				if strings.Contains(line.Text, "KONVEYOR_LOG") {
+					log.Info("language server log", "line", line.Text)
+				}
+			}
+		}()
+	})
 	return &svcClient, returnErr
 }
 
@@ -614,7 +640,7 @@ func resolveSourcesJarsForMaven(ctx context.Context, log logr.Logger, location,
 
 	decompileJobs := []decompileJob{}
 
-	log.V(5).Info("resolving dependency sources")
+	log.Info("resolving dependency sources")
 
 	args := []string{
 		"-B",
@@ -632,7 +658,7 @@ func resolveSourcesJarsForMaven(ctx context.Context, log logr.Logger, location,
 		return err
 	}
 
-	log.V(8).WithValues("output", mvnOutput).Info("got maven output")
+	log.WithValues("output", mvnOutput).Info("got maven output")
 
 	reader := bytes.NewReader(mvnOutput)
 	artifacts, err := parseUnresolvedSources(reader)
@@ -645,7 +671,7 @@ func resolveSourcesJarsForMaven(ctx context.Context, log logr.Logger, location,
 		return nil
 	}
 	for _, artifact := range artifacts {
-		log.V(5).WithValues("artifact", artifact).Info("sources for artifact not found, decompiling...")
+		log.WithValues("artifact", artifact).Info("sources for artifact not found, decompiling...")
 
 		groupDirs := filepath.Join(strings.Split(artifact.GroupId, ".")...)
 		artifactDirs := filepath.Join(strings.Split(artifact.ArtifactId, ".")...)
@@ -669,7 +695,7 @@ func resolveSourcesJarsForMaven(ctx context.Context, log logr.Logger, location,
 			filepath.Join(filepath.Dir(decompileJob.inputPath),
 				fmt.Sprintf("%s-sources.jar", jarName)))
 		if err != nil {
-			log.V(5).Error(err, "failed to move decompiled file", "file", decompileJob.outputPath)
+			log.Error(err, "failed to move decompiled file", "file", decompileJob.outputPath)
 		}
 	}
 	return nil

diff --git a/external-providers/java-external-provider/pkg/java_external_provider/service_client.go b/external-providers/java-external-provider/pkg/java_external_provider/service_client.go
@@ -54,8 +54,12 @@ func (p *javaServiceClient) Evaluate(ctx context.Context, cap string, conditionI
 	if cond.Referenced.Pattern == "" {
 		return provider.ProviderEvaluateResponse{}, fmt.Errorf("provided query pattern empty")
 	}
-	symbols := p.GetAllSymbols(ctx, cond.Referenced.Pattern, cond.Referenced.Location)
-	p.log.V(5).Info("Symbols retrieved", "symbols", symbols)
+	symbols, err := p.GetAllSymbols(ctx, cond.Referenced.Pattern, cond.Referenced.Location)
+	if err != nil {
+		p.log.Error(err, "unable to get symbols", "symbols", symbols, "cap", cap, "conditionInfo", cond)
+		return provider.ProviderEvaluateResponse{}, err
+	}
+	p.log.Info("Symbols retrieved", "symbols", len(symbols), "cap", cap, "conditionInfo", cond)
 
 	incidents := []provider.IncidentContext{}
 	switch locationToCode[strings.ToLower(cond.Referenced.Location)] {
@@ -101,7 +105,7 @@ func (p *javaServiceClient) Evaluate(ctx context.Context, cap string, conditionI
 	}, nil
 }
 
-func (p *javaServiceClient) GetAllSymbols(ctx context.Context, query, location string) []protocol.WorkspaceSymbol {
+func (p *javaServiceClient) GetAllSymbols(ctx context.Context, query, location string) ([]protocol.WorkspaceSymbol, error) {
 	// This command will run the added bundle to the language server. The command over the wire needs too look like this.
 	// in this case the project is hardcoded in the init of the Langauge Server above
 	// workspace/executeCommand '{"command": "io.konveyor.tackle.ruleEntry", "arguments": {"query":"*customresourcedefinition","project": "java"}}'
@@ -130,12 +134,14 @@ func (p *javaServiceClient) GetAllSymbols(ctx context.Context, query, location s
 	if err != nil {
 		if jsonrpc2.IsRPCClosed(err) {
 			p.log.Error(err, "connection to the language server is closed, language server is not running")
+			return refs, fmt.Errorf("connection to the language server is closed, language server is not running")
 		} else {
 			p.log.Error(err, "unable to ask for Konveyor rule entry")
+			return refs, fmt.Errorf("unable to ask for Konveyor rule entry")
 		}
 	}
 
-	return refs
+	return refs, nil
 }
 
 func (p *javaServiceClient) GetAllReferences(ctx context.Context, symbol protocol.WorkspaceSymbol) []protocol.Location {
@@ -262,4 +268,5 @@ func (p *javaServiceClient) initialization(ctx context.Context) {
 		p.log.Error(err, "initialize failed")
 	}
 	p.log.V(2).Info("java connection initialized")
+
 }
diff --git a/go.mod b/go.mod
@@ -48,6 +48,6 @@ require (
 	go.opentelemetry.io/otel/exporters/jaeger v1.11.2
 	go.opentelemetry.io/otel/sdk v1.11.2
 	golang.org/x/net v0.22.0
-	golang.org/x/sys v0.18.0 // indirect
+	golang.org/x/sys v0.22.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 )
diff --git a/go.sum b/go.sum
@@ -113,8 +113,8 @@ golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.18.0 h1:DBdB3niSjOA/O0blCZBqDefyWNYveAYMNF1Wum0DYQ4=
-golang.org/x/sys v0.18.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.22.0 h1:RI27ohtqKCnwULzJLqkv897zojh5/DwS/ENaMzUOaWI=
+golang.org/x/sys v0.22.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

diff --git a/provider/provider.go b/provider/provider.go
@@ -496,6 +496,7 @@ func (p ProviderCondition) Evaluate(ctx context.Context, log logr.Logger, condCt
 		//TODO(fabianvf)
 		panic(err)
 	}
+	log = log.WithValues("provider info", "cap", p.Capability, "condInfo", p.ConditionInfo)
 	templatedInfo, err := templateCondition(serializedInfo, condCtx.Template)
 	if err != nil {
 		//TODO(fabianvf)
@@ -508,6 +509,11 @@ func (p ProviderCondition) Evaluate(ctx context.Context, log logr.Logger, condCt
 		return engine.ConditionResponse{}, err
 	}
 
+	if len(resp.Incidents) == 0 {
+		log.V(5).Info("no incidents found")
+		return engine.ConditionResponse{}, err
+	}
+
 	var deps map[uri.URI][]*Dep
 	if p.DepLabelSelector != nil {
 		deps, err = p.Client.GetDependencies(ctx)
@@ -565,7 +571,7 @@ func (p ProviderCondition) Evaluate(ctx context.Context, log logr.Logger, condCt
 
 	log.V(8).Info("condition response", "ruleID", p.Rule.RuleID, "response", cr, "cap", p.Capability, "conditionInfo", p.ConditionInfo, "client", p.Client)
 	if len(resp.Incidents)-len(incidents) > 0 {
-		log.V(5).Info("filtered out incidents based on dep label selector", "filteredOutCount", len(resp.Incidents)-len(incidents))
+		log.V(5).Info("filtered out incidents based on dep label selector", "filteredOutCount", len(resp.Incidents)-len(incidents), "keptCount", len(incidents))
 	}
 	return cr, nil
 
@@ -894,5 +900,4 @@ func ToProviderInputOutputCap(r *openapi3.Reflector, log logr.Logger, input, out
 	})
 	cap.Output = *outputSchemaOrRef
 	return cap, nil
-
 }
diff --git a/provider/server.go b/provider/server.go
@@ -128,7 +128,7 @@ func (s *server) Start(ctx context.Context) error {
 	}
 	libgrpc.RegisterProviderServiceServer(gs, s)
 	reflection.Register(gs)
-	log.Printf("server listening at %v", lis.Addr())
+	s.Log.Info(fmt.Sprintf("server listening at %v", lis.Addr()))
 	if err := gs.Serve(lis); err != nil {
 		log.Fatalf("failed to serve: %v", err)
 	}