From 274973a04cde2a70bc4ef77ad574ea7d4df10fe6 Mon Sep 17 00:00:00 2001 From: Christie Wilson Date: Tue, 26 Jun 2018 16:38:06 -0700 Subject: [PATCH] Do not log in log library Okay this is slightly more repeated code, but hear me out! When you log in a library, it means the caller has no control over whether those logs are emitted or not - case in point, the e2e tests are using this library, and now they dump the json config and log level at the beginning of every test, which we don't want and can't control. This commit changes the `logging` lib such that it's the caller's responsibility to decide whether to log or not. This also changes the logic such that the logging configuration is no longer logged at debug. --- cmd/activator/main.go | 6 +- cmd/autoscaler/main.go | 6 +- cmd/controller/main.go | 7 +- cmd/queue/main.go | 13 +++- cmd/webhook/main.go | 6 +- pkg/logging/config.go | 34 ++++++---- pkg/logging/config_test.go | 128 ++++++++++++++++++++++++++++++++++--- test/logging.go | 6 +- 8 files changed, 179 insertions(+), 27 deletions(-) diff --git a/cmd/activator/main.go b/cmd/activator/main.go index e6ce107c9843..565db92eef43 100644 --- a/cmd/activator/main.go +++ b/cmd/activator/main.go @@ -103,7 +103,11 @@ func (a *activationHandler) handler(w http.ResponseWriter, r *http.Request) { func main() { flag.Parse() - logger := logging.NewLoggerFromDefaultConfigMap("loglevel.activator").Named("activator") + + var logger *zap.SugaredLogger + if logger, err := logging.NewDefaultConfigMapLogger(logging.DefaultLoggingConfigPath, "activator"); err != nil { + logger.Errorf("Error initializing logger: %s", err) + } defer logger.Sync() logger.Info("Starting the knative activator") diff --git a/cmd/autoscaler/main.go b/cmd/autoscaler/main.go index 98ca51587fab..58a91a8984be 100644 --- a/cmd/autoscaler/main.go +++ b/cmd/autoscaler/main.go @@ -230,7 +230,11 @@ func handler(w http.ResponseWriter, r *http.Request) { func main() { flag.Parse() - logger = logging.NewLoggerFromDefaultConfigMap("loglevel.autoscaler").Named("autoscaler") + + var logger *zap.SugaredLogger + if logger, err := logging.NewDefaultConfigMapLogger(logging.DefaultLoggingConfigPath, "autoscaler"); err != nil { + logger.Errorf("Error initializing logger: %s", err) + } defer logger.Sync() initEnv() diff --git a/cmd/controller/main.go b/cmd/controller/main.go index f8150ef0ce0c..a5cff02ae98a 100644 --- a/cmd/controller/main.go +++ b/cmd/controller/main.go @@ -22,6 +22,7 @@ import ( "github.com/knative/serving/pkg" "github.com/knative/serving/pkg/configmap" + "go.uber.org/zap" "github.com/josephburnett/k8sflag/pkg/k8sflag" "github.com/knative/serving/pkg/controller" @@ -76,7 +77,11 @@ var ( func main() { flag.Parse() - logger := logging.NewLoggerFromDefaultConfigMap("loglevel.controller").Named("controller") + + var logger *zap.SugaredLogger + if logger, err := logging.NewDefaultConfigMapLogger(logging.DefaultLoggingConfigPath, "controller"); err != nil { + logger.Errorf("Error initializing logger: %s", err) + } defer logger.Sync() if loggingEnableVarLogCollection.Get() { diff --git a/cmd/queue/main.go b/cmd/queue/main.go index fa2d88e11e89..f9ab0b2fc5a4 100644 --- a/cmd/queue/main.go +++ b/cmd/queue/main.go @@ -262,9 +262,20 @@ func setupAdminHandlers(server *http.Server) { server.ListenAndServe() } +func initializeLogging() *zap.SugaredLogger { + configJSON := os.Getenv("SERVING_LOGGING_CONFIG") + levelOverride := os.Getenv("SERVING_LOGGING_LEVEL") + genericLogger, err := logging.NewLogger(configJSON, levelOverride) + logger = genericLogger.Named("queueproxy") + if err != nil { + logger.Errorf("Error initializing logger: %s", err) + } + return logger +} + func main() { flag.Parse() - logger = logging.NewLogger(os.Getenv("SERVING_LOGGING_CONFIG"), os.Getenv("SERVING_LOGGING_LEVEL")).Named("queueproxy") + logger = initializeLogging() defer logger.Sync() initEnv() diff --git a/cmd/webhook/main.go b/cmd/webhook/main.go index 050d6f99d04c..fb90599173e3 100644 --- a/cmd/webhook/main.go +++ b/cmd/webhook/main.go @@ -31,7 +31,11 @@ import ( func main() { flag.Parse() - logger := logging.NewLoggerFromDefaultConfigMap("loglevel.webhook").Named("webhook") + + var logger *zap.SugaredLogger + if logger, err := logging.NewDefaultConfigMapLogger(logging.DefaultLoggingConfigPath, "webhook"); err != nil { + logger.Errorf("Error initializing logger: %s", err) + } defer logger.Sync() logger.Info("Starting the Configuration Webhook") diff --git a/pkg/logging/config.go b/pkg/logging/config.go index 6e2177bbee6f..d265aa820129 100644 --- a/pkg/logging/config.go +++ b/pkg/logging/config.go @@ -19,21 +19,25 @@ package logging import ( "encoding/json" "errors" + "fmt" - "github.com/knative/serving/pkg/logging/logkey" "github.com/josephburnett/k8sflag/pkg/k8sflag" "go.uber.org/zap" "go.uber.org/zap/zapcore" ) +// DefaultLoggingConfigPath is the path where the zap logging +// config will be written in a default Knative deployment. +const DefaultLoggingConfigPath = "/etc/config-logging" + // NewLogger creates a logger with the supplied configuration. // If configuration is empty, a fallback configuration is used. // If configuration cannot be used to instantiate a logger, // the same fallback configuration is used. -func NewLogger(configJSON string, levelOverride string) *zap.SugaredLogger { +func NewLogger(configJSON string, levelOverride string) (*zap.SugaredLogger, error) { logger, err := newLoggerFromConfig(configJSON, levelOverride) if err == nil { - return logger.Sugar() + return logger.Sugar(), nil } logger, err2 := zap.NewProduction() @@ -41,16 +45,23 @@ func NewLogger(configJSON string, levelOverride string) *zap.SugaredLogger { panic(err2) } - logger.Error("Failed to parse the logging config. Falling back to default logger.", zap.Error(err), zap.String(logkey.JSONConfig, configJSON)) - return logger.Sugar() + return logger.Sugar(), fmt.Errorf("Failed to parse the logging config. Falling back to default logger. Error: %s. Config: %s", err, configJSON) } -// NewLoggerFromDefaultConfigMap creates a logger using the configuration within /etc/config-logging file. -func NewLoggerFromDefaultConfigMap(logLevelKey string) *zap.SugaredLogger { - loggingFlagSet := k8sflag.NewFlagSet("/etc/config-logging") +// NewDefaultConfigMapLogger creates a logging object for the +// for the logLevelKey within configPath corresponding +// to the provided componentKey. +func NewDefaultConfigMapLogger(configPath string, componentKey string) (*zap.SugaredLogger, error) { + logLevelKey := "loglevel." + componentKey + + loggingFlagSet := k8sflag.NewFlagSet(configPath) + fmt.Println(loggingFlagSet) zapCfg := loggingFlagSet.String("zap-logger-config", "") zapLevelOverride := loggingFlagSet.String(logLevelKey, "") - return NewLogger(zapCfg.Get(), zapLevelOverride.Get()) + + genericLogger, err := NewLogger(zapCfg.Get(), zapLevelOverride.Get()) + logger := genericLogger.Named(componentKey) + return logger, err } func newLoggerFromConfig(configJSON string, levelOverride string) (*zap.Logger, error) { @@ -65,6 +76,7 @@ func newLoggerFromConfig(configJSON string, levelOverride string) (*zap.Logger, if len(levelOverride) > 0 { var level zapcore.Level + // If the levelOverride can't be parsed, we just ignore it and continue. if err := level.Set(levelOverride); err == nil { loggingCfg.Level = zap.NewAtomicLevelAt(level) } @@ -75,7 +87,5 @@ func newLoggerFromConfig(configJSON string, levelOverride string) (*zap.Logger, return nil, err } - logger.Info("Successfully created the logger.", zap.String(logkey.JSONConfig, configJSON)) - logger.Sugar().Infof("Logging level set to %v", loggingCfg.Level) - return logger, nil + return logger, err } diff --git a/pkg/logging/config_test.go b/pkg/logging/config_test.go index fe39e7b518e8..a2e340c2cca3 100644 --- a/pkg/logging/config_test.go +++ b/pkg/logging/config_test.go @@ -17,25 +17,74 @@ limitations under the License. package logging import ( + "fmt" + "io/ioutil" + "os" + "path/filepath" "testing" "go.uber.org/zap" ) -func TestNewLogger(t *testing.T) { - logger := NewLogger("", "") +const completeConfig = `{ + "level": "info", + "development": false, + "sampling": { + "initial": 100, + "thereafter": 100 + }, + "outputPaths": ["stdout"], + "errorOutputPaths": ["stderr"], + "encoding": "json", + "encoderConfig": { + "timeKey": "", + "levelKey": "level", + "nameKey": "logger", + "callerKey": "caller", + "messageKey": "msg", + "stacktraceKey": "stacktrace", + "lineEnding": "", + "levelEncoder": "", + "timeEncoder": "", + "durationEncoder": "", + "callerEncoder": "" + } +}` +const minimalConfigTemplate = `{ + "level": "%s", + "outputPaths": ["stdout"], + "errorOutputPaths": ["stderr"], + "encoding": "json" +}` + +func TestNewLoggerEmptyConfig(t *testing.T) { + logger, err := NewLogger("", "") + if err == nil { + t.Error("expected error when providing empty config") + } if logger == nil { t.Error("expected a non-nil logger") } +} - logger = NewLogger("some invalid JSON here", "") +func TestNewLoggerInvalidJson(t *testing.T) { + logger, err := NewLogger("some invalid JSON here", "") + if err == nil { + t.Error("expected error when providing invalid config") + } if logger == nil { t.Error("expected a non-nil logger") } +} +func TestNewLoggerValidErrorConfig(t *testing.T) { // No good way to test if all the config is applied, // but at the minimum, we can check and see if level is getting applied. - logger = NewLogger("{\"level\": \"error\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "") + jsonConfig := fmt.Sprintf(minimalConfigTemplate, "error") + logger, err := NewLogger(jsonConfig, "") + if err != nil { + t.Errorf("did not expect error when providing valid config with error log level: %s", err) + } if logger == nil { t.Error("expected a non-nil logger") } @@ -45,8 +94,14 @@ func TestNewLogger(t *testing.T) { if ce := logger.Desugar().Check(zap.ErrorLevel, "test"); ce == nil { t.Error("expected to get error logs from the logger configured with error as min threshold") } +} - logger = NewLogger("{\"level\": \"info\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "") +func TestNewLoggerValidInfoConfig(t *testing.T) { + jsonConfig := fmt.Sprintf(minimalConfigTemplate, "info") + logger, err := NewLogger(jsonConfig, "") + if err != nil { + t.Errorf("did not expect error when providing valid config with info log level: %s", err) + } if logger == nil { t.Error("expected a non-nil logger") } @@ -56,9 +111,14 @@ func TestNewLogger(t *testing.T) { if ce := logger.Desugar().Check(zap.InfoLevel, "test"); ce == nil { t.Error("expected to get info logs from the logger configured with info as min threshold") } +} - // Test logging override - logger = NewLogger("{\"level\": \"error\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "info") +func TestNewLoggerOverrideInfo(t *testing.T) { + jsonConfig := fmt.Sprintf(minimalConfigTemplate, "error") + logger, err := NewLogger(jsonConfig, "info") + if err != nil { + t.Errorf("did not expect error when providing valid config with overridden info log level: %s", err) + } if logger == nil { t.Error("expected a non-nil logger") } @@ -68,9 +128,14 @@ func TestNewLogger(t *testing.T) { if ce := logger.Desugar().Check(zap.InfoLevel, "test"); ce == nil { t.Error("expected to get info logs from the logger configured with info as min threshold") } +} - // Invalid logging override - logger = NewLogger("{\"level\": \"error\", \"outputPaths\": [\"stdout\"],\"errorOutputPaths\": [\"stderr\"],\"encoding\": \"json\"}", "randomstring") +func TestNewLoggerInvalidOverride(t *testing.T) { + jsonConfig := fmt.Sprintf(minimalConfigTemplate, "error") + logger, err := NewLogger(jsonConfig, "randomstring") + if err != nil { + t.Errorf("did not expect error when providing invalid log level override, it should just be ignored: %s", err) + } if logger == nil { t.Error("expected a non-nil logger") } @@ -81,3 +146,48 @@ func TestNewLogger(t *testing.T) { t.Error("expected to get error logs from the logger configured with error as min threshold") } } + +func TestNewDefaultConfigMapLogger(t *testing.T) { + dir, err := ioutil.TempDir("", "") + if err != nil { + t.Fatalf("Could not create temporary directory for test config: %s", err) + } + defer os.RemoveAll(dir) + if err := writeConfig(dir, "loglevel.myfoo", "info"); err != nil { + t.Fatalf("Failed to write example config to temporary dir %s: %s", dir, err) + } + if err := writeConfig(dir, "zap-logger-config", completeConfig); err != nil { + t.Fatalf("Failed to write example config to temporary dir %s: %s", dir, err) + } + + logger, err := NewDefaultConfigMapLogger(dir, "myfoo") + if err != nil { + t.Errorf("did not expect error when creating logger from config file: %s", err) + } + if logger == nil { + t.Error("expected logger to be created successfully") + } +} +func TestNewDefaultConfigMapLoggerInvalidUsesDefault(t *testing.T) { + dir, err := ioutil.TempDir("", "") + if err != nil { + t.Fatalf("Could not create temporary directory for test config: %s", err) + } + defer os.RemoveAll(dir) + if err := writeConfig(dir, "zap-logger-config", "catbus"); err != nil { + t.Fatalf("Failed to write example config to temporary dir %s: %s", dir, err) + } + + logger, err := NewDefaultConfigMapLogger(dir, "myfoo") + if err == nil { + t.Error("expected error when creating logger from invalid config file") + } + if logger == nil { + t.Error("expected default logger to be created successfully") + } +} + +func writeConfig(dir, key, value string) error { + filename := filepath.Join(dir, key) + return ioutil.WriteFile(filename, []byte(value), 0666) +} diff --git a/test/logging.go b/test/logging.go index ab8d68e85715..e2fa487b5ede 100644 --- a/test/logging.go +++ b/test/logging.go @@ -85,7 +85,11 @@ func newLogger(logLevel string) *zap.SugaredLogger { } }` configJSON := fmt.Sprintf(configJSONTemplate, logLevel) - return logging.NewLogger(string(configJSON), logLevel) + logger, err := logging.NewLogger(configJSON, logLevel) + if err != nil { + logger.Errorf("Error initializing logger: %s", err) + } + return logger } func initializeMetricExporter() {