structured logging: handle unusual keys?

[pohly]

/kind feature

Describe the solution you'd like

The current design decision is to dump keys as strings without any checks. If those keys contain spaces, line breaks, or other weird characters, then the log output will get messed up.

Presumably this was done for the sake of performance. We should measure the impact of validating keys and substituting unsafe ones. If the overhead is acceptable, we might decide to make the code more robust.

TODO:

• add test cases with non-string keys (int, bool, struct) to test/output.go with the expected result for the current code, submit PR for discussion
• decide if and how to enhance the output
• if we agree on changes, implement those and compare performance of go test -bench=. before and after the changes

Anything else you would like to add:

Brought up in #273 (comment)

/wg structured-logging

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

/help

[k8s-ci-robot]

@pohly:
This request has been marked as needing help from a contributor.

Guidelines

Please ensure that the issue body includes answers to the following questions:

• Why are we solving this issue?
• To address this issue, are there any code changes? If there are code changes, what needs to be done in the code and what places can the assignee treat as reference points?
• Does this issue have zero to low barrier of entry?
• How can the assignee reach out to you for help?

For more details on the requirements of such an issue, please see here and ensure that they are met.

If this request no longer meets these requirements, the label can be removed
by commenting with the /remove-help command.

In response to this:

/help

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.

[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
/lifecycle frozen

[harshanarayana]

/assign

[pohly]

Not sure where this use comment is now, but it seems relevant, so let me quote and reply:

I was adding a few test cases to the output.go as suggested in the description of this issue and add some additional thing to benchmarking. But zapr has a different way of handling non string keys in
the KVList.: DPanic("non-string key argument passed to logging, ignoring all later arguments", zapIt("invalid key", key)

So it panics instead of continuing with the tests?

Skipping such tests is one way of avoiding this, but ultimately we want to test also such behavior. Perhaps the logger invocation can be wrapped with a defer func() { if r := recover(); r != nil { ... that then records the panic and continues? The panic then needs to be part of the expected log output.

[harshanarayana]

@pohly I was adding that comment from my phone. Seems like I deleted it by mistake. Thanks for getting back to me.

So it panics instead of continuing with the tests?

No it does not. It causes a log entry with "level":"dpanic" to show up. Part of how the zap handles things in development logger mode.

I started adding a few tests and there are considerable difference in how the zapr handles the log in comparison with klog. Will open a PR with some example tests cases to start the discussion