From 844f1b2a7a17d461e4e078947819d3c320ff19f7 Mon Sep 17 00:00:00 2001 From: mgyorke Date: Fri, 24 May 2024 17:59:02 +0300 Subject: [PATCH] chore(log): Add trace level logging of legacy CLI request --- cliv2/go.mod | 2 +- cliv2/internal/proxy/proxy.go | 39 +++++++++++++++----------- cliv2/internal/proxy/proxy_test.go | 17 ++++++----- cliv2/pkg/basic_workflows/legacycli.go | 17 +++++------ 4 files changed, 42 insertions(+), 33 deletions(-) diff --git a/cliv2/go.mod b/cliv2/go.mod index 59ed6bcb57..1f6373ecf6 100644 --- a/cliv2/go.mod +++ b/cliv2/go.mod @@ -202,4 +202,4 @@ require ( // version 2491eb6c1c75 contains a valid license replace github.com/mattn/go-localereader v0.0.1 => github.com/mattn/go-localereader v0.0.2-0.20220822084749-2491eb6c1c75 -//replace github.com/snyk/go-application-framework => ../../go-application-framework +// replace github.com/snyk/go-application-framework => ../../go-application-framework diff --git a/cliv2/internal/proxy/proxy.go b/cliv2/internal/proxy/proxy.go index f4d64ad2b7..0395cc6f32 100644 --- a/cliv2/internal/proxy/proxy.go +++ b/cliv2/internal/proxy/proxy.go @@ -12,7 +12,10 @@ import ( "os" "github.com/google/uuid" + "github.com/rs/zerolog" "github.com/snyk/go-application-framework/pkg/configuration" + "github.com/snyk/go-application-framework/pkg/networking" + pkg_utils "github.com/snyk/go-application-framework/pkg/utils" "github.com/snyk/go-application-framework/pkg/networking/certs" "github.com/snyk/go-httpauth/pkg/httpauth" @@ -26,7 +29,7 @@ import ( type WrapperProxy struct { httpServer *http.Server - DebugLogger *log.Logger + DebugLogger *zerolog.Logger CertificateLocation string upstreamProxy func(*http.Request) (*url.URL, error) transport *http.Transport @@ -50,9 +53,8 @@ const ( PROXY_USERNAME = "snykcli" ) -func NewWrapperProxy(config configuration.Configuration, cliVersion string, debugLogger *log.Logger) (*WrapperProxy, error) { +func NewWrapperProxy(config configuration.Configuration, cliVersion string, debugLogger *zerolog.Logger) (*WrapperProxy, error) { var p WrapperProxy - p.DebugLogger = debugLogger p.cliVersion = cliVersion p.addHeaderFunc = func(request *http.Request) error { return nil } @@ -60,7 +62,8 @@ func NewWrapperProxy(config configuration.Configuration, cliVersion string, debu insecureSkipVerify := config.GetBool(configuration.INSECURE_HTTPS) certName := "snyk-embedded-proxy" - certPEMBlock, keyPEMBlock, err := certs.MakeSelfSignedCert(certName, []string{}, p.DebugLogger) + p.DebugLogger = debugLogger + certPEMBlock, keyPEMBlock, err := certs.MakeSelfSignedCert(certName, []string{}, log.New(&pkg_utils.ToZeroLogDebug{Logger: p.DebugLogger}, "", 0)) if err != nil { return nil, err } @@ -100,12 +103,11 @@ func NewWrapperProxy(config configuration.Configuration, cliVersion string, debu } } - p.DebugLogger.Println("Using additional CAs from file: ", extraCaCertFile) + debugLogger.Debug().Msgf("Using additional CAs from file: %v", extraCaCertFile) } } - p.DebugLogger.Println("Temporary CertificateLocation:", p.CertificateLocation) - + debugLogger.Debug().Msgf("Temporary CertificateLocation: %v", p.CertificateLocation) certPEMString := string(certPEMBlock) err = utils.WriteToFile(p.CertificateLocation, certPEMString) if err != nil { @@ -147,6 +149,8 @@ func (p *WrapperProxy) replaceVersionHandler(r *http.Request, ctx *goproxy.Proxy p.DebugLogger.Printf("Failed to add header: %s", err) } + networking.LogRequest(r, p.DebugLogger) + return r, nil } @@ -157,7 +161,7 @@ func (p *WrapperProxy) checkBasicCredentials(user, password string) bool { func (p *WrapperProxy) HandleConnect(req string, ctx *goproxy.ProxyCtx) (*goproxy.ConnectAction, string) { basic := auth.BasicConnect("", p.checkBasicCredentials) action, str := basic.HandleConnect(req, ctx) - p.DebugLogger.Println("HandleConnect - basic authentication result: ", action, str) + p.DebugLogger.Print("HandleConnect - basic authentication result: ", action, str) if action == goproxy.OkConnect { action, str = goproxy.AlwaysMitm.HandleConnect(req, ctx) @@ -169,7 +173,8 @@ func (p *WrapperProxy) HandleConnect(req string, ctx *goproxy.ProxyCtx) (*goprox func (p *WrapperProxy) Start() error { proxy := goproxy.NewProxyHttpServer() proxy.Tr = p.transport - proxy.Logger = p.DebugLogger + // zerolog based logger also works but it will print empty lines between logs + proxy.Logger = log.New(&pkg_utils.ToZeroLogDebug{Logger: p.DebugLogger}, "", 0) proxy.OnRequest().DoFunc(p.replaceVersionHandler) proxy.OnRequest().HandleConnect(p) proxy.Verbose = true @@ -179,7 +184,7 @@ func (p *WrapperProxy) Start() error { p.httpServer = proxyServer - p.DebugLogger.Println("starting proxy") + p.DebugLogger.Print("starting proxy") address := "127.0.0.1:0" l, err := net.Listen("tcp", address) if err != nil { @@ -187,7 +192,7 @@ func (p *WrapperProxy) Start() error { } p.port = l.Addr().(*net.TCPAddr).Port - p.DebugLogger.Println("Wrapper proxy is listening on port: ", p.port) + p.DebugLogger.Print("Wrapper proxy is listening on port: ", p.port) go func() { _ = p.httpServer.Serve(l) // this blocks until the server stops and gives you an error which can be ignored @@ -209,13 +214,13 @@ func (p *WrapperProxy) Stop() { func (p *WrapperProxy) Close() { p.Stop() - p.DebugLogger.Println("deleting temp cert file:", p.CertificateLocation) + p.DebugLogger.Print("deleting temp cert file:", p.CertificateLocation) err := os.Remove(p.CertificateLocation) if err != nil { - p.DebugLogger.Println("failed to delete cert file") - p.DebugLogger.Println(err) + p.DebugLogger.Print("failed to delete cert file") + p.DebugLogger.Print(err) } else { - p.DebugLogger.Println("deleted temp cert file:", p.CertificateLocation) + p.DebugLogger.Print("deleted temp cert file:", p.CertificateLocation) } } @@ -238,11 +243,11 @@ func setCAFromBytes(certPEMBlock []byte, keyPEMBlock []byte) error { func (p *WrapperProxy) SetUpstreamProxyAuthentication(mechanism httpauth.AuthenticationMechanism) { if mechanism != p.authMechanism { p.authMechanism = mechanism - p.DebugLogger.Printf("Enabled Proxy Authentication Mechanism: %s\n", httpauth.StringFromAuthenticationMechanism(p.authMechanism)) + p.DebugLogger.Printf("Enabled Proxy Authentication Mechanism: %s", httpauth.StringFromAuthenticationMechanism(p.authMechanism)) } if httpauth.IsSupportedMechanism(p.authMechanism) { // since Negotiate is not covered by the go http stack, we skip its proxy handling and inject a custom Handling via the DialContext - p.authenticator = httpauth.NewProxyAuthenticator(p.authMechanism, p.upstreamProxy, p.DebugLogger) + p.authenticator = httpauth.NewProxyAuthenticator(p.authMechanism, p.upstreamProxy, log.New(&pkg_utils.ToZeroLogDebug{Logger: p.DebugLogger}, "", 0)) p.transport.DialContext = p.authenticator.DialContext p.transport.Proxy = nil } else { // for other mechanisms like basic we switch back to go default behavior diff --git a/cliv2/internal/proxy/proxy_test.go b/cliv2/internal/proxy/proxy_test.go index c0eb2bfb30..359f954fcc 100644 --- a/cliv2/internal/proxy/proxy_test.go +++ b/cliv2/internal/proxy/proxy_test.go @@ -10,8 +10,10 @@ import ( "os" "testing" + "github.com/rs/zerolog" "github.com/snyk/go-application-framework/pkg/configuration" "github.com/snyk/go-application-framework/pkg/networking/certs" + gafUtils "github.com/snyk/go-application-framework/pkg/utils" "github.com/snyk/go-httpauth/pkg/httpauth" "github.com/snyk/cli/cliv2/internal/constants" @@ -21,7 +23,7 @@ import ( "github.com/stretchr/testify/assert" ) -var debugLogger *log.Logger = log.New(os.Stderr, "", log.Ldate|log.Ltime|log.Lmicroseconds|log.Lshortfile) +var debugLogger = zerolog.New(os.Stderr).With().Timestamp().Logger() func helper_getHttpClient(gateway *proxy.WrapperProxy, useProxyAuth bool) (*http.Client, error) { rootCAs, _ := x509.SystemCertPool() @@ -86,7 +88,7 @@ func Test_closingProxyDeletesTempCert(t *testing.T) { config.Set(configuration.CACHE_PATH, basecache) config.Set(configuration.INSECURE_HTTPS, false) - wp, err := proxy.NewWrapperProxy(config, version, debugLogger) + wp, err := proxy.NewWrapperProxy(config, version, &debugLogger) assert.Nil(t, err) err = wp.Start() @@ -110,7 +112,7 @@ func Test_canGoThroughProxy(t *testing.T) { setup(t, basecache, version) defer teardown(t, basecache) - wp, err := proxy.NewWrapperProxy(config, version, debugLogger) + wp, err := proxy.NewWrapperProxy(config, version, &debugLogger) assert.Nil(t, err) err = wp.Start() @@ -143,7 +145,7 @@ func Test_proxyRejectsWithoutBasicAuthHeader(t *testing.T) { setup(t, basecache, version) defer teardown(t, basecache) - wp, err := proxy.NewWrapperProxy(config, version, debugLogger) + wp, err := proxy.NewWrapperProxy(config, version, &debugLogger) assert.Nil(t, err) err = wp.Start() @@ -192,7 +194,7 @@ func Test_SetUpstreamProxy(t *testing.T) { httpauth.UnknownMechanism, } - objectUnderTest, err = proxy.NewWrapperProxy(config, version, debugLogger) + objectUnderTest, err = proxy.NewWrapperProxy(config, version, &debugLogger) assert.Nil(t, err) // running different cases @@ -231,7 +233,8 @@ func Test_appendExtraCaCert(t *testing.T) { setup(t, basecache, version) defer teardown(t, basecache) - certPem, _, err := certs.MakeSelfSignedCert("mycert", []string{"dns"}, debugLogger) + loggerWrapper := log.New(&gafUtils.ToZeroLogDebug{Logger: &debugLogger}, "", 0) + certPem, _, err := certs.MakeSelfSignedCert("mycert", []string{"dns"}, loggerWrapper) assert.NoError(t, err) file, err := os.CreateTemp("", "") assert.NoError(t, err) @@ -240,7 +243,7 @@ func Test_appendExtraCaCert(t *testing.T) { t.Setenv(constants.SNYK_CA_CERTIFICATE_LOCATION_ENV, file.Name()) - wp, err := proxy.NewWrapperProxy(config, version, debugLogger) + wp, err := proxy.NewWrapperProxy(config, version, &debugLogger) assert.Nil(t, err) certsPem, err := os.ReadFile(wp.CertificateLocation) diff --git a/cliv2/pkg/basic_workflows/legacycli.go b/cliv2/pkg/basic_workflows/legacycli.go index 5ed9cdfcfb..3ed93af28f 100644 --- a/cliv2/pkg/basic_workflows/legacycli.go +++ b/cliv2/pkg/basic_workflows/legacycli.go @@ -66,7 +66,8 @@ func legacycliWorkflow( var errWriter *bufio.Writer config := invocation.GetConfiguration() - debugLogger := invocation.GetLogger() + debugLogger := invocation.GetEnhancedLogger() // uses zerolog + debugLoggerDefault := invocation.GetLogger() // uses log networkAccess := invocation.GetNetworkAccess() oauthIsAvailable := config.GetBool(configuration.FF_OAUTH_AUTH_FLOW_ENABLED) @@ -78,13 +79,13 @@ func legacycliWorkflow( proxyAuthenticationMechanism := httpauth.AuthenticationMechanismFromString(proxyAuthenticationMechanismString) analyticsDisabled := config.GetBool(configuration.ANALYTICS_DISABLED) - debugLogger.Println("Arguments:", args) - debugLogger.Println("Use StdIO:", useStdIo) - debugLogger.Println("Working directory:", workingDirectory) + debugLogger.Print("Arguments:", args) + debugLogger.Print("Use StdIO:", useStdIo) + debugLogger.Print("Working directory:", workingDirectory) // init cli object var cli *cliv2.CLI - cli, err = cliv2.NewCLIv2(config, debugLogger) + cli, err = cliv2.NewCLIv2(config, debugLoggerDefault) if err != nil { return output, err } @@ -108,9 +109,9 @@ func legacycliWorkflow( if _, ok := envMap[constants.SNYK_OAUTH_ACCESS_TOKEN_ENV]; !ok { env := []string{constants.SNYK_OAUTH_ACCESS_TOKEN_ENV + "=randomtoken"} cli.AppendEnvironmentVariables(env) - debugLogger.Println("Authentication: Oauth token handling delegated to Extensible CLI.") + debugLogger.Print("Authentication: Oauth token handling delegated to Extensible CLI.") } else { - debugLogger.Println("Authentication: Using oauth token from Environment Variable.") + debugLogger.Print("Authentication: Using oauth token from Environment Variable.") } } } @@ -160,7 +161,7 @@ func legacycliWorkflow( errWriter.Flush() if isDebug { - debugLogger.Println(errBuffer.String()) + debugLogger.Print(errBuffer.String()) } contentType := "text/plain"