From 23304302a419c1add83fe96bc0ab8de362fe687e Mon Sep 17 00:00:00 2001
From: Halvard Skogsrud <halvard@google.com>
Date: Fri, 12 Nov 2021 06:46:22 +1100
Subject: [PATCH] fix(log): Send Go std `log` to `logrus`, and output `ggcr`
 logs (#6815)

* fix(log): Output ggcr logs

Previously, Skaffold discarded log messages from
[`go-containerregistry`](https://github.com/google/go-containerregistry)
(a.k.a `ggcr`).

This change enables `ggcr` log messages, with severity tied to
Skaffold's log level.

Related: #6041

* fix(log): Send Go std `log` to `logrus`

Includes `ggcr` logs.
---
 pkg/skaffold/output/log/log.go      | 44 ++++++++++++++++++++
 pkg/skaffold/output/log/log_test.go | 62 +++++++++++++++++++++++++++++
 2 files changed, 106 insertions(+)

diff --git a/pkg/skaffold/output/log/log.go b/pkg/skaffold/output/log/log.go
index e9f68eec885..49f7ee57e73 100644
--- a/pkg/skaffold/output/log/log.go
+++ b/pkg/skaffold/output/log/log.go
@@ -20,7 +20,9 @@ import (
 	"context"
 	"fmt"
 	"io"
+	stdlog "log"
 
+	ggcrlogs "github.com/google/go-containerregistry/pkg/logs"
 	"github.com/sirupsen/logrus"
 
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/constants"
@@ -96,5 +98,47 @@ func SetupLogs(stdErr io.Writer, level string, timestamp bool, hook logrus.Hook)
 		FullTimestamp: timestamp,
 	})
 	logrus.AddHook(hook)
+	setupStdLog(logrus.StandardLogger(), lvl)
+	setupGGCRLogging(logrus.StandardLogger(), lvl)
 	return nil
 }
+
+// setupStdLog writes Go's standard library `log` messages to logrus at Info level.
+//
+// This function uses SetFlags() to standardize the output format.
+//
+// TODO(halvards) Add *stdlog.Logger argument (from stdlog.Default) when the build moves to Go >= 1.16.
+// We can't unit test this function in isolation when we're modifying the singleton stdlog instance.
+func setupStdLog(logger *logrus.Logger, lvl logrus.Level) {
+	stdlog.SetFlags(0)
+	if lvl >= logrus.InfoLevel {
+		stdlog.SetOutput(logger.WriterLevel(logrus.InfoLevel))
+	}
+}
+
+// setupGGCRLogging enables go-containerregistry logging, mapping its levels to logrus.
+//
+// The mapping is:
+// - ggcr Warn -> logrus Error
+// - ggcr Progress -> logrus Info
+// - ggcr Debug -> logrus Trace
+//
+// The reasons for this mapping are:
+// - `ggcr` defines `Warn` as "non-fatal errors": https://github.com/google/go-containerregistry/blob/main/pkg/logs/logs.go#L24
+// - `ggcr` `Debug` logging is _very_ verbose and includes HTTP requests and responses, with non-sensitive headers and non-binary payloads.
+//
+// This function uses SetFlags() to standardize the output format.
+func setupGGCRLogging(logger *logrus.Logger, lvl logrus.Level) {
+	if lvl >= logrus.ErrorLevel {
+		ggcrlogs.Warn.SetOutput(logger.WriterLevel(logrus.ErrorLevel))
+		ggcrlogs.Warn.SetFlags(0)
+	}
+	if lvl >= logrus.InfoLevel {
+		ggcrlogs.Progress.SetOutput(logger.WriterLevel(logrus.InfoLevel))
+		ggcrlogs.Progress.SetFlags(0)
+	}
+	if lvl >= logrus.TraceLevel {
+		ggcrlogs.Debug.SetOutput(logger.WriterLevel(logrus.TraceLevel))
+		ggcrlogs.Debug.SetFlags(0)
+	}
+}
diff --git a/pkg/skaffold/output/log/log_test.go b/pkg/skaffold/output/log/log_test.go
index 61424f36aac..a8bd3bd6caf 100644
--- a/pkg/skaffold/output/log/log_test.go
+++ b/pkg/skaffold/output/log/log_test.go
@@ -20,6 +20,7 @@ import (
 	"context"
 	"testing"
 
+	ggcrlogs "github.com/google/go-containerregistry/pkg/logs"
 	"github.com/sirupsen/logrus"
 
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/constants"
@@ -89,3 +90,64 @@ func TestKanikoLogLevel(t *testing.T) {
 		testutil.CheckDeepEqual(t, test.expected, kanikoLevel)
 	}
 }
+
+func TestSetupGGCRLogging(t *testing.T) {
+	tests := []struct {
+		description           string
+		logLevel              logrus.Level
+		expectWarnEnabled     bool
+		expectProgressEnabled bool
+		expectDebugEnabled    bool
+	}{
+		{
+			description: "fatal log level disables ggcr logging",
+			logLevel:    logrus.FatalLevel,
+		},
+		{
+			description:       "error log level enables ggcr warn logging",
+			logLevel:          logrus.ErrorLevel,
+			expectWarnEnabled: true,
+		},
+		{
+			description:       "warn log level enables ggcr warn logging",
+			logLevel:          logrus.WarnLevel,
+			expectWarnEnabled: true,
+		},
+		{
+			description:           "info log level enables ggcr warn and progress logging",
+			logLevel:              logrus.InfoLevel,
+			expectWarnEnabled:     true,
+			expectProgressEnabled: true,
+		},
+		{
+			description:           "debug log level enables ggcr warn and progress logging",
+			logLevel:              logrus.DebugLevel,
+			expectWarnEnabled:     true,
+			expectProgressEnabled: true,
+		},
+		{
+			description:           "trace log level enables ggcr warn and progress and debug logging",
+			logLevel:              logrus.TraceLevel,
+			expectWarnEnabled:     true,
+			expectProgressEnabled: true,
+			expectDebugEnabled:    true,
+		},
+	}
+	for _, test := range tests {
+		testutil.Run(t, test.description, func(t *testutil.T) {
+			setupGGCRLogging(logrus.New(), test.logLevel)
+			t.CheckDeepEqual(test.expectWarnEnabled, ggcrlogs.Enabled(ggcrlogs.Warn))
+			t.CheckDeepEqual(test.expectProgressEnabled, ggcrlogs.Enabled(ggcrlogs.Progress))
+			t.CheckDeepEqual(test.expectDebugEnabled, ggcrlogs.Enabled(ggcrlogs.Debug))
+			if test.expectWarnEnabled {
+				t.CheckDeepEqual(0, ggcrlogs.Warn.Flags())
+			}
+			if test.expectProgressEnabled {
+				t.CheckDeepEqual(0, ggcrlogs.Progress.Flags())
+			}
+			if test.expectDebugEnabled {
+				t.CheckDeepEqual(0, ggcrlogs.Debug.Flags())
+			}
+		})
+	}
+}