Skip to content

Commit

Permalink
Merge pull request #69 from dims/revert-yuwenma-dedup-log
Browse files Browse the repository at this point in the history 
Revert "Fix the log duplication issue for --log-file."
  • Loading branch information
@k8s-ci-robot
k8s-ci-robot committed Jun 12, 2019
2 parents 78315d9 + 941d47b commit d98d8ac
Show file tree
Hide file tree
Showing 2 changed files with 55 additions and 170 deletions.
161 changes: 54 additions & 107 deletions klog.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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.
Expand All @@ -803,73 +765,66 @@ 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 {
l.mu.Unlock()
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
Expand Down Expand Up @@ -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
}
}
}
}

Expand Down Expand Up @@ -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.
//
Expand Down
64 changes: 1 addition & 63 deletions klog_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,63 +22,14 @@ import (
"fmt"
"io/ioutil"
stdLog "log"
"os"
"path/filepath"
"regexp"
"runtime"
"strconv"
"strings"
"testing"
"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.

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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")
}
Expand All @@ -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)
}
Expand Down

0 comments on commit d98d8ac

Please sign in to comment.