Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

api: do not log controller-runtime messages after context cancel #5213

Merged
merged 1 commit into from
Nov 23, 2021

Conversation

milas
Copy link
Contributor

@milas milas commented Nov 22, 2021

This is mostly annoying in tests when trying to reproduce an issue
and running with something like -count 100. With the async nature
of the reconcilers, it's pretty inevitable that some things will
still be in-flight when the tests are done (and so cancel the context
to clean up resources), and a bunch of irrelevant errors that are
really just wrapped "context canceled" get logged out.

This is mostly annoying in tests when trying to reproduce an issue
and running with something like `-count 100`. With the async nature
of the reconcilers, it's pretty inevitable that some things will
still be in-flight when the tests are done (and so cancel the context
to clean up resources), and a bunch of irrelevant errors that are
really just wrapped "context canceled" get logged out.
@milas milas requested a review from landism November 22, 2021 21:34
@milas
Copy link
Contributor Author

milas commented Nov 22, 2021

FYI this isn't perfect, you still can get stuff like:

E1122 16:27:26.765708   72779 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/tilt.dev/v1alpha1/uiresources/%28Tiltfile%29" audit-ID="201a6f2b-df7d-405a-8ba3-2c86feb57f01"
E1122 16:27:26.765806   72779 timeout.go:135] post-timeout activity - time-elapsed: 11.253µs, GET "/apis/tilt.dev/v1alpha1/uiresources/(Tiltfile)" result: <nil>

I'm guessing these are doing something sketchy like writing directly to os.Stderr 😬

We already have some other string patterns we ignore, I held off on adding these for the moment, but I think timeout or abort while handling and post-timeout activity are probably both phrases we can add to the filter.

Copy link
Member

@landism landism left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

huzzah! this was really spammy!

you still can get stuff like

fwiw, it looks like these are just writing directly to klog w/ severity 2, which doesn't seem toooo sketchy and also wouldn't go through the filter, I assume?

runtime.HandleError(fmt.Errorf("timeout or abort while handling: method=%v URI=%q audit-ID=%q", req.Method, req.RequestURI, request.GetAuditIDTruncated(req)))

logging.printDepth(errorLog, logging.logr, logging.filter, depth, args...)

@milas
Copy link
Contributor Author

milas commented Nov 23, 2021

Interesting - I was still seeing them sporadically in the logs when testing. I guess something else funky is going on there 🤷

@milas milas merged commit 531cfcd into master Nov 23, 2021
@milas milas deleted the milas/controller-runtime-log-spam branch November 23, 2021 17:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants