Skip to content

Commit

Permalink
feat(instrumentation): add trace level logging of request
Browse files Browse the repository at this point in the history
  • Loading branch information
@mgyorke
mgyorke committed May 24, 2024
1 parent 4c795e0 commit 176d595
Show file tree
Hide file tree
Showing 4 changed files with 42 additions and 33 deletions.
2 changes: 1 addition & 1 deletion cliv2/go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
39 changes: 22 additions & 17 deletions cliv2/internal/proxy/proxy.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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
Expand All @@ -50,17 +53,17 @@ 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 }

cacheDirectory := config.GetString(configuration.CACHE_PATH)
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
}
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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
}

Expand All @@ -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)
Expand All @@ -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
Expand All @@ -179,15 +184,15 @@ 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 {
return err
}

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
Expand All @@ -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)
}
}

Expand All @@ -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
Expand Down
17 changes: 10 additions & 7 deletions cliv2/internal/proxy/proxy_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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()
Expand Down Expand Up @@ -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()
Expand All @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand Down
17 changes: 9 additions & 8 deletions cliv2/pkg/basic_workflows/legacycli.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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
}
Expand All @@ -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.")
}
}
}
Expand Down Expand Up @@ -160,7 +161,7 @@ func legacycliWorkflow(
errWriter.Flush()

if isDebug {
debugLogger.Println(errBuffer.String())
debugLogger.Print(errBuffer.String())
}

contentType := "text/plain"
Expand Down

0 comments on commit 176d595

Please sign in to comment.