Allow setting log level for calico-apiserver

[george-angel]

Our logging agents current have a rate limit of 10 messages/s that calico-apiserver breaks occasionally. We would like to be able to set the log level for calico-apiserver component to not log INFO level messages.

Expected Behavior

Being able to set -v=0 or similar to have component only log WARN and higher level messages.

Current Behavior

I believe there is no way to control the log level.

Possible Solution

Expose a flag to be able to control log level. Alternatively tone down INFO level messages

Steps to Reproduce (for bugs)

Run default deployment of calico-apiserver as specified in manifests.

Context

@caseydavenport suggested that perhaps the component can be made less verbose in general: https://calicousers.slack.com/archives/C0BCA117T/p1693607380841419?thread_ts=1693466596.872479&cid=C0BCA117T

Your Environment

• Calico version: v3.25.0
• Orchestrator version (e.g. kubernetes, mesos, rkt): Kubernetes v1.27.2
• Operating System and version: "Flatcar Container Linux by Kinvolk 3510.2.5 (Oklo)"

[cyclinder]

@george-angel We can drop some log levels to something less chatty. Can you show the manifest of the calico-apiserver and logs? I want to know which logs need to be dropped the level.

[george-angel]

calico-apiserver Deployment: https://github.com/utilitywarehouse/calico-manifests/blob/master/base/apiserver.yaml#L15-L86

We use a Kustomize patch to set -v=0: https://github.com/utilitywarehouse/calico-manifests/blob/master/base/apiserver-args.yaml#L10-L11

Our config for dropping logs on the logging agent: https://github.com/utilitywarehouse/system-manifests/blob/master/promtail/promtail-config.yaml#L28-L32

And example snippet what I can see if I remove the exclusion config:

2024-02-05 16:32:49.926 time="2024-02-05T09:32:49Z" level=info msg="Main client watcher loop"
2024-02-05 16:32:49.925 I0205 09:32:49.925659       1 resource.go:206] Watch called with key: projectcalico.org/felixconfigurations on resource FelixConfiguration
2024-02-05 16:32:49.918 time="2024-02-05T09:32:49Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:32:49.918 time="2024-02-05T09:32:49Z" level=info msg="Process backend watcher done event in main client"
2024-02-05 16:32:27.714 time="2024-02-05T09:32:27Z" level=info msg="Main client watcher loop"
2024-02-05 16:32:27.713 I0205 09:32:27.713301       1 resource.go:206] Watch called with key: projectcalico.org/caliconodestatuses on resource CalicoNodeStatus
2024-02-05 16:32:27.706 time="2024-02-05T09:32:27Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:32:27.706 time="2024-02-05T09:32:27Z" level=info msg="Process backend watcher done event in main client"
2024-02-05 16:32:07.291 time="2024-02-05T09:32:07Z" level=info msg="Main client watcher loop"
2024-02-05 16:32:07.290 I0205 09:32:07.290146       1 resource.go:206] Watch called with key: projectcalico.org/clusterinformations on resource ClusterInformation
2024-02-05 16:32:07.283 time="2024-02-05T09:32:07Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:32:07.282 time="2024-02-05T09:32:07Z" level=info msg="Process backend watcher done event in main client"
2024-02-05 16:32:07.190 time="2024-02-05T09:32:07Z" level=info msg="Main client watcher loop"
2024-02-05 16:32:07.189 I0205 09:32:07.189481       1 resource.go:206] Watch called with key: projectcalico.org/globalnetworksets on resource GlobalNetworkSet
2024-02-05 16:32:07.181 time="2024-02-05T09:32:07Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:32:07.181 time="2024-02-05T09:32:07Z" level=info msg="Process backend watcher done event in main client"
2024-02-05 16:31:55.970 time="2024-02-05T09:31:55Z" level=info msg="Main client watcher loop"
2024-02-05 16:31:55.969 I0205 09:31:55.969179       1 resource.go:206] Watch called with key: projectcalico.org/bgpconfigurations on resource BGPConfiguration
2024-02-05 16:31:55.961 time="2024-02-05T09:31:55Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:31:55.961 time="2024-02-05T09:31:55Z" level=info msg="Process backend watcher done event in main client"

Thank you!

[cyclinder]

Thanks for the details. @george-angel

From the logs, the log keeps repeating the following 4 logs:

2024-02-05 16:32:49.925 I0205 09:32:49.925659       1 resource.go:206] Watch called with key: projectcalico.org/felixconfigurations on resource FelixConfiguration
2024-02-05 16:32:49.918 time="2024-02-05T09:32:49Z" level=info msg="Terminating main client watcher loop"
2024-02-05 16:32:49.918 time="2024-02-05T09:32:49Z" level=info msg="Process backend watcher done event in main client"
2024-02-05 16:32:27.714 time="2024-02-05T09:32:27Z" level=info msg="Main client watcher loop"

The first one comes from calico-apiserver, whose logging level we can easily drop. But the remaining three logs come from the k8s client's codebase, and it doesn't look like we can drop its log level directly ):

[george-angel]

@cyclinder Every little helps :)

I'm happy to try a new release with changed log level and see if its still a problem and raise a separate issue if the remaining k8s client logs cause problems?

[cyclinder]

I can try to fix the log level from the calico, and I agree there needs a separate issue for k8s client logs.

[caseydavenport]

I believe this PR will help here: https://github.com/projectcalico/calico/pull/8697

It sets the Calico log output based on the -v argument passed to the apiserver.

-v=0 will log ERROR -v=1 will log INFO -v=2 will log DEBUG

It also downgrades the "called with key" logs