diff --git a/backend/apid/apid.go b/backend/apid/apid.go index f80bb59cf8..5136c03c13 100644 --- a/backend/apid/apid.go +++ b/backend/apid/apid.go @@ -321,18 +321,18 @@ func (a *APId) Start() error { if a.serveWaitTime <= 0 { a.ready() } else { - logger.Warnf("starting apid as temporarily unavailable for: %s", a.serveWaitTime) + Logger.Warnf("starting apid as temporarily unavailable for: %s", a.serveWaitTime) go func() { select { case <-time.After(a.serveWaitTime): a.ready() - logger.Warn("apid is now available") + Logger.Warn("apid is now available") case <-a.stopping: } }() } - logger.Warn("starting apid on address: ", a.HTTPServer.Addr) + Logger.Warn("starting apid on address: ", a.HTTPServer.Addr) ln, err := net.Listen("tcp", a.HTTPServer.Addr) if err != nil { return fmt.Errorf("failed to start apid: %s", err) @@ -361,9 +361,9 @@ func (a *APId) Start() error { func (a *APId) Stop() error { if err := a.HTTPServer.Shutdown(context.TODO()); err != nil { // failure/timeout shutting down the server gracefully - logger.Error("failed to shutdown http server gracefully - forcing shutdown") + Logger.Error("failed to shutdown http server gracefully - forcing shutdown") if closeErr := a.HTTPServer.Close(); closeErr != nil { - logger.Error("failed to shutdown http server forcefully") + Logger.Error("failed to shutdown http server forcefully") } } diff --git a/backend/apid/logger.go b/backend/apid/logger.go index 7856727683..6e6053b07e 100644 --- a/backend/apid/logger.go +++ b/backend/apid/logger.go @@ -2,6 +2,17 @@ package apid import "github.com/sirupsen/logrus" -var logger = logrus.WithFields(logrus.Fields{ +var Logger = logrus.New().WithFields(logrus.Fields{ "component": "apid", }) + +func init() { + Logger.Logger.SetFormatter(&logrus.JSONFormatter{}) + + // There are other functions and fields that could be of interest. We could + // allow their configuration too, for example to have different component + // spit out their log in different files: + // - SetNoLock() + // - Out + // - SetOutput(output io.Writer) +} diff --git a/backend/apid/middlewares/authentication.go b/backend/apid/middlewares/authentication.go index 7e73e743f2..62f4498a5c 100644 --- a/backend/apid/middlewares/authentication.go +++ b/backend/apid/middlewares/authentication.go @@ -33,7 +33,7 @@ func (a Authentication) Then(next http.Handler) http.Handler { headerString = strings.TrimPrefix(headerString, "Bearer ") token, err := jwt.ValidateToken(headerString) if err != nil { - logger.WithError(err).Warn("invalid token") + Logger.WithError(err).Warn("invalid token") actionErr := actions.NewErrorf(actions.Unauthenticated, "invalid credentials") SimpleLogger{}.Then(errorWriter{err: actionErr}.Then(next)).ServeHTTP(w, r.WithContext(ctx)) return @@ -49,7 +49,7 @@ func (a Authentication) Then(next http.Handler) http.Handler { headerString = strings.TrimPrefix(headerString, "Key ") claims, err := extractAPIKeyClaims(ctx, headerString, a.Store) if err != nil { - logger.WithError(err).Warn("invalid api key") + Logger.WithError(err).Warn("invalid api key") actionErr := actions.NewErrorf(actions.Unauthenticated, "invalid credentials") SimpleLogger{}.Then(errorWriter{err: actionErr}.Then(next)).ServeHTTP(w, r.WithContext(ctx)) return diff --git a/backend/apid/middlewares/authorization.go b/backend/apid/middlewares/authorization.go index 83aaa99e2f..770410e1ed 100644 --- a/backend/apid/middlewares/authorization.go +++ b/backend/apid/middlewares/authorization.go @@ -51,7 +51,7 @@ func (a Authorization) Then(next http.Handler) http.Handler { )) return } - logger.WithError(err).Warning("unexpected error occurred during authorization") + Logger.WithError(err).Warning("unexpected error occurred during authorization") writeErr(w, actions.NewErrorf( actions.InternalErr, "unexpected error occurred during authorization", diff --git a/backend/apid/middlewares/awaitstartup.go b/backend/apid/middlewares/awaitstartup.go index 20e686a1bf..2240df6d1b 100644 --- a/backend/apid/middlewares/awaitstartup.go +++ b/backend/apid/middlewares/awaitstartup.go @@ -25,7 +25,7 @@ func (m *AwaitStartupMiddleware) Then(next http.Handler) http.Handler { ready := m.isReady m.mu.RUnlock() if !ready { - logger.Info("apid temporarily unavailable during startup") + Logger.Info("apid temporarily unavailable during startup") if m.RetryAfterSeconds > 0 { w.Header().Set("Retry-After", fmt.Sprint(m.RetryAfterSeconds)) } diff --git a/backend/apid/middlewares/error.go b/backend/apid/middlewares/error.go index a89a6e16fa..3591cde461 100644 --- a/backend/apid/middlewares/error.go +++ b/backend/apid/middlewares/error.go @@ -36,7 +36,7 @@ func writeErr(w http.ResponseWriter, err error) { errJSON, err := json.Marshal(errRes) if err != nil { - logger.WithError(err).Error("unable to marshal error") + Logger.WithError(err).Error("unable to marshal error") } w.WriteHeader(st) diff --git a/backend/apid/middlewares/logger.go b/backend/apid/middlewares/logger.go index aeeb814645..339c8dd1a1 100644 --- a/backend/apid/middlewares/logger.go +++ b/backend/apid/middlewares/logger.go @@ -2,6 +2,10 @@ package middlewares import "github.com/sirupsen/logrus" -var logger = logrus.WithFields(logrus.Fields{ +var Logger = logrus.New().WithFields(logrus.Fields{ "component": "apid", }) + +func init() { + Logger.Logger.SetFormatter(&logrus.JSONFormatter{}) +} diff --git a/backend/apid/middlewares/logging.go b/backend/apid/middlewares/logging.go index cbfcea5a16..33b052fe25 100644 --- a/backend/apid/middlewares/logging.go +++ b/backend/apid/middlewares/logging.go @@ -16,7 +16,7 @@ type SimpleLogger struct{} // Then middleware func (m SimpleLogger) Then(next http.Handler) http.Handler { - if logger.Logger.Level < logrus.InfoLevel { + if Logger.Logger.Level < logrus.InfoLevel { return next } @@ -32,7 +32,7 @@ func (m SimpleLogger) Then(next http.Handler) http.Handler { } duration := float64(time.Since(start)) / float64(time.Millisecond) - logEntry := logger.WithFields(logrus.Fields{ + logEntry := Logger.WithFields(logrus.Fields{ "duration": fmt.Sprintf("%.3fms", duration), "status": writerWithCapture.Status(), "size": writerWithCapture.Size(), diff --git a/backend/apid/middlewares/refresh_token.go b/backend/apid/middlewares/refresh_token.go index 2274fba37c..66277acd12 100644 --- a/backend/apid/middlewares/refresh_token.go +++ b/backend/apid/middlewares/refresh_token.go @@ -39,7 +39,7 @@ func (m RefreshToken) Then(next http.Handler) http.Handler { // it's expired accessToken, err := jwt.ValidateExpiredToken(accessTokenString) if err != nil { - logger.WithError(err).Error("access token is invalid") + Logger.WithError(err).Error("access token is invalid") http.Error(w, "Request unauthorized", http.StatusUnauthorized) return } @@ -47,7 +47,7 @@ func (m RefreshToken) Then(next http.Handler) http.Handler { // Retrieve the claims for the access token accessClaims, err := jwt.GetClaims(accessToken) if err != nil { - logger.WithError(err).Error("could not parse the access token claims") + Logger.WithError(err).Error("could not parse the access token claims") http.Error(w, err.Error(), http.StatusBadRequest) return } @@ -61,7 +61,7 @@ func (m RefreshToken) Then(next http.Handler) http.Handler { payload := &types.Tokens{} err = decoder.Decode(payload) if err != nil { - logger.WithError(err).Error("could not decode the refresh token") + Logger.WithError(err).Error("could not decode the refresh token") http.Error(w, err.Error(), http.StatusBadRequest) return } @@ -69,7 +69,7 @@ func (m RefreshToken) Then(next http.Handler) http.Handler { // Now we want to validate the refresh token refreshToken, err := jwt.ValidateToken(payload.Refresh) if err != nil { - logger.WithError(err).Error("refresh token is invalid") + Logger.WithError(err).Error("refresh token is invalid") http.Error(w, "Request unauthorized", http.StatusUnauthorized) return } @@ -77,14 +77,14 @@ func (m RefreshToken) Then(next http.Handler) http.Handler { // Retrieve the claims for the refresh token refreshClaims, err := jwt.GetClaims(refreshToken) if err != nil { - logger.WithError(err).Error("could not parse the refresh token claims") + Logger.WithError(err).Error("could not parse the refresh token claims") http.Error(w, err.Error(), http.StatusBadRequest) return } // Make sure the refresh token belongs to the same user as the access token if accessClaims.Subject == "" || accessClaims.Subject != refreshClaims.Subject { - logger.WithFields(logrus.Fields{ + Logger.WithFields(logrus.Fields{ "user": refreshClaims.Subject, "access_token": accessClaims.Subject, "refresh_token": refreshClaims.Subject, diff --git a/backend/authentication/authenticator.go b/backend/authentication/authenticator.go index 218f1048a4..626e4ee889 100644 --- a/backend/authentication/authenticator.go +++ b/backend/authentication/authenticator.go @@ -29,13 +29,13 @@ func (a *Authenticator) Authenticate(ctx context.Context, username, password str for _, provider := range a.providers { claims, err := provider.Authenticate(ctx, username, password) if err != nil || claims == nil { - logger.WithError(err).Debugf( + Logger.WithError(err).Debugf( "could not authenticate with provider %q", provider.Type(), ) continue } - logger.WithFields(logrus.Fields{ + Logger.WithFields(logrus.Fields{ "subject": claims.Subject, "groups": claims.Groups, "provider_id": claims.Provider.ProviderID, @@ -48,7 +48,7 @@ func (a *Authenticator) Authenticate(ctx context.Context, username, password str // TODO(palourde): We might want to return a more meaningful and actionnable // error message, but we don't want to leak sensitive information. - logger.WithField("username", username).Error("authentication failed") + Logger.WithField("username", username).Error("authentication failed") return nil, errors.New("authentication failed") } diff --git a/backend/authentication/logger.go b/backend/authentication/logger.go index 597e572e25..97a11ec5c6 100644 --- a/backend/authentication/logger.go +++ b/backend/authentication/logger.go @@ -2,6 +2,10 @@ package authentication import "github.com/sirupsen/logrus" -var logger = logrus.WithFields(logrus.Fields{ +var Logger = logrus.New().WithFields(logrus.Fields{ "component": "authentication", }) + +func init() { + Logger.Logger.SetFormatter(&logrus.JSONFormatter{}) +} diff --git a/backend/backend.go b/backend/backend.go index 2450ee7b3d..602d6af4a3 100644 --- a/backend/backend.go +++ b/backend/backend.go @@ -13,6 +13,7 @@ import ( "github.com/prometheus/client_golang/prometheus" "github.com/sensu/sensu-go/backend/resource" + "github.com/sirupsen/logrus" "github.com/spf13/viper" "go.etcd.io/etcd/client/pkg/v3/logutil" "go.etcd.io/etcd/client/pkg/v3/transport" @@ -27,6 +28,7 @@ import ( "github.com/sensu/sensu-go/backend/apid" "github.com/sensu/sensu-go/backend/apid/actions" "github.com/sensu/sensu-go/backend/apid/graphql" + "github.com/sensu/sensu-go/backend/apid/middlewares" "github.com/sensu/sensu-go/backend/apid/routers" "github.com/sensu/sensu-go/backend/authentication" "github.com/sensu/sensu-go/backend/authentication/jwt" @@ -321,6 +323,36 @@ func Initialize(ctx context.Context, config *Config) (*Backend, error) { return nil, err } + // Somewhere in this function, we parse the log level string and set the + // logging level on individual module loggers accordingly + for facility, level := range config.LogLevel { + level, err := logrus.ParseLevel(level) + if err != nil { + return nil, err + } + + switch facility { + // This is the global level, for anything that's doesn't have a + // dedicated module logger + case "": + logrus.SetLevel(level) + + // Some modules, like apid, have submodules with independent loggers. + // Some, like the middleware submodule, claim to be the "apid" + // component. Others are their own component. + case "apid": + apid.Logger.Logger.SetLevel(level) + middlewares.Logger.Logger.SetLevel(level) + case "apid.graphql": + // apidGraphqlImport.Logger.Logger.SetLevel(level) + case "apid.router": + // apidRouterImport.Logger.Logger.SetLevel(level) + + case "authentication": + authentication.Logger.Logger.SetLevel(level) + } + } + // Create the store, which lives on top of etcd stor := etcdstore.NewStore(b.Client, config.EtcdName) b.Store = stor diff --git a/backend/cmd/logger_unix.go b/backend/cmd/logger_unix.go index b692507181..bc06e07ec3 100644 --- a/backend/cmd/logger_unix.go +++ b/backend/cmd/logger_unix.go @@ -12,6 +12,18 @@ import ( "github.com/sirupsen/logrus" ) +// This needs to be adapted, or scrapped altogether in favor of some form of +// live configuration reloading. If we try to keep this mechanism, we are in a +// catch 22: if we increment all the loggers by one from their current level +// we'll end up in a mess of levels, and if we set all the loggers to the same +// global value we loose the differenciated log levels until the next restart. +// +// Many Unix daemons like sshd and unbound implement graceful configuration +// reloading to circumvent this issue: SIGHUP is used to tell the process to +// reread the configuration file it was started with and adjust the +// configuration accordingly (for some compatible configuration parameters, not +// all), typically without dropping active connections. +// See: https://en.wikipedia.org/wiki/Signal_(IPC)#SIGHUP func init() { sigs := make(chan os.Signal, 1) signal.Notify(sigs, syscall.SIGUSR1) diff --git a/backend/cmd/start.go b/backend/cmd/start.go index 9d319beb69..b4ad9299ec 100644 --- a/backend/cmd/start.go +++ b/backend/cmd/start.go @@ -205,11 +205,48 @@ func StartCommand(initialize InitializeFunc) *cobra.Command { return setupErr } - level, err := logrus.ParseLevel(viper.GetString(flagLogLevel)) - if err != nil { - return err + getLogLevelMap := func(s string) map[string]string { + entries := strings.Split(s, ",") + + m := make(map[string]string) + for _, e := range entries { + tokens := strings.Split(e, ":") + + var k, v string + switch len(tokens) { + // There is no ':' in the entry, this is the global log + // level + case 1: + k = "" + v = strings.TrimSpace(tokens[0]) + + // This is a : entry + case 2: + k = strings.TrimSpace(tokens[0]) + v = strings.TrimSpace(tokens[1]) + + default: + // TODO: error? + } + + m[k] = v + } + + return m + } + + logLevelString := viper.GetString(flagLogLevel) + logLevel := getLogLevelMap(logLevelString) + + if logLevel[""] != "" { + globalLevel, err := logrus.ParseLevel(logLevel[""]) + if err != nil { + return err + } + logrus.SetLevel(globalLevel) + } else { + // TODO: logrus.SetLevel() to some default level } - logrus.SetLevel(level) // If no clustering options are provided, default to a static // cluster 'defaultEtcdName=defaultEtcdPeerURL'. @@ -241,6 +278,7 @@ func StartCommand(initialize InitializeFunc) *cobra.Command { DeregistrationHandler: viper.GetString(flagDeregistrationHandler), CacheDir: viper.GetString(flagCacheDir), StateDir: viper.GetString(flagStateDir), + LogLevel: logLevel, EtcdAdvertiseClientURLs: viper.GetStringSlice(flagEtcdAdvertiseClientURLs), EtcdListenClientURLs: viper.GetStringSlice(flagEtcdListenClientURLs), @@ -325,16 +363,19 @@ func StartCommand(initialize InitializeFunc) *cobra.Command { } // Etcd log level - if cfg.EtcdLogLevel == "" { - switch level { - case logrus.TraceLevel: - cfg.EtcdLogLevel = "debug" - case logrus.WarnLevel: - cfg.EtcdLogLevel = "warn" - default: - cfg.EtcdLogLevel = level.String() - } - } + // This needs to be folded into the `--log-level` flag, with the + // `--etcd-log-level` flags becoming deprecated ways to set + // logLevel["etcd"] and logLevel["etcd-client"] + // if cfg.EtcdLogLevel == "" { + // switch level { + // case logrus.TraceLevel: + // cfg.EtcdLogLevel = "debug" + // case logrus.WarnLevel: + // cfg.EtcdLogLevel = "warn" + // default: + // cfg.EtcdLogLevel = level.String() + // } + // } ctx, cancel := context.WithCancel(context.Background()) defer cancel() @@ -549,6 +590,7 @@ func flagSet(server bool) *pflag.FlagSet { flagSet.String(flagTrustedCAFile, viper.GetString(flagTrustedCAFile), "TLS CA certificate bundle in PEM format") flagSet.Bool(flagInsecureSkipTLSVerify, viper.GetBool(flagInsecureSkipTLSVerify), "skip TLS verification (not recommended!)") flagSet.Bool(flagDebug, false, "enable debugging and profiling features") + // TODO: Change the help message flagSet.String(flagLogLevel, viper.GetString(flagLogLevel), "logging level [panic, fatal, error, warn, info, debug, trace]") flagSet.Int(backend.FlagEventdWorkers, viper.GetInt(backend.FlagEventdWorkers), "number of workers spawned for processing incoming events") flagSet.Int(backend.FlagEventdBufferSize, viper.GetInt(backend.FlagEventdBufferSize), "number of incoming events that can be buffered") diff --git a/backend/config.go b/backend/config.go index 03b7d4516a..2b62c0c16c 100644 --- a/backend/config.go +++ b/backend/config.go @@ -114,7 +114,10 @@ type Config struct { TLS *corev2.TLSOptions - LogLevel string + // LogLevel maps a component name to its log level. The "" key interpreted + // as the global, default level. This could/should even be + // map[string]logrus.Level + LogLevel map[string]string EtcdLogLevel string EtcdClientLogLevel string diff --git a/backend/etcd/etcd.go b/backend/etcd/etcd.go index 6b721b9403..5c1535ef8b 100644 --- a/backend/etcd/etcd.go +++ b/backend/etcd/etcd.go @@ -416,6 +416,7 @@ func (ww *watchWrapper) Watch(ctx context.Context, key string, opts ...clientv3. return ww.Watcher.Watch(&blankContext{ctx}, key, opts...) } +// TODO: Need to do something here? func LogLevelToZap(level string) zapcore.Level { switch level { case "debug":