chore: add logging to snyk code bundles for troubleshooting (#700)

Author: bastiandoetsch

application/di/test_init.go

@@ -17,6 +17,7 @@
 package di
 
 import (
+	"path/filepath"
 	"testing"
 
 	"github.com/snyk/snyk-ls/domain/snyk/persistence"
@@ -53,6 +54,8 @@ func TestInit(t *testing.T) {
 	defer initMutex.Unlock()
 	t.Helper()
 	c := config.CurrentConfig()
+	// we want to isolate CLI fake installs
+	c.CliSettings().SetPath(filepath.Join(t.TempDir(), "fake-cli"))
 	// we don't want to open browsers when testing
 	types.DefaultOpenBrowserFunc = func(url string) {}
 	notifier = domainNotify.NewNotifier()

application/server/configuration_test.go

@@ -187,7 +187,7 @@ func Test_UpdateSettings(t *testing.T) {
 			SendErrorReports:             "true",
 			Organization:                 expectedOrgId,
 			ManageBinariesAutomatically:  "false",
-			CliPath:                      "C:\\Users\\CliPath\\snyk-ls.exe",
+			CliPath:                      filepath.Join(t.TempDir(), "cli"),
 			Token:                        "a fancy token",
 			FilterSeverity:               types.DefaultSeverityFilter(),
 			TrustedFolders:               []string{"trustedPath1", "trustedPath2"},
@@ -234,7 +234,7 @@ func Test_UpdateSettings(t *testing.T) {
 		assert.True(t, c.IsErrorReportingEnabled())
 		assert.Equal(t, expectedOrgId, c.Organization())
 		assert.False(t, c.ManageBinariesAutomatically())
-		assert.Equal(t, "C:\\Users\\CliPath\\snyk-ls.exe", c.CliSettings().Path())
+		assert.Equal(t, settings.CliPath, c.CliSettings().Path())
 		assert.Equal(t, types.DefaultSeverityFilter(), c.FilterSeverity())
 		assert.Subset(t, []string{"trustedPath1", "trustedPath2"}, c.TrustedFolders())
 		assert.Equal(t, settings.OsPlatform, c.OsPlatform())

application/server/notification_test.go

@@ -18,6 +18,7 @@ package server
 
 import (
 	"context"
+	"path/filepath"
 	"reflect"
 	"testing"
 	"time"
@@ -174,7 +175,7 @@ func Test_IsAvailableCliNotification(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	var expected = types.SnykIsAvailableCli{CliPath: "path"}
+	var expected = types.SnykIsAvailableCli{CliPath: filepath.Join(t.TempDir(), "cli")}
 
 	di.Notifier().Send(expected)
 	assert.Eventually(

application/server/server_smoke_test.go

@@ -203,6 +203,7 @@ func Test_SmokeIssueCaching(t *testing.T) {
 		checkDiagnosticPublishingForCachingSmokeTest(t, jsonRPCRecorder, 2, 3, c)
 		checkScanResultsPublishingForCachingSmokeTest(t, jsonRPCRecorder, folderJuice, folderGoof, c)
 	})
+
 	t.Run("clears issues from cache correctly", func(t *testing.T) {
 		loc, jsonRPCRecorder := setupServer(t)
 		c := testutil.SmokeTest(t, false)

application/server/server_test.go

@@ -353,7 +353,7 @@ func Test_TextDocumentCodeLenses_shouldReturnCodeLenses(t *testing.T) {
 			Organization:                "fancy org",
 			Token:                       "xxx",
 			ManageBinariesAutomatically: "true",
-			CliPath:                     "",
+			CliPath:                     filepath.Join(t.TempDir(), "cli"),
 			FilterSeverity:              types.DefaultSeverityFilter(),
 			EnableTrustedFoldersFeature: "false",
 		},
@@ -410,7 +410,7 @@ func Test_TextDocumentCodeLenses_dirtyFileShouldFilterCodeLenses(t *testing.T) {
 			Organization:                "fancy org",
 			Token:                       "xxx",
 			ManageBinariesAutomatically: "true",
-			CliPath:                     "",
+			CliPath:                     filepath.Join(t.TempDir(), "cli"),
 			FilterSeverity:              types.DefaultSeverityFilter(),
 			EnableTrustedFoldersFeature: "false",
 		},
@@ -638,6 +638,7 @@ func Test_initialize_handlesUntrustedFoldersWhenAutomaticAuthentication(t *testi
 	loc, jsonRPCRecorder := setupServer(t)
 	initializationOptions := types.Settings{
 		EnableTrustedFoldersFeature: "true",
+		CliPath:                     filepath.Join(t.TempDir(), "cli"),
 	}
 	params := types.InitializeParams{
 		InitializationOptions: initializationOptions,
@@ -661,6 +662,7 @@ func Test_initialize_handlesUntrustedFoldersWhenAuthenticated(t *testing.T) {
 	initializationOptions := types.Settings{
 		EnableTrustedFoldersFeature: "true",
 		Token:                       "token",
+		CliPath:                     filepath.Join(t.TempDir(), "cli"),
 	}
 
 	fakeAuthenticationProvider := di.AuthenticationService().Provider().(*authentication.FakeAuthenticationProvider)
@@ -687,6 +689,7 @@ func Test_initialize_doesnotHandleUntrustedFolders(t *testing.T) {
 	loc, jsonRPCRecorder := setupServer(t)
 	initializationOptions := types.Settings{
 		EnableTrustedFoldersFeature: "true",
+		CliPath:                     filepath.Join(t.TempDir(), "cli"),
 	}
 	params := types.InitializeParams{
 		InitializationOptions: initializationOptions,

infrastructure/code/bundle.go

@@ -98,7 +98,7 @@ func getIssueLangAndRuleId(issue snyk.Issue) (string, string, bool) {
 }
 
 func (b *Bundle) retrieveAnalysis(ctx context.Context, t *progress.Tracker) ([]snyk.Issue, error) {
-	logger := b.logger.With().Str("method", "retrieveAnalysis").Logger()
+	logger := b.logger.With().Str("method", "retrieveAnalysis").Str("requestId", b.requestId).Logger()
 
 	if b.BundleHash == "" {
 		logger.Warn().Str("rootPath", b.rootPath).Msg("bundle hash is empty")
@@ -129,7 +129,6 @@ func (b *Bundle) retrieveAnalysis(ctx context.Context, t *progress.Tracker) ([]s
 
 		if err != nil {
 			logger.Error().Err(err).
-				Str("requestId", b.requestId).
 				Int("fileCount", len(b.UploadBatches)).
 				Msg("error retrieving diagnostics...")
 			b.errorReporter.CaptureError(err, codeClientObservability.ErrorReporterOptions{ErrorDiagnosticPath: b.rootPath})
@@ -138,8 +137,7 @@ func (b *Bundle) retrieveAnalysis(ctx context.Context, t *progress.Tracker) ([]s
 		}
 
 		if status.message == completeStatus {
-			logger.Trace().Str("requestId", b.requestId).
-				Msg("sending diagnostics...")
+			logger.Trace().Msg("sending diagnostics...")
 			t.ReportWithMessage(90, "Analysis complete.")
 
 			b.issueEnhancer.addIssueActions(ctx, issues, b.BundleHash)

infrastructure/code/snyk_code_http_client.go

@@ -21,6 +21,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"fmt"
 	"io"
 	"math"
 	"net/http"
@@ -106,12 +107,12 @@ func (s *SnykCodeHTTPClient) GetFilters(ctx context.Context) (
 	span := s.instrumentor.StartSpan(ctx, method)
 	defer s.instrumentor.Finish(span)
 
-	responseBody, err := s.doCall(span.Context(), "GET", "/filters", nil)
+	body, _, err := s.doCall(span.Context(), "GET", "/filters", nil)
 	if err != nil {
 		return FiltersResponse{ConfigFiles: nil, Extensions: nil}, err
 	}
 
-	err = json.Unmarshal(responseBody, &filters)
+	err = json.Unmarshal(body, &filters)
 	if err != nil {
 		return FiltersResponse{ConfigFiles: nil, Extensions: nil}, err
 	}
@@ -134,53 +135,50 @@ func (s *SnykCodeHTTPClient) CreateBundle(
 		return "", nil, err
 	}
 
-	responseBody, err := s.doCall(span.Context(), "POST", "/bundle", requestBody)
+	body, _, err := s.doCall(span.Context(), "POST", "/bundle", requestBody)
 	if err != nil {
 		return "", nil, err
 	}
 
 	var bundle bundleResponse
-	err = json.Unmarshal(responseBody, &bundle)
+	err = json.Unmarshal(body, &bundle)
 	if err != nil {
 		return "", nil, err
 	}
 	s.c.Logger().Debug().Str("method", method).Msg("API: Create done")
 	return bundle.BundleHash, bundle.MissingFiles, nil
 }
 
-func (s *SnykCodeHTTPClient) doCall(ctx context.Context,
-	method string,
-	path string,
-	requestBody []byte,
-) (responseBody []byte, _ error) {
+func (s *SnykCodeHTTPClient) doCall(ctx context.Context, method string, path string, requestBody []byte) ([]byte, int, error) {
 	span := s.instrumentor.StartSpan(ctx, "code.doCall")
 	defer s.instrumentor.Finish(span)
 
 	const retryCount = 3
+
+	// we only retry, if we get a retryable http status code
 	for i := 0; i < retryCount; i++ {
 		requestId, err := performance2.GetTraceId(span.Context())
 		if err != nil {
-			return nil, errors.New("Code request id was not provided. " + err.Error())
+			return nil, 0, errors.New("Code request id was not provided. " + err.Error())
 		}
 
 		bodyBuffer, err := s.encodeIfNeeded(method, requestBody)
 		if err != nil {
-			return nil, err
+			return nil, 0, err
 		}
 
 		c := config.CurrentConfig()
 		req, err := s.newRequest(c, method, path, bodyBuffer, requestId)
 		if err != nil {
-			return nil, err
+			return nil, 0, err
 		}
 
 		s.c.Logger().Trace().Str("requestBody", string(requestBody)).Str("snyk-request-id", requestId).Msg("SEND TO REMOTE")
 
-		response, body, err := s.httpCall(req) //nolint:bodyclose // false positive
-		responseBody = body
+		responseBody, httpStatusCode, err := s.httpCall(req)
 
-		if response != nil && responseBody != nil {
-			s.c.Logger().Trace().Str("response.Status", response.Status).
+		if responseBody != nil {
+			s.c.Logger().Trace().Int("response.Status", httpStatusCode).
 				Str("responseBody", string(responseBody)).
 				Str("snyk-request-id", requestId).
 				Msg("RECEIVED FROM REMOTE")
@@ -191,51 +189,58 @@ func (s *SnykCodeHTTPClient) doCall(ctx context.Context,
 		}
 
 		if err != nil {
-			return nil, err // no retries for errors
+			return nil, 0, err // no retries for errors
 		}
 
-		err = s.checkResponseCode(response)
+		err = s.checkResponseCode(httpStatusCode)
 		if err != nil {
-			if retryErrorCodes[response.StatusCode] {
+			if retryErrorCodes[httpStatusCode] {
 				s.c.Logger().Debug().Err(err).Str("method", method).Int("attempts done", i+1).Msgf("retrying")
 				if i < retryCount-1 {
 					time.Sleep(5 * time.Second)
 					continue
 				}
 				// return the error on last try
-				return nil, err
+				return nil, httpStatusCode, err
 			}
-			return nil, err
+			return nil, httpStatusCode, err
 		}
 		// no error, we can break the retry loop
-		break
+		return responseBody, httpStatusCode, nil
 	}
-	return responseBody, nil
+	return nil, 0, nil
 }
 
-func (s *SnykCodeHTTPClient) httpCall(req *http.Request) (*http.Response, []byte, error) {
+func (s *SnykCodeHTTPClient) httpCall(req *http.Request) ([]byte, int, error) {
 	method := "code.httpCall"
+	logger := s.c.Logger().With().Str("method", method).Logger()
+	statusCode := 0
+
 	response, err := s.client().Do(req)
 	if err != nil {
-		s.c.Logger().Err(err).Str("method", method).Msgf("got http error")
-		s.errorReporter.CaptureError(err, codeClientObservability.ErrorReporterOptions{ErrorDiagnosticPath: req.RequestURI})
-		return nil, nil, err
+		logger.Err(err).Msgf("got http error")
+		return nil, statusCode, err
+	}
+
+	if response == nil {
+		return nil, 0, nil
 	}
 
 	defer func() {
-		closeErr := response.Body.Close()
-		if closeErr != nil {
-			s.c.Logger().Err(closeErr).Msg("Couldn't close response body in call to Snyk Code")
+		bodyCloseErr := response.Body.Close()
+		if bodyCloseErr != nil {
+			logger.Err(bodyCloseErr).Msg("failed to close response body")
 		}
 	}()
-	responseBody, err := io.ReadAll(response.Body)
 
-	if err != nil {
-		s.c.Logger().Err(err).Str("method", method).Msgf("error reading response body")
-		s.errorReporter.CaptureError(err, codeClientObservability.ErrorReporterOptions{ErrorDiagnosticPath: req.RequestURI})
-		return nil, nil, err
+	statusCode = response.StatusCode
+	responseBody, readErr := io.ReadAll(response.Body)
+
+	if readErr != nil {
+		logger.Err(readErr).Msg("failed to read response body")
+		return responseBody, statusCode, err
 	}
-	return response, responseBody, nil
+	return responseBody, statusCode, nil
 }
 
 func (s *SnykCodeHTTPClient) newRequest(
@@ -313,11 +318,16 @@ func (s *SnykCodeHTTPClient) ExtendBundle(
 	removedFiles []string,
 ) (string, []string, error) {
 	method := "code.ExtendBundle"
-	s.c.Logger().Debug().Str("method", method).Msg("API: Extending bundle for " + strconv.Itoa(len(files)) + " files")
-	defer s.c.Logger().Debug().Str("method", method).Msg("API: Extend done")
-
 	span := s.instrumentor.StartSpan(ctx, method)
 	defer s.instrumentor.Finish(span)
+	requestId, err := performance2.GetTraceId(span.Context())
+	logger := s.c.Logger().With().Str("method", method).Str("requestId", requestId).Logger()
+	if err != nil {
+		logger.Err(err).Msg("failed to get request id")
+	}
+
+	logger.Debug().Msg("API: Extending bundle for " + strconv.Itoa(len(files)) + " files")
+	defer logger.Debug().Msg("API: Extend done")
 
 	requestBody, err := json.Marshal(extendBundleRequest{
 		Files:        files,
@@ -327,7 +337,12 @@ func (s *SnykCodeHTTPClient) ExtendBundle(
 		return "", nil, err
 	}
 
-	responseBody, err := s.doCall(span.Context(), "PUT", "/bundle/"+bundleHash, requestBody)
+	responseBody, httpStatus, err := s.doCall(span.Context(), "PUT", "/bundle/"+bundleHash, requestBody)
+	if httpStatus == http.StatusBadRequest {
+		logger.Err(err).Msg("got an HTTP 400 Bad Request, dumping bundle infos for analysis")
+		logger.Error().Any("fileHashes", files).Send()
+		logger.Error().Any("removedFiles", removedFiles).Send()
+	}
 	if err != nil {
 		return "", nil, err
 	}
@@ -364,7 +379,7 @@ func (s *SnykCodeHTTPClient) RunAnalysis(
 		return nil, AnalysisStatus{}, err
 	}
 
-	responseBody, err := s.doCall(span.Context(), "POST", "/analysis", requestBody)
+	responseBody, _, err := s.doCall(span.Context(), "POST", "/analysis", requestBody)
 	failed := AnalysisStatus{message: "FAILED"}
 	if err != nil {
 		s.c.Logger().Err(err).Str("method", method).Str("responseBody", string(responseBody)).Msg("error response from analysis")
@@ -434,11 +449,11 @@ func (s *SnykCodeHTTPClient) analysisRequestBody(options *AnalysisOptions) ([]by
 	return requestBody, err
 }
 
-func (s *SnykCodeHTTPClient) checkResponseCode(r *http.Response) error {
-	if r.StatusCode >= 200 && r.StatusCode <= 299 {
+func (s *SnykCodeHTTPClient) checkResponseCode(statusCode int) error {
+	if statusCode >= 200 && statusCode <= 400 {
 		return nil
 	}
-	return errors.New("Unexpected response code: " + r.Status)
+	return fmt.Errorf("Unexpected response code: %d", statusCode)
 }
 
 type AutofixStatus struct {
@@ -508,7 +523,7 @@ func (s *SnykCodeHTTPClient) RunAutofix(ctx context.Context, options AutofixOpti
 		return AutofixResponse{}, err
 	}
 
-	responseBody, err := s.doCall(span.Context(), "POST", "/autofix/suggestions", requestBody)
+	responseBody, _, err := s.doCall(span.Context(), "POST", "/autofix/suggestions", requestBody)
 
 	if err != nil {
 		logger.Err(err).Str("responseBody", string(responseBody)).Msg("error response from autofix")
@@ -578,7 +593,7 @@ func (s *SnykCodeHTTPClient) SubmitAutofixFeedback(ctx context.Context, fixId st
 		return err
 	}
 
-	responseBody, err := s.doCall(span.Context(), "POST", "/autofix/event", requestBody)
+	responseBody, _, err := s.doCall(span.Context(), "POST", "/autofix/event", requestBody)
 	if err != nil {
 		s.c.Logger().Err(err).Str("method", method).Str("responseBody", string(responseBody)).Msg("error response for autofix feedback")
 		return err

infrastructure/code/snyk_code_http_client_test.go

@@ -127,7 +127,7 @@ func TestSnykCodeBackendService_doCall_shouldRetry(t *testing.T) {
 		}
 	}
 	s := NewSnykCodeHTTPClient(c, NewCodeInstrumentor(), newTestCodeErrorReporter(), dummyClientFunc)
-	_, err := s.doCall(context.Background(), "GET", "https://httpstat.us/500", nil)
+	_, _, err := s.doCall(context.Background(), "GET", "https://httpstat.us/500", nil)
 	assert.Error(t, err)
 	assert.Equal(t, 3, d.calls)
 }
@@ -139,7 +139,7 @@ func TestSnykCodeBackendService_doCall_rejected(t *testing.T) {
 	}
 
 	s := NewSnykCodeHTTPClient(c, NewCodeInstrumentor(), newTestCodeErrorReporter(), dummyClientFunc)
-	_, err := s.doCall(context.Background(), "GET", "https://127.0.0.1", nil)
+	_, _, err := s.doCall(context.Background(), "GET", "https://127.0.0.1", nil)
 	assert.Error(t, err)
 }
 

infrastructure/snyk_api/snyk_api.go

@@ -217,7 +217,7 @@ func (s *SnykApiClientImpl) getApiResponse(caller string, path string, v interfa
 }
 
 func checkResponseCode(r *http.Response) *SnykApiError {
-	if r.StatusCode >= 200 && r.StatusCode <= 399 {
+	if r.StatusCode >= 200 && r.StatusCode <= 299 {
 		return nil
 	}