Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Modify output method of loggingT to handle Logger/InfoLogger correctly #118

Closed
wants to merge 1 commit into from
Closed

Modify output method of loggingT to handle Logger/InfoLogger correctly #118

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 8 additions & 5 deletions klog.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -812,14 +812,17 @@ func (l *loggingT) output(s severity, log logr.InfoLogger, buf *buffer, file str
}
}
data := buf.Bytes()
if log != nil {
// TODO: set 'severity' and caller information as structured log info
// keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line}
// In later version, we should check argument s is either errorLog or infoLog.
// However for now, as backward compatibility, all s other than errorLog goes to l.logr.Info().
// if l.logr != nil && (s == errorLog || s == infoLog) {
vanou marked this conversation as resolved.
Show resolved Hide resolved
if l.logr != nil {
if s == errorLog {
l.logr.Error(nil, string(data))
l.logr.Error(nil, string(data), "severity", severityName[s], "file", file, "line", line)
} else {
log.Info(string(data))
l.logr.Info(string(data), "severity", severityName[s], "file", file, "line", line)
}
} else if log != nil && s == infoLog {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It should technically never be possible to get into a state where log == nil, l.logr != nil and s == errorLog right? Because there is no Error method on an InfoLogger. I ask because otherwise there is a risk we drop errors here 😄

This logic looks right to me :) just trying to validate my own assumptions!

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @munnerz .

Yes, that is underlying idea of this line. Ideally, it should not happen.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Makes sense. If l.logr == nil, log != nil and s is not infoLog, it seems like log messages will be silently dropped. I'm not sure if this is a feasible situation to be in, but with the previous code we'd always log unconditionally if log != nil. Is there a reason for the s == infoLog check on this line?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, as you said, if l.logr == nil, log != nil and s is not infoLog, log messages will be dropped.
I read logr package's README and thought it's good approach that klog only handles infoLog or errorLog when logr.InfoLogger or logr.Logger is used. Because user of logr.InfoLogger & logr.Logger only expects Info or Error, I think.
So, future development of klog should care about this logr's idea.

As I wrote in klog_test.go, currently this commit doesn't hurt klog package's code. And there is no public method/function with which user can specify severity value of output method.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because user of logr.InfoLogger & logr.Logger only expects Info or Error, I think.

There are log levels in between (e.g. warning) that do not have direct equivalents in a logr world (as logr only has levels). The thinking is to treat any un-levelled log message that specifies a non-info level severity as an Info message and pass along the severity as a 'key/value' in the log line (i.e. severity=warn) (except for Errors, which are always passed to the root Logger via the Error method). The reason this severity k/v pair wasn't added when SetLogger was originally added can be seen here: #20 (comment)

Mostly there wasn't clear consensus as to what 'keys' should be used and what the onus is on implementors of the logr interface wrt setting these keys so other consumers can consume them reliably 😄

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understand why k/v isn't added. It's hard problem, until some set of standard keys is established.

Thanks!

log.Info(string(data), "severity", severityName[s], "file", file, "line", line)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the above branching looks mostly correct to me, but i pinged the #klog channel of k8s slack for more reviewers.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks!

} else if l.toStderr {
os.Stderr.Write(data)
} else {
Expand Down
298 changes: 298 additions & 0 deletions klog_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"bytes"
"flag"
"fmt"
"github.com/go-logr/logr"
"io/ioutil"
stdLog "log"
"os"
Expand Down Expand Up @@ -639,3 +640,300 @@ func TestInitFlags(t *testing.T) {
t.Fatal("Expected log_file_max_size to be 2048")
}
}

func createTestValueOfLoggingT() *loggingT {
l := new(loggingT)
l.toStderr = true
l.alsoToStderr = false
l.stderrThreshold = errorLog
l.verbosity = Level(0)
l.skipHeaders = false
l.skipLogHeaders = false
l.addDirHeader = false
return l
}

// testInfoLogger implements logr.infoLogger.
var _ logr.InfoLogger = testInfoLogger{}

// testInfoLogger doesn't write log to any place.
// testInfoLogger.Info() only stores values passed as argument
// to another value of type testInfoLogger.
type testInfoLogger struct {
verbosity int
message string
keysAndValues []interface{}
enabled bool

store *testInfoLogger
}

func (il testInfoLogger) Info(msg string, kvs ...interface{}) {
il.store.message = msg
il.store.keysAndValues = append(il.keysAndValues, kvs...)
}

func (il testInfoLogger) Enabled() bool {
return il.enabled
}

// testLogger implements logr.Logger.
var _ logr.Logger = testLogger{}

// testLogger doesn't write log to any place.
// testLogger.Info() & testLogger.Error() only store values passed as argument
// to another value of type testLogger.
type testLogger struct {
name []string
verbosity int // verbosity of logr.Logger should be 0.
err error
message string
keysAndValues []interface{}
enabled bool

store *testLogger
}

func (l testLogger) Info(msg string, kvs ...interface{}) {
l.store.message = msg
l.store.keysAndValues = append(l.keysAndValues, kvs...)
}

func (l testLogger) Enabled() bool {
return l.enabled
}

func (l testLogger) Error(err error, msg string, kvs ...interface{}) {
l.store.err = err
l.store.message = msg
l.store.keysAndValues = append(l.keysAndValues, kvs...)
}

func (l testLogger) V(level int) logr.InfoLogger {
ril := testInfoLogger{}
ril.verbosity = level
ril.message = l.message
ril.keysAndValues = l.keysAndValues
ril.enabled = true
return ril
}

func (l testLogger) WithValues(kvs ...interface{}) logr.Logger {
rl := l
rl.keysAndValues = append(rl.keysAndValues, kvs...)
return rl
}

func (l testLogger) WithName(name string) logr.Logger {
rl := l
rl.name = append(rl.name, name)
return rl
}

func compareKeysAndValues(a, b []interface{}) bool {
if len(a) != len(b) {
return false
}

for i := 0; i < len(a); i++ {
if a[i] != b[i] {
return false
}
}

return true
}

/*
output method of loggingT is called at
* println method of loggingT
* printDepth method of loggingT
* printf method of loggingT
* printWithFileLine method of loggingT
* print method of loggingT (This method calls printDepth. So indirectly call output.)

And above methods are called at
* Write method of logBridge
* Info method of Verbose
* Infoln method of Verbose
* Infof method of Verbose
* Info function
* InfoDepth function
* Infoln function
* Infof function
* Warning function
* WarningDepth function
* Warningln function
* Warningf function
* Error function
* ErrorDepth function
* Errorln function
* Errorf function
* Fatal function
* FatalDepth function
* Fatalln function
* Fatalf function
* Exit function
* ExitDepth function
* Exitln function
* Exitf function
and
* receiver of output method is global variable logging in all these methods
* argument log of output method is
1. Verbose.logr at Info, Infoln and Infof method of Verbose with argument s as infoLog, or
2. global variable logging at all other these methods with argument s as any severity.

So currently, there should be 4 situations in which logr.InfoLogger/logr.Logger is handled:
* (Situation 1) log argument is set with severity as infoLog & logr field of receiver l is set
=> Info method of l.logr is called.
* (Situation 2) log argument is set with severity as infoLog & logr field of receiver l is not set
=> Info method of log argument (type logr.InfoLogger) is called.
* (Situation 3) logr field of receiver l is set & l.logr is passed as log argument with severity as any value
=> * [Situation 3-1] If severity is errorLog, Error method of l.logr is called
* [Situation 3-2] If severity is not infoLog, Info method of l.logr is called

This test function checks whether above 4 situations hold by runing sub-tests.
*/
func TestOutput(t *testing.T) {
// Situation 1
t.Run("Situation 1", func(t *testing.T) {
kv1 := []interface{}{
"severity", severityName[infoLog],
"file", "keyValue1",
"line", 1,
}

msg1 := "situation1"

bf1 := &buffer{}
bf1.next = nil
bf1.Reset()
// Call fmt.Fprintln() to emulate output method is called by println method of loggingT.
fmt.Fprintln(bf1, msg1)

// Value of type *testLogger to which test is run
tl1 := new(testLogger)

// Value of type loggingT which call output method
l1 := createTestValueOfLoggingT()
l1.logr = testLogger{store: tl1}

// Want value of testLogger
wantLogger1 := testLogger{}
// Because we call fmt.Fprintln() above to emulate println method, add "\n"
wantLogger1.message = msg1 + "\n"
wantLogger1.keysAndValues = kv1

l1.output(infoLog, l1.logr, bf1, "keyValue1", 1, false)

if tl1.message != wantLogger1.message || !compareKeysAndValues(tl1.keysAndValues, wantLogger1.keysAndValues) {
t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger1.message, wantLogger1.keysAndValues, tl1.message, tl1.keysAndValues)
}
})

// Situation 2
t.Run("Situation 2", func(t *testing.T) {
kv2 := []interface{}{
"severity", severityName[infoLog],
"file", "keyValue2",
"line", 2,
}

msg2 := "situation2"

bf2 := &buffer{}
bf2.next = nil
bf2.Reset()
// Call fmt.Fprintln() to emulate output method is called by println method of loggingT.
fmt.Fprintln(bf2, msg2)

// Value of type *testLogger to which test is run
tl2 := new(testLogger)

// Value of type loggingT which call output method & logr filed is not set (empty)
el2 := createTestValueOfLoggingT()

l2 := createTestValueOfLoggingT()
l2.logr = testLogger{store: tl2}

// Want value of testLogger
wantLogger2 := testLogger{}
// Because we call fmt.Fprintln() above to emulate println method, add "\n"
wantLogger2.message = msg2 + "\n"
wantLogger2.keysAndValues = kv2

el2.output(infoLog, l2.logr, bf2, "keyValue2", 2, false)

if tl2.message != wantLogger2.message || !compareKeysAndValues(tl2.keysAndValues, wantLogger2.keysAndValues) {
t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger2.message, wantLogger2.keysAndValues, tl2.message, tl2.keysAndValues)
}
})

// Situation 3-1 & 3-2
// Currently, in output method, logr.Logger.Error(err error, msg string, keysAndValues ...interface{})
// is called with nil as err argument. So we don't check whether value passed as err is correctly set.
testCases := []struct {
subt string
kv []interface{}
msg string
severity severity
file string
line int
}{
{
subt: "Situation 3-1",
kv: []interface{}{
"severity", severityName[errorLog],
"file", "keyValue31",
"line", 31,
},
msg: "situation31",
severity: errorLog,
file: "keyValue31",
line: 31,
},
{
subt: "Situation 3-2",
kv: []interface{}{
"severity", severityName[warningLog],
"file", "keyValue32",
"line", 32,
},
msg: "situation32",
severity: warningLog,
file: "keyValue32",
line: 32,
},
}

for _, tv := range testCases {
t.Run(tv.subt, func(t *testing.T) {

bf3 := &buffer{}
bf3.next = nil
bf3.Reset()
// Call fmt.Fprintln() to emulate output method is called by println method of loggingT.
fmt.Fprintln(bf3, tv.msg)

// Value of type *testLogger to which test is run
tl3 := new(testLogger)

// Value of type loggingT which call output method
l3 := createTestValueOfLoggingT()
l3.logr = testLogger{store: tl3}

// Want value of testLogger
wantLogger3 := testLogger{}
// Because we call fmt.Fprintln() above to emulate println method, add "\n"
wantLogger3.message = tv.msg + "\n"
wantLogger3.keysAndValues = tv.kv

l3.output(tv.severity, l3.logr, bf3, tv.file, tv.line, false)

if tl3.message != wantLogger3.message || !compareKeysAndValues(tl3.keysAndValues, wantLogger3.keysAndValues) {
t.Errorf("output method of loggingT doesn't call logr.Logger.Info correctly:\nwant:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\ngot:\n\tmessage:\t%v\n\tkeysAndValues:\t%v\n", wantLogger3.message, wantLogger3.keysAndValues, tl3.message, tl3.keysAndValues)
}
})
}

}