Fix the log duplication issue for --log-file #78

dims · 2019-07-30T21:28:55Z

What this PR does / why we need it:

when we use a log-file, all the items in l.file array point to the
same file. we are currently using a switch statement with fallthrough
which ends up logging the same line multiple times. So check if we are
using a log-file and just write the data once.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #

Special notes for your reviewer:

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

Release note:

NONE

dims · 2019-07-30T21:30:25Z

benchmark with "fix"

dims@bigbox:~/go/src/k8s.io/klog$ go test -benchmem -run=^$ k8s.io/klog -bench "^(BenchmarkLogs)$" -v -count=10
goos: linux
goarch: amd64
pkg: k8s.io/klog
BenchmarkLogs-20    	  200000	      8123 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7999 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7580 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      8165 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7790 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      8584 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7789 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7952 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      7665 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	      8583 ns/op	     556 B/op	       6 allocs/op
PASS
ok  	k8s.io/klog	25.716s

benchmark without the "fix"

dims@bigbox:~/go/src/k8s.io/klog$ go test -benchmem -run=^$ k8s.io/klog -bench "^(BenchmarkLogs)$" -v -count=10
goos: linux
goarch: amd64
pkg: k8s.io/klog
BenchmarkLogs-20    	  100000	     10248 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10330 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10996 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10331 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	     10166 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  200000	     10168 ns/op	     556 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10920 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10079 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10913 ns/op	     560 B/op	       6 allocs/op
BenchmarkLogs-20    	  100000	     10162 ns/op	     560 B/op	       6 allocs/op
PASS
ok  	k8s.io/klog	24.772s

dims · 2019-07-30T21:30:45Z

/assign @vincepri @yuwenma

dims · 2019-07-30T21:31:51Z

/approve cancel

neolit123 · 2019-07-30T21:41:50Z

klog.go

+
+		if logging.logFile != "" {
+			if l.file[infoLog] == nil {
+				if err := l.createFiles(s); err != nil {


should this be l.createFiles(infoLog)?
i don't know the details of the duplication issue, but does logging.logFile imply infoLog severity only?

Fixed @neolit123. added some comments to clarify what we are doing

dims · 2019-08-02T01:38:34Z

/assign @tallclair

@yuwenma @tallclair can you please review since both of you worked on the previous attempt? (in kubernetes/kubernetes#78466)

when we use a `log-file`, all the items in l.file array point to the same file. we are currently using a switch statement with fallthrough which ends up logging the same line multiple times. So check if we are using a `log-file` and just write the data once. Change-Id: I3396558f487daf9db2c5e21e29a7a6bee618d64a

yuwenma · 2019-08-07T15:19:09Z

@dims The PR lgtm. The only concern I have is that: Even if user provides --log-file flag, they should still be able to use --alsologtostderr flag to require standard output. This requires storing logs individually by severity level. Also, in such case users should be able to use --stderrthreshold to change the severity level of the standard output (e.g. if stderrthreshold is warning, all logs in warning and above warning will be printed in the stdout).

The above feature is no longer available after this PR goes in. Is this what we want? If so, can you add a docstring for alsologtostderr and stderrthreshold flags to explain this behavior?

tallclair

/lgtm

I could have sworn I reviewed a very similar change before, but don't know what happened to it...

tallclair · 2019-08-07T17:00:58Z

klog.go

+		if logging.logFile != "" {
+			// Since we are using a single log file, all of the items in l.file array
+			// will point to the same file, so just use one of them to write data.
+			if l.file[infoLog] == nil {


nit: can we declare a constant to make this more explicit?

const singleFileLog = infoLog

k8s-ci-robot · 2019-08-07T17:06:28Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: tallclair

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [tallclair]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

tallclair · 2019-08-07T17:08:54Z

@yuwenma I don't understand your comment - it looks like the stderr output happens before these changes? Or were you commenting on an older version of this PR?

yuwenma · 2019-08-07T17:21:48Z

@yuwenma I don't understand your comment - it looks like the stderr output happens before these changes? Or were you commenting on an older version of this PR?

yeah, i was referring to a old change.

/lgtm

k8s-ci-robot added do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Jul 30, 2019

k8s-ci-robot requested review from neolit123 and pohly July 30, 2019 21:29

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jul 30, 2019

k8s-ci-robot assigned vincepri Jul 30, 2019

k8s-ci-robot removed the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jul 30, 2019

dims assigned yuwenma Jul 30, 2019

neolit123 reviewed Jul 30, 2019

View reviewed changes

dims force-pushed the dedup-log-attempt-2 branch from 5dd7e85 to e07c880 Compare August 2, 2019 01:36

dims changed the title ~~[WIP] Attempt #2 - Fix the log duplication issue for --log-file~~ Fix the log duplication issue for --log-file Aug 2, 2019

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Aug 2, 2019

k8s-ci-robot assigned tallclair Aug 2, 2019

dims force-pushed the dedup-log-attempt-2 branch from e07c880 to bf4884f Compare August 5, 2019 13:49

tallclair reviewed Aug 7, 2019

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 7, 2019

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Aug 7, 2019

k8s-ci-robot merged commit 3ca30a5 into kubernetes:master Aug 7, 2019

dims mentioned this pull request Apr 17, 2020

Need benchmark tests to prevent regressions #70

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix the log duplication issue for --log-file #78

Fix the log duplication issue for --log-file #78

dims commented Jul 30, 2019 •

edited

Loading

dims commented Jul 30, 2019

dims commented Jul 30, 2019 •

edited

Loading

dims commented Jul 30, 2019

neolit123 Jul 30, 2019

dims Aug 2, 2019

dims commented Aug 2, 2019

yuwenma commented Aug 7, 2019

tallclair left a comment

tallclair Aug 7, 2019

k8s-ci-robot commented Aug 7, 2019

tallclair commented Aug 7, 2019

yuwenma commented Aug 7, 2019

Fix the log duplication issue for --log-file #78

Fix the log duplication issue for --log-file #78

Conversation

dims commented Jul 30, 2019 • edited Loading

dims commented Jul 30, 2019

dims commented Jul 30, 2019 • edited Loading

dims commented Jul 30, 2019

neolit123 Jul 30, 2019

Choose a reason for hiding this comment

dims Aug 2, 2019

Choose a reason for hiding this comment

dims commented Aug 2, 2019

yuwenma commented Aug 7, 2019

tallclair left a comment

Choose a reason for hiding this comment

tallclair Aug 7, 2019

Choose a reason for hiding this comment

k8s-ci-robot commented Aug 7, 2019

tallclair commented Aug 7, 2019

yuwenma commented Aug 7, 2019

dims commented Jul 30, 2019 •

edited

Loading

dims commented Jul 30, 2019 •

edited

Loading