core/config: remove debug option, always use json logs (#4857)

* core/config: remove debug option, always use json logs

* go mod tidy

authorize/grpc_test.go

@@ -257,7 +257,7 @@ fYCZHo3CID0gRSemaQ/jYMgyeBFrHIr6icZh
 
 	var logOutput bytes.Buffer
 	zl := zerolog.New(&logOutput)
-	testutil.SetLogger(t, &zl)
+	testutil.SetLogger(t, zl)
 
 	ctx := context.Background()
 	for i := range cases {

config/log.go

@@ -34,12 +34,6 @@ func (mgr *LogManager) OnConfigChange(_ context.Context, cfg *Config) {
 	mgr.mu.Lock()
 	defer mgr.mu.Unlock()
 
-	if cfg.Options.Debug {
-		log.EnableDebug()
-	} else {
-		log.DisableDebug()
-	}
-
 	if cfg.Options.LogLevel != "" {
 		log.SetLevel(cfg.Options.LogLevel.ToZerolog())
 	}

config/options.go

@@ -57,7 +57,7 @@ type Options struct {
 	// InstallationID is used to indicate a unique installation of pomerium. Useful for telemetry.
 	InstallationID string `mapstructure:"installation_id" yaml:"installation_id,omitempty"`
 
-	// Debug outputs human-readable logs to Stdout.
+	// Debug is deprecated.
 	Debug bool `mapstructure:"pomerium_debug" yaml:"pomerium_debug,omitempty"`
 
 	// LogLevel sets the global override for log level. All Loggers will use at least this value.
@@ -313,7 +313,6 @@ type certificateFilePair struct {
 
 // DefaultOptions are the default configuration options for pomerium
 var defaultOptions = Options{
-	Debug:                    false,
 	LogLevel:                 LogLevelInfo,
 	Services:                 "all",
 	CookieHTTPOnly:           true,
@@ -1438,7 +1437,6 @@ func (o *Options) ApplySettings(ctx context.Context, certsIndex *cryptutil.Certi
 	}
 
 	set(&o.InstallationID, settings.InstallationId)
-	set(&o.Debug, settings.Debug)
 	setLogLevel(&o.LogLevel, settings.LogLevel)
 	setAccessLogFields(&o.AccessLogFields, settings.AccessLogFields)
 	setAuthorizeLogFields(&o.AuthorizeLogFields, settings.AuthorizeLogFields)

config/options_test.go

@@ -722,7 +722,7 @@ func TestDeprecatedClientCAOptions(t *testing.T) {
 
 	var logOutput bytes.Buffer
 	zl := zerolog.New(&logOutput)
-	testutil.SetLogger(t, &zl)
+	testutil.SetLogger(t, zl)
 
 	t.Run("CA", func(t *testing.T) {
 		logOutput.Reset()

examples/config/config.example.yaml

@@ -2,7 +2,6 @@
 
 #
 # address: ":8443" # optional, default is 443
-# pomerium_debug: true # optional, default is false
 # service: "all" # optional, default is all
 # log_level: info # optional, default is debug
 

go.mod

@@ -37,7 +37,6 @@ require (
 	github.com/jackc/pgx/v5 v5.5.0
 	github.com/klauspost/compress v1.17.4
 	github.com/martinlindhe/base36 v1.1.1
-	github.com/mattn/go-isatty v0.0.20
 	github.com/mholt/acmez v1.2.0
 	github.com/minio/minio-go/v7 v7.0.65
 	github.com/mitchellh/hashstructure/v2 v2.0.2
@@ -153,6 +152,7 @@ require (
 	github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0 // indirect
 	github.com/magiconair/properties v1.8.7 // indirect
 	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/matttproud/golang_protobuf_extensions/v2 v2.0.0 // indirect
 	github.com/miekg/dns v1.1.55 // indirect
 	github.com/minio/md5-simd v1.1.2 // indirect

internal/log/log.go

@@ -7,6 +7,7 @@ import (
 	"os"
 
 	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 
@@ -14,7 +15,6 @@ import (
 )
 
 var (
-	logger    = atomicutil.NewValue(new(zerolog.Logger))
 	zapLogger = atomicutil.NewValue(new(zap.Logger))
 	zapLevel  zap.AtomicLevel
 )
@@ -32,31 +32,16 @@ func init() {
 		zapLevel,
 	)))
 
-	DisableDebug()
-}
-
-// DisableDebug tells the logger to use stdout and json output.
-func DisableDebug() {
 	l := zerolog.New(os.Stdout).With().Timestamp().Logger()
-	SetLogger(&l)
+	log.Logger = l
+	// set the default context logger
+	zerolog.DefaultContextLogger = &l
 	zapLevel.SetLevel(zapcore.InfoLevel)
 }
 
-// EnableDebug tells the logger to use stdout and pretty print output.
-func EnableDebug() {
-	l := zerolog.New(os.Stdout).With().Timestamp().Logger().Output(zerolog.ConsoleWriter{Out: os.Stdout})
-	SetLogger(&l)
-	zapLevel.SetLevel(zapcore.DebugLevel)
-}
-
-// SetLogger sets zerolog the logger.
-func SetLogger(l *zerolog.Logger) {
-	logger.Store(l)
-}
-
-// Logger returns the global logger.
+// Logger returns the zerolog Logger.
 func Logger() *zerolog.Logger {
-	return logger.Load()
+	return &log.Logger
 }
 
 // ZapLogger returns the global zap logger.

internal/log/log_test.go

@@ -4,97 +4,106 @@ import (
 	"context"
 	"errors"
 	"flag"
+	"os"
 	"time"
 
 	"github.com/rs/zerolog"
+	zerologlog "github.com/rs/zerolog/log"
 
 	"github.com/pomerium/pomerium/internal/log"
 )
 
-// setup would normally be an init() function, however, there seems
-// to be something awry with the testing framework when we set the
-// global Logger from an init()
-func setup() {
-	// UNIX Time is faster and smaller than most timestamps
-	// If you set zerolog.TimeFieldFormat to an empty string,
-	// logs will write with UNIX time
-	zerolog.TimeFieldFormat = ""
+func captureOutput(f func()) {
 	// In order to always output a static time to stdout for these
 	// examples to pass, we need to override zerolog.TimestampFunc
 	// and log.Logger globals -- you would not normally need to do this
+	originalTimestampFunc := zerolog.TimestampFunc
 	zerolog.TimestampFunc = func() time.Time {
 		return time.Date(2008, 1, 8, 17, 5, 5, 0, time.UTC)
 	}
-	log.DisableDebug()
+
+	originalLogger := zerologlog.Logger
+	newLogger := originalLogger.
+		Output(os.Stdout).
+		Level(zerolog.TraceLevel)
+	zerologlog.Logger = newLogger
+	zerolog.DefaultContextLogger = &newLogger
+
+	f()
+
+	zerolog.DefaultContextLogger = &originalLogger
+	zerolog.TimestampFunc = originalTimestampFunc
+	zerologlog.Logger = originalLogger
 }
 
 // Simple logging example using the Print function in the log package
 // Note that both Print and Printf are at the debug log level by default
 func ExamplePrint() {
-	setup()
-
+	captureOutput(func() {
 		log.Print("hello world")
-	// Output: {"level":"debug","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 func ExampleWith() {
-	setup()
+	captureOutput(func() {
 		sublog := log.With().Str("foo", "bar").Logger()
 		sublog.Debug().Msg("hello world")
-	// Output: {"level":"debug","foo":"bar","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"debug","foo":"bar","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Simple logging example using the Printf function in the log package
 func ExamplePrintf() {
-	setup()
-
+	captureOutput(func() {
 		log.Printf("hello %s", "world")
-	// Output: {"level":"debug","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log with no particular "level"
 func ExampleLog() {
-	setup()
+	captureOutput(func() {
 		log.Log(context.Background()).Msg("hello world")
-
-	// Output: {"time":1199811905,"message":"hello world"}
+	})
+	// Output: {"time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log at a particular "level" (in this case, "debug")
 func ExampleDebug() {
-	setup()
+	captureOutput(func() {
 		log.Debug(context.Background()).Msg("hello world")
-
-	// Output: {"level":"debug","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log at a particular "level" (in this case, "info")
 func ExampleInfo() {
-	setup()
+	captureOutput(func() {
 		log.Info(context.Background()).Msg("hello world")
-
-	// Output: {"level":"info","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"info","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log at a particular "level" (in this case, "warn")
 func ExampleWarn() {
-	setup()
+	captureOutput(func() {
 		log.Warn(context.Background()).Msg("hello world")
-
-	// Output: {"level":"warn","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"warn","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log at a particular "level" (in this case, "error")
 func ExampleError() {
-	setup()
+	captureOutput(func() {
 		log.Error(context.Background()).Msg("hello world")
-
-	// Output: {"level":"error","time":1199811905,"message":"hello world"}
+	})
+	// Output: {"level":"error","time":"2008-01-08T17:05:05Z","message":"hello world"}
 }
 
 // Example of a log at a particular "level" (in this case, "fatal")
 func ExampleFatal() {
-	setup()
+	captureOutput(func() {
 		err := errors.New("a repo man spends his life getting into tense situations")
 		service := "myservice"
 
@@ -102,14 +111,14 @@ func ExampleFatal() {
 			Err(err).
 			Str("service", service).
 			Msg("Cannot start")
-
-	// Outputs: {"level":"fatal","time":1199811905,"error":"a repo man spends his life getting into tense situations","service":"myservice","message":"Cannot start myservice"}
+	})
+	// Outputs: {"level":"fatal","time":"2008-01-08T17:05:05Z","error":"a repo man spends his life getting into tense situations","service":"myservice","message":"Cannot start myservice"}
 }
 
 // This example uses command-line flags to demonstrate various outputs
 // depending on the chosen log level.
 func Example() {
-	setup()
+	captureOutput(func() {
 		debug := flag.Bool("debug", false, "sets log level to debug")
 
 		flag.Parse()
@@ -128,12 +137,12 @@ func Example() {
 			value := "bar"
 			e.Str("foo", value).Msg("some debug message")
 		}
-
-	// Output: {"level":"info","time":1199811905,"message":"This message appears when log level set to Debug or Info"}
+	})
+	// Output: {"level":"info","time":"2008-01-08T17:05:05Z","message":"This message appears when log level set to Debug or Info"}
 }
 
 func ExampleSetLevel() {
-	setup()
+	captureOutput(func() {
 		log.SetLevel(zerolog.InfoLevel)
 		log.Debug(context.Background()).Msg("Debug")
 		log.Info(context.Background()).Msg("Debug or Info")
@@ -148,17 +157,16 @@ func ExampleSetLevel() {
 		log.Error(context.Background()).Msg("Debug or Info or Warn or Error")
 		log.SetLevel(zerolog.DebugLevel)
 		log.Debug(context.Background()).Msg("Debug")
-
+	})
 	// Output:
-	// {"level":"info","time":1199811905,"message":"Debug or Info"}
-	// {"level":"warn","time":1199811905,"message":"Debug or Info or Warn"}
-	// {"level":"error","time":1199811905,"message":"Debug or Info or Warn or Error"}
-	// {"level":"debug","time":1199811905,"message":"Debug"}
+	// {"level":"info","time":"2008-01-08T17:05:05Z","message":"Debug or Info"}
+	// {"level":"warn","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn"}
+	// {"level":"error","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn or Error"}
+	// {"level":"debug","time":"2008-01-08T17:05:05Z","message":"Debug"}
 }
 
 func ExampleContext() {
-	setup()
-
+	captureOutput(func() {
 		bg := context.Background()
 		ctx1 := log.WithContext(bg, func(c zerolog.Context) zerolog.Context {
 			return c.Str("param_one", "one")
@@ -177,10 +185,10 @@ func ExampleContext() {
 			})
 		}
 		log.Info(ctx1).Str("non_ctx_param", "value").Msg("after counter")
-
-	/*
-		{"level":"warn","ctx":"one","param":"first","time":1199811905,"message":"first"}
-		{"level":"warn","ctx":"two","param":"second","time":1199811905,"message":"second"}
-		{"level":"warn","param":"third","time":1199811905,"message":"third"}
-	*/
+	})
+	// Output:
+	// {"level":"warn","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"background"}
+	// {"level":"warn","param_one":"one","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"first"}
+	// {"level":"warn","param_one":"one","param_two":"two","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"second"}
+	// {"level":"info","param_one":"one","counter":0,"counter":1,"counter":2,"counter":3,"counter":4,"counter":5,"counter":6,"counter":7,"counter":8,"counter":9,"non_ctx_param":"value","time":"2008-01-08T17:05:05Z","message":"after counter"}
 }

internal/testutil/log.go

@@ -4,15 +4,20 @@ import (
 	"testing"
 
 	"github.com/rs/zerolog"
-
-	"github.com/pomerium/pomerium/internal/log"
+	"github.com/rs/zerolog/log"
 )
 
 // SetLogger sets the given logger as the global logger for the remainder of
 // the current test. Because the logger is global, this must not be called from
 // parallel tests.
-func SetLogger(t *testing.T, logger *zerolog.Logger) {
-	originalLogger := log.Logger()
-	t.Cleanup(func() { log.SetLogger(originalLogger) })
-	log.SetLogger(logger)
+func SetLogger(t *testing.T, logger zerolog.Logger) {
+	t.Helper()
+
+	originalLogger := log.Logger
+	t.Cleanup(func() { log.Logger = originalLogger })
+	log.Logger = logger
+
+	originalContextLogger := zerolog.DefaultContextLogger
+	t.Cleanup(func() { zerolog.DefaultContextLogger = originalContextLogger })
+	zerolog.DefaultContextLogger = &logger
 }

internal/zero/cmd/command.go

@@ -10,10 +10,9 @@ import (
 	"path/filepath"
 	"syscall"
 
-	"github.com/mattn/go-isatty"
 	"github.com/rs/zerolog"
-	"github.com/rs/zerolog/log"
 
+	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/internal/zero/controller"
 )
 
@@ -68,24 +67,14 @@ func withInterrupt(ctx context.Context) context.Context {
 }
 
 func setupLogger() error {
-	if isatty.IsTerminal(os.Stdin.Fd()) {
-		log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
-	} else {
-		log.Logger = zerolog.New(os.Stderr)
-	}
-
 	if rawLvl, ok := os.LookupEnv("LOG_LEVEL"); ok {
 		lvl, err := zerolog.ParseLevel(rawLvl)
 		if err != nil {
 			return err
 		}
-		log.Logger = log.Logger.Level(lvl)
-	} else {
-		log.Logger = log.Logger.Level(zerolog.InfoLevel)
+		log.SetLevel(lvl)
 	}
 
-	// set the default context logger
-	zerolog.DefaultContextLogger = &log.Logger
 	return nil
 }
 

pkg/grpc/config/config.proto

@@ -138,7 +138,6 @@ message Settings {
   message StringList { repeated string values = 1; }
 
   optional string installation_id = 71;
-  optional bool debug = 2;
   optional string log_level = 3;
   optional StringList access_log_fields = 114;
   optional StringList authorize_log_fields = 115;