Repository: cerbos/cerbos
Pull request #1255 (2022-09-29 16:04:16)

feat: Temporary log level change with USR1 signal


Patch:
diff --git a/cmd/cerbos/run/run.go b/cmd/cerbos/run/run.go
index 92ea3dd0..bc498460 100644
--- a/cmd/cerbos/run/run.go
+++ b/cmd/cerbos/run/run.go
@@ -75,7 +75,10 @@ type Cmd struct {
 }
 
 func (c *Cmd) Run(k *kong.Kong) error {
-	logging.InitLogging(c.LogLevel)
+	notifyCtx, stopFunc := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
+	defer stopFunc()
+
+	logging.InitLogging(notifyCtx, c.LogLevel)
 	defer zap.L().Sync() //nolint:errcheck
 
 	log := zap.S().Named("run")
@@ -83,9 +86,6 @@ func (c *Cmd) Run(k *kong.Kong) error {
 	undo, _ := maxprocs.Set(maxprocs.Logger(log.Infof))
 	defer undo()
 
-	notifyCtx, stopFunc := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
-	defer stopFunc()
-
 	if err := c.loadConfig(); err != nil {
 		log.Errorw("Failed to load configuration", "error", err)
 		return err
diff --git a/cmd/cerbos/server/server.go b/cmd/cerbos/server/server.go
index 1a36094e..56ad8fb9 100644
--- a/cmd/cerbos/server/server.go
+++ b/cmd/cerbos/server/server.go
@@ -55,7 +55,10 @@ type Cmd struct {
 }
 
 func (c *Cmd) Run() error {
-	logging.InitLogging(string(c.LogLevel))
+	ctx, stopFunc := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
+	defer stopFunc()
+
+	logging.InitLogging(ctx, string(c.LogLevel))
 	defer zap.L().Sync() //nolint:errcheck
 
 	log := zap.S().Named("server")
@@ -72,9 +75,6 @@ func (c *Cmd) Run() error {
 		defer agent.Close()
 	}
 
-	ctx, stopFunc := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
-	defer stopFunc()
-
 	// load any config overrides
 	confOverrides := map[string]any{}
 	for _, override := range c.Set {
diff --git a/internal/observability/logging/logging.go b/internal/observability/logging/logging.go
index 10530cc7..1b625299 100644
--- a/internal/observability/logging/logging.go
+++ b/internal/observability/logging/logging.go
@@ -6,7 +6,11 @@ package logging
 import (
 	"context"
 	"os"
+	"os/signal"
 	"strings"
+	"sync/atomic"
+	"syscall"
+	"time"
 
 	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
 	"github.com/mattn/go-isatty"
@@ -17,29 +21,26 @@ import (
 	"github.com/cerbos/cerbos/internal/util"
 )
 
+const tmpLogLevelDuration = 10 * time.Minute
+
 type ctxLog struct{}
 
 var ctxLogKey = &ctxLog{}
 
 // InitLogging initializes the global logger.
-func InitLogging(level string) {
+func InitLogging(ctx context.Context, level string) {
 	if envLevel := os.Getenv("CERBOS_LOG_LEVEL"); envLevel != "" {
-		doInitLogging(envLevel)
+		doInitLogging(ctx, envLevel)
 		return
 	}
 
-	doInitLogging(level)
+	doInitLogging(ctx, level)
 }
 
-func doInitLogging(level string) {
+func doInitLogging(ctx context.Context, level string) {
 	var logger *zap.Logger
 
-	errorPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-		return lvl >= zapcore.ErrorLevel
-	})
-
 	minLogLevel := zapcore.InfoLevel
-
 	switch strings.ToUpper(level) {
 	case "DEBUG":
 		minLogLevel = zapcore.DebugLevel
@@ -51,13 +52,6 @@ func doInitLogging(level string) {
 		minLogLevel = zapcore.ErrorLevel
 	}
 
-	infoPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-		return lvl < zapcore.ErrorLevel && lvl >= minLogLevel
-	})
-
-	consoleErrors := zapcore.Lock(os.Stderr)
-	consoleInfo := zapcore.Lock(os.Stdout)
-
 	encoderConf := ecszap.NewDefaultEncoderConfig().ToZapCoreEncoderConfig()
 	var consoleEncoder zapcore.Encoder
 
@@ -68,6 +62,18 @@ func doInitLogging(level string) {
 		consoleEncoder = zapcore.NewConsoleEncoder(encoderConf)
 	}
 
+	consoleErrors := zapcore.Lock(os.Stderr)
+	consoleInfo := zapcore.Lock(os.Stdout)
+	atomicLevel := zap.NewAtomicLevelAt(minLogLevel)
+
+	errorPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
+		return atomicLevel.Enabled(lvl) && lvl >= zapcore.ErrorLevel
+	})
+
+	infoPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
+		return atomicLevel.Enabled(lvl) && lvl < zapcore.ErrorLevel
+	})
+
 	core := zapcore.NewTee(
 		zapcore.NewCore(consoleEncoder, consoleErrors, errorPriority),
 		zapcore.NewCore(consoleEncoder, consoleInfo, infoPriority),
@@ -86,6 +92,44 @@ func doInitLogging(level string) {
 			return lvl > zapcore.ErrorLevel
 		}))),
 	)
+
+	handleUSR1Signal(ctx, minLogLevel, &atomicLevel)
+}
+
+// setLevelForDuration sets the global log level to the given level for a given duration. Reverts to the original
+// level after the duration.
+func setLevelForDuration(level, originalLevel zapcore.Level, duration time.Duration, inProgress *atomic.Bool, atomicLevel *zap.AtomicLevel) {
+	log := zap.S().Named("logging")
+
+	log.Infof("Temporarily setting global log level to %s for %s", level, duration)
+	atomicLevel.SetLevel(level)
+
+	time.AfterFunc(duration, func() {
+		log.Infof("Reverting global log level to %s", originalLevel)
+		atomicLevel.SetLevel(originalLevel)
+		inProgress.Store(false)
+	})
+}
+
+// handleUSR1Signal sets the log level to zapcore.DebugLevel for some duration in case syscall.SIGUSR1 received.
+func handleUSR1Signal(ctx context.Context, originalLevel zapcore.Level, atomicLevel *zap.AtomicLevel) {
+	sigusr1 := make(chan os.Signal, 1)
+	signal.Notify(sigusr1, syscall.SIGUSR1)
+
+	go func() {
+		inProgress := atomic.Bool{}
+		for {
+			select {
+			case <-ctx.Done():
+				return
+			case <-sigusr1:
+				if !inProgress.Load() {
+					inProgress.Store(true)
+					setLevelForDuration(zapcore.DebugLevel, originalLevel, tmpLogLevelDuration, &inProgress, atomicLevel)
+				}
+			}
+		}
+	}()
 }
 
 // FromContext returns the logger from the context if one exists. Otherwise it returns a new logger.


Test patch:
diff --git a/internal/test/test.go b/internal/test/test.go
index 960be9bf..b584507d 100644
--- a/internal/test/test.go
+++ b/internal/test/test.go
@@ -28,7 +28,7 @@ import (
 
 func init() {
 	if logLevel := os.Getenv("CERBOS_TEST_LOG_LEVEL"); logLevel != "" {
-		logging.InitLogging(logLevel)
+		logging.InitLogging(context.Background(), logLevel)
 	}
 }