Remove Redundant logs

[hawksight]

Can we remove redundant logs about the server missing resource for datagatherer? It makes it very difficult to actually see logs that do mean something.

What happened?

Take a look at this snippet of logs:

2024/09/23 13:41:32 retrying in 1m55.254386533s after error: post to server failed: received response with status code 404. Body: []
W0923 13:41:33.351182       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers: the server could not find the requested resource
2024/09/23 13:41:33 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers"
W0923 13:41:33.694672       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
2024/09/23 13:41:33 datagatherer informer for "route.openshift.io/v1, Resource=routes" has failed and is backing off due to error: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
W0923 13:41:41.794445       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=virtualservices: the server could not find the requested resource
2024/09/23 13:41:41 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=virtualservices"
W0923 13:41:47.544162       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list cas-issuer.jetstack.io/v1beta1, Resource=googlecasissuers: the server could not find the requested resource
2024/09/23 13:41:47 server missing resource for datagatherer of "cas-issuer.jetstack.io/v1beta1, Resource=googlecasissuers"
W0923 13:41:49.478712       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaissuers: the server could not find the requested resource
2024/09/23 13:41:49 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaissuers"
W0923 13:41:58.449284       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=gateways: the server could not find the requested resource
2024/09/23 13:41:58 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=gateways"
W0923 13:42:03.759841       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list firefly.venafi.com/v1, Resource=issuers: issuers.firefly.venafi.com is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "issuers" in API group "firefly.venafi.com" at the cluster scope
2024/09/23 13:42:03 datagatherer informer for "firefly.venafi.com/v1, Resource=issuers" has failed and is backing off due to error: failed to list firefly.venafi.com/v1, Resource=issuers: issuers.firefly.venafi.com is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "issuers" in API group "firefly.venafi.com" at the cluster scope
W0923 13:42:13.822678       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list cas-issuer.jetstack.io/v1beta1, Resource=googlecasclusterissuers: the server could not find the requested resource
2024/09/23 13:42:13 server missing resource for datagatherer of "cas-issuer.jetstack.io/v1beta1, Resource=googlecasclusterissuers"
W0923 13:42:17.917563       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=virtualservices: the server could not find the requested resource
2024/09/23 13:42:17 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=virtualservices"
W0923 13:42:26.587788       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers: the server could not find the requested resource
2024/09/23 13:42:26 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers"
W0923 13:42:27.221710       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
2024/09/23 13:42:27 datagatherer informer for "route.openshift.io/v1, Resource=routes" has failed and is backing off due to error: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
W0923 13:42:35.502389       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaissuers: the server could not find the requested resource
2024/09/23 13:42:35 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaissuers"
W0923 13:42:47.105401       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list cas-issuer.jetstack.io/v1beta1, Resource=googlecasissuers: the server could not find the requested resource
2024/09/23 13:42:47 server missing resource for datagatherer of "cas-issuer.jetstack.io/v1beta1, Resource=googlecasissuers"
W0923 13:42:50.029914       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list cas-issuer.jetstack.io/v1beta1, Resource=googlecasclusterissuers: the server could not find the requested resource
2024/09/23 13:42:50 server missing resource for datagatherer of "cas-issuer.jetstack.io/v1beta1, Resource=googlecasclusterissuers"
W0923 13:42:53.687645       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=gateways: the server could not find the requested resource
2024/09/23 13:42:53 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=gateways"
W0923 13:42:58.046565       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list firefly.venafi.com/v1, Resource=issuers: issuers.firefly.venafi.com is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "issuers" in API group "firefly.venafi.com" at the cluster scope
2024/09/23 13:42:58 datagatherer informer for "firefly.venafi.com/v1, Resource=issuers" has failed and is backing off due to error: failed to list firefly.venafi.com/v1, Resource=issuers: issuers.firefly.venafi.com is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "issuers" in API group "firefly.venafi.com" at the cluster scope
W0923 13:43:03.315884       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=virtualservices: the server could not find the requested resource
2024/09/23 13:43:03 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=virtualservices"
W0923 13:43:23.872934       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
2024/09/23 13:43:23 datagatherer informer for "route.openshift.io/v1, Resource=routes" has failed and is backing off due to error: failed to list route.openshift.io/v1, Resource=routes: routes.route.openshift.io is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource "routes" in API group "route.openshift.io" at the cluster scope
W0923 13:43:25.693858       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaissuers: the server could not find the requested resource
2024/09/23 13:43:25 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaissuers"
W0923 13:43:26.194047       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers: the server could not find the requested resource
2024/09/23 13:43:26 server missing resource for datagatherer of "awspca.cert-manager.io/v1beta1, Resource=awspcaclusterissuers"
2024/09/23 13:43:27 Posting data to: https://api.venafi.cloud/
2024/09/23 13:43:27 retrying in 2m53.275055834s after error: post to server failed: received response with status code 404. Body: []
W0923 13:43:33.822935       1 reflector.go:547] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:232: failed to list networking.istio.io/v1alpha3, Resource=gateways: the server could not find the requested resource
2024/09/23 13:43:33 server missing resource for datagatherer of "networking.istio.io/v1alpha3, Resource=gateways"

What should had happened?

If the cluster doesn't have a resource, stop looking for it. Or at the very least limit the logs about this 1 line only.

Worst case the agent is being a very bad citizen in the cluster continually polling the k8s API for things that just aren't there.

Possible fixes

1. Log reduction
2. Possible logic change

I did previously try adding --strict but this seems to have no effect in my previous attempts.

Log Filtering

I manually tried taking a small agent log and filtering out a bunch of log lines to see what diference it would make. Here's my resutls:

-rw-r--r--  1 peter.fiddes  staff  64328 23 Sep 14:47 agent-full.log
-rw-r--r--  1 peter.fiddes  staff   6836 23 Sep 14:54 agent-processed.log

Here's my very quick commands:

k logs venafi-kubernetes-agent-5b99574597-8nh9p > agent-full.log
awk '!/server missing resource for datagatherer of/' agent-full.log > agent-processed.log
sed -i .bckp '/the server could not find the requested resource/d' agent-processed.log
sed -i .bckp '/cannot list resource/d' agent-processed.log

I've attached both log fils here to see which you prefer to look at:

• agent-processed.log
• agent-full.log

[maelvls]

Thanks for sharing this issue, Peter. I'm happy to report that we have had this on our radar for a bit (VC-33564) and have started investigating.

[wallrj]

@hawksight We've made a few changes and discoveries which should address this problem.

1. The error message server missing resource for datagatherer has been converted to a debug level (V(1)) Info message since venafi-kubernetes-agent-1.3.0, so you should no longer see it unless you turn up the --log-level: https://github.com/jetstack/jetstack-secure/pull/617
2. The warning message failed to list ... the server could not find the requested resource is going to be removed from client-go in a forthcoming release: https://github.com/kubernetes/kubernetes/pull/126387#discussion_r1850000365, and we will upgrade that dependency in venafi-kubernetes-agent as soon as it becomes available.
3. If you enable --logging-format=json, (available since venafi-kubernetes-agent-1.3.0) all warning messages will be rendered as Info messages instead and will be written to stdout rather than stderr. On Google Cloud Platform, messages on stdout will be treated as severity=Info: https://github.com/jetstack/jetstack-secure/pull/596
4. That warning message, failed to list ... the server could not find the requested resource, is now easier to filter out on the logging server, because all log messages now include a file name and line number reference. If you enable --logging-format=json and use Google Cloud Log Explorer, the following query will now hide those logs: -jsonPayload.caller="cache/reflector.go:561"

[hawksight]

@wallrj - thank you for detailed notes.

1. 👍
2. Should we have a separate issue for tracking, or just leave this issue open?
3. 👍
4. Do you by chance have a jq equivalent of the gcloud filter? Most of the debugging I do with customers usually involves kubectl logs ... and cloud logging platform may vary. A handy jq filter it likely to be more useful for most of my cases. Appreciate that in production usage, your option is more applicable.

[wallrj]

@hawksight Let's close this. We've fixed most of the redundant logs.

Here's a jq filtering example, courtesy of Copilot:

$ jq -n '{"msg": "foo"},{"msg": "bar"},{"msg": "baz"}' | jq 'select(.msg | test("foo|bar") | not)'
{
  "msg": "baz"
}

This query uses the select function to include only those records where the msg field does not match the regular expression ^foo. The test function checks if the msg field matches the pattern, and the not function negates the result, effectively removing the matching records.

Alternatively, you could just use grep and a series of file:line expressions e.g.

kubectl logs ... | grep -v -e "reflector.go:123" -e "client.go:456"

Another thing I forgot to mention is that we've also fixed the RBAC to allow the agent to list OpenShift routes and Firefly resources, so you should no longer see those is forbidden: User "system:serviceaccount:venafi:venafi-kubernetes-agent" cannot list resource messages.

• #616
• #620