From 6d7bb05fcc95003273b27b0bda7010a2e6f4ceef Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Thu, 3 Apr 2025 15:48:54 +0800 Subject: [PATCH 1/8] fix: improve debug log Signed-off-by: Junjie Gao --- cmd/notation/internal/flag/options.go | 11 +++++++++++ internal/trace/context.go | 2 ++ internal/trace/transport.go | 4 ++-- 3 files changed, 15 insertions(+), 2 deletions(-) diff --git a/cmd/notation/internal/flag/options.go b/cmd/notation/internal/flag/options.go index 44cec099e..a51064d5c 100644 --- a/cmd/notation/internal/flag/options.go +++ b/cmd/notation/internal/flag/options.go @@ -17,12 +17,14 @@ import ( "context" "fmt" "os" + "runtime" "slices" "strings" "github.com/notaryproject/notation-go/log" "github.com/notaryproject/notation/v2/cmd/notation/internal/display/output" "github.com/notaryproject/notation/v2/internal/trace" + "github.com/notaryproject/notation/v2/internal/version" "github.com/sirupsen/logrus" "github.com/spf13/cobra" "github.com/spf13/pflag" @@ -78,6 +80,15 @@ func (opts *LoggingFlagOpts) InitializeLogger(ctx context.Context) context.Conte } else { return ctx } + + // Log environment information + logger := log.GetLogger(ctx) + logger.Infof("Notation Version: %s", version.GetVersion()) + if version.GitCommit != "" { + logger.Infof("Git Commit: %s", version.GitCommit) + } + logger.Infof("OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH) + return withExecutableTrace(ctx) } diff --git a/internal/trace/context.go b/internal/trace/context.go index 322696062..5537c0345 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -42,6 +42,8 @@ func WithLoggerLevel(ctx context.Context, level logrus.Level) context.Context { var formatter logrus.TextFormatter if level == logrus.DebugLevel { formatter.FullTimestamp = true + // Set timestamp format to include nanoseconds and timezone + formatter.TimestampFormat = "2006-01-02 15:04:05.000000000 -07:00" } else { formatter.DisableTimestamp = true } diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 5c631c62b..688814780 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -69,7 +69,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error e := log.GetLogger(ctx) // log the request - e.Debugf("Request #%d\n> Request: %q %q\n> Request headers:\n%s", + e.Debugf("Request #%d\n> Request: %q %q\n> Request headers:\n%s\n\n", id, req.Method, req.URL, logHeader(req.Header)) // log the response @@ -79,7 +79,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error } else if resp == nil { e.Errorf("No response obtained for request %s %q", req.Method, req.URL) } else { - e.Debugf("Response #%d\n< Response status: %q\n< Response headers:\n%s", + e.Debugf("Response #%d\n< Response status: %q\n< Response headers:\n%s\n\n", id, resp.Status, logHeader(resp.Header)) } return resp, err From b03038ef8107cd1fe8042ff982ad3f770c68ff5d Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Thu, 3 Apr 2025 16:34:00 +0800 Subject: [PATCH 2/8] fix: update time format Signed-off-by: Junjie Gao --- internal/trace/context.go | 21 +++++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) diff --git a/internal/trace/context.go b/internal/trace/context.go index 5537c0345..9b10c55d8 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -43,7 +43,7 @@ func WithLoggerLevel(ctx context.Context, level logrus.Level) context.Context { if level == logrus.DebugLevel { formatter.FullTimestamp = true // Set timestamp format to include nanoseconds and timezone - formatter.TimestampFormat = "2006-01-02 15:04:05.000000000 -07:00" + formatter.TimestampFormat = "2006-01-02 15:04:05.000000000Z" } else { formatter.DisableTimestamp = true } @@ -54,6 +54,23 @@ func WithLoggerLevel(ctx context.Context, level logrus.Level) context.Context { logger.SetFormatter(&formatter) logger.SetLevel(level) - // save logger to context + // Add UTC hook to convert timestamps to UTC + logger.AddHook(&UTCHook{}) + return log.WithLogger(ctx, logger) } + +// UTCHook is a hook for logrus that converts timestamps to UTC +type UTCHook struct{} + +// Levels returns the levels this hook is enabled for +func (h *UTCHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +// Fire is called by logrus when a log entry is created. +// This implementation converts the timestamp to UTC. +func (h *UTCHook) Fire(entry *logrus.Entry) error { + entry.Time = entry.Time.UTC() + return nil +} From 394e3591f4e314c82a4246497413b2688582751f Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Thu, 3 Apr 2025 16:37:10 +0800 Subject: [PATCH 3/8] fix: update Signed-off-by: Junjie Gao --- internal/trace/context.go | 1 - 1 file changed, 1 deletion(-) diff --git a/internal/trace/context.go b/internal/trace/context.go index 9b10c55d8..0d681d343 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -42,7 +42,6 @@ func WithLoggerLevel(ctx context.Context, level logrus.Level) context.Context { var formatter logrus.TextFormatter if level == logrus.DebugLevel { formatter.FullTimestamp = true - // Set timestamp format to include nanoseconds and timezone formatter.TimestampFormat = "2006-01-02 15:04:05.000000000Z" } else { formatter.DisableTimestamp = true From 556caf9a744554b80b81dd5df9964f5cbce0d681 Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Thu, 3 Apr 2025 16:59:53 +0800 Subject: [PATCH 4/8] fix: update E2E Signed-off-by: Junjie Gao --- test/e2e/suite/plugin/install.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/e2e/suite/plugin/install.go b/test/e2e/suite/plugin/install.go index 746babf6a..379a9c2f1 100644 --- a/test/e2e/suite/plugin/install.go +++ b/test/e2e/suite/plugin/install.go @@ -64,35 +64,35 @@ var _ = Describe("notation plugin install", func() { It("with zip bomb single file exceeds 256 MiB size limit in zip format", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_zip.zip"), "-v"). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_zip.zip")). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip bomb single file exceeds 256 MiB size limit in tar.gz format", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_tarGz.tar.gz"), "-v"). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_tarGz.tar.gz")). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip bomb total file size exceeds 256 MiB size limit", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_bomb.zip"), "-v"). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_bomb.zip")). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip slip", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_slip.zip"), "-v"). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_slip.zip")). MatchErrContent("Error: plugin installation failed: file name in zip cannot contain '..', but found \"../../../../../../../../tmp/evil.txt\"\n") }) }) It("with valid plugin file path", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "-v"). + notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath). MatchContent("Successfully installed plugin e2e-plugin, version 1.0.0\n") }) }) @@ -116,7 +116,7 @@ var _ = Describe("notation plugin install", func() { It("with plugin already installed but force install", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "-v"). + notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath). MatchContent("Successfully installed plugin e2e-plugin, version 1.0.0\n") notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "--force"). From 440b321b312b41a99e6580316225ed6dda1e50cc Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Mon, 14 Apr 2025 06:18:32 +0000 Subject: [PATCH 5/8] fix: update Signed-off-by: Junjie Gao --- cmd/notation/internal/flag/options.go | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/cmd/notation/internal/flag/options.go b/cmd/notation/internal/flag/options.go index a51064d5c..fb7e76a66 100644 --- a/cmd/notation/internal/flag/options.go +++ b/cmd/notation/internal/flag/options.go @@ -17,14 +17,12 @@ import ( "context" "fmt" "os" - "runtime" "slices" "strings" "github.com/notaryproject/notation-go/log" "github.com/notaryproject/notation/v2/cmd/notation/internal/display/output" "github.com/notaryproject/notation/v2/internal/trace" - "github.com/notaryproject/notation/v2/internal/version" "github.com/sirupsen/logrus" "github.com/spf13/cobra" "github.com/spf13/pflag" @@ -81,14 +79,6 @@ func (opts *LoggingFlagOpts) InitializeLogger(ctx context.Context) context.Conte return ctx } - // Log environment information - logger := log.GetLogger(ctx) - logger.Infof("Notation Version: %s", version.GetVersion()) - if version.GitCommit != "" { - logger.Infof("Git Commit: %s", version.GitCommit) - } - logger.Infof("OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH) - return withExecutableTrace(ctx) } From c88b397ce5822cc8d47769e73b357a69bdd06dc4 Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Mon, 14 Apr 2025 07:20:30 +0000 Subject: [PATCH 6/8] fix: restore test Signed-off-by: Junjie Gao --- test/e2e/suite/plugin/install.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/e2e/suite/plugin/install.go b/test/e2e/suite/plugin/install.go index 379a9c2f1..746babf6a 100644 --- a/test/e2e/suite/plugin/install.go +++ b/test/e2e/suite/plugin/install.go @@ -64,35 +64,35 @@ var _ = Describe("notation plugin install", func() { It("with zip bomb single file exceeds 256 MiB size limit in zip format", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_zip.zip")). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_zip.zip"), "-v"). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip bomb single file exceeds 256 MiB size limit in tar.gz format", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_tarGz.tar.gz")). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "large_file_tarGz.tar.gz"), "-v"). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip bomb total file size exceeds 256 MiB size limit", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_bomb.zip")). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_bomb.zip"), "-v"). MatchErrContent("Error: plugin installation failed: total file size reached the 256 MiB size limit\n") }) }) It("with zip slip", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_slip.zip")). + notation.ExpectFailure().Exec("plugin", "install", "--file", filepath.Join(NotationE2EMaliciousPluginArchivePath, "zip_slip.zip"), "-v"). MatchErrContent("Error: plugin installation failed: file name in zip cannot contain '..', but found \"../../../../../../../../tmp/evil.txt\"\n") }) }) It("with valid plugin file path", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath). + notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "-v"). MatchContent("Successfully installed plugin e2e-plugin, version 1.0.0\n") }) }) @@ -116,7 +116,7 @@ var _ = Describe("notation plugin install", func() { It("with plugin already installed but force install", func() { Host(nil, func(notation *utils.ExecOpts, _ *Artifact, vhost *utils.VirtualHost) { - notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath). + notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "-v"). MatchContent("Successfully installed plugin e2e-plugin, version 1.0.0\n") notation.Exec("plugin", "install", "--file", NotationE2EPluginTarGzPath, "--force"). From b5e93b972e3c5b3a062e8ea344d1ef51037597c3 Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Mon, 14 Apr 2025 07:22:29 +0000 Subject: [PATCH 7/8] fix: update Signed-off-by: Junjie Gao --- cmd/notation/internal/flag/options.go | 1 - 1 file changed, 1 deletion(-) diff --git a/cmd/notation/internal/flag/options.go b/cmd/notation/internal/flag/options.go index fb7e76a66..44cec099e 100644 --- a/cmd/notation/internal/flag/options.go +++ b/cmd/notation/internal/flag/options.go @@ -78,7 +78,6 @@ func (opts *LoggingFlagOpts) InitializeLogger(ctx context.Context) context.Conte } else { return ctx } - return withExecutableTrace(ctx) } From eb8f9e74b7f3be3e2cb0888dc85eda91f43811f5 Mon Sep 17 00:00:00 2001 From: Junjie Gao Date: Mon, 12 May 2025 07:46:57 +0000 Subject: [PATCH 8/8] fix: add 2 new lines after request or reponse log Signed-off-by: Junjie Gao --- internal/trace/transport.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 688814780..76ca9c751 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -69,7 +69,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error e := log.GetLogger(ctx) // log the request - e.Debugf("Request #%d\n> Request: %q %q\n> Request headers:\n%s\n\n", + e.Debugf("Request #%d\n> Request: %q %q\n> Request headers:\n%s\n\n\n", id, req.Method, req.URL, logHeader(req.Header)) // log the response @@ -79,7 +79,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error } else if resp == nil { e.Errorf("No response obtained for request %s %q", req.Method, req.URL) } else { - e.Debugf("Response #%d\n< Response status: %q\n< Response headers:\n%s\n\n", + e.Debugf("Response #%d\n< Response status: %q\n< Response headers:\n%s\n\n\n", id, resp.Status, logHeader(resp.Header)) } return resp, err