[KEP][sig-instrumentation] Structured logging #1367

serathius · 2019-11-15T20:01:11Z

Review progress:

@thockin (SIG Architecture, klog owner, Google)
@dims (SIG Architecture Chair, klog owner, VMware)
@brancz (SIG Instrumentation TL, Red Hat)
@mtaufen (component-base owner, Google)
@derekwaynecarr (SIG Architecture Chair, SIG Node Chair, Red Hat)

Please let me know if you think you should be added to this list.

Proposal was presented on:

sig-instrumentation meeting 2019-12-12
sig-architecture meeting 2020-01-16
wg-component-standard meeting 2020-02-11

PR will be merged when all reviewers give their lgtm.

piosz · 2019-11-15T20:21:26Z

cc @smarterclayton @deads2k @liggitt @wojtek-t

piosz · 2019-11-15T20:21:43Z

@kubernetes/sig-instrumentation-feature-requests

RainbowMango · 2019-11-18T09:53:39Z

I guess @kubernetes/sig-architecture-feature-requests should be involved.

keps/sig-instrumentation/20191115-structured-logging.md

serathius · 2019-11-19T23:23:40Z

PTAL @bogdandrutu

mtaufen · 2019-11-20T19:15:30Z

/wg component-standard
/assign

mtaufen

Thanks @serathius, IMO this would be a significant improvement to our existing logging capability.

Other folks who may be interested:
/cc @dashpole @liggitt @stealthybox @derekwaynecarr @vishh

keps/sig-instrumentation/20191115-structured-logging.md

ehashman · 2019-11-27T18:05:44Z

/assign

Won't be able to review before the US Thanksgiving holiday but I'll give this a look next week.

keps/sig-instrumentation/20191115-structured-logging.md

deads2k · 2020-03-05T21:24:21Z

keps/sig-instrumentation/20191115-structured-logging.md

+* Only for log lines generated by klog (e.g. prefix `I0129 03:26:19.857798       1 garbagecollector.go:517]`)
+* Identified by code line that generated log (e.g. `garbagecollector.go:517`)
+
+We assume that exact details of taking measurements can be improved, but overall methodology is solid. With those criteria we concluded that covering 99.9% of logs on master node are generated by 22 log messages. Exact list of those logs is provided in the detail design section.


It seems like this is just telling you where the noise is, not where the value is. Why assume that today's noise is where the value lies.

The volume of logs produced by each klog call is just a proxy for the importance of those logs but indeed it does not mean that those logs are the most valuable.
If you can provide any other criteria to select logs which should be migrated first we might include it in this proposal.

What I like most about this retooled KEP is that it is incremental. Do the "obvious" ones now. As we find more that are valuable, convert them.

deads2k · 2020-03-05T21:27:48Z

keps/sig-instrumentation/20191115-structured-logging.md

+Example:
+
+```go
+klog.InfoS("Pod status updated", "pod", "kubedns", "status", "ready")


most systems I've seen like this desire a message key so that minor changes between versions (line numbers for instance) don't make it impossible to see that the same message (or a new one) is appearing.

With log message now not including arguments we can normalize it and use it as a key.

keps/sig-instrumentation/20191115-structured-logging.md

deads2k · 2020-03-05T21:31:44Z

keps/sig-instrumentation/20191115-structured-logging.md

+```
+
+
+### Logging configuration


This appears to be missing filtering per sink. If we're going to introduce new logging configure APIs, that one seems like a big win. Also, the old glog vmodule for loglevel has pretty significant limitations.

What kind of filtering would you like to have?
The existing glog vmodule for loglevel will be still available.

I think of this KEP as pretty surgical WRT klog - 2 new functions, 1 new flag. Going beyond that is possible, but a different KEP?

serathius · 2020-03-06T22:08:22Z

Addressed feedback:

Support changing serialization (@deads2k )

Added a section that explicitly mentions how logger implementation can be overridden.

keps/sig-instrumentation/20191115-structured-logging.md

derekwaynecarr

I agree this is an improvement. I would prefer we could address objects across time and space and not just space which I why I desired uid. If I look at a log for a problem, it may often deal with the same named resource, but maybe I’m uncommon.

thockin

This KEP is really 3 things, kind of specc'ed at the same time:

Add structured functions to klog and document the output format
Add a JSON output format to klog
Convert kubernetes to use the structured mechanism in a few places
3a) Add some convenience for logging kubernetes objects

The KEP kind of mixes them up. I'm not proposing to rewrite it, just saying for clarity.

A couple of my comments here are hard blockers, most just need to be discussed and resolved.

keps/sig-instrumentation/20191115-structured-logging.md

thockin · 2020-03-09T17:57:43Z

keps/sig-instrumentation/20191115-structured-logging.md

+
+To address problem of inconsistency in referencing of Kubernetes objects, new klog methods will include additional logic for handling their formatting. Kubernetes objects will be recognized by checking for `ObjectMeta` structure.
+
+Namespaced objects will be represented by joining their name and namespace with `/` character. Pattern: `<namespace>/<name>`, example for pod: `kube-system/kubedns`


The Go way to do this would be to implement an interface, e.g. a .Log() []struct{k,v string} method. But we don't have methods on our API definitions, generally.

KEP blocker:

Can you explain how this will actually work? Is this something that will be auto-detected? e.g. I pass in an arbitrary pointer and you test if it has metadata via reflection? Is that for any pointer? Any value? How much will that impact runtime of logging?

Do we need a klog.KObj() function which is the "hint" to expand ..., "pod", klog.Kobj(pod), ... into pod/name="foo", pod/namespace="bar" ?

keps/sig-instrumentation/20191115-structured-logging.md

thockin · 2020-03-09T18:23:30Z

keps/sig-instrumentation/20191115-structured-logging.md

+Proposed serialization of Kubernetes objects will not include additional fields beside those proposed available in `text` format.
+Discussion for additional fields needed in representation of Kubernetes objects is out of scope of this KEP.
+
+Serialization of arbitrary structures will ignore pointers to avoid hard to predict performance hits caused by deep nested structures or cycles.


This is a challenge. On one hand, it's close to compatible with %v. On the other hand, if we're incrementally converting, we should consider what is "right".

What you propose ("shallow"). Arguably wrong for many types. Would need a hint (e.g. klog.Deep(foo)) to allow full expansion.

Default to "deep". Arguably dangerous. Would maybe need a hint (e.g. klog.Shallow(foo)) to allow alternative, though you could push that onto callers.

Respect stringer interface and call .String() on objects passed in. klog (and glogr) do not surrently respect stringer. stdlib log does: https://play.golang.org/p/p0_pRZlWciH

I lean towards deep, but am open to discuss.

Not a KEP blocker, but DOES need to be resolved.

thockin · 2020-03-09T18:29:37Z

keps/sig-instrumentation/20191115-structured-logging.md

+```
+
+
+### Logging configuration


I think of this KEP as pretty surgical WRT klog - 2 new functions, 1 new flag. Going beyond that is possible, but a different KEP?

keps/sig-instrumentation/20191115-structured-logging.md

serathius · 2020-03-13T11:43:07Z

Pushing update to KEP, addressing feedback:

Move json implementation to Alpha (@thockin)
Change default verbosity to 0 (@thockin)
Reintroduce helper functions for referencing K8s objects as intermediary step (@thockin)

…ogging * Move JSON implementation to Alpha phase * Change default verbosity to 0 * Clean up effort phases * Detail serialization strategy and it's motivation * Change strategy for serializing time.Time to be consistent with `ts` field * Reintroduce helper functions for k8s references

thockin

Really minor points from me.

/lgtm
/approve

thockin · 2020-03-13T16:55:31Z

keps/sig-instrumentation/20191115-structured-logging.md

+* Namespaced objects will be represented by joining their name and namespace with `/` character. Pattern: `<namespace>/<name>`, example for pod: `kube-system/kubedns`
+* Non-namespaced objects will be represented by their name. Pattern: `<name>`, example for node: `cluster1-vm-72x33b8p-34jz`
+
+Object UID in logs is much less popular, but still useful in some situation. In situation caller should consider adding a separate field with object UID.


No edit needed, but I do think we should consider (after this lands) adding UID to the normal format. It will need its own evaluation and testing.

We will consider tackling UID after Alpha.

thockin · 2020-03-13T17:09:41Z

keps/sig-instrumentation/20191115-structured-logging.md


-Proposed serialization of Kubernetes objects will not include additional fields beside those proposed available in `text` format.
-Discussion for additional fields needed in representation of Kubernetes objects is out of scope of this KEP.
+Proposed Serialization of types (we will expand list of special cases if needed):


Document string as %q ?

We also should define whether we intend to respect stringer (method .String() string) or not. Both klog and zap do, so we probably should spec that.

Thanks.
Will check how klog and zap do it and update KEP based on that.

k8s-ci-robot · 2020-03-13T17:21:03Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: brancz, dims, serathius, thockin

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:

~~keps/sig-instrumentation/OWNERS~~ [brancz,dims]

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

serathius · 2020-03-13T17:27:30Z

All reviewers gave their "/lgtm". Merging KEP as "provisional". I will start adding tasks to #1602 and start working on moving KEP to "implementable" state.
/unhold

k8s-ci-robot assigned brancz Nov 15, 2019

k8s-ci-robot requested review from bgrant0607, dims and thockin November 15, 2019 20:01

[KEP][sig-instrumentation] Structured logging

e688dcd

serathius force-pushed the structured-logging branch from 57c07c9 to e688dcd Compare November 15, 2019 20:06

piosz self-assigned this Nov 15, 2019

k8s-ci-robot added the kind/feature Categorizes issue or PR as related to a new feature. label Nov 15, 2019

k8s-ci-robot added the sig/architecture Categorizes an issue or PR as relevant to SIG Architecture. label Nov 18, 2019

logicalhan reviewed Nov 18, 2019

View reviewed changes

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

pohly reviewed Nov 19, 2019

View reviewed changes

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

k8s-ci-robot assigned mtaufen Nov 20, 2019

k8s-ci-robot added the wg/component-standard Categorizes an issue or PR as relevant to WG Component Standard. label Nov 20, 2019

mtaufen reviewed Nov 25, 2019

View reviewed changes

k8s-ci-robot requested review from dashpole, derekwaynecarr, liggitt, stealthybox and vishh November 25, 2019 03:15

wojtek-t reviewed Nov 27, 2019

View reviewed changes

deads2k reviewed Mar 5, 2020

View reviewed changes

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

deads2k reviewed Mar 5, 2020

View reviewed changes

keps/sig-instrumentation/20191115-structured-logging.md Outdated Show resolved Hide resolved

deads2k reviewed Mar 5, 2020

View reviewed changes

serathius mentioned this pull request Mar 6, 2020

Structured logging #1602

Open

39 tasks

Allow for changing serialzation by providing custom logr implementation

9a35736

derekwaynecarr reviewed Mar 7, 2020

View reviewed changes

keps/sig-instrumentation/20191115-structured-logging.md Show resolved Hide resolved

derekwaynecarr reviewed Mar 7, 2020

View reviewed changes

thockin reviewed Mar 9, 2020

View reviewed changes

grahamwhaley mentioned this pull request Mar 11, 2020

Klog logging intel/intel-device-plugins-for-kubernetes#323

Closed

k8s-ci-robot added the do-not-merge/invalid-commit-message Indicates that a PR should not merge because it has an invalid commit message. label Mar 13, 2020

serathius force-pushed the structured-logging branch 2 times, most recently from 7ab9358 to 18edf4c Compare March 13, 2020 11:33

k8s-ci-robot removed the do-not-merge/invalid-commit-message Indicates that a PR should not merge because it has an invalid commit message. label Mar 13, 2020

serathius force-pushed the structured-logging branch from 18edf4c to afb1e23 Compare March 13, 2020 11:34

serathius force-pushed the structured-logging branch from afb1e23 to 55d56e4 Compare March 13, 2020 12:09

thockin reviewed Mar 13, 2020

View reviewed changes

k8s-ci-robot assigned thockin Mar 13, 2020

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 13, 2020

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 13, 2020

k8s-ci-robot merged commit eba1491 into kubernetes:master Mar 13, 2020

k8s-ci-robot added this to the v1.18 milestone Mar 13, 2020

serathius mentioned this pull request May 18, 2020

Update structured logging KEP for milestone #1787

Merged

serathius mentioned this pull request Sep 27, 2022

Add fully qualified resource reference type kubernetes/klog#351

Open

[KEP][sig-instrumentation] Structured logging #1367

[KEP][sig-instrumentation] Structured logging #1367

serathius commented Nov 15, 2019 •

edited

piosz commented Nov 15, 2019

piosz commented Nov 15, 2019

RainbowMango commented Nov 18, 2019

serathius commented Nov 19, 2019

mtaufen commented Nov 20, 2019

mtaufen left a comment

ehashman commented Nov 27, 2019

deads2k Mar 5, 2020

44past4 Mar 6, 2020

thockin Mar 9, 2020

deads2k Mar 5, 2020

serathius Mar 6, 2020

deads2k Mar 5, 2020 •

edited

44past4 Mar 6, 2020

thockin Mar 9, 2020

serathius commented Mar 6, 2020

derekwaynecarr left a comment

thockin left a comment

thockin Mar 9, 2020

thockin Mar 9, 2020

thockin Mar 9, 2020

serathius commented Mar 13, 2020

thockin left a comment

thockin Mar 13, 2020

serathius Mar 16, 2020

thockin Mar 13, 2020

thockin Mar 13, 2020

serathius Mar 16, 2020

k8s-ci-robot commented Mar 13, 2020

serathius commented Mar 13, 2020 •

edited


		To address problem of inconsistency in referencing of Kubernetes objects, new klog methods will include additional logic for handling their formatting. Kubernetes objects will be recognized by checking for `ObjectMeta` structure.

		Namespaced objects will be represented by joining their name and namespace with `/` character. Pattern: `<namespace>/<name>`, example for pod: `kube-system/kubedns`

		```


		### Logging configuration

		```


		### Logging configuration

[KEP][sig-instrumentation] Structured logging #1367

[KEP][sig-instrumentation] Structured logging #1367

Conversation

serathius commented Nov 15, 2019 • edited

piosz commented Nov 15, 2019

piosz commented Nov 15, 2019

RainbowMango commented Nov 18, 2019

serathius commented Nov 19, 2019

mtaufen commented Nov 20, 2019

mtaufen left a comment

Choose a reason for hiding this comment

ehashman commented Nov 27, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

deads2k Mar 5, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

serathius commented Mar 6, 2020

derekwaynecarr left a comment

Choose a reason for hiding this comment

thockin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

serathius commented Mar 13, 2020

thockin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

k8s-ci-robot commented Mar 13, 2020

serathius commented Mar 13, 2020 • edited

serathius commented Nov 15, 2019 •

edited

deads2k Mar 5, 2020 •

edited

serathius commented Mar 13, 2020 •

edited