Fix broken json logging #6779
Merged
Fix broken json logging #6779
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
jetstack-bot
added
release-note-none
jetstack-bot
added
release-note
|
/cherrypick release-1.14 |
|
@inteon: once the present PR merges, I will cherry-pick it on top of release-1.14 in a new PR and assign it to you. In response to this:
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. |
wallrj
approved these changes
Feb 21, 2024
There was a problem hiding this comment.
Thanks @inteon
I tested it locally and observed that controller, webhook, cainjector, and startupapicheck now all log using text format by default and log in json format when you supply --logging-format=json.
acmesolver does not have a --logging-format option and logs in text format by default.
$ go run ./cmd/acmesolver/
I0221 09:59:01.936360 237080 solver.go:51] "starting listener" logger="cert-manager.acmesolver" expected_domain="" expected_token="" expected_key="" listen_port=8089
^CError: http: Server closed
Usage:
acmesolver [flags]
Flags:
--domain string the domain name to verify
-h, --help help for acmesolver
--key string the challenge key to respond with
--listen-port int the port number to listen on for connections (default 8089)
--token string the challenge token to verify against
E0221 09:59:08.412760 237080 main.go:39] "error executing command" err="http: Server closed" logger="cert-manager"
exit status 1startupapicheck check api --logging-format=json logs the --help output and a non-json message "exit status 1" to stderr when it exits if it fails.
$ go run ./cmd/startupapicheck check api --logging-format=json >/dev/null
...
-v, --v Level[=2] number for the log level verbosity
--vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format)
{"ts":1708509667519.7598,"caller":"startupapicheck/main.go:81","msg":"error executing command","logger":"cert-manager","err":"the cert-manager CRDs are not yet installed on the Kubernetes API server"}
exit status 1All the components seem to print the --help contents to stderr when they fail. Here's another example.
$ go run ./cmd/cainjector/ --logging-format=json >/dev/null
{"ts":1708510096166.3782,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510097162.4548,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510098167.0452,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510099162.8765,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510100162.8022,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510101163.4583,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510102162.845,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510103163.0078,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510104162.4485,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510105164.5286,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510106163.504,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510107164.492,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510108164.838,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510109164.4238,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510110162.733,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510111164.6616,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510112163.48,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510113165.1387,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510114163.4695,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510115164.6423,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510116165.3406,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510117161.9958,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510118164.8777,"caller":"app/controller.go:149","msg":"cainjector has been configured to watch certificates, but certificates.cert-manager.io CRD not found, retrying with a backoff...","v":0,"logger":"cert-manager.cainjector"}
{"ts":1708510120244.8757,"caller":"app/controller.go:152","msg":"error checking if certificates.cert-manager.io CRD is installed","logger":"cert-manager.cainjector","err":"Get \"https://127.0.0.1:46421/apis/apiextensions.k8s.io/v1/customresourcedefinitions/certificates.cert-manager.io\": dial tcp 127.0.0.1:46421: connect: connection refused - error from a previous attempt: EOF"}
{"ts":1708510120245.0347,"caller":"app/controller.go:159","msg":"error retrieving certificate.cert-manager.io CRDs","logger":"cert-manager.cainjector","err":"Get \"https://127.0.0.1:46421/apis/apiextensions.k8s.io/v1/customresourcedefinitions/certificates.cert-manager.io\": dial tcp 127.0.0.1:46421: connect: connection refused - error from a previous attempt: EOF"}
Error: Get "https://127.0.0.1:46421/apis/apiextensions.k8s.io/v1/customresourcedefinitions/certificates.cert-manager.io": dial tcp 127.0.0.1:46421: connect: connection refused - error from a previous attempt: EOF
Usage:
cainjector [flags]
Flags:
--config string Path to a file containing a CAInjectorConfiguration object used to configure the controller
--enable-apiservices-injectable Inject CA data to annotated APIServices. This functionality is not required if cainjector is only used as cert-manager's internal component and setting it to false might reduce memory consumption (default true)
--enable-certificates-data-source Enable configuring cert-manager.io Certificate resources as potential sources for CA data. Requires cert-manager.io Certificate CRD to be installed. This data source can be disabled to reduce memory consumption if you only use cainjector as part of cert-manager's installation (default true)
--enable-customresourcedefinitions-injectable Inject CA data to annotated CustomResourceDefinitions. This functionality is not required if cainjecor is only used as cert-manager's internal component and setting it to false might slightly reduce memory consumption (default true)
--enable-mutatingwebhookconfigurations-injectable Inject CA data to annotated MutatingWebhookConfigurations. This functionality is required for cainjector to work correctly as cert-manager's internal component (default true)
--enable-profiling Enable profiling for controller.
--enable-validatingwebhookconfigurations-injectable Inject CA data to annotated ValidatingWebhookConfigurations. This functionality is required for cainjector to correctly function as cert-manager's internal component (default true)
--feature-gates mapStringBool A set of key=value pairs that describe feature gates for alpha/experimental features. Options are:
AllAlpha=true|false (ALPHA - default=false)
AllBeta=true|false (BETA - default=false)
ServerSideApply=true|false (ALPHA - default=false)
-h, --help help for cainjector
--kubeconfig string Paths to a kubeconfig. Only required if out-of-cluster.
--leader-elect If true, cainjector will perform leader election between instances to ensure no more than one instance of cainjector operates at a time
--leader-election-lease-duration duration The duration that non-leader candidates will wait after observing a leadership renewal until attempting to acquire leadership of a led but unrenewed leader slot. This is effectively the maximum duration that a leader can be stopped before it is replaced by another candidate. This is only applicable if leader election is enabled.
--leader-election-namespace string Namespace used to perform leader election. Only used if leader election is enabled
--leader-election-renew-deadline duration The interval between attempts by the acting master to renew a leadership slot before it stops leading. This must be less than or equal to the lease duration. This is only applicable if leader election is enabled.
--leader-election-retry-period duration The duration the clients should wait between attempting acquisition and renewal of a leadership. This is only applicable if leader election is enabled.
--log-flush-frequency duration Maximum number of seconds between log flushes (default 5s)
--logging-format string Sets the log format. Permitted formats: "json" (gated by LoggingBetaOptions), "text". (default "text")
--namespace string If set, this limits the scope of cainjector to a single namespace. If set, cainjector will not update resources with certificates outside of the configured namespace.
--profiler-address string The host and port that Go profiler should listen on, i.e localhost:6060. Ensure that profiler is not exposed on a public address. Profiler will be served at /debug/pprof. (default "localhost:6060")
-v, --v Level number for the log level verbosity
--vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format)
{"ts":1708510120246.381,"caller":"cainjector/main.go:40","msg":"error executing command","logger":"cert-manager","err":"Get \"https://127.0.0.1:46421/apis/apiextensions.k8s.io/v1/customresourcedefinitions/certificates.cert-manager.io\": dial tcp 127.0.0.1:46421: connect: connection refused - error from a previous attempt: EOF"}
exit status 1These all seem like issues we should address if we want to properly fix the problem @petermajn reported:
Logging-format json sometimes writes plaintext messages
So I'd be inclined to remove the "Fixes: " line from the PR description.
But I like that this PR is small and easy to review and gets cert-manager back to where it was in 1.13 and can be easily cherrypicked into previous release branches if necessary.
We should create followup PRs to ensure that all the components only print json to stderr if they are configured that way.
And we should create a followup PR to test our json logging, maybe by setting --logging-format=json in all our E2E components and checking for invalid json that has been logged during the tests.
/approve
/lgtm
/hold in case you agree that TODO is the correct function to use and in case you agree that it needs a comment explaining that it is a temporary solution while we update all the code to get loggers from arguments or from context.
pkg/logs/logs.go
Outdated
|
|
||
| "github.com/cert-manager/cert-manager/pkg/api" | ||
| ) | ||
|
|
||
| var ( | ||
| Log = textlogger.NewLogger(textlogger.NewConfig()).WithName("cert-manager") | ||
| Log = klog.Background().WithName("cert-manager") |
There was a problem hiding this comment.
The documentation for this function suggests that it should be marked as a TODO item (and called as klog.TODO()) to remind us to fix this in the near future:
https://github.com/kubernetes/klog/blob/007e661a007dacdf017ad9c1b53e9f96d32d4b7d/contextual.go#L166-L185
Background retrieves the fallback logger. It should not be called before that logger was initialized by the program and not by code that should better receive a logger via its parameters. TODO can be used as a temporary solution for such code.
TODO can be used as a last resort by code that has no means of receiving a logger from its caller. FromContext or an explicit logger parameter should be used instead.
So perhaps using TODO would make it clearer that this is something we need to fix.
jetstack-bot
added
do-not-merge/hold
Signed-off-by: Tim Ramlot <42113979+inteon@users.noreply.github.com>
inteon
force-pushed
the
fix_json_logging
branch
from
bcb5507
to
8fd62df
Compare
jetstack-bot
added
lgtm
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: wallrj 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:
Approvers can indicate their approval by writing |
|
/kind bug |
jetstack-bot
added
kind/bug
|
@inteon: new pull request created: #6781 In response to this:
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. |
|
|
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Fixes #6768
In #6587 (https://github.com/cert-manager/cert-manager/pull/6587/files#diff-8f2f7b96261d29c4991c0025fde03c2edb0411a9aa7afaa834b5cf19837b5b2eL41), I updated the global
Logdefinition inlog.go.I based the updated code on the deprecation message of the
klogr.NewWithOptions()command that we were using.It seems like the proposed replacement
textlogger.NewLogger(textlogger.NewConfig())does not get updated when we parse & set the logging flags.This PR fixes this bug by using
klog.Background()instead.Before:
After:
Kind
/kind bug
Release Note