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

silence the 'log.SetLogger(...) was never called; logs will not be displayed' error #4885

Merged
merged 1 commit into from
Apr 30, 2024

Conversation

zhzhuang-zju
Copy link
Contributor

What type of PR is this?
/kind cleanup

What this PR does / why we need it:
Refer to #4868, when karmada-webhook is started, the error log.SetLogger(...) was never called; logs will not be displayed will be displayed, which is very confusing.
Here's the answer to why this log appears and how to fix it.
Viewing the function call chain, refer to:

// getLogger constructs a logger from the injected log and LogConstructor.
func (wh *Webhook) getLogger(req *Request) logr.Logger {
wh.setupLogOnce.Do(func() {
if wh.log.GetSink() == nil {
wh.log = logf.Log.WithName("admission")
}
})

If the log of webhook is nil, it will end up calling
func eventuallyFulfillRoot() {
if logFullfilled.Load() {
return
}
if time.Since(rootLogCreated).Seconds() >= 30 {
if logFullfilled.CompareAndSwap(false, true) {
stack := debug.Stack()
stackLines := bytes.Count(stack, []byte{'\n'})
sep := []byte{'\n', '\t', '>', ' ', ' '}
fmt.Fprintf(os.Stderr,
"[controller-runtime] log.SetLogger(...) was never called; logs will not be displayed.\nDetected at:%s%s", sep,
// prefix every line, so it's clear this is a stack trace related to the above message
bytes.Replace(stack, []byte{'\n'}, sep, stackLines-1),
)
SetLogger(logr.New(NullLogSink{}))
}
}
}

And the SetLogger is not called within the first 30 seconds of a binaries lifetime, finally printed out log.SetLogger(...) was never called; logs will not be displayed error.
Through the above analysis, there are two ways to solve this problem:

  • Initializing the webhook's log
    Looking at the source code, there are two ways to initialize, in addition to the one above, there is one as follows:

    // StandaloneWebhook prepares a webhook for use without a webhook.Server,
    // passing in the information normally populated by webhook.Server
    // and instrumenting the webhook with metrics.
    //
    // Use this to attach your webhook to an arbitrary HTTP server or mux.
    //
    // Note that you are responsible for terminating TLS if you use StandaloneWebhook
    // in your own server/mux. In order to be accessed by a kubernetes cluster,
    // all webhook servers require TLS.
    func StandaloneWebhook(hook *Webhook, opts StandaloneOptions) (http.Handler, error) {
    if opts.Logger.GetSink() != nil {
    hook.log = opts.Logger
    }
    if opts.MetricsPath == "" {
    return hook, nil
    }
    return metrics.InstrumentedHook(opts.MetricsPath, hook), nil
    }

    Since this initialization method does not apply to webhook.Server, this method does not work

  • call SetLogger to get any actual logging.
    That's what I ended up using, by calling SetLogger first to silence the 'log.SetLogger(...) was never called; logs will not be displayed' error.

BTW, it was a breaking change in the release notes 0.15.0 of controller-runtime. Previously, when the pkg/log package was imported, there was an init function that spawned a goroutine, which set a null logger after 30 seconds. Therefore, versions prior to 0.15.0 will not have this problem.

Which issue(s) this PR fixes:
Fixes #4868

Special notes for your reviewer:

Does this PR introduce a user-facing change?:


@karmada-bot karmada-bot added kind/cleanup Categorizes issue or PR as related to cleaning up code, process, or technical debt. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Apr 29, 2024
@codecov-commenter
Copy link

codecov-commenter commented Apr 29, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 53.06%. Comparing base (95bf37f) to head (f5de886).

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #4885      +/-   ##
==========================================
- Coverage   53.07%   53.06%   -0.01%     
==========================================
  Files         251      251              
  Lines       20389    20389              
==========================================
- Hits        10821    10820       -1     
  Misses       8855     8855              
- Partials      713      714       +1     
Flag Coverage Δ
unittests 53.06% <ø> (-0.01%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@zhzhuang-zju
Copy link
Contributor Author

@karmada-bot karmada-bot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Apr 29, 2024
Copy link
Member

@XiShanYongYe-Chang XiShanYongYe-Chang left a comment

Choose a reason for hiding this comment

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

Thanks a lot!
/lgtm

@karmada-bot karmada-bot added the lgtm Indicates that a PR is ready to be merged. label Apr 29, 2024
Copy link
Member

@whitewindmills whitewindmills left a comment

Choose a reason for hiding this comment

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

Does this problem exist other components?

Copy link
Contributor

@liangyuanpeng liangyuanpeng left a comment

Choose a reason for hiding this comment

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

Thank you for your excellent analysis.

maybe we also need to update the webhook of example?
https://github.com/karmada-io/karmada/blob/master/examples/customresourceinterpreter/webhook/main.go

cmd/webhook/main.go Outdated Show resolved Hide resolved
cmd/webhook/main.go Outdated Show resolved Hide resolved
@zhzhuang-zju
Copy link
Contributor Author

Does this problem exist other components?

Good advice. I'm lining it up.

@zhzhuang-zju
Copy link
Contributor Author

Does this problem exist other components?

After troubleshooting, components karmada-controller-manager and karmada-metrics-adapter also have this problem. They both call the method

// NewForConfig creates a new client for the given config.
func NewForConfig(config *rest.Config) (client.Client, error) {
return client.New(config, client.Options{
Scheme: aggregatedScheme,
})
}
, which will eventually print log.SetLogger(...) was never called; logs will not be displayed error.
Component karmada-controller-manager only calls the above function if len(opts.ClusterAPIKubeconfig) !=0 , and that's why we don't usually find this error in component karmada-controller-manager !

@karmada-bot karmada-bot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed lgtm Indicates that a PR is ready to be merged. size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Apr 29, 2024
…splayed' error

Signed-off-by: zhzhuang-zju <m17799853869@163.com>
@karmada-bot karmada-bot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Apr 29, 2024
Copy link
Member

@RainbowMango RainbowMango left a comment

Choose a reason for hiding this comment

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

/approve

@whitewindmills @liangyuanpeng
Do you want to take another look?

Does this problem exist other components?

maybe we also need to update the webhook of example?

Excellent comments! By the way. Thanks.

@karmada-bot
Copy link
Collaborator

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: RainbowMango

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 /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@karmada-bot karmada-bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 30, 2024
@whitewindmills
Copy link
Member

/lgtm

@karmada-bot karmada-bot added the lgtm Indicates that a PR is ready to be merged. label Apr 30, 2024
@karmada-bot karmada-bot merged commit 54ad963 into karmada-io:master Apr 30, 2024
12 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. kind/cleanup Categorizes issue or PR as related to cleaning up code, process, or technical debt. lgtm Indicates that a PR is ready to be merged. size/S Denotes a PR that changes 10-29 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

karmada-webhook: log.SetLogger(...) was never called; logs will not be displayed.
7 participants