structured logging text output: handle arbitrary values

[pohly]

What happened?

The klog.InfoS output was meant to machine readable. In particular it should be possible to split the log output into individual messages.

The argument in kubernetes/klog#268 (comment) was that the klog header can be used to split the output, the same way as current log parsers already do it (backwards compatibility).

That approach does not work when a struct gets logged as value in a key/value pair and that struct contains multi-line data which contains klog headers.

What did you expect to happen?

One of the following would solve the problem:

• document how values are logged in text mode and update Kubernetes log parsers accordingly so that they handle corner cases correctly
• quote structs (but not simple types like ints) - this is actually what's currently in the KEP, it's just wasn't implemented at the end
• switch to a different text format with indention (structured logging: support log messages with line breaks klog#268)

How can we reproduce it (as minimally and precisely as possible)?

type MyStruct struct {
	Name     string
	Data     string
	internal int
}

func main() {
	klog.InitFlags(nil)
	flag.Parse()

	logData := MyStruct{
		Name: "log output from some program",
		Data: `I0000 12:00:00.000000  123456 main.go:42] Starting
E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
`,
	}
	klog.V(0).InfoS("using InfoS", "logData", logData)
}

This currently prints:

I1115 19:05:02.598278  142908 structured_logging.go:65] "using InfoS" logData={Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
 internal:0}

Anything else we need to know?

IMHO text output does not need to be machine-readable, so I favor the third solution because it also addresses #104868 without reverting to non-structured logging.

Kubernetes version

1.23 and older

Cloud provider

n/a

OS version

No response

Install tools

n/a

Container runtime (CRI) and and version (if applicable)

No response

Related plugins (CNI, CSI, ...) and versions (if applicable)

No response

[pohly]

/sig instrumentation
/wg structured-logging

[pohly]

Log ingestion written for the traditional klog output format will not handle this correctly, for example https://github.com/kubernetes/kubernetes/blob/master/cluster/addons/fluentd-elasticsearch/fluentd-es-configmap.yaml#L234

When using klog.Infof, the code which formats the log message can avoid this problem.

We need a similar solution for klog.InfoS.

[ehashman]

/triage accepted

[pohly]

We have this problem in kubelet. With the benchmark + log analysis tool from #106594 I found the following struct parameters with embedded multi-line strings in a kubelet log:

          ===== container =====
        &Container{Name:terminate-cmd-rpn,Image:k8s.gcr.io/e2e-test-images/busybox:1.29-2,Command:[sh -c 
        f=/restart-count/restartCount
        count=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})
        if [ $count -eq 1 ]; then
        	exit 1
        fi
        if [ $count -eq 2 ]; then
        	exit 0
        fi
        while true; do sleep 1; done
        ],Args:[],WorkingDir:,Ports:[]ContainerPort{},Env:[]EnvVar{},Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{},},VolumeMounts:[]VolumeMount{VolumeMount{Name:restart-count,ReadOnly:false,MountPath:/restart-count,SubPath:,MountPropagation:nil,SubPathExpr:,},VolumeMount{Name:kube-api-access-87lbt,ReadOnly:true,MountPath:/var/run/secrets/kubernetes.io/serviceaccount,SubPath:,MountPropagation:nil,SubPathExpr:,},},LivenessProbe:nil,ReadinessProbe:nil,Lifecycle:nil,TerminationMessagePath:/dev/termination-log,ImagePullPolicy:IfNotPresent,SecurityContext:nil,Stdin:false,StdinOnce:false,TTY:false,EnvFrom:[]EnvFromSource{},TerminationMessagePolicy:File,VolumeDevices:[]VolumeDevice{},StartupProbe:nil,}

Update: this value is logged as a string in the JSON output. That's odd, the original value is a *v1.Container -> #106652

[pohly]

/assign

Fixed in klog. I'll make sure to get klog released and import it into Kubernetes.

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle stale
• Mark this issue or PR as rotten with /lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[pohly]

/remove-lifecycle stale

[pohly]

The klog release with the fix is in Kubernetes 1.24.

/close

[k8s-ci-robot]

@pohly: Closing this issue.

In response to this:

The klog release with the fix is in Kubernetes 1.24.

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.