structured logging: better support for multi-line strings

[pohly]

What would you like to be added?

When using InfoS or ErrorS with a key/value that has a multi-line string as value, that value will appear as quoted string in the log message, i.e. the log message will still be a single line.

It would be nicer to print the value in text mode so that it goes across multiple lines, with clear indicators for start and end of the value. Indention could be used to avoid mistaking some embedded line as the start of a new log message.

In JSON mode, the value should be formatted normally.

/sig instrumentation
/wg structured-logging

Why is this needed?

Always printing as a single line can can make the log output unreadable (#104868).

[pohly]

When adding something like this, #106262 can be reverted and implemented differently.

[pohly]

My original thinking was that only objects that explicitly ask for multi-line output get formatted that way. But that means that we need to review log calls very carefully.

An alternative is to automatically switch from quoting strings to multi-line output based on some heuristic, for example when there's more than one line break.

[pohly]

Here's a potential implementation: kubernetes/klog#268

[NikhilSharmaWe]

@pohly If structured logging is needed in any other case I can contribute, please inform if needed.

[shivanshuraj1333]

/triage accepted
/assign @pohly
/priority important-soon
/area logging
/cc @kubernetes/wg-structured-logging-reviews

/cc @serathius

[pohly]

We have the same problem as in kube-scheduler also in kubelet, it's just that no-one has seen and/or complained about the multi-line strings. With the benchmark + log analysis tool from #106594 I found the following multi-line string parameters in a kubelet log:

             ===== statusDiff =====
          &v1.PodStatus{
        - 	Phase:                      "Running",
        + 	Phase:                      "Failed",
          	Conditions:                 {{Type: "Initialized", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:09:18 +0000 UTC"}}, {Type: "Ready", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:09:28 +0000 UTC"}}, {Type: "ContainersReady", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:09:28 +0000 UTC"}}, {Type: "PodScheduled", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:09:18 +0000 UTC"}}},
        - 	Message:                    "",
        + 	Message:                    "Pod was active on the node longer than the specified deadline",
        - 	Reason:                     "",
        + 	Reason:                     "DeadlineExceeded",
          	NominatedNodeName:          "",
          	HostIP:                     "172.18.0.2",
          	PodIP:                      "10.244.1.3",
          	PodIPs:                     {{IP: "10.244.1.3"}},
          	StartTime:                  s"2021-11-19 02:09:18 +0000 UTC",
        - 	InitContainerStatuses:      nil,
        + 	InitContainerStatuses:      []v1.ContainerStatus{},
          	ContainerStatuses:          {{Name: "nginx", State: {Running: &{StartedAt: {Time: s"2021-11-19 02:09:28 +0000 UTC"}}}, Ready: true, Image: "k8s.gcr.io/e2e-test-images/nginx:1.14-2", ...}},
          	QOSClass:                   "BestEffort",
        - 	EphemeralContainerStatuses: nil,
        + 	EphemeralContainerStatuses: []v1.ContainerStatus{},
          }
        
        
          ===== statusDiff =====
          &v1.PodStatus{
        - 	Phase: "Pending",
        + 	Phase: "Succeeded",
          	Conditions: []v1.PodCondition{
          		{
          			... // 2 identical fields
          			LastProbeTime:      {},
          			LastTransitionTime: {Time: s"2021-11-19 02:11:37 +0000 UTC"},
        - 			Reason:             "",
        + 			Reason:             "PodCompleted",
          			Message:            "",
          		},
          		{
          			... // 2 identical fields
          			LastProbeTime:      {},
          			LastTransitionTime: {Time: s"2021-11-19 02:11:37 +0000 UTC"},
        - 			Reason:             "ContainersNotReady",
        + 			Reason:             "PodCompleted",
        - 			Message:            "containers with unready status: [env-test]",
        + 			Message:            "",
          		},
          		{
          			... // 2 identical fields
          			LastProbeTime:      {},
          			LastTransitionTime: {Time: s"2021-11-19 02:11:37 +0000 UTC"},
        - 			Reason:             "ContainersNotReady",
        + 			Reason:             "PodCompleted",
        - 			Message:            "containers with unready status: [env-test]",
        + 			Message:            "",
          		},
          		{Type: "PodScheduled", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:11:37 +0000 UTC"}},
          	},
          	Message:               "",
          	Reason:                "",
          	NominatedNodeName:     "",
          	HostIP:                "172.18.0.2",
        - 	PodIP:                 "",
        + 	PodIP:                 "10.244.1.111",
        - 	PodIPs:                nil,
        + 	PodIPs:                []v1.PodIP{{IP: "10.244.1.111"}},
          	StartTime:             s"2021-11-19 02:11:37 +0000 UTC",
        - 	InitContainerStatuses: nil,
        + 	InitContainerStatuses: []v1.ContainerStatus{},
          	ContainerStatuses: []v1.ContainerStatus{
          		{
          			Name: "env-test",
          			State: v1.ContainerState{
        - 				Waiting:    s"&ContainerStateWaiting{Reason:ContainerCreating,Message:,}",
        + 				Waiting:    nil,
          				Running:    nil,
        - 				Terminated: nil,
        + 				Terminated: s"&ContainerStateTerminated{ExitCode:0,Signal:0,Reason:Completed,Message:,StartedAt:2021-11-19 02:11:38 +0000 UTC,FinishedAt:2021-11-19 02:11:38 +0000 UTC,ContainerID:containerd://e43345a3dd3180196a45e7dff74c9fc553412287da3ddfcd22c2f61663d5fc2a,}",
          			},
          			LastTerminationState: {},
          			Ready:                false,
          			RestartCount:         0,
          			Image:                "k8s.gcr.io/e2e-test-images/busybox:1.29-2",
        - 			ImageID:              "",
        + 			ImageID:              "k8s.gcr.io/e2e-test-images/busybox@sha256:c318242786b139d18676b1c09a0ad7f15fc17f8f16a5b2e625cd0dc8c9703daf",
        - 			ContainerID:          "",
        + 			ContainerID:          "containerd://e43345a3dd3180196a45e7dff74c9fc553412287da3ddfcd22c2f61663d5fc2a",
          			Started:              &false,
          		},
          	},
          	QOSClass:                   "BestEffort",
        - 	EphemeralContainerStatuses: nil,
        + 	EphemeralContainerStatuses: []v1.ContainerStatus{},
          }
        
      
        
          ===== statusDiff =====
          &v1.PodStatus{
        - 	Phase: "Pending",
        + 	Phase: "Running",
          	Conditions: []v1.PodCondition{
          		{Type: "Initialized", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:17:04 +0000 UTC"}},
        - 		{
        - 			Type:               "Ready",
        - 			Status:             "False",
        - 			LastTransitionTime: s"2021-11-19 02:17:04 +0000 UTC",
        - 			Reason:             "ContainersNotReady",
        - 			Message:            "containers with unready status: [test-deployment]",
        - 		},
        + 		{
        + 			Type:               "Ready",
        + 			Status:             "True",
        + 			LastTransitionTime: s"2021-11-19 02:17:06 +0000 UTC",
        + 		},
        - 		{
        - 			Type:               "ContainersReady",
        - 			Status:             "False",
        - 			LastTransitionTime: s"2021-11-19 02:17:04 +0000 UTC",
        - 			Reason:             "ContainersNotReady",
        - 			Message:            "containers with unready status: [test-deployment]",
        - 		},
        + 		{
        + 			Type:               "ContainersReady",
        + 			Status:             "True",
        + 			LastTransitionTime: s"2021-11-19 02:17:06 +0000 UTC",
        + 		},
          		{Type: "PodScheduled", Status: "True", LastTransitionTime: {Time: s"2021-11-19 02:17:04 +0000 UTC"}},
          	},
          	Message:               "",
          	Reason:                "",
          	NominatedNodeName:     "",
          	HostIP:                "172.18.0.2",
        - 	PodIP:                 "",
        + 	PodIP:                 "10.244.1.93",
        - 	PodIPs:                nil,
        + 	PodIPs:                []v1.PodIP{{IP: "10.244.1.93"}},
          	StartTime:             s"2021-11-19 02:17:04 +0000 UTC",
        - 	InitContainerStatuses: nil,
        + 	InitContainerStatuses: []v1.ContainerStatus{},
          	ContainerStatuses: []v1.ContainerStatus{
          		{
          			Name: "test-deployment",
          			State: v1.ContainerState{
        - 				Waiting:    s"&ContainerStateWaiting{Reason:ContainerCreating,Message:,}",
        + 				Waiting:    nil,
        - 				Running:    nil,
        + 				Running:    s"&ContainerStateRunning{StartedAt:2021-11-19 02:17:06 +0000 UTC,}",
          				Terminated: nil,
          			},
          			LastTerminationState: {},
        - 			Ready:                false,
        + 			Ready:                true,
          			RestartCount:         0,
          			Image:                "k8s.gcr.io/pause:3.6",
        - 			ImageID:              "",
        + 			ImageID:              "sha256:6270bb605e12e581514ada5fd5b3216f727db55dc87d5889c790e4c760683fee",
        - 			ContainerID:          "",
        + 			ContainerID:          "containerd://c600978fc95a7d2a68e849fda206d590b121e1910bd95f4280586d9fa359d163",
        - 			Started:              &false,
        + 			Started:              &true,
          		},
          	},
          	QOSClass:                   "BestEffort",
        - 	EphemeralContainerStatuses: nil,
        + 	EphemeralContainerStatuses: []v1.ContainerStatus{},
          }