[Spike] Proof of concept for modular logging

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")
  }
  }
 

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)
+}

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

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",

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))
  }

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)

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{})
+}

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(),

backend/apid/middlewares/refresh_token.go

@@ -39,15 +39,15 @@ 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
  }
 
  // 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,30 +61,30 @@ 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
  }
 
  // 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
  }
 
  // 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,

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")
 }
 

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{})
+}

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

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)

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 <component>:<log-level> 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")