From 941d47b86666d5d187b8a527c34a98e9e0a3eaed Mon Sep 17 00:00:00 2001 From: Davanum Srinivas Date: Wed, 12 Jun 2019 08:22:18 -0400 Subject: [PATCH] Revert "Fix the log duplication issue for --log-file." This reverts commit 7eb35e258ba4db2804592067f9a07051fa3af2d0. --- klog.go | 161 +++++++++++++++++---------------------------------- klog_test.go | 64 +------------------- 2 files changed, 55 insertions(+), 170 deletions(-) diff --git a/klog.go b/klog.go index b033996c0..10330d7ef 100644 --- a/klog.go +++ b/klog.go @@ -414,16 +414,6 @@ func InitFlags(flagset *flag.FlagSet) { logging.logDir = "" logging.logFile = "" logging.logFileMaxSizeMB = 1800 - // TODO: The default value of toStderr should be false. - // Ideally, toStderr can be deprecated. - // If --log-file is set, only log to the dedicated log-file. - // If --alsoToStderr is true, whether or not --log-file is set, we will - // log to stderr. - // Since kubernetes/kubernetes are currently using klog with - // default --toStderr to be true, we can't change this default value - // directly. - // As a compromise, when --log-file is set, the toStdErr is reset to - // be false. e.g. See function `IsSingleMode`. logging.toStderr = true logging.alsoToStderr = false logging.skipHeaders = false @@ -477,8 +467,6 @@ type loggingT struct { mu sync.Mutex // file holds writer for each of the log types. file [numSeverity]flushSyncWriter - // file holds writer for the dedicated file when --log-file is set. - singleModeFile flushSyncWriter // 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. @@ -523,16 +511,6 @@ type buffer struct { var logging loggingT -func (l *loggingT) IsSingleMode() bool { - if l.logFile != "" { - // TODO: Remove the toStdErr reset when switching the logging.toStderr - // default value to be false. - l.toStderr = false - return true - } - return false -} - // setVState sets a consistent state for V logging. // l.mu is held. func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool) { @@ -758,40 +736,24 @@ func (rb *redirectBuffer) Write(bytes []byte) (n int, err error) { // SetOutput sets the output destination for all severities func SetOutput(w io.Writer) { - // In single-mode, all severity logs are tracked in a single dedicated file. - if logging.IsSingleMode() { + for s := fatalLog; s >= infoLog; s-- { rb := &redirectBuffer{ w: w, } - logging.singleModeFile = rb - } else { - for s := fatalLog; s >= infoLog; s-- { - rb := &redirectBuffer{ - w: w, - } - logging.file[s] = rb - } + logging.file[s] = rb } } // SetOutputBySeverity sets the output destination for specific severity func SetOutputBySeverity(name string, w io.Writer) { - // In single-mode, all severity logs are tracked in a single dedicated file. - // Guarantee this buffer exists whatever severity output is trying to be set. - if logging.IsSingleMode() { - if logging.singleModeFile == nil { - logging.singleModeFile = &redirectBuffer{w: w} - } - } else { - sev, ok := severityByName(name) - if !ok { - panic(fmt.Sprintf("SetOutputBySeverity(%q): unrecognized severity name", name)) - } - rb := &redirectBuffer{ - w: w, - } - logging.file[sev] = rb + sev, ok := severityByName(name) + if !ok { + panic(fmt.Sprintf("SetOutputBySeverity(%q): unrecognized severity name", name)) } + rb := &redirectBuffer{ + w: w, + } + logging.file[sev] = rb } // output writes the data to the log files and releases the buffer. @@ -803,7 +765,32 @@ func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoTo } } data := buf.Bytes() - l.writeLogData(s, data) + if l.toStderr { + os.Stderr.Write(data) + } else { + if alsoToStderr || l.alsoToStderr || s >= l.stderrThreshold.get() { + os.Stderr.Write(data) + } + if l.file[s] == nil { + if err := l.createFiles(s); err != nil { + os.Stderr.Write(data) // Make sure the message appears somewhere. + l.exit(err) + } + } + switch s { + case fatalLog: + l.file[fatalLog].Write(data) + fallthrough + case errorLog: + l.file[errorLog].Write(data) + fallthrough + case warningLog: + l.file[warningLog].Write(data) + fallthrough + case infoLog: + l.file[infoLog].Write(data) + } + } if s == fatalLog { // If we got here via Exit rather than Fatal, print no stacks. if atomic.LoadUint32(&fatalNoStacks) > 0 { @@ -811,65 +798,33 @@ func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoTo timeoutFlush(10 * time.Second) os.Exit(1) } + // Dump all goroutine stacks before exiting. + // First, make sure we see the trace for the current goroutine on standard error. + // If -logtostderr has been specified, the loop below will do that anyway + // as the first stack in the full dump. + if !l.toStderr { + os.Stderr.Write(stacks(false)) + } + // Write the stack trace for all goroutines to the files. + trace := stacks(true) logExitFunc = func(error) {} // If we get a write error, we'll still exit below. - l.writeLogData(fatalLog, stacks(true)) + for log := fatalLog; log >= infoLog; log-- { + if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set. + f.Write(trace) + } + } l.mu.Unlock() timeoutFlush(10 * time.Second) os.Exit(255) // C++ uses -1, which is silly because it's anded with 255 anyway. } l.putBuffer(buf) l.mu.Unlock() - // Note: The stats estimate logs for each severity level individually, - // even in the situation that log-file is specified and - // all severity-level logs are tracked only in the infoLog file. if stats := severityStats[s]; stats != nil { atomic.AddInt64(&stats.lines, 1) atomic.AddInt64(&stats.bytes, int64(len(data))) } } -// writeLogData writes |data| to the `s` and lower severity files. -// e.g. If Severity level is Error, the data will be written to all the Error, -// Warning, and Info log file. However, if --log_file flag is provided, klog -// no longer tracks logs separately due to their severity level, but rather -// only write to the singleModeFile which later on will be flushed to the -// dedicated log_file. -func (l *loggingT) writeLogData(s severity, data []byte) { - shouldAlsoToStderr := l.alsoToStderr && s >= l.stderrThreshold.get() - if l.IsSingleMode() { - if shouldAlsoToStderr { - os.Stderr.Write(data) - } - if l.singleModeFile == nil { - now := time.Now() - sb := &syncBuffer{ - logger: l, - maxbytes: CalculateMaxSize(), - } - if err := sb.rotateFile(now, true); err != nil { - l.exit(err) - } - l.singleModeFile = sb - } - l.singleModeFile.Write(data) - } else { - if l.toStderr || shouldAlsoToStderr { - os.Stderr.Write(data) - } - for currSeverity := s; currSeverity >= infoLog; currSeverity-- { - if l.file[currSeverity] == nil { - if err := l.createFiles(currSeverity); err != nil { - os.Stderr.Write(data) // Make sure the message appears somewhere. - l.exit(err) - } - } - if f := l.file[currSeverity]; f != nil { // Can be nil if -logtostderr is set. - f.Write(data) - } - } - } -} - // timeoutFlush calls Flush and returns when it completes or after timeout // elapses, whichever happens first. This is needed because the hooks invoked // by Flush may deadlock when glog.Fatal is called from a hook that holds @@ -1047,21 +1002,13 @@ func (l *loggingT) lockAndFlushAll() { // flushAll flushes all the logs and attempts to "sync" their data to disk. // l.mu is held. func (l *loggingT) flushAll() { - if l.IsSingleMode() { - file := l.singleModeFile + // Flush from fatal down, in case there's trouble flushing. + for s := fatalLog; s >= infoLog; s-- { + file := l.file[s] if file != nil { file.Flush() // ignore error file.Sync() // ignore error } - } else { - // Flush from fatal down, in case there's trouble flushing. - for s := fatalLog; s >= infoLog; s-- { - file := l.file[s] - if file != nil { - file.Flush() // ignore error - file.Sync() // ignore error - } - } } } @@ -1147,9 +1094,9 @@ type Verbose bool // The returned value is a boolean of type Verbose, which implements Info, Infoln // and Infof. These methods will write to the Info log if called. // Thus, one may write either -// if glog.V(2) { glog.Info("log this") } +// if glog.V(2) { glog.Info("log this") } // or -// glog.V(2).Info("log this") +// glog.V(2).Info("log this") // The second form is shorter but the first is cheaper if logging is off because it does // not evaluate its arguments. // diff --git a/klog_test.go b/klog_test.go index 533d2212f..c59a7bf34 100644 --- a/klog_test.go +++ b/klog_test.go @@ -22,9 +22,7 @@ import ( "fmt" "io/ioutil" stdLog "log" - "os" "path/filepath" - "regexp" "runtime" "strconv" "strings" @@ -32,53 +30,6 @@ import ( "time" ) -// Test that no duplicated logs are written to logfile. -func TestDedupLogsInSingleLogFileMode(t *testing.T) { - setFlags() - - tmpLogFile := "tmp-klog" - errMsg := "Test. This is an error" - tmpFile, err := ioutil.TempFile("", tmpLogFile) - defer deleteFile(tmpFile.Name()) - - if err != nil { - t.Fatalf("unexpected error: %v", err) - } - logging.logFile = tmpFile.Name() - logging.toStderr = false - logging.alsoToStderr = false - logging.skipLogHeaders = true - Error(errMsg) - logging.flushAll() - - f, err := os.Open(tmpFile.Name()) - if err != nil { - t.Fatalf("error %v", err) - } - content := make([]byte, 1000) - f.Read(content) - tmpFile.Close() - - // the log message is of format (w/ header): Lmmdd hh:mm:ss.uuuuuu threadid file:line] %v - expectedRegx := fmt.Sprintf( - `E[0-9]{4}\s+[0-9]{2}:[0-9]{2}:[0-9]{2}.[0-9]{6}\s+[0-9]+\s+klog_test.go:[0-9]+]\s+%v`, errMsg) - re := regexp.MustCompile(expectedRegx) - actual := string(content) - // Verify the logFile doesn't have duplicated log items. If log-file not specified, Error log will also show - // up in Warning and Info log. - if !re.MatchString(actual) { - t.Fatalf("Was expecting Error and Fatal logs both show up and show up only once, result equals\n %v", - actual) - } -} - -func deleteFile(path string) { - var err = os.Remove(path) - if err != nil { - fmt.Println(err.Error()) - } -} - // TODO: This test package should be refactored so that tests cannot // interfere with each-other. @@ -137,18 +88,6 @@ func contains(s severity, str string, t *testing.T) bool { // setFlags configures the logging flags how the test expects them. func setFlags() { logging.toStderr = false - logging.logFile = "" - logging.alsoToStderr = false - logging.skipLogHeaders = false - - for s := fatalLog; s >= infoLog; s-- { - if logging.file[s] != nil { - os.Remove(logging.file[s].(*syncBuffer).file.Name()) - logging.file[s] = nil - } - } - logging.singleModeFile = nil - } // Test that Info works as advertised. @@ -462,7 +401,7 @@ func TestOpenAppendOnStart(t *testing.T) { // Logging creates the file Info(x) - _, ok := logging.singleModeFile.(*syncBuffer) + _, ok := logging.file[infoLog].(*syncBuffer) if !ok { t.Fatal("info wasn't created") } @@ -472,7 +411,6 @@ func TestOpenAppendOnStart(t *testing.T) { // ensure we wrote what we expected logging.flushAll() b, err := ioutil.ReadFile(logging.logFile) - if err != nil { t.Fatalf("unexpected error: %v", err) }