textlogger write through

[pohly]

What this PR does / why we need it:

kubernetes/kubernetes#114672 uses the textlogger for output routing instead of the legacy code in klog. However, this changes the output for unstructured output (gets quoted) and makes it slower (double encoding).

To avoid both, this PR adds an API for setting a logger that can take formatted data from klog and then writes it directly.

Release note:

NONE

[logicalhan]

/assign @serathius @thockin
/triage accepted

[serathius]

Overall comment whether we need this temporary solution to avoid double encoding.

As discussed on WG meeting, I'm not necessary against performance regressions if:

• If avoids hacks and allows more simplicity
• Doesn't break out performance goals. For K8s our canonical performance benchmark is scalability tests. cc @wojtek-t

[pohly]

As discussed on WG meeting, I'm not necessary against performance regressions

It's not just the performance regressions, the output also becomes less readable. Before:

I0127 11:50:17.513183   32691 logger.go:77] Log using Infof, key: value
I0127 11:50:17.513222   32691 logger.go:83] Log with sensitive key, data: {"secret"}

With double encoding:

I0127 11:51:10.937134   33070 logger.go:77] "Log using Infof, key: value\n"
I0127 11:51:10.937207   33070 logger.go:83] "Log with sensitive key, data: {\"secret\"}\n"

I forgot to point that out in the WG meeting.

[pohly]

Doesn't break out performance goals. For K8s our canonical performance benchmark is scalability tests.

I consider that the "acceptance test" for logging changes. But I think we should also strive to achieve the same results with as little extra CPU cycles as possible.

[serathius]

Overall lgtm, however name WriteKlogBuffer is little contentious. If I understand it will not be a full fledged feature, just a a temporary workaround to avoid double encoding until we migrate k/k to structured logging. At that point it will not be useful and can be removed. Is that right?

If that so WriteKlogBuffer makes somewhat sense as it a workaround for klog. However It would be clearer if it's called something like KlogEncoderBypass or something similar.

Outside of name, I think WriteKlogBuffer comment is somewhat misleading, it nicely documents the function to make it easier for use, however I don't think we should recommend using it. If the motivation that I wrote above it true, than comment should clearly state:

• This function is a klog specific workaround to avoid double encoding.
• It's only until k/k is migrated to structured logging, after that will be removed.
• It should not be used by any other logger, please don't use it

[pohly]

If I understand it will not be a full fledged feature, just a a temporary workaround to avoid double encoding until we migrate k/k to structured logging. At that point it will not be useful and can be removed. Is that right?

Unfortunately not. It needs to become part of the klog v2 API, which means we cannot remove it even when Kubernetes itself no longer needs it.

it nicely documents the function to make it easier for use, however I don't think we should recommend using it.

As it has to become officially part of the API, we should treat it like that and document how to use it.

[pohly]

I've been thinking about avoiding this public API, but both klog and textlogger are designed to be completely independent from each other. They just share some internal packages.

Moving the klog state into such an internal package wouldn't help: textlogger then could provide an API to install itself there, but it would make textlogger depend on quite a bit of extra baggage - IMHO not a good solution.

[serathius]

cc @liggitt @dims who might be interested in the problem

[banjoh]

I'm keen to see how this PR progresses. I'm blocked by the same problem. I'm implementing my own logr.Logger and setting it using klog.SetLogger(logger). My log output ends up with newlines like below. NOTE: I'm not using textlogger meaning this issue will affect anyone who implements their own logger, I think.

[evans] $ ./bin/app -v=2
I0208 16:27:50.193136   72871 root.go:58] "Log message from klog\n"
I0208 16:27:50.193154   72871 root.go:59] "Info message from klog with verbosity 1\n"
I0208 16:27:50.193170   72871 root.go:60] "Infof message from klog with verbosity 1: arg1\n"

Without my logger

I0208 16:29:03.835147   73224 root.go:54] Log message from klog
I0208 16:29:03.835168   73224 root.go:55] Info message from klog with verbosity 1
I0208 16:29:03.835196   73224 root.go:56] Infof message from klog with verbosity 1: arg1

FWIW I tested using https://github.com/go-logr/stdr and https://github.com/go-logr/glogr with the same results, as I expected.

[pohly]

I'm keen to see how this PR progresses. I'm blocked by the same problem. I'm implementing my own logr.Logger and setting it using klog.SetLogger(logger).

So do you intend to use WriteKlogBuffer in combination with your logger? How? If you just pass through the log output unchanged, won't that lead to a mixture of different formats (klog text format, structured logging from your logger)? Is that desired?

With the intended usage in combination with textlogger, all messages would be using klog text format, so there is no such inconsistency.

[banjoh]

This is what I intend to achieve.

I would like to intercept logs (with whatever formatting they are in) and write them to a separate file (not the one created when you pass in log_file, or log_dir). Exploring the library led me to writing my own logr.Logger and passing it to klog.SetLogger(logger) where I'd have my implementation.

You ask why? Our library heavily uses k8s client-go and we would like to grab logs emitted by the library.

If you just pass through the log output unchanged, won't that lead to a mixture of different formats (klog text format, structured logging from your logger)? Is that desired?

I'm looking for the lowest denominator in the framework to intercept the logs and write elsewhere. My logger will not do any formatting. I ended up using textLogger to retain as much of the formatting as possible. By the look of things, WriteKlogBuffer looks promising.

I'm open to suggestions here.

[banjoh]

I addition to the k8s client-go dependency, we would like to use klog's verbosity levels. I know logr loggers have the same interfaces but I thought it would be better to sick with one logging implementation.

[pohly]

From a brief look at your LogSink implementation it seems that you should be able to use the textlogger directly?

Or what functionality is missing?

[banjoh]

Or what functionality is missing?

I'm missing the part where I can "tee" the logs elsewhere (e.g to a file). I added this change to demonstrate what I mean. Ignore the double formatting done by funcr.Formatter. Its there for demonstration purposes only.

Sample invocation

func main() {
	klog.SetLogger(logger.New(logger.Options{
		Verbosity: 1,
	}))
	klog.Info("Hello, world!")
}

Output looks like this

[evans] $ go run main.go
I0208 18:46:40.134371   89450 main.go:12] "Hello, world!\n"
TEE'd LOG:  "level"=0 "msg"="Hello, world!\n"

With your PR, I'd like to see if all I need is to implement WriteKlogBuffer instead of trying to route Info and Error calls to my logger.

[banjoh]

// The buffer will contain exactly the same data that klog normally would write
// into its own output stream(s). In particular this includes the header, if
// klog is configured to write one. The callback then can divert that data into
// its own output streams. The buffer may or may not end in a line break.

This comment is what led me to think this change might suite my needs

[pohly]

textlogger writes to an io.Writer, set for the config with Output. The (implicit) guarantee is that there will be one Write call per message - I probably should make that explicit in the documentation.

The implementation of that io.Writer can redirect the actual bytes however it wants. I am using that in kubernetes/kubernetes#114672 to write info messages to stdout and error messages to stderr, with buffering of info messages.

[pohly]

So if your goal is to redirect output, then both textlogger and this PR will be relevant for you. My point was just that you don't need to wrap textlogger in your own sink for that.

[banjoh]

My point was just that you don't need to wrap textlogger in your own sink for that.

Thanks for the call out. I'll adjust my code accordingly.

textlogger writes to an io.Writer, set for the config with Output. The (implicit) guarantee is that there will be one Write call per message - I probably should make that explicit in the documentation.

This will do the trick with my code looking like this now. Its much simpler and cleaner.

type MyWriter struct{}

func (w *MyWriter) Write(p []byte) (n int, err error) {
	// TODO: Tee my logs to other destinations using https://pkg.go.dev/io#MultiWriter
	fmt.Printf("Written: %s", p)
	return 0, nil
}

// Implementation
klog.SetLogger(textlogger.NewLogger(textlogger.NewConfig(
	textlogger.Verbosity(1),
	textlogger.Output(&logger.MyWriter{}),
)))

Written: I0209 10:10:03.647496   14593 root.go:49] "Hello World!\n"
Written: I0209 10:10:03.647514   14593 root.go:50] "Hello World! with verbosity 1\n"

As a side note, setting the output in klog like so klog.SetOutput(&logger.MyWriter{}) does not have my writer called, which I found a bit misleading. I'm not sure in what conditions it should work. Here is a simple example

package main

import (
	"fmt"

	"k8s.io/klog/v2"
)

type MyWriter struct{}
func (w *MyWriter) Write(p []byte) (n int, err error) {
	fmt.Printf("Written: %s", p)
	return 0, nil
}

func main() {
	klog.SetOutput(&MyWriter{})
	klog.Info("Hello, world!")
}

[evans] $ go run main.go
I0209 10:29:53.239060   17318 main.go:19] Hello, world!

I also noticed this comment claiming the textlogger to be experimental. Are there plans to bring the API to stability?

[pohly]

As a side note, setting the output in klog like so klog.SetOutput(&logger.MyWriter{}) does not have my writer called, which I found a bit misleading.

Was that when you also did klog.SetLogger? When a logger is set, klog should hand over all log entries to that logger and not use the output file.

Never mind, I didn't read carefully. SetOutput only has an effect when klog is not configured to write to stderr. With --logtostderr=false it starts using the file, potentially multiple times per log entry (!), once for each severity level. It's really baroque.

I also noticed this comment claiming the textlogger to be experimental. Are there plans to bring the API to stability?

Yes, as soon as we are confident that the API is sane and no longer needs to be changed in incompatible ways. I think it's almost there, only #368 needs to be merged first.

[banjoh]

@pohly anyway I can be of assistance here, or is this change waiting for someone to review and give a thumbs up?

[pohly]

Someone needs to review and decide whether it's worth adding this to klog.

[dims]

Let's not beat ourselves up if WriteKlogBuffer doesn't feel appropriate. it's still in a separate package with a very few set of references, hoping it stays that way:
https://cs.github.com/?scopeName=All+repos&scope=&q=%2Fklog%5C%2Fv2%5C%2Ftextlogger%2F

/approve
/lgtm

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, pohly

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 [dims]

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