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

chore(kuma-cp): improved xds logging #4436

Merged
merged 3 commits into from
Jun 10, 2022
Merged

Conversation

jakubdyszkiewicz
Copy link
Contributor

Summary

This PR improves XDS logging. Right now you have 0 logs about XDS on INFO and a massive amount of logs on DEBUG.
Logs on debug are "cryptic" and require knowledge about the CP implementation (what is OnStreamRequest etc).
Logging entire DiscoveryRequest/Response even on debug was too much. Especially with gigantic Node object for every log.
I was trying to pick the minimal amount of information that could inform the user what is going on with the XDS exchange without knowledge about implementation.

I was also considering implementing full resource logging on trace but

  • we don't have a trace level and logging it on debug seems quite dangerous (data leak, amount of data)
  • because of TypedConfig, it's hard to extract a data to be visible. For example, we need to unmarshal Any to Listener, but HttpConnectionManager is again marshaled to Any

After this change

2022-06-07T10:06:03.115Z	INFO	xds.status-tracker	proxy connected	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "dataplane", "dpVersion": "dev-180084f18-amd64", "subscriptionID": "38109ce9-05ee-44b2-921b-e70783e564cb"}
2022-06-07T10:06:03.115Z	INFO	xds.status-tracker	config requested	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Cluster", "version": "", "resourceNames": []}
2022-06-07T10:06:04.725Z	INFO	xds-server.reconcile	config has changed	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "versions": ["9ea1e367-60f9-43a1-ac47-11fab40b14f5", "282a31dc-98d4-4381-ada3-caefce2a9ed4", "410acad6-db6f-426c-8c4b-4ccebdb6edcf"]}
2022-06-07T10:06:04.725Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Cluster", "version": "282a31dc-98d4-4381-ada3-caefce2a9ed4", "requestedResourceNames": [], "resources": 8}
2022-06-07T10:06:04.790Z	INFO	xds.status-tracker	config requested	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "", "resourceNames": ["redis_kuma-demo_svc_6379", "demo-app_kuma-demo_svc_5000"]}
2022-06-07T10:06:04.790Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Cluster", "version": "282a31dc-98d4-4381-ada3-caefce2a9ed4"}
2022-06-07T10:06:04.790Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "9ea1e367-60f9-43a1-ac47-11fab40b14f5", "requestedResourceNames": ["redis_kuma-demo_svc_6379", "demo-app_kuma-demo_svc_5000"], "resources": 2}
2022-06-07T10:06:04.790Z	INFO	xds.status-tracker	config requested	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Listener", "version": "", "resourceNames": []}
2022-06-07T10:06:04.791Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Listener", "version": "410acad6-db6f-426c-8c4b-4ccebdb6edcf", "requestedResourceNames": [], "resources": 12}
2022-06-07T10:06:04.791Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "9ea1e367-60f9-43a1-ac47-11fab40b14f5"}
2022-06-07T10:06:04.837Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Listener", "version": "410acad6-db6f-426c-8c4b-4ccebdb6edcf"}
2022-06-07T10:06:06.118Z	INFO	xds-server.reconcile	config has changed	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "versions": ["ed71310c-ae0e-4b05-996a-d0d2be1961f5", "1c534a33-e629-4f88-a45a-ef2d48390df9", "2d179aa2-47a0-4be0-a467-e477ec962cf6"]}
2022-06-07T10:06:06.118Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Cluster", "version": "1c534a33-e629-4f88-a45a-ef2d48390df9", "requestedResourceNames": [], "resources": 8}
2022-06-07T10:06:06.118Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "ed71310c-ae0e-4b05-996a-d0d2be1961f5", "requestedResourceNames": ["redis_kuma-demo_svc_6379", "demo-app_kuma-demo_svc_5000"], "resources": 2}
2022-06-07T10:06:06.118Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Listener", "version": "2d179aa2-47a0-4be0-a467-e477ec962cf6", "requestedResourceNames": [], "resources": 12}
2022-06-07T10:06:06.131Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "9ea1e367-60f9-43a1-ac47-11fab40b14f5"}
2022-06-07T10:06:06.147Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Cluster", "version": "1c534a33-e629-4f88-a45a-ef2d48390df9"}
2022-06-07T10:06:06.147Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "ed71310c-ae0e-4b05-996a-d0d2be1961f5"}
2022-06-07T10:06:06.147Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "27c1a168-4459-4e59-ba73-28a157e017c0", "requestedResourceNames": ["demo-app_kuma-demo_svc_5000", "redis_kuma-demo_svc_6379"], "resources": 2}
2022-06-07T10:06:06.147Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "Listener", "version": "2d179aa2-47a0-4be0-a467-e477ec962cf6"}
2022-06-07T10:06:06.148Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "27c1a168-4459-4e59-ba73-28a157e017c0"}
2022-06-07T10:07:41.118Z	INFO	xds-server.reconcile	config has changed	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "versions": ["1eb6b1f9-6aaf-455a-917c-ecb2a8961977"]}
2022-06-07T10:07:41.118Z	INFO	xds.status-tracker	config sent	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "1eb6b1f9-6aaf-455a-917c-ecb2a8961977", "requestedResourceNames": ["demo-app_kuma-demo_svc_5000", "redis_kuma-demo_svc_6379"], "resources": 2}
2022-06-07T10:07:41.118Z	INFO	xds.status-tracker	config accepted	{"proxyName": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "streamID": 1, "type": "ClusterLoadAssignment", "version": "1eb6b1f9-6aaf-455a-917c-ecb2a8961977"}
2022-06-07T10:08:09.341Z	INFO	xds.status-tracker	proxy disconnected	{"streamID": 1, "name": "redis-58f9d884db-9xcqd.kuma-demo", "mesh": "default", "subscriptionID": "38109ce9-05ee-44b2-921b-e70783e564cb"}

Issues resolved

Fix #4033

Documentation

No docs.

Testing

  • Unit tests
  • E2E tests
  • Manual testing on Universal
  • Manual testing on Kubernetes

Backwards compatibility

- [ ] Update UPGRADE.md with any steps users will need to take when upgrading.
- [ ] Add backport-to-stable label if the code follows our backporting policy

Signed-off-by: Jakub Dyszkiewicz <jakub.dyszkiewicz@gmail.com>
@jakubdyszkiewicz jakubdyszkiewicz requested a review from a team as a code owner June 7, 2022 10:43
pkg/xds/server/callbacks/dataplane_status_tracker.go Outdated Show resolved Hide resolved
pkg/xds/server/callbacks/dataplane_status_tracker.go Outdated Show resolved Hide resolved
pkg/xds/server/callbacks/dataplane_status_tracker.go Outdated Show resolved Hide resolved
pkg/xds/server/v3/reconcile.go Outdated Show resolved Hide resolved
Signed-off-by: Jakub Dyszkiewicz <jakub.dyszkiewicz@gmail.com>
Signed-off-by: Jakub Dyszkiewicz <jakub.dyszkiewicz@gmail.com>
if statusTrackerLog.V(1).Enabled() {
log = log.WithValues("node", req.Node())
}
log.Info("proxy connected")
Copy link
Contributor

Choose a reason for hiding this comment

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

maybe instead of

proxy connected	{"proxyName": "redis"...

it can be

connected {"type": "dataplane", "name": "redis"...

so we could easily see if this is dataplane or zoneingress or zoneegress

Copy link
Contributor Author

Choose a reason for hiding this comment

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

we already log the type "type", md.GetProxyType(), in 156 line. I'd rather keep "proxy connected" instead of "connected".

It's proxyName instead of name for consistency, see #4436 (comment)

@jakubdyszkiewicz jakubdyszkiewicz merged commit 4b5e6db into master Jun 10, 2022
@jakubdyszkiewicz jakubdyszkiewicz deleted the chore/xds-logging branch June 10, 2022 12:36
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.

Revamp logging for XDS
3 participants