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.

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

Add missing Depth logging functions. #280

Merged
merged 1 commit into from Feb 4, 2022
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
98 changes: 96 additions & 2 deletions klog.go
Expand Up @@ -699,7 +699,11 @@ func (buf *buffer) someDigits(i, d int) int {
}

func (l *loggingT) println(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) {
buf, file, line := l.header(s, 0)
l.printlnDepth(s, logger, filter, 1, args...)
Copy link

Choose a reason for hiding this comment

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

I'm seeing off-by-one errors during stack unwinding after updating to a klog with this change.

Why is this 1 and not something else? Was that tested?

Copy link

Choose a reason for hiding this comment

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

I can change that to 2 without any test failing. Looks like we don't have any test for this in klog itself.

Copy link
Author

Choose a reason for hiding this comment

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

sorry, I assumed that 1 for stack unwinding is correct value due to

func Exitf(format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) logging.printf(fatalLog, logging.logr, logging.filter, format, args...) }

Copy link
Author

Choose a reason for hiding this comment

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

Copy link

Choose a reason for hiding this comment

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

It breaks in Kubernetes when testing the JSON logger, i.e. when SetLogger is used with a Logger implementation that itself does stack unwinding. We can't test that in klog with just a unit test because we must not depend on such a logger.

}

func (l *loggingT) printlnDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) {
Copy link

Choose a reason for hiding this comment

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

What is suspicious here is that depth is not passed through to l.output. Wrapping printlnDepth with println and keeping the same constant 0 as before can't be right.

Copy link
Author

Choose a reason for hiding this comment

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

I assume it should be something like depth+1

Copy link

Choose a reason for hiding this comment

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

Pasing depth through fixed it for me -> #287

Copy link

Choose a reason for hiding this comment

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

Whether it is "1" or "depth + 1" depends a lot on the actual semantic, which isn't well defined. This is almost impossible to get right without tests 😢

In this case one can reason like this: 0 was correct before, now we add one layer and pass depth=1 -> passing depth is right, depth+1 would be one level too many. Testing with the JSON tests in Kubernetes confirms that.

buf, file, line := l.header(s, depth)
// if logger is set, we clear the generated header as we rely on the backing
// logger implementation to print headers
if logger != nil {
Expand Down Expand Up @@ -736,7 +740,11 @@ func (l *loggingT) printDepth(s severity, logger *logr.Logger, filter LogFilter,
}

func (l *loggingT) printf(s severity, logger *logr.Logger, filter LogFilter, format string, args ...interface{}) {
buf, file, line := l.header(s, 0)
l.printfDepth(s, logger, filter, 1, format, args...)
}

func (l *loggingT) printfDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, format string, args ...interface{}) {
buf, file, line := l.header(s, depth)
// if logr is set, we clear the generated header as we rely on the backing
// logr implementation to print headers
if logger != nil {
Expand Down Expand Up @@ -1459,6 +1467,14 @@ func (v Verbose) Info(args ...interface{}) {
}
}

// InfoDepth is equivalent to the global InfoDepth function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) InfoDepth(depth int, args ...interface{}) {
if v.enabled {
logging.printDepth(infoLog, v.logr, v.filter, depth, args...)
}
}

// Infoln is equivalent to the global Infoln function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) Infoln(args ...interface{}) {
Expand All @@ -1467,6 +1483,14 @@ func (v Verbose) Infoln(args ...interface{}) {
}
}

// InfolnDepth is equivalent to the global InfolnDepth function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) InfolnDepth(depth int, args ...interface{}) {
if v.enabled {
logging.printlnDepth(infoLog, v.logr, v.filter, depth, args...)
}
}

// Infof is equivalent to the global Infof function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) Infof(format string, args ...interface{}) {
Expand All @@ -1475,6 +1499,14 @@ func (v Verbose) Infof(format string, args ...interface{}) {
}
}

// InfofDepth is equivalent to the global InfofDepth function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) InfofDepth(depth int, format string, args ...interface{}) {
if v.enabled {
logging.printfDepth(infoLog, v.logr, v.filter, depth, format, args...)
}
}

// InfoS is equivalent to the global InfoS function, guarded by the value of v.
// See the documentation of V for usage.
func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) {
Expand Down Expand Up @@ -1530,12 +1562,24 @@ func Infoln(args ...interface{}) {
logging.println(infoLog, logging.logr, logging.filter, args...)
}

// InfolnDepth acts as Infoln but uses depth to determine which call frame to log.
// InfolnDepth(0, "msg") is the same as Infoln("msg").
func InfolnDepth(depth int, args ...interface{}) {
logging.printlnDepth(infoLog, logging.logr, logging.filter, depth, args...)
}

// Infof logs to the INFO log.
// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
func Infof(format string, args ...interface{}) {
logging.printf(infoLog, logging.logr, logging.filter, format, args...)
}

// InfofDepth acts as Infof but uses depth to determine which call frame to log.
// InfofDepth(0, "msg", args...) is the same as Infof("msg", args...).
func InfofDepth(depth int, format string, args ...interface{}) {
logging.printfDepth(infoLog, logging.logr, logging.filter, depth, format, args...)
}

// InfoS structured logs to the INFO log.
// The msg argument used to add constant description to the log line.
// The key/value pairs would be join by "=" ; a newline is always appended.
Expand Down Expand Up @@ -1566,12 +1610,24 @@ func Warningln(args ...interface{}) {
logging.println(warningLog, logging.logr, logging.filter, args...)
}

// WarninglnDepth acts as Warningln but uses depth to determine which call frame to log.
// WarninglnDepth(0, "msg") is the same as Warningln("msg").
func WarninglnDepth(depth int, args ...interface{}) {
logging.printDepth(warningLog, logging.logr, logging.filter, depth, args...)
Copy link

Choose a reason for hiding this comment

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

Also should be logging.printlnDepth here.

Copy link
Author

Choose a reason for hiding this comment

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

Should I do a PR fix for that?

Copy link
Author

Choose a reason for hiding this comment

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

There is also FatallnDepth( with similar issue

}

// Warningf logs to the WARNING and INFO logs.
// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
func Warningf(format string, args ...interface{}) {
logging.printf(warningLog, logging.logr, logging.filter, format, args...)
}

// WarningfDepth acts as Warningf but uses depth to determine which call frame to log.
// WarningfDepth(0, "msg", args...) is the same as Warningf("msg", args...).
func WarningfDepth(depth int, format string, args ...interface{}) {
logging.printfDepth(warningLog, logging.logr, logging.filter, depth, format, args...)
}

// Error logs to the ERROR, WARNING, and INFO logs.
// Arguments are handled in the manner of fmt.Print; a newline is appended if missing.
func Error(args ...interface{}) {
Expand All @@ -1590,12 +1646,24 @@ func Errorln(args ...interface{}) {
logging.println(errorLog, logging.logr, logging.filter, args...)
}

// ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log.
// ErrorlnDepth(0, "msg") is the same as Errorln("msg").
func ErrorlnDepth(depth int, args ...interface{}) {
logging.printDepth(errorLog, logging.logr, logging.filter, depth, args...)
Copy link

Choose a reason for hiding this comment

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

Shouldn't this be logging.printlnDepth? Errorln uses logging.println.

Copy link
Author

Choose a reason for hiding this comment

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

hmm, yea

}

// Errorf logs to the ERROR, WARNING, and INFO logs.
// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
func Errorf(format string, args ...interface{}) {
logging.printf(errorLog, logging.logr, logging.filter, format, args...)
}

// ErrorfDepth acts as Errorf but uses depth to determine which call frame to log.
// ErrorfDepth(0, "msg", args...) is the same as Errorf("msg", args...).
func ErrorfDepth(depth int, format string, args ...interface{}) {
logging.printfDepth(errorLog, logging.logr, logging.filter, depth, format, args...)
}

// ErrorS structured logs to the ERROR, WARNING, and INFO logs.
// the err argument used as "err" field of log line.
// The msg argument used to add constant description to the log line.
Expand Down Expand Up @@ -1635,13 +1703,25 @@ func Fatalln(args ...interface{}) {
logging.println(fatalLog, logging.logr, logging.filter, args...)
}

// FatallnDepth acts as Fatalln but uses depth to determine which call frame to log.
// FatallnDepth(0, "msg") is the same as Fatalln("msg").
func FatallnDepth(depth int, args ...interface{}) {
logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...)
}

// Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs,
// including a stack trace of all running goroutines, then calls os.Exit(255).
// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
func Fatalf(format string, args ...interface{}) {
logging.printf(fatalLog, logging.logr, logging.filter, format, args...)
}

// FatalfDepth acts as Fatalf but uses depth to determine which call frame to log.
// FatalfDepth(0, "msg", args...) is the same as Fatalf("msg", args...).
func FatalfDepth(depth int, format string, args ...interface{}) {
logging.printfDepth(fatalLog, logging.logr, logging.filter, depth, format, args...)
}

// fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks.
// It allows Exit and relatives to use the Fatal logs.
var fatalNoStacks uint32
Expand All @@ -1666,13 +1746,27 @@ func Exitln(args ...interface{}) {
logging.println(fatalLog, logging.logr, logging.filter, args...)
}

// ExitlnDepth acts as Exitln but uses depth to determine which call frame to log.
// ExitlnDepth(0, "msg") is the same as Exitln("msg").
func ExitlnDepth(depth int, args ...interface{}) {
atomic.StoreUint32(&fatalNoStacks, 1)
logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...)
}

// Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1).
// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing.
func Exitf(format string, args ...interface{}) {
atomic.StoreUint32(&fatalNoStacks, 1)
logging.printf(fatalLog, logging.logr, logging.filter, format, args...)
}

// ExitfDepth acts as Exitf but uses depth to determine which call frame to log.
// ExitfDepth(0, "msg", args...) is the same as Exitf("msg", args...).
func ExitfDepth(depth int, format string, args ...interface{}) {
atomic.StoreUint32(&fatalNoStacks, 1)
logging.printfDepth(fatalLog, logging.logr, logging.filter, depth, format, args...)
}

// LogFilter is a collection of functions that can filter all logging calls,
// e.g. for sanitization of arguments and prevent accidental leaking of secrets.
type LogFilter interface {
Expand Down