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

Reduce verbose logs that dump large objects #6197

Merged
merged 1 commit into from
Apr 9, 2024

Conversation

tnqn
Copy link
Member

@tnqn tnqn commented Apr 8, 2024

While debugging an issue with improved log level, I found that periodical events like updating monitoring CRs and EndpointSlice events lead to a lot of logs, each of which took considerable space as they dump the entire objects, while we rarely need them.


Before the patch:

I0408 04:23:36.457147       1 agent.go:95] Updating agent monitoring CRD &{TypeMeta:
{Kind: APIVersion:} ObjectMeta:{Name:kind-worker2 GenerateName: Namespace: SelfLink:
UID:6427a66a-d181-4992-8198-2bab3b8c650f ResourceVersion:649256 Generation:1500
CreationTimestamp:2024-04-07 03:23:34 +0000 UTC DeletionTimestamp:<nil>
DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Finalizers:
[] ManagedFields:[{Manager:antrea-controller Operation:Update APIVersion:crd.antrea.io/v1beta1
Time:2024-04-07 03:23:34 +0000 UTC FieldsType:FieldsV1 FieldsV1:{"f:networkPolicyControllerInfo":
{},"f:nodeRef":{},"f:ovsInfo":{},"f:podRef":{}} Subresource:}{Manager:antrea-agent Operation:Update
APIVersion:crd.antrea.io/v1beta1 Time:2024-04-08 04:22:36 +0000 UTC FieldsType:FieldsV1 FieldsV1:
{"f:agentConditions":{},"f:apiCABundle":{},"f:apiPort":{},"f:localPodNum":
{},"f:networkPolicyControllerInfo":{"f:appliedToGroupNum":{},"f:networkPolicyNum":
{}},"f:nodePortLocalPortRange":{},"f:nodeRef":{"f:kind":{},"f:name":{}},"f:nodeSubnets":
{},"f:ovsInfo":{"f:bridgeName":{},"f:flowTable":{".":{},"f:ARPResponder":{},"f:ARPSpoofGuard":
{},"f:AntreaPolicyEgressRule":{},"f:AntreaPolicyIngressRule":{},"f:Classifier":
{},"f:ConntrackCommit":{},"f:ConntrackState":{},"f:ConntrackZone":{},"f:EgressDefaultRule":
{},"f:EgressMark":{},"f:EgressMetric":{},"f:EgressRule":{},"f:EndpointDNAT":
{},"f:IngressDefaultRule":{},"f:IngressMetric":{},"f:IngressRule":{},"f:IngressSecurityClassifier":
{},"f:L2ForwardingCalc":{},"f:L3DecTTL":{},"f:L3Forwarding":{},"f:Output":
{},"f:PipelineRootClassifier":{},"f:PreRoutingClassifier":{},"f:SNAT":{},"f:SNATMark":
{},"f:ServiceLB":{},"f:SessionAffinity":{},"f:SpoofGuard":{},"f:UnSNAT":{}},"f:version":
{}},"f:podRef":{"f:kind":{},"f:name":{},"f:namespace":{}},"f:version":{}} Subresource:}]}
Version:v1.15.0 PodRef:{Kind:Pod Namespace:kube-system Name:antrea-agent-clgm7 UID: APIVersion:
ResourceVersion: FieldPath:} NodeRef:{Kind:Node Namespace: Name:kind-worker2 UID: APIVersion:
ResourceVersion: FieldPath:} NodeSubnets:[10.244.2.0/24] OVSInfo:{Version:2.17.7 BridgeName:br-int
FlowTable:map[ARPResponder:4 ARPSpoofGuard:4 AntreaPolicyEgressRule:16 AntreaPolicyIngressRule:9
Classifier:6 ConntrackCommit:2 ConntrackState:5 ConntrackZone:2 EgressDefaultRule:1 EgressMark:7
EgressMetric:6 EgressRule:1 EndpointDNAT:11 IngressDefaultRule:1 IngressMetric:1 IngressRule:1
IngressSecurityClassifier:6 L2ForwardingCalc:5 L3DecTTL:3 L3Forwarding:12 Output:10
PipelineRootClassifier:3 PreRoutingClassifier:2 SNAT:5 SNATMark:4 ServiceLB:9 SessionAffinity:2
SpoofGuard:4 UnSNAT:3]} NetworkPolicyControllerInfo:{NetworkPolicyNum:1 AddressGroupNum:0
AppliedToGroupNum:1} LocalPodNum:2 AgentConditions:[{Type:AgentHealthy Status:True
LastHeartbeatTime:2024-04-08 04:23:36.4571215 +0000 UTC m=+63502.507715345 Reason: Message:}
{Type:ControllerConnectionUp Status:True LastHeartbeatTime:2024-04-08 04:23:36.4571215 +0000 UTC
m=+63502.507715345 Reason: Message:} {Type:OVSDBConnectionUp Status:True
LastHeartbeatTime:2024-04-08 04:23:36.4571215 +0000 UTC m=+63502.507715345 Reason: Message:}
{Type:OpenflowConnectionUp Status:True LastHeartbeatTime:2024-04-08 04:23:36.4571215 +0000 UTC
m=+63502.507715345 Reason: Message:}] APIPort:10350 APICABundle:[45 45 45 45 45 66 69 71 73 78 32
67 69 82 84 73 70 73 67 65 84 69 45 45 45 45 45 10 77 73 73 68 84 84 67 67 65 106 87 103 65 119 73
66 65 103 73 66 65 106 65 78 66 103 107 113 104 107 105 71 57 119 48 66 65 81 115 70 65 68 65 105
77 83 65 119 72 103 89 68 86 81 81 68 68 66 100 115 98 50 78 104 10 98 71 104 118 99 51 81 116 89
50 70 65 77 84 99 120 77 106 81 52 78 106 99 120 78 106 65 101 70 119 48 121 78 68 65 48 77 68 99
119 79 84 81 49 77 84 90 97 70 119 48 121 78 84 65 48 77 68 99 119 79 84 81 49 10 77 84 90 97 77 66
56 120 72 84 65 98 66 103 78 86 66 65 77 77 70 71 120 118 89 50 70 115 97 71 57 122 100 69 65 120
78 122 69 121 78 68 103 50 78 122 69 50 77 73 73 66 73 106 65 78 66 103 107 113 104 107 105 71 10
57 119 48 66 65 81 69 70 65 65 79 67 65 81 56 65 77 73 73 66 67 103 75 67 65 81 69 65 49 79 88 55
111 109 116 84 90 68 115 118 112 72 113 113 112 116 120 79 56 50 99 50 120 122 71 68 106 109 53 54
52 69 84 97 10 73 120 110 53 109 101 54 43 122 103 97 84 79 75 85 47 57 112 67 103 112 86 83 100
115 122 116 102 57 83 113 108 54 72 104 85 82 119 116 106 120 47 104 111 110 71 80 82 81 79 101 106
103 90 65 98 104 57 66 105 73 43 97 43 10 122 81 119 103 50 76 97 122 97 43 122 76 49 121 121 121
116 50 84 103 79 76 109 84 101 110 88 49 67 50 116 116 106 100 117 57 78 77 85 71 72 109 56 79 57
118 113 103 102 79 119 102 97 103 66 86 118 111 74 107 51 54 89 78 10 118 54 77 102 71 72 98 66 115
90 72 115 65 79 119 43 79 70 54 82 114 74 111 103 113 43 103 73 102 106 82 80 66 69 86 118 113 71
112 85 85 67 49 51 122 98 118 70 110 86 103 71 97 47 73 113 84 79 48 84 84 77 68 77 10 109 73 47 53
107 69 77 87 112 104 110 120 53 47 87 121 69 97 89 57 51 77 101 98 65 80 87 119 71 71 55 90 109 47
52 51 70 98 106 49 89 43 104 82 66 56 88 88 108 80 97 105 77 122 49 55 120 67 108 79 57 99 115 70
10 100 90 79 97 54 86 81 113 83 43 122 57 122 111 80 111 100 118 119 103 78 43 50 69 73 83 47 86 89
83 120 80 71 108 112 97 85 121 72 110 72 86 49 76 106 97 77 88 75 119 73 68 65 81 65 66 111 52 71
81 77 73 71 78 10 77 65 52 71 65 49 85 100 68 119 69 66 47 119 81 69 65 119 73 70 111 68 65 84 66
103 78 86 72 83 85 69 68 68 65 75 66 103 103 114 66 103 69 70 66 81 99 68 65 84 65 77 66 103 78 86
72 82 77 66 65 102 56 69 10 65 106 65 65 77 66 56 71 65 49 85 100 73 119 81 89 77 66 97 65 70 75 77
72 71 78 101 121 57 122 90 108 52 47 97 115 79 47 75 53 65 113 56 67 89 48 70 102 77 68 99 71 65 49
85 100 69 81 81 119 77 67 54 67 10 67 87 120 118 89 50 70 115 97 71 57 122 100 73 73 74 98 71 57
106 89 87 120 111 98 51 78 48 104 119 82 47 65 65 65 66 104 120 65 65 65 65 65 65 65 65 65 65 65 65
65 65 65 65 65 65 65 65 65 66 77 65 48 71 10 67 83 113 71 83 73 98 51 68 81 69 66 67 119 85 65 65
52 73 66 65 81 65 111 106 90 68 107 107 89 57 114 117 119 112 113 78 107 53 75 82 103 75 81 111 119
71 119 100 118 100 121 79 102 107 83 106 109 99 55 70 77 57 103 10 73 120 51 70 115 54 102 113 53
82 75 52 50 57 66 82 74 49 112 65 103 101 71 115 78 119 90 119 65 72 43 53 115 118 102 111 103 72
101 69 83 47 73 97 68 110 68 109 73 111 74 120 69 85 83 89 114 102 50 120 101 48 85 104 10 83 69
101 101 108 76 89 102 88 85 55 90 65 121 83 89 48 90 71 48 55 107 53 110 73 50 111 99 122 98 67 112
76 100 48 111 86 114 68 43 97 68 66 117 66 97 47 110 122 102 117 90 52 108 54 104 48 86 80 70 86
122 48 111 10 85 76 74 70 72 107 100 117 47 56 66 70 77 57 68 105 56 66 50 72 110 55 53 49 104 49
43 115 105 68 101 71 79 77 70 49 83 52 122 82 89 77 103 55 112 116 98 87 112 73 80 70 119 89 113
109 80 57 77 74 52 112 101 108 10 83 90 57 113 83 66 118 84 69 73 84 67 47 66 51 107 72 67 116 112
109 43 70 56 65 68 80 120 109 53 50 79 101 98 83 108 65 47 80 99 120 54 105 51 122 111 119 47 74 86
98 100 102 120 113 121 109 115 85 112 49 65 108 89 10 86 55 75 85 82 76 47 112 84 121 99 77 99 52
54 82 107 80 121 71 119 97 109 99 73 99 109 75 49 74 99 53 72 109 90 54 108 65 75 73 53 69 81 103
10 45 45 45 45 45 69 78 68 32 67 69 82 84 73 70 73 67 65 84 69 45 45 45 45 45 10 45 45 45 45 45 66
69 71 73 78 32 67 69 82 84 73 70 73 67 65 84 69 45 45 45 45 45 10 77 73 73 68 65 84 67 67 65 101
109 103 65 119 73 66 65 103 73 66 65 84 65 78 66 103 107 113 104 107 105 71 57 119 48 66 65 81 115
70 65 68 65 105 77 83 65 119 72 103 89 68 86 81 81 68 68 66 100 115 98 50 78 104 10 98 71 104 118
99 51 81 116 89 50 70 65 77 84 99 120 77 106 81 52 78 106 99 120 78 106 65 101 70 119 48 121 78 68
65 48 77 68 99 119 79 84 81 49 77 84 90 97 70 119 48 121 78 84 65 48 77 68 99 119 79 84 81 49 10 77
84 90 97 77 67 73 120 73 68 65 101 66 103 78 86 66 65 77 77 70 50 120 118 89 50 70 115 97 71 57 122
100 67 49 106 89 85 65 120 78 122 69 121 78 68 103 50 78 122 69 50 77 73 73 66 73 106 65 78 66 103
107 113 10 104 107 105 71 57 119 48 66 65 81 69 70 65 65 79 67 65 81 56 65 77 73 73 66 67 103 75 67
65 81 69 65 50 71 88 82 87 117 77 49 115 86 84 50 101 84 106 110 98 79 107 110 108 71 116 57 85 75
55 54 119 80 122 55 10 110 99 52 57 105 119 100 117 75 99 110 83 52 83 74 83 54 121 43 90 102 78
103 122 76 81 122 102 107 105 89 74 107 54 109 105 89 111 115 110 84 100 69 68 82 67 120 54 54 104
47 73 88 97 106 55 109 112 47 75 90 106 67 67 10 65 48 101 105 73 56 76 116 83 102 43 72 109 103
104 89 50 82 108 54 43 105 98 72 88 56 90 105 80 47 120 111 71 90 102 50 99 116 81 116 118 54 122
65 114 56 52 107 84 101 108 108 48 67 47 97 75 122 47 80 51 52 47 104 10 75 106 83 90 111 81 81 77
114 82 88 114 87 88 112 79 55 117 106 108 85 107 121 72 100 49 49 78 103 97 47 119 80 98 104 80 49
118 89 54 57 73 81 56 105 115 110 112 103 97 70 79 76 55 114 52 56 83 66 73 83 82 103 49 10 103 51
75 101 99 55 79 120 74 102 74 86 113 84 97 74 90 103 89 73 97 74 119 116 114 47 77 85 102 53 103 85
50 73 89 86 48 106 103 82 90 56 87 114 121 112 107 47 48 43 76 108 111 84 113 52 48 55 75 79 65 57
75 103 10 48 86 86 115 54 83 88 56 56 74 70 104 98 77 69 67 117 79 120 75 86 90 67 101 75 52 88 48
52 108 55 80 53 106 100 72 114 50 77 67 83 82 69 83 83 57 72 116 118 82 76 70 97 119 73 68 65 81 65
66 111 48 73 119 10 81 68 65 79 66 103 78 86 72 81 56 66 65 102 56 69 66 65 77 67 65 113 81 119 68
119 89 68 86 82 48 84 65 81 72 47 66 65 85 119 65 119 69 66 47 122 65 100 66 103 78 86 72 81 52 69
70 103 81 85 111 119 99 89 10 49 55 76 51 78 109 88 106 57 113 119 55 56 114 107 67 114 119 74 106
81 86 56 119 68 81 89 74 75 111 90 73 104 118 99 78 65 81 69 76 66 81 65 68 103 103 69 66 65 75 66
117 75 111 47 79 43 81 71 80 114 55 106 68 10 75 52 104 70 52 52 118 120 110 76 102 52 77 76 68 53
71 90 71 115 88 88 119 118 80 51 55 117 56 78 67 105 85 81 86 87 43 108 114 114 76 83 114 54 90 107
97 113 111 112 71 66 48 69 65 57 85 70 112 68 52 69 69 52 10 87 120 50 48 87 100 122 86 65 107 108
53 76 71 82 78 97 120 89 108 116 82 112 49 114 110 52 99 116 119 70 74 43 72 101 98 86 114 116 74
99 112 54 99 49 73 109 68 49 113 101 54 101 78 113 107 107 81 50 107 54 68 106 112 10 54 100 112 73
89 68 51 70 53 51 55 53 117 81 122 118 114 112 121 86 85 102 99 73 78 100 121 106 109 88 105 48 67
103 82 75 82 111 112 80 113 87 110 109 88 88 50 89 66 119 89 120 104 83 106 116 84 79 53 76 87 81
99 80 10 50 66 109 49 101 54 88 90 108 54 67 47 51 48 72 90 81 88 83 118 105 85 76 119 65 105 89 50
108 49 81 49 52 110 73 75 65 116 106 87 48 52 120 113 107 74 54 56 90 49 65 98 99 74 119 52 84 89
68 100 76 114 82 108 10 73 108 75 89 86 75 109 57 108 104 100 87 43 47 100 112 110 65 50 53 118 79
119 54 86 101 72 72 106 65 68 108 47 52 80 82 111 68 88 88 77 79 107 78 89 89 80 100 72 107 54 83
116 102 119 118 109 110 111 69 105 117 106 112 10 99 114 104 53 107 109 52 61 10 45 45 45 45 45 69
78 68 32 67 69 82 84 73 70 73 67 65 84 69 45 45 45 45 45 10] NodePortLocalPortRange:61000-62000},
partial: true

I0408 12:06:12.622084       1 config.go:350] "Calling handler.OnEndpointSliceUpdate"
from="&EndpointSlice{ObjectMeta:{kube-dns-scb4w kube-dns- kube-system
35761052-78e1-4cfe-9476-60a5537cce90 549852 16 2024-04-03 06:27:12 +0000 UTC <nil> <nil> map
[endpointslice.kubernetes.io/managed-by:endpointslice-controller.k8s.io k8s-app:kube-dns
kubernetes.io/cluster-service:true kubernetes.io/name:CoreDNS kubernetes.io/service-name:kube-dns]
map[] [{v1 Service kube-dns f3b58516-2b0b-46ed-9d06-dee7d7e47b2e 0xc000e6ee80 0xc000e6ee81}] [] [
{kube-controller-manager Update discovery.k8s.io/v1 2024-04-07 10:45:23 +0000 UTC FieldsV1
{\"f:addressType\":{},\"f:endpoints\":{},\"f:metadata\":{\"f:generateName\":{},\"f:labels\":{\".\":
{},\"f:endpointslice.kubernetes.io/managed-by\":{},\"f:k8s-app\":
{},\"f:kubernetes.io/cluster-service\":{},\"f:kubernetes.io/name\":
{},\"f:kubernetes.io/service-name\":{}},\"f:ownerReferences\":{\".\":{},\"k:
{\\\"uid\\\":\\\"f3b58516-2b0b-46ed-9d06-dee7d7e47b2e\\\"}\":{}}},\"f:ports\":{}} }]},Endpoints:
[]Endpoint{Endpoint{Addresses:[10.244.0.4],Conditions:EndpointConditions
{Ready:*true,Serving:*true,Terminating:*false,},Hostname:nil,TargetRef:&v1.ObjectReference
{Kind:Pod,Namespace:kube-system,Name:coredns-6944c95467-q4zj2,UID:0847fb21-8d2a-48a8-99ca-3ba8664248b8,APIVersion:,ResourceVersion:,FieldPath:,},DeprecatedTopology:map[string]string{},NodeName:*kind-control-plane,Zone:nil,Hints:nil,},Endpoint{Addresses:[10.244.0.5],Conditions:EndpointConditions{Ready:*true,Serving:*true,Terminating:*false,},Hostname:nil,TargetRef:&v1.ObjectReference{Kind:Pod,Namespace:kube-system,Name:coredns-6944c95467-jfp67,UID:f240671f-3e6f-4a86-9011-c47e6750b6e1,APIVersion:,ResourceVersion:,FieldPath:,},DeprecatedTopology:map[string]string{},NodeName:*kind-control-plane,Zone:nil,Hints:nil,},},Ports:[]EndpointPort{EndpointPort{Name:*metrics,Protocol:*TCP,Port:*9153,AppProtocol:nil,},EndpointPort{Name:*dns,Protocol:*UDP,Port:*53,AppProtocol:nil,},EndpointPort{Name:*dns-tcp,Protocol:*TCP,Port:*53,AppProtocol:nil,},},AddressType:IPv4,}"
to="&EndpointSlice{ObjectMeta:{kube-dns-scb4w kube-dns- kube-system
35761052-78e1-4cfe-9476-60a5537cce90 549852 16 2024-04-03 06:27:12 +0000 UTC <nil> <nil> map
[endpointslice.kubernetes.io/managed-by:endpointslice-controller.k8s.io k8s-app:kube-dns
kubernetes.io/cluster-service:true kubernetes.io/name:CoreDNS kubernetes.io/service-name:kube-dns]
map[] [{v1 Service kube-dns f3b58516-2b0b-46ed-9d06-dee7d7e47b2e 0xc000e6ee80 0xc000e6ee81}] [] [
{kube-controller-manager Update discovery.k8s.io/v1 2024-04-07 10:45:23 +0000 UTC FieldsV1
{\"f:addressType\":{},\"f:endpoints\":{},\"f:metadata\":{\"f:generateName\":{},\"f:labels\":{\".\":
{},\"f:endpointslice.kubernetes.io/managed-by\":{},\"f:k8s-app\":
{},\"f:kubernetes.io/cluster-service\":{},\"f:kubernetes.io/name\":
{},\"f:kubernetes.io/service-name\":{}},\"f:ownerReferences\":{\".\":{},\"k:
{\\\"uid\\\":\\\"f3b58516-2b0b-46ed-9d06-dee7d7e47b2e\\\"}\":{}}},\"f:ports\":{}} }]},Endpoints:
[]Endpoint{Endpoint{Addresses:[10.244.0.4],Conditions:EndpointConditions
{Ready:*true,Serving:*true,Terminating:*false,},Hostname:nil,TargetRef:&v1.ObjectReference
{Kind:Pod,Namespace:kube-system,Name:coredns-6944c95467-q4zj2,UID:0847fb21-8d2a-48a8-99ca-3ba8664248b8,APIVersion:,ResourceVersion:,FieldPath:,},DeprecatedTopology:map[string]string{},NodeName:*kind-control-plane,Zone:nil,Hints:nil,},Endpoint{Addresses:[10.244.0.5],Conditions:EndpointConditions{Ready:*true,Serving:*true,Terminating:*false,},Hostname:nil,TargetRef:&v1.ObjectReference{Kind:Pod,Namespace:kube-system,Name:coredns-6944c95467-jfp67,UID:f240671f-3e6f-4a86-9011-c47e6750b6e1,APIVersion:,ResourceVersion:,FieldPath:,},DeprecatedTopology:map[string]string{},NodeName:*kind-control-plane,Zone:nil,Hints:nil,},},Ports:[]EndpointPort{EndpointPort{Name:*metrics,Protocol:*TCP,Port:*9153,AppProtocol:nil,},EndpointPort{Name:*dns,Protocol:*UDP,Port:*53,AppProtocol:nil,},EndpointPort{Name:*dns-tcp,Protocol:*TCP,Port:*53,AppProtocol:nil,},},AddressType:IPv4,}"

While debugging an issue with improved log level, I found that
periodical events like updating monitoring CRs and EndpointSlice events
lead to a lot of logs, each of which took considerable space as they
dump the entire objects, while we rarely need them.

This patch reduces some less useful verbose logs.

Signed-off-by: Quan Tian <[email protected]>
@tnqn tnqn changed the title Reduce verbose log for monitoring Reduce verbose logs that dump large objects Apr 8, 2024
@tnqn tnqn requested a review from antoninbas April 8, 2024 12:50
@antoninbas
Copy link
Contributor

/skip-all

@tnqn tnqn merged commit 19caf9c into antrea-io:main Apr 9, 2024
52 of 55 checks passed
@tnqn tnqn deleted the reduce-verbose-log branch April 9, 2024 02:45
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.

2 participants