From 0f41b56f8b6c786a3c5c70be6472bc22309bf1c2 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 6 Apr 2022 08:48:41 +0200 Subject: [PATCH] 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 | 95 +++++++++++++++++++++++++++++++--- klog_test.go | 142 ++++++++++++++++++++++++++++++++++++++++++--------- 2 files changed, 206 insertions(+), 31 deletions(-) diff --git a/klog.go b/klog.go index 8f5871adb..54e8d1627 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,75 @@ 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 and +// returns a function that, when called, restores those settings. +// This does not invalidate caches. The restore function may get called +// more than once. +func CaptureState() func() { + logging.mu.Lock() + defer logging.mu.Unlock() + flushDRunning := logging.flushD.isRunning() + moduleSpec := logging.vmodule.serialize() + logger := globalLogger + loggerOptions := globalLoggerOptions + maxSize := MaxSize + state := 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, + } + return func() { + // This needs to be done before mutex locking. + if flushDRunning && !logging.flushD.isRunning() { + // This is not quite accurate: StartFlushDaemon might + // have been called with some different interval. + interval := state.flushInterval + if interval == 0 { + interval = flushInterval + } + logging.flushD.run(interval) + } else if !flushDRunning && logging.flushD.isRunning() { + logging.flushD.stop() + } + + logging.mu.Lock() + defer logging.mu.Unlock() + + logging.toStderr = state.toStderr + logging.alsoToStderr = state.alsoToStderr + logging.stderrThreshold = state.stderrThreshold + logging.file = state.file + logging.flushInterval = state.flushInterval + logging.traceLocation = state.traceLocation + logging.verbosity = state.verbosity + logging.logDir = state.logDir + logging.logFile = state.logFile + logging.logFileMaxSizeMB = state.logFileMaxSizeMB + logging.skipHeaders = state.skipHeaders + logging.skipLogHeaders = state.skipLogHeaders + logging.addDirHeader = state.addDirHeader + logging.oneOutput = state.oneOutput + logging.filter = state.filter + filter, _ := parseModuleSpec(moduleSpec) + logging.setVState(state.verbosity, filter, true) + globalLogger = logger + globalLoggerOptions = loggerOptions + MaxSize = 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 a23f5716f..6fb3746f9 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()() setFlags() defer logging.swap(logging.newBuffers()) Info("test") @@ -117,6 +118,7 @@ func TestInfo(t *testing.T) { } func TestInfoDepth(t *testing.T) { + defer CaptureState()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() setFlags() testData := map[string]struct { testLogFile string @@ -750,6 +757,7 @@ func TestInitFlags(t *testing.T) { } func TestInfoObjectRef(t *testing.T) { + defer CaptureState()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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()() 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. + restore := CaptureState() + defer 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. + 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) + } +}