Repository: kubernetes/klog
Pull request #141 (2020-04-16 18:31:46)

klog: do not repeat messages on all severity flushSyncWriter
If a log message for a particular severity is created, it should be
enough to log such message in its flushSyncWriter. Having a fallthrough
on each switch statement will make the messages to be duplicated on each
flushSyncWriters that follows the selected case.

Signed-off-by: André Martins <aanm90@gmail.com>

**Release note**:
```release-note
klog: do not repeat messages for all severity writers
```

k8s-ci-robot: [APPROVALNOTIFIER] This PR is **NOT APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/141#" title="Author self-approved">aanm</a>*
To complete the [pull request process](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process), please assign **tallclair**
You can assign the PR to them by writing `/assign @tallclair` in a comment when ready.

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

<details open>
Needs approval from an approver in each of these files:

- **[OWNERS](https://github.com/kubernetes/klog/blob/master/OWNERS)**

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":["tallclair"]} -->
dims: /assign @DirectXMan12 @thockin 
DirectXMan12: it's not entirely clear to me why we're doing this -- is there a motivating issue, etc with discussion?  It's also not clear that we can do this in klog v1 -- otherwise we'd be breaking compat.
DirectXMan12: or rather, more broadly, it's not clear to me if folks rely on this behavior -- I *think* the current behavior is design such that a given writer gets all output as if it had been passed a V flag, conceptually (literally not the same due to the general weirdness around V, etc) -- the "info" writer is as if the user had passed a flag asking for the "info" verbosity, and so on.  This seems like advantageous behavior in some cases, and something that folks could very likely be relying on.
thockin: So, this behavior is one of my very least favorite behaviors is glog.  I have almost exclusively see it used as `--logtostderr`, so I don't know if this would be a breaking change, but it sure could be.

If we want to make this change, we should probably declare version 3.0.0 of klog ?
dims: /hold

ENOWAY if it means a v3!!! we still haven't moved folks to v2 yet (k/k is still on v1).
thockin: At the end of the day, I don't own klog day-to-day.  This is a very "grey"
change.  Strictly speaking it is breaking, but it's not clear if that
actually matters.

If I were driving, I would not do this (or I would require a flag that says
--klog-one-output-file or something).

On Fri, Apr 24, 2020 at 3:29 AM Davanum Srinivas <notifications@github.com>
wrote:

> /hold
>
> ENOWAY if it means a v3!!! we still haven't moved folks to v2 yet (k/k is
> still on v1).
>
> —
> You are receiving this because you were assigned.
> Reply to this email directly, view it on GitHub
> <https://github.com/kubernetes/klog/pull/141#issuecomment-618932741>, or
> unsubscribe
> <https://github.com/notifications/unsubscribe-auth/ABKWAVDLBOKMMEAKXKZYDVLROFSW5ANCNFSM4MJ76SMA>
> .
>

DirectXMan12: I think the main problem is that, at least in v1, we're kinda stuck with the behavior (more specifically, we've made okay-ish seeming changes like this, and then had to revert when we broke something significant).  A flag could work, though.
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **NOT APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/141#" title="Author self-approved">aanm</a>*
To complete the [pull request process](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process), please assign **directxman12**
You can assign the PR to them by writing `/assign @directxman12` in a comment when ready.

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

<details open>
Needs approval from an approver in each of these files:

- **[OWNERS](https://github.com/kubernetes/klog/blob/master/OWNERS)**

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":["directxman12"]} -->
aanm: @DirectXMan12 thanks for the proposal. I've introduced `--skip_propagation` to keep existing functionality untouched.
DirectXMan12: /lgtm

this seem fine to others?
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/141#" title="Author self-approved">aanm</a>*, *<a href="https://github.com/kubernetes/klog/pull/141#issuecomment-635007421" title="LGTM">DirectXMan12</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/kubernetes/klog/blob/master/OWNERS)~~ [DirectXMan12]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->

Patch:
diff --git a/klog.go b/klog.go
index ae2b861..8293150 100644
--- a/klog.go
+++ b/klog.go
@@ -413,6 +413,7 @@ func init() {
 	logging.skipHeaders = false
 	logging.addDirHeader = false
 	logging.skipLogHeaders = false
+	logging.oneOutput = false
 	go logging.flushDaemon()
 }
 
@@ -432,6 +433,7 @@ func InitFlags(flagset *flag.FlagSet) {
 	flagset.Var(&logging.verbosity, "v", "number for the log level verbosity")
 	flagset.BoolVar(&logging.addDirHeader, "add_dir_header", logging.addDirHeader, "If true, adds the file directory to the header of the log messages")
 	flagset.BoolVar(&logging.skipHeaders, "skip_headers", logging.skipHeaders, "If true, avoid header prefixes in the log messages")
+	flagset.BoolVar(&logging.oneOutput, "one_output", logging.oneOutput, "If true, only write logs to their native severity level (vs also writing to each lower severity level")
 	flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files")
 	flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr")
 	flagset.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
@@ -505,6 +507,9 @@ type loggingT struct {
 
 	// If set, all output will be redirected unconditionally to the provided logr.Logger
 	logr logr.Logger
+
+	// If true, messages will not be propagated to lower severity log levels
+	oneOutput bool
 }
 
 // buffer holds a byte Buffer for reuse. The zero value is ready for use.
@@ -919,18 +924,22 @@ func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, file string,
 				}
 			}
 
-			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 l.oneOutput {
+				l.file[s].Write(data)
+			} else {
+				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)
+				}
 			}
 		}
 	}


Test patch:
diff --git a/integration_tests/klog_test.go b/integration_tests/klog_test.go
index 6c515e6..565fd8a 100644
--- a/integration_tests/klog_test.go
+++ b/integration_tests/klog_test.go
@@ -40,6 +40,12 @@ var (
 		2: {stackTraceRE, fatalLogRE, errorLogRE},
 		3: {stackTraceRE, fatalLogRE},
 	}
+	expectedOneOutputInDirREs = map[int]res{
+		0: {infoLogRE},
+		1: {warningLogRE},
+		2: {errorLogRE},
+		3: {fatalLogRE},
+	}
 
 	defaultNotExpectedInDirREs = map[int]res{
 		0: {},
@@ -135,6 +141,18 @@ func TestDestinationsWithDifferentFlags(t *testing.T) {
 			expectedInDir:       defaultExpectedInDirREs,
 			notExpectedInDir:    defaultNotExpectedInDirREs,
 		},
+		"with log dir only and one_output": {
+			// Everything, including the trace on fatal, goes to the log files in the log dir
+
+			logdir: true,
+			flags:  []string{"-logtostderr=false", "-alsologtostderr=false", "-stderrthreshold=1000", "-one_output=true"},
+
+			expectedLogDir: true,
+
+			notExpectedOnStderr: allLogREs,
+			expectedInDir:       expectedOneOutputInDirREs,
+			notExpectedInDir:    defaultNotExpectedInDirREs,
+		},
 		"with log dir and logtostderr": {
 			// Everything, including the trace on fatal, goes to stderr. The -log_dir is
 			// ignored, nothing goes to the log files in the log dir.
@@ -182,6 +200,19 @@ func TestDestinationsWithDifferentFlags(t *testing.T) {
 			expectedInDir:    defaultExpectedInDirREs,
 			notExpectedInDir: defaultNotExpectedInDirREs,
 		},
+		"with log dir, alsologtostderr and one_output": {
+			// Everything, including the trace on fatal, goes to the log file in the
+			// log dir AND to stderr.
+
+			logdir: true,
+			flags:  []string{"-alsologtostderr=true", "-logtostderr=false", "-stderrthreshold=1000", "-one_output=true"},
+
+			expectedLogDir: true,
+
+			expectedOnStderr: allLogREs,
+			expectedInDir:    expectedOneOutputInDirREs,
+			notExpectedInDir: defaultNotExpectedInDirREs,
+		},
 	}
 
 	binaryFileExtention := ""
diff --git a/klog_test.go b/klog_test.go
index ff95814..8003c3d 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -241,6 +241,33 @@ func TestError(t *testing.T) {
 	}
 }
 
+// Test that an Error log does not goes to Warning and Info.
+// Even in the Info log, the source character will be E, so the data should
+// all be identical.
+func TestErrorWithOneOutput(t *testing.T) {
+	setFlags()
+	logging.oneOutput = true
+	buf := logging.newBuffers()
+	defer func() {
+		logging.swap(buf)
+		logging.oneOutput = false
+	}()
+	Error("test")
+	if !contains(errorLog, "E", t) {
+		t.Errorf("Error has wrong character: %q", contents(errorLog))
+	}
+	if !contains(errorLog, "test", t) {
+		t.Error("Error failed")
+	}
+	str := contents(errorLog)
+	if contains(warningLog, str, t) {
+		t.Error("Warning failed")
+	}
+	if contains(infoLog, str, t) {
+		t.Error("Info failed")
+	}
+}
+
 // Test that a Warning log goes to Info.
 // Even in the Info log, the source character will be W, so the data should
 // all be identical.
@@ -260,6 +287,30 @@ func TestWarning(t *testing.T) {
 	}
 }
 
+// Test that a Warning log does not goes to Info.
+// Even in the Info log, the source character will be W, so the data should
+// all be identical.
+func TestWarningWithOneOutput(t *testing.T) {
+	setFlags()
+	logging.oneOutput = true
+	buf := logging.newBuffers()
+	defer func() {
+		logging.swap(buf)
+		logging.oneOutput = false
+	}()
+	Warning("test")
+	if !contains(warningLog, "W", t) {
+		t.Errorf("Warning has wrong character: %q", contents(warningLog))
+	}
+	if !contains(warningLog, "test", t) {
+		t.Error("Warning failed")
+	}
+	str := contents(warningLog)
+	if contains(infoLog, str, t) {
+		t.Error("Info failed")
+	}
+}
+
 // Test that a V log goes to Info.
 func TestV(t *testing.T) {
 	setFlags()