From 296f5e641c87b3dfe70dcb6616ac45aad87e3557 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 6 Apr 2022 08:48:41 +0200 Subject: [PATCH 1/2] save and restore state This is useful in several unit tests. At least one test in klog_test.go itself left klog in a different state after it ran. --- klog.go | 116 ++++++++++++++++++++++++++++++++++++++--- klog_test.go | 142 ++++++++++++++++++++++++++++++++++++++++++--------- 2 files changed, 227 insertions(+), 31 deletions(-) diff --git a/klog.go b/klog.go index 8f5871ad..f5650ffc 100644 --- a/klog.go +++ b/klog.go @@ -242,6 +242,10 @@ func (m *moduleSpec) String() string { // Lock because the type is not atomic. TODO: clean this up. logging.mu.Lock() defer logging.mu.Unlock() + return m.serialize() +} + +func (m *moduleSpec) serialize() string { var b bytes.Buffer for i, f := range m.filter { if i > 0 { @@ -263,6 +267,17 @@ var errVmoduleSyntax = errors.New("syntax error: expect comma-separated list of // Set will sets module value // Syntax: -vmodule=recordio=2,file=1,gfs*=3 func (m *moduleSpec) Set(value string) error { + filter, err := parseModuleSpec(value) + if err != nil { + return err + } + logging.mu.Lock() + defer logging.mu.Unlock() + logging.setVState(logging.verbosity, filter, true) + return nil +} + +func parseModuleSpec(value string) ([]modulePat, error) { var filter []modulePat for _, pat := range strings.Split(value, ",") { if len(pat) == 0 { @@ -271,15 +286,15 @@ func (m *moduleSpec) Set(value string) error { } patLev := strings.Split(pat, "=") if len(patLev) != 2 || len(patLev[0]) == 0 || len(patLev[1]) == 0 { - return errVmoduleSyntax + return nil, errVmoduleSyntax } pattern := patLev[0] v, err := strconv.ParseInt(patLev[1], 10, 32) if err != nil { - return errors.New("syntax error: expect comma-separated list of filename=N") + return nil, errors.New("syntax error: expect comma-separated list of filename=N") } if v < 0 { - return errors.New("negative value for vmodule level") + return nil, errors.New("negative value for vmodule level") } if v == 0 { continue // Ignore. It's harmless but no point in paying the overhead. @@ -287,10 +302,7 @@ func (m *moduleSpec) Set(value string) error { // TODO: check syntax of filter? filter = append(filter, modulePat{pattern, isLiteral(pattern), Level(v)}) } - logging.mu.Lock() - defer logging.mu.Unlock() - logging.setVState(logging.verbosity, filter, true) - return nil + return filter, nil } // isLiteral reports whether the pattern is a literal string, that is, has no metacharacters @@ -520,6 +532,96 @@ func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool var timeNow = time.Now // Stubbed out for testing. +// CaptureState gathers information about all current klog settings. +// The result can be used to restore those settings. +func CaptureState() State { + logging.mu.Lock() + defer logging.mu.Unlock() + return &state{ + // We cannot simply copy the entire struct because + // it contains a mutex which cannot be copied. + loggingT: loggingT{ + toStderr: logging.toStderr, + alsoToStderr: logging.alsoToStderr, + stderrThreshold: logging.stderrThreshold, + file: logging.file, + flushInterval: logging.flushInterval, + traceLocation: logging.traceLocation, + verbosity: logging.verbosity, + logDir: logging.logDir, + logFile: logging.logFile, + logFileMaxSizeMB: logging.logFileMaxSizeMB, + skipHeaders: logging.skipHeaders, + skipLogHeaders: logging.skipLogHeaders, + addDirHeader: logging.addDirHeader, + oneOutput: logging.oneOutput, + filter: logging.filter, + }, + logger: globalLogger, + flushDRunning: logging.flushD.isRunning(), + moduleSpec: logging.vmodule.serialize(), + loggerOptions: globalLoggerOptions, + maxSize: MaxSize, + } +} + +// State stores a snapshot of klog settings. It gets created with CaptureState +// and can be used to restore the entire state. Modifying individual settings +// is supported via the command line flags. +type State interface { + // Restore restore the entire state. It may get called more than once. + Restore() +} + +type state struct { + loggingT + + logger *Logger + loggerOptions loggerOptions + flushDRunning bool + moduleSpec string + maxSize uint64 +} + +func (s *state) Restore() { + // This needs to be done before mutex locking. + if s.flushDRunning && !logging.flushD.isRunning() { + // This is not quite accurate: StartFlushDaemon might + // have been called with some different interval. + interval := s.flushInterval + if interval == 0 { + interval = flushInterval + } + logging.flushD.run(interval) + } else if !s.flushDRunning && logging.flushD.isRunning() { + logging.flushD.stop() + } + + logging.mu.Lock() + defer logging.mu.Unlock() + + logging.toStderr = s.toStderr + logging.alsoToStderr = s.alsoToStderr + logging.stderrThreshold = s.stderrThreshold + logging.file = s.file + logging.flushInterval = s.flushInterval + logging.traceLocation = s.traceLocation + logging.verbosity = s.verbosity + logging.logDir = s.logDir + logging.logFile = s.logFile + logging.logFileMaxSizeMB = s.logFileMaxSizeMB + logging.skipHeaders = s.skipHeaders + logging.skipLogHeaders = s.skipLogHeaders + logging.addDirHeader = s.addDirHeader + logging.oneOutput = s.oneOutput + logging.filter = s.filter + filter, _ := parseModuleSpec(s.moduleSpec) + logging.setVState(s.verbosity, filter, true) + globalLogger = s.logger + globalLoggerOptions = s.loggerOptions + MaxSize = s.maxSize +} + /* header formats a log header as defined by the C++ implementation. It returns a buffer containing the formatted header and the user's file and line number. diff --git a/klog_test.go b/klog_test.go index a23f5716..5ecb9802 100644 --- a/klog_test.go +++ b/klog_test.go @@ -105,6 +105,7 @@ func setFlags() { // Test that Info works as advertised. func TestInfo(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) Info("test") @@ -117,6 +118,7 @@ func TestInfo(t *testing.T) { } func TestInfoDepth(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) @@ -176,6 +178,7 @@ func TestCopyStandardLogToPanic(t *testing.T) { // Test that using the standard log package logs to INFO. func TestStandardLog(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) stdLog.Print("test") @@ -189,6 +192,7 @@ func TestStandardLog(t *testing.T) { // Test that the header has the correct format. func TestHeader(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) defer func(previous func() time.Time) { timeNow = previous }(timeNow) @@ -212,6 +216,7 @@ func TestHeader(t *testing.T) { } func TestHeaderWithDir(t *testing.T) { + defer CaptureState().Restore() setFlags() logging.addDirHeader = true defer logging.swap(logging.newBuffers()) @@ -231,6 +236,7 @@ func TestHeaderWithDir(t *testing.T) { // Even in the Info log, the source character will be E, so the data should // all be identical. func TestError(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) Error("test") @@ -253,13 +259,10 @@ func TestError(t *testing.T) { // Even in the Info log, the source character will be E, so the data should // all be identical. func TestErrorWithOneOutput(t *testing.T) { + defer CaptureState().Restore() setFlags() logging.oneOutput = true - buf := logging.newBuffers() - defer func() { - logging.swap(buf) - logging.oneOutput = false - }() + defer logging.swap(logging.newBuffers()) Error("test") if !contains(severity.ErrorLog, "E", t) { t.Errorf("Error has wrong character: %q", contents(severity.ErrorLog)) @@ -280,6 +283,7 @@ func TestErrorWithOneOutput(t *testing.T) { // Even in the Info log, the source character will be W, so the data should // all be identical. func TestWarning(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) Warning("test") @@ -299,13 +303,10 @@ func TestWarning(t *testing.T) { // Even in the Info log, the source character will be W, so the data should // all be identical. func TestWarningWithOneOutput(t *testing.T) { + defer CaptureState().Restore() setFlags() logging.oneOutput = true - buf := logging.newBuffers() - defer func() { - logging.swap(buf) - logging.oneOutput = false - }() + defer logging.swap(logging.newBuffers()) Warning("test") if !contains(severity.WarningLog, "W", t) { t.Errorf("Warning has wrong character: %q", contents(severity.WarningLog)) @@ -321,10 +322,10 @@ func TestWarningWithOneOutput(t *testing.T) { // Test that a V log goes to Info. func TestV(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) logging.verbosity.Set("2") - defer logging.verbosity.Set("0") V(2).Info("test") if !contains(severity.InfoLog, "I", t) { t.Errorf("Info has wrong character: %q", contents(severity.InfoLog)) @@ -336,10 +337,10 @@ func TestV(t *testing.T) { // Test that a vmodule enables a log in this file. func TestVmoduleOn(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) logging.vmodule.Set("klog_test=2") - defer logging.vmodule.Set("") if !V(1).Enabled() { t.Error("V not enabled for 1") } @@ -360,10 +361,10 @@ func TestVmoduleOn(t *testing.T) { // Test that a vmodule of another file does not enable a log in this file. func TestVmoduleOff(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) logging.vmodule.Set("notthisfile=2") - defer logging.vmodule.Set("") for i := 1; i <= 3; i++ { if V(Level(i)).Enabled() { t.Errorf("V enabled for %d", i) @@ -376,6 +377,7 @@ func TestVmoduleOff(t *testing.T) { } func TestSetOutputDataRace(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) var wg sync.WaitGroup @@ -416,6 +418,7 @@ func TestSetOutputDataRace(t *testing.T) { } func TestLogToOutput(t *testing.T) { + defer CaptureState().Restore() logging.toStderr = true defer logging.swap(logging.newBuffers()) buf := new(bytes.Buffer) @@ -450,9 +453,9 @@ var vGlobs = map[string]bool{ // Test that vmodule globbing works as advertised. func testVmoduleGlob(pat string, match bool, t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) - defer logging.vmodule.Set("") logging.vmodule.Set(pat) if V(2).Enabled() != match { t.Errorf("incorrect match for %q: got %#v expected %#v", pat, V(2), match) @@ -467,13 +470,13 @@ func TestVmoduleGlob(t *testing.T) { } func TestRollover(t *testing.T) { + defer CaptureState().Restore() setFlags() var err error defer func(previous func(error)) { logExitFunc = previous }(logExitFunc) logExitFunc = func(e error) { err = e } - defer func(previous uint64) { MaxSize = previous }(MaxSize) MaxSize = 512 Info("x") // Be sure we have a file. info, ok := logging.file[severity.InfoLog].(*syncBuffer) @@ -516,6 +519,7 @@ func TestOpenAppendOnStart(t *testing.T) { y string = "yyyyyyyyyy" ) + defer CaptureState().Restore() setFlags() var err error defer func(previous func(error)) { logExitFunc = previous }(logExitFunc) @@ -580,6 +584,7 @@ func TestOpenAppendOnStart(t *testing.T) { } func TestLogBacktraceAt(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) // The peculiar style of this code simplifies line counting and maintenance of the @@ -660,6 +665,7 @@ func BenchmarkKObj(b *testing.B) { } func BenchmarkLogs(b *testing.B) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) @@ -688,6 +694,7 @@ func BenchmarkLogs(b *testing.B) { // Test the logic on checking log size limitation. func TestFileSizeCheck(t *testing.T) { + defer CaptureState().Restore() setFlags() testData := map[string]struct { testLogFile string @@ -750,6 +757,7 @@ func TestInitFlags(t *testing.T) { } func TestInfoObjectRef(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) @@ -879,6 +887,7 @@ func TestKRef(t *testing.T) { // Test that InfoS and InfoSDepth work as advertised. func TestInfoS(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) timeNow = func() time.Time { @@ -935,6 +944,7 @@ func TestInfoS(t *testing.T) { // Test that Verbose.InfoS works as advertised. func TestVInfoS(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) timeNow = func() time.Time { @@ -990,7 +1000,6 @@ second value line`}, } logging.verbosity.Set("2") - defer logging.verbosity.Set("0") for l := Level(0); l < Level(4); l++ { for _, data := range testDataInfo { @@ -1019,6 +1028,7 @@ second value line`}, // Test that ErrorS and ErrorSDepth work as advertised. func TestErrorS(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) timeNow = func() time.Time { @@ -1147,10 +1157,10 @@ func (f *sampleLogFilter) FilterS(msg string, keysAndValues []interface{}) (stri } func TestLogFilter(t *testing.T) { + defer CaptureState().Restore() setFlags() defer logging.swap(logging.newBuffers()) SetLogFilter(&sampleLogFilter{}) - defer SetLogFilter(nil) funcs := []struct { name string logFunc func(args ...interface{}) @@ -1316,8 +1326,8 @@ func TestInfoWithLogr(t *testing.T) { for _, data := range testDataInfo { t.Run(data.msg, func(t *testing.T) { l := logr.New(logger) + defer CaptureState().Restore() SetLogger(l) - defer ClearLogger() defer logger.reset() Info(data.msg) @@ -1356,9 +1366,9 @@ func TestInfoSWithLogr(t *testing.T) { for _, data := range testDataInfo { t.Run(data.msg, func(t *testing.T) { + defer CaptureState().Restore() l := logr.New(logger) SetLogger(l) - defer ClearLogger() defer logger.reset() InfoS(data.msg, data.keysValues...) @@ -1424,9 +1434,9 @@ func TestErrorSWithLogr(t *testing.T) { for _, data := range testDataInfo { t.Run(data.msg, func(t *testing.T) { + defer CaptureState().Restore() l := logr.New(logger) SetLogger(l) - defer ClearLogger() defer logger.reset() ErrorS(data.err, data.msg, data.keysValues...) @@ -1483,8 +1493,8 @@ func TestCallDepthLogr(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { l := logr.New(logger) - SetLogger(l) defer ClearLogger() + SetLogger(l) defer logger.reset() defer logger.resetCallDepth() @@ -1505,8 +1515,8 @@ func TestCallDepthLogrInfoS(t *testing.T) { logger := &callDepthTestLogr{} logger.resetCallDepth() l := logr.New(logger) + defer CaptureState().Restore() SetLogger(l) - defer ClearLogger() // Add wrapper to ensure callDepthTestLogr +2 offset is correct. logFunc := func() { @@ -1528,8 +1538,8 @@ func TestCallDepthLogrErrorS(t *testing.T) { logger := &callDepthTestLogr{} logger.resetCallDepth() l := logr.New(logger) + defer CaptureState().Restore() SetLogger(l) - defer ClearLogger() // Add wrapper to ensure callDepthTestLogr +2 offset is correct. logFunc := func() { @@ -1548,11 +1558,11 @@ func TestCallDepthLogrErrorS(t *testing.T) { } func TestCallDepthLogrGoLog(t *testing.T) { + defer CaptureState().Restore() logger := &callDepthTestLogr{} logger.resetCallDepth() l := logr.New(logger) SetLogger(l) - defer ClearLogger() CopyStandardLogTo("INFO") // Add wrapper to ensure callDepthTestLogr +2 offset is correct. @@ -1921,3 +1931,87 @@ func TestStopFlushDaemon(t *testing.T) { t.Error("expected flushD to be stopped") } } + +func TestCaptureState(t *testing.T) { + var fs flag.FlagSet + InitFlags(&fs) + + // Capture state. + oldState := map[string]string{} + fs.VisitAll(func(f *flag.Flag) { + oldState[f.Name] = f.Value.String() + }) + originalLogger := Background() + file := logging.file + + // And through dedicated API. + // Ensure we always restore. + state := CaptureState() + defer state.Restore() + + // Change state. + for name, value := range map[string]string{ + // All of these are non-standard values. + "v": "10", + "vmodule": "abc=2", + "log_dir": "/tmp", + "log_file_max_size": "10", + "logtostderr": "false", + "alsologtostderr": "true", + "add_dir_header": "true", + "skip_headers": "true", + "one_output": "true", + "skip_log_headers": "true", + "stderrthreshold": "1", + "log_backtrace_at": "foobar.go:100", + } { + f := fs.Lookup(name) + if f == nil { + t.Fatalf("could not look up %q", name) + } + currentValue := f.Value.String() + if currentValue == value { + t.Fatalf("%q is already set to non-default %q?!", name, value) + } + if err := f.Value.Set(value); err != nil { + t.Fatalf("setting %q to %q: %v", name, value, err) + } + } + StartFlushDaemon(time.Minute) + if !logging.flushD.isRunning() { + t.Error("Flush daemon should have been started.") + } + logger := logr.Discard() + SetLoggerWithOptions(logger, ContextualLogger(true)) + actualLogger := Background() + if logger != actualLogger { + t.Errorf("Background logger should be %v, got %v", logger, actualLogger) + } + buffer := bytes.Buffer{} + SetOutput(&buffer) + if file == logging.file { + t.Error("Output files should have been modified.") + } + + // Let klog restore the state. + state.Restore() + + // Verify that the original state is back. + fs.VisitAll(func(f *flag.Flag) { + oldValue := oldState[f.Name] + currentValue := f.Value.String() + if oldValue != currentValue { + t.Errorf("%q should have been restored to %q, is %q instead", f.Name, oldValue, currentValue) + } + }) + if logging.flushD.isRunning() { + t.Error("Flush daemon should have been stopped.") + } + actualLogger = Background() + if originalLogger != actualLogger { + t.Errorf("Background logger should be %v, got %v", originalLogger, actualLogger) + } + if file != logging.file { + t.Errorf("Output files should have been restored to %v, got %v", file, logging.file) + } +} From 3c90bf9a79bf6ed7c82fa8cafeaf1681c8555255 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 9 May 2022 12:30:36 +0200 Subject: [PATCH 2/2] refactor global state Global state consists of user-controlled settings and some additional runtime variables (mutex, cache). Storing all settings, and just those, in a single struct with a deepCopy function makes state capturing simpler. --- contextual.go | 38 ++++------ klog.go | 200 +++++++++++++++++++++++++------------------------- klog_test.go | 29 +++++++- 3 files changed, 138 insertions(+), 129 deletions(-) diff --git a/contextual.go b/contextual.go index 0bf19280..65ac479a 100644 --- a/contextual.go +++ b/contextual.go @@ -34,18 +34,6 @@ import ( // mutex locking. var ( - // contextualLoggingEnabled controls whether contextual logging is - // active. Disabling it may have some small performance benefit. - contextualLoggingEnabled = true - - // globalLogger is the global Logger chosen by users of klog, nil if - // none is available. - globalLogger *Logger - - // globalLoggerOptions contains the options that were supplied for - // globalLogger. - globalLoggerOptions loggerOptions - // klogLogger is used as fallback for logging through the normal klog code // when no Logger is set. klogLogger logr.Logger = logr.New(&klogger{}) @@ -81,10 +69,10 @@ func SetLogger(logger logr.Logger) { // routing log entries through klogr into klog and then into the actual Logger // backend. func SetLoggerWithOptions(logger logr.Logger, opts ...LoggerOption) { - globalLogger = &logger - globalLoggerOptions = loggerOptions{} + logging.logger = &logger + logging.loggerOptions = loggerOptions{} for _, opt := range opts { - opt(&globalLoggerOptions) + opt(&logging.loggerOptions) } } @@ -119,8 +107,8 @@ type loggerOptions struct { // Modifying the logger is not thread-safe and should be done while no other // goroutines invoke log calls, usually during program initialization. func ClearLogger() { - globalLogger = nil - globalLoggerOptions = loggerOptions{} + logging.logger = nil + logging.loggerOptions = loggerOptions{} } // EnableContextualLogging controls whether contextual logging is enabled. @@ -132,14 +120,14 @@ func ClearLogger() { // // This must be called during initialization before goroutines are started. func EnableContextualLogging(enabled bool) { - contextualLoggingEnabled = enabled + logging.contextualLoggingEnabled = enabled } // FromContext retrieves a logger set by the caller or, if not set, // falls back to the program's global logger (a Logger instance or klog // itself). func FromContext(ctx context.Context) Logger { - if contextualLoggingEnabled { + if logging.contextualLoggingEnabled { if logger, err := logr.FromContext(ctx); err == nil { return logger } @@ -160,10 +148,10 @@ func TODO() Logger { // better receive a logger via its parameters. TODO can be used as a temporary // solution for such code. func Background() Logger { - if globalLoggerOptions.contextualLogger { - // Is non-nil because globalLoggerOptions.contextualLogger is + if logging.loggerOptions.contextualLogger { + // Is non-nil because logging.loggerOptions.contextualLogger is // only true if a logger was set. - return *globalLogger + return *logging.logger } return klogLogger @@ -172,7 +160,7 @@ func Background() Logger { // LoggerWithValues returns logger.WithValues(...kv) when // contextual logging is enabled, otherwise the logger. func LoggerWithValues(logger Logger, kv ...interface{}) Logger { - if contextualLoggingEnabled { + if logging.contextualLoggingEnabled { return logger.WithValues(kv...) } return logger @@ -181,7 +169,7 @@ func LoggerWithValues(logger Logger, kv ...interface{}) Logger { // LoggerWithName returns logger.WithName(name) when contextual logging is // enabled, otherwise the logger. func LoggerWithName(logger Logger, name string) Logger { - if contextualLoggingEnabled { + if logging.contextualLoggingEnabled { return logger.WithName(name) } return logger @@ -190,7 +178,7 @@ func LoggerWithName(logger Logger, name string) Logger { // NewContext returns logr.NewContext(ctx, logger) when // contextual logging is enabled, otherwise ctx. func NewContext(ctx context.Context, logger Logger) context.Context { - if contextualLoggingEnabled { + if logging.contextualLoggingEnabled { return logr.NewContext(ctx, logger) } return ctx diff --git a/klog.go b/klog.go index f5650ffc..ef7a48ab 100644 --- a/klog.go +++ b/klog.go @@ -438,8 +438,20 @@ func Flush() { logging.lockAndFlushAll() } -// loggingT collects all the global state of the logging setup. -type loggingT struct { +// settings collects global settings. +type settings struct { + // contextualLoggingEnabled controls whether contextual logging is + // active. Disabling it may have some small performance benefit. + contextualLoggingEnabled bool + + // logger is the global Logger chosen by users of klog, nil if + // none is available. + logger *Logger + + // loggerOptions contains the options that were supplied for + // globalLogger. + loggerOptions loggerOptions + // Boolean flags. Not handled atomically because the flag.Value interface // does not let us avoid the =true, and that shorthand is necessary for // compatibility. TODO: does this matter enough to fix? Seems unlikely. @@ -449,26 +461,14 @@ type loggingT struct { // Level flag. Handled atomically. stderrThreshold severityValue // The -stderrthreshold flag. - // bufferCache maintains the free list. It uses its own mutex - // so buffers can be grabbed and printed to without holding the main lock, - // for better parallelization. - bufferCache buffer.Buffers + // Access to all of the following fields must be protected via a mutex. - // mu protects the remaining elements of this structure and is - // used to synchronize logging. - mu sync.Mutex // file holds writer for each of the log types. file [severity.NumSeverity]flushSyncWriter - // flushD holds a flushDaemon that frequently flushes log file buffers. - flushD *flushDaemon // flushInterval is the interval for periodic flushing. If zero, // the global default will be used. flushInterval time.Duration - // pcs is used in V to avoid an allocation when computing the caller's PC. - pcs [1]uintptr - // vmap is a cache of the V Level for each V() call site, identified by PC. - // It is wiped whenever the vmodule flag changes state. - vmap map[uintptr]Level + // filterLength stores the length of the vmodule filter chain. If greater // than zero, it means vmodule is enabled. It may be read safely // using sync.LoadInt32, but is only modified under mu. @@ -508,6 +508,43 @@ type loggingT struct { filter LogFilter } +// deepCopy creates a copy that doesn't share anything with the original +// instance. +func (s settings) deepCopy() settings { + // vmodule is a slice and would be shared, so we have copy it. + filter := make([]modulePat, len(s.vmodule.filter)) + for i := range s.vmodule.filter { + filter[i] = s.vmodule.filter[i] + } + s.vmodule.filter = filter + + return s +} + +// loggingT collects all the global state of the logging setup. +type loggingT struct { + settings + + // bufferCache maintains the free list. It uses its own mutex + // so buffers can be grabbed and printed to without holding the main lock, + // for better parallelization. + bufferCache buffer.Buffers + + // flushD holds a flushDaemon that frequently flushes log file buffers. + // Uses its own mutex. + flushD *flushDaemon + + // mu protects the remaining elements of this structure and the fields + // in settingsT which need a mutex lock. + mu sync.Mutex + + // pcs is used in V to avoid an allocation when computing the caller's PC. + pcs [1]uintptr + // vmap is a cache of the V Level for each V() call site, identified by PC. + // It is wiped whenever the vmodule flag changes state. + vmap map[uintptr]Level +} + var logging loggingT // setVState sets a consistent state for V logging. @@ -538,29 +575,8 @@ func CaptureState() State { logging.mu.Lock() defer logging.mu.Unlock() return &state{ - // We cannot simply copy the entire struct because - // it contains a mutex which cannot be copied. - loggingT: loggingT{ - toStderr: logging.toStderr, - alsoToStderr: logging.alsoToStderr, - stderrThreshold: logging.stderrThreshold, - file: logging.file, - flushInterval: logging.flushInterval, - traceLocation: logging.traceLocation, - verbosity: logging.verbosity, - logDir: logging.logDir, - logFile: logging.logFile, - logFileMaxSizeMB: logging.logFileMaxSizeMB, - skipHeaders: logging.skipHeaders, - skipLogHeaders: logging.skipLogHeaders, - addDirHeader: logging.addDirHeader, - oneOutput: logging.oneOutput, - filter: logging.filter, - }, - logger: globalLogger, + settings: logging.settings.deepCopy(), flushDRunning: logging.flushD.isRunning(), - moduleSpec: logging.vmodule.serialize(), - loggerOptions: globalLoggerOptions, maxSize: MaxSize, } } @@ -574,12 +590,9 @@ type State interface { } type state struct { - loggingT + settings - logger *Logger - loggerOptions loggerOptions flushDRunning bool - moduleSpec string maxSize uint64 } @@ -600,25 +613,8 @@ func (s *state) Restore() { logging.mu.Lock() defer logging.mu.Unlock() - logging.toStderr = s.toStderr - logging.alsoToStderr = s.alsoToStderr - logging.stderrThreshold = s.stderrThreshold - logging.file = s.file - logging.flushInterval = s.flushInterval - logging.traceLocation = s.traceLocation - logging.verbosity = s.verbosity - logging.logDir = s.logDir - logging.logFile = s.logFile - logging.logFileMaxSizeMB = s.logFileMaxSizeMB - logging.skipHeaders = s.skipHeaders - logging.skipLogHeaders = s.skipLogHeaders - logging.addDirHeader = s.addDirHeader - logging.oneOutput = s.oneOutput - logging.filter = s.filter - filter, _ := parseModuleSpec(s.moduleSpec) - logging.setVState(s.verbosity, filter, true) - globalLogger = s.logger - globalLoggerOptions = s.loggerOptions + logging.settings = s.settings + logging.setVState(s.verbosity, s.vmodule.filter, true) MaxSize = s.maxSize } @@ -790,7 +786,7 @@ func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, serialize.KVListFormat(&b.Buffer, "err", err) } serialize.KVListFormat(&b.Buffer, keysAndValues...) - l.printDepth(s, globalLogger, nil, depth+1, &b.Buffer) + l.printDepth(s, logging.logger, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. l.bufferCache.PutBuffer(b) } @@ -867,7 +863,7 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf // TODO: set 'severity' and caller information as structured log info // keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line} if s == severity.ErrorLog { - globalLogger.WithCallDepth(depth+3).Error(nil, string(data)) + logging.logger.WithCallDepth(depth+3).Error(nil, string(data)) } else { log.WithCallDepth(depth + 3).Info(string(data)) } @@ -1211,8 +1207,8 @@ func (l *loggingT) flushAll() { file.Sync() // ignore error } } - if globalLoggerOptions.flush != nil { - globalLoggerOptions.flush() + if logging.loggerOptions.flush != nil { + logging.loggerOptions.flush() } } @@ -1260,7 +1256,7 @@ func (lb logBridge) Write(b []byte) (n int, err error) { } // printWithFileLine with alsoToStderr=true, so standard log messages // always appear on standard error. - logging.printWithFileLine(severity.Severity(lb), globalLogger, logging.filter, file, line, true, text) + logging.printWithFileLine(severity.Severity(lb), logging.logger, logging.filter, file, line, true, text) return len(b), nil } @@ -1298,10 +1294,10 @@ type Verbose struct { } func newVerbose(level Level, b bool) Verbose { - if globalLogger == nil { + if logging.logger == nil { return Verbose{b, nil} } - v := globalLogger.V(int(level)) + v := logging.logger.V(int(level)) return Verbose{b, &v} } @@ -1420,7 +1416,7 @@ func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) { // InfoSDepth acts as InfoS but uses depth to determine which call frame to log. // InfoSDepth(0, "msg") is the same as InfoS("msg"). func InfoSDepth(depth int, msg string, keysAndValues ...interface{}) { - logging.infoS(globalLogger, logging.filter, depth, msg, keysAndValues...) + logging.infoS(logging.logger, logging.filter, depth, msg, keysAndValues...) } // InfoSDepth is equivalent to the global InfoSDepth function, guarded by the value of v. @@ -1449,37 +1445,37 @@ func (v Verbose) ErrorS(err error, msg string, keysAndValues ...interface{}) { // Info logs to the INFO log. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Info(args ...interface{}) { - logging.print(severity.InfoLog, globalLogger, logging.filter, args...) + logging.print(severity.InfoLog, logging.logger, logging.filter, args...) } // InfoDepth acts as Info but uses depth to determine which call frame to log. // InfoDepth(0, "msg") is the same as Info("msg"). func InfoDepth(depth int, args ...interface{}) { - logging.printDepth(severity.InfoLog, globalLogger, logging.filter, depth, args...) + logging.printDepth(severity.InfoLog, logging.logger, logging.filter, depth, args...) } // Infoln logs to the INFO log. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Infoln(args ...interface{}) { - logging.println(severity.InfoLog, globalLogger, logging.filter, args...) + logging.println(severity.InfoLog, logging.logger, logging.filter, args...) } // InfolnDepth acts as Infoln but uses depth to determine which call frame to log. // InfolnDepth(0, "msg") is the same as Infoln("msg"). func InfolnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.InfoLog, globalLogger, logging.filter, depth, args...) + logging.printlnDepth(severity.InfoLog, logging.logger, logging.filter, depth, args...) } // Infof logs to the INFO log. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Infof(format string, args ...interface{}) { - logging.printf(severity.InfoLog, globalLogger, logging.filter, format, args...) + logging.printf(severity.InfoLog, logging.logger, logging.filter, format, args...) } // InfofDepth acts as Infof but uses depth to determine which call frame to log. // InfofDepth(0, "msg", args...) is the same as Infof("msg", args...). func InfofDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.InfoLog, globalLogger, logging.filter, depth, format, args...) + logging.printfDepth(severity.InfoLog, logging.logger, logging.filter, depth, format, args...) } // InfoS structured logs to the INFO log. @@ -1491,79 +1487,79 @@ func InfofDepth(depth int, format string, args ...interface{}) { // output: // >> I1025 00:15:15.525108 1 controller_utils.go:116] "Pod status updated" pod="kubedns" status="ready" func InfoS(msg string, keysAndValues ...interface{}) { - logging.infoS(globalLogger, logging.filter, 0, msg, keysAndValues...) + logging.infoS(logging.logger, logging.filter, 0, msg, keysAndValues...) } // Warning logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Warning(args ...interface{}) { - logging.print(severity.WarningLog, globalLogger, logging.filter, args...) + logging.print(severity.WarningLog, logging.logger, logging.filter, args...) } // WarningDepth acts as Warning but uses depth to determine which call frame to log. // WarningDepth(0, "msg") is the same as Warning("msg"). func WarningDepth(depth int, args ...interface{}) { - logging.printDepth(severity.WarningLog, globalLogger, logging.filter, depth, args...) + logging.printDepth(severity.WarningLog, logging.logger, logging.filter, depth, args...) } // Warningln logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Warningln(args ...interface{}) { - logging.println(severity.WarningLog, globalLogger, logging.filter, args...) + logging.println(severity.WarningLog, logging.logger, logging.filter, args...) } // WarninglnDepth acts as Warningln but uses depth to determine which call frame to log. // WarninglnDepth(0, "msg") is the same as Warningln("msg"). func WarninglnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.WarningLog, globalLogger, logging.filter, depth, args...) + logging.printlnDepth(severity.WarningLog, logging.logger, logging.filter, depth, args...) } // Warningf logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Warningf(format string, args ...interface{}) { - logging.printf(severity.WarningLog, globalLogger, logging.filter, format, args...) + logging.printf(severity.WarningLog, logging.logger, logging.filter, format, args...) } // WarningfDepth acts as Warningf but uses depth to determine which call frame to log. // WarningfDepth(0, "msg", args...) is the same as Warningf("msg", args...). func WarningfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.WarningLog, globalLogger, logging.filter, depth, format, args...) + logging.printfDepth(severity.WarningLog, logging.logger, logging.filter, depth, format, args...) } // Error logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Error(args ...interface{}) { - logging.print(severity.ErrorLog, globalLogger, logging.filter, args...) + logging.print(severity.ErrorLog, logging.logger, logging.filter, args...) } // ErrorDepth acts as Error but uses depth to determine which call frame to log. // ErrorDepth(0, "msg") is the same as Error("msg"). func ErrorDepth(depth int, args ...interface{}) { - logging.printDepth(severity.ErrorLog, globalLogger, logging.filter, depth, args...) + logging.printDepth(severity.ErrorLog, logging.logger, logging.filter, depth, args...) } // Errorln logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Errorln(args ...interface{}) { - logging.println(severity.ErrorLog, globalLogger, logging.filter, args...) + logging.println(severity.ErrorLog, logging.logger, logging.filter, args...) } // ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log. // ErrorlnDepth(0, "msg") is the same as Errorln("msg"). func ErrorlnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.ErrorLog, globalLogger, logging.filter, depth, args...) + logging.printlnDepth(severity.ErrorLog, logging.logger, logging.filter, depth, args...) } // Errorf logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Errorf(format string, args ...interface{}) { - logging.printf(severity.ErrorLog, globalLogger, logging.filter, format, args...) + logging.printf(severity.ErrorLog, logging.logger, logging.filter, format, args...) } // ErrorfDepth acts as Errorf but uses depth to determine which call frame to log. // ErrorfDepth(0, "msg", args...) is the same as Errorf("msg", args...). func ErrorfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.ErrorLog, globalLogger, logging.filter, depth, format, args...) + logging.printfDepth(severity.ErrorLog, logging.logger, logging.filter, depth, format, args...) } // ErrorS structured logs to the ERROR, WARNING, and INFO logs. @@ -1576,52 +1572,52 @@ func ErrorfDepth(depth int, format string, args ...interface{}) { // output: // >> E1025 00:15:15.525108 1 controller_utils.go:114] "Failed to update pod status" err="timeout" func ErrorS(err error, msg string, keysAndValues ...interface{}) { - logging.errorS(err, globalLogger, logging.filter, 0, msg, keysAndValues...) + logging.errorS(err, logging.logger, logging.filter, 0, msg, keysAndValues...) } // ErrorSDepth acts as ErrorS but uses depth to determine which call frame to log. // ErrorSDepth(0, "msg") is the same as ErrorS("msg"). func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) { - logging.errorS(err, globalLogger, logging.filter, depth, msg, keysAndValues...) + logging.errorS(err, logging.logger, logging.filter, depth, msg, keysAndValues...) } // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls OsExit(255). // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Fatal(args ...interface{}) { - logging.print(severity.FatalLog, globalLogger, logging.filter, args...) + logging.print(severity.FatalLog, logging.logger, logging.filter, args...) } // FatalDepth acts as Fatal but uses depth to determine which call frame to log. // FatalDepth(0, "msg") is the same as Fatal("msg"). func FatalDepth(depth int, args ...interface{}) { - logging.printDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, logging.logger, logging.filter, depth, args...) } // Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls OsExit(255). // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Fatalln(args ...interface{}) { - logging.println(severity.FatalLog, globalLogger, logging.filter, args...) + logging.println(severity.FatalLog, logging.logger, logging.filter, args...) } // FatallnDepth acts as Fatalln but uses depth to determine which call frame to log. // FatallnDepth(0, "msg") is the same as Fatalln("msg"). func FatallnDepth(depth int, args ...interface{}) { - logging.printlnDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, logging.logger, logging.filter, depth, args...) } // Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls OsExit(255). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Fatalf(format string, args ...interface{}) { - logging.printf(severity.FatalLog, globalLogger, logging.filter, format, args...) + logging.printf(severity.FatalLog, logging.logger, logging.filter, format, args...) } // FatalfDepth acts as Fatalf but uses depth to determine which call frame to log. // FatalfDepth(0, "msg", args...) is the same as Fatalf("msg", args...). func FatalfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(severity.FatalLog, globalLogger, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, logging.logger, logging.filter, depth, format, args...) } // fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks. @@ -1632,41 +1628,41 @@ var fatalNoStacks uint32 // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Exit(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.print(severity.FatalLog, globalLogger, logging.filter, args...) + logging.print(severity.FatalLog, logging.logger, logging.filter, args...) } // ExitDepth acts as Exit but uses depth to determine which call frame to log. // ExitDepth(0, "msg") is the same as Exit("msg"). func ExitDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, logging.logger, logging.filter, depth, args...) } // Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls OsExit(1). func Exitln(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.println(severity.FatalLog, globalLogger, logging.filter, args...) + logging.println(severity.FatalLog, logging.logger, logging.filter, args...) } // ExitlnDepth acts as Exitln but uses depth to determine which call frame to log. // ExitlnDepth(0, "msg") is the same as Exitln("msg"). func ExitlnDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printlnDepth(severity.FatalLog, globalLogger, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, logging.logger, logging.filter, depth, args...) } // Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls OsExit(1). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Exitf(format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printf(severity.FatalLog, globalLogger, logging.filter, format, args...) + logging.printf(severity.FatalLog, logging.logger, logging.filter, format, args...) } // ExitfDepth acts as Exitf but uses depth to determine which call frame to log. // ExitfDepth(0, "msg", args...) is the same as Exitf("msg", args...). func ExitfDepth(depth int, format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printfDepth(severity.FatalLog, globalLogger, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, logging.logger, logging.filter, depth, format, args...) } // LogFilter is a collection of functions that can filter all logging calls, diff --git a/klog_test.go b/klog_test.go index 5ecb9802..177050dc 100644 --- a/klog_test.go +++ b/klog_test.go @@ -1879,8 +1879,10 @@ func TestFlushDaemon(t *testing.T) { } testClock := testingclock.NewFakeClock(time.Now()) testLog := loggingT{ - flushInterval: time.Second, - flushD: newFlushDaemon(spyFunc, testClock), + settings: settings{ + flushInterval: time.Second, + }, + flushD: newFlushDaemon(spyFunc, testClock), } // Calling testLog will call createFile, which should start the daemon. @@ -2015,3 +2017,26 @@ func TestCaptureState(t *testing.T) { t.Errorf("Output files should have been restored to %v, got %v", file, logging.file) } } + +func TestSettingsDeepCopy(t *testing.T) { + logger := logr.Discard() + + settings := settings{ + logger: &logger, + vmodule: moduleSpec{ + filter: []modulePat{ + {pattern: "a"}, + {pattern: "b"}, + {pattern: "c"}, + }, + }, + } + copy := settings.deepCopy() + if !reflect.DeepEqual(settings, copy) { + t.Fatalf("Copy not identical to original settings. Original:\n %+v\nCopy: %+v", settings, copy) + } + settings.vmodule.filter[1].pattern = "x" + if copy.vmodule.filter[1].pattern == settings.vmodule.filter[1].pattern { + t.Fatal("Copy should not have shared vmodule.filter.") + } +}