Skip to content

Instantly share code, notes, and snippets.

@squeed

squeed/info.md

Created January 8, 2024 12:51
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save squeed/752d105c569db3eb328de191d37a4ed8 to your computer and use it in GitHub Desktop.
Save squeed/752d105c569db3eb328de191d37a4ed8 to your computer and use it in GitHub Desktop.
Download ZIP
cilium agent log: envoy takes too long
Raw
info.md

Background:

Allocating two new identities and updating the policy engine can take too long, tripping a circuit-breaker (100ms) and returning a DNS message early to the endpoint.

I have an excerpt from an agent log that shows this. The summary:

  • 29.960481392Z: ipcache starts
  • 29.964383980Z: allocation complete, update policy engine
  • 29.987019603Z: policy engine update complete, waiting for Envoy to update
  • 30.036687960Z: Envoy updates complete. Time spent: 49ms

49ms is extremely high. Looking at wait times for the entire CI run, the basic statistics in microseconds are:

Max Mean Median Min Stddev 95%ile 99%ile
93618.858 911.274136865342 68.328 9.358 7016.63851906122 434.1398 26600.23856
Raw
log.txt
2024-01-02T10:54:29.946323909Z level=debug msg="Resolving identity" identityLabels="cidr:2606:4700:4700::1111/128,reserved:world-ipv6" subsys=identity-cache
2024-01-02T10:54:29.947348947Z level=debug msg="Waited for endpoints to regenerate due to a DNS response" duration=29.996467ms endpointID=2949 qname=one.one.one.one. subsys=daemon
2024-01-02T10:54:29.947431581Z level=debug msg="Responding to original DNS query" DNSRequestID=17708 dnsName=one.one.one.one. endpointID=2949 identity=42841 ipAddr="10.244.2.240:41167" subsys=fqdn/dnsproxy
2024-01-02T10:54:29.947526412Z level=debug msg="dnsproxy: Wrote DNS response (95/95 bytes) from 10.244.1.99:53 to 10.244.2.240:41167" subsys=fqdn/dnsproxy
2024-01-02T10:54:29.960481392Z level=debug msg="Resolving identity" identityLabels="cidr:2606:4700:4700::1001/128,reserved:world-ipv6" subsys=identity-cache
2024-01-02T10:54:29.961530719Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777421 labels="[cidr:0--0/0 cidr:0--0/1 cidr:0--0/2 cidr:2000--0/3 cidr:2000--0/4 cidr:2000--0/5 cidr:2400--0/6 cidr:2600--0/10 cidr:2600--0/11 cidr:2600--0/12 cidr:2600--0/13 cidr:2600--0/7 cidr:2600--0/8 cidr:2600--0/9 cidr:2604--0/14 cidr:2606--0/15 cidr:2606--0/16 cidr:2606--0/17 cidr:2606-4000--0/18 cidr:2606-4000--0/19 cidr:2606-4000--0/20 cidr:2606-4000--0/21 cidr:2606-4400--0/22 cidr:2606-4600--0/23 cidr:2606-4700--0/24 cidr:2606-4700--0/25 cidr:2606-4700--0/26 cidr:2606-4700--0/27 cidr:2606-4700--0/28 cidr:2606-4700--0/29 cidr:2606-4700--0/30 cidr:2606-4700--0/31 cidr:2606-4700--0/32 cidr:2606-4700--0/33 cidr:2606-4700-4000--0/34 cidr:2606-4700-4000--0/35 cidr:2606-4700-4000--0/36 cidr:2606-4700-4000--0/37 cidr:2606-4700-4400--0/38 cidr:2606-4700-4600--0/39 cidr:2606-4700-4700--0/100 cidr:2606-4700-4700--0/101 cidr:2606-4700-4700--0/102 cidr:2606-4700-4700--0/103 cidr:2606-4700-4700--0/104 cidr:2606-4700-4700--0/105 cidr:2606-4700-4700--0/106 cidr:2606-4700-4700--0/107 cidr:2606-4700-4700--0/108 cidr:2606-4700-4700--0/109 cidr:2606-4700-4700--0/110 cidr:2606-4700-4700--0/111 cidr:2606-4700-4700--0/112 cidr:2606-4700-4700--0/113 cidr:2606-4700-4700--0/114 cidr:2606-4700-4700--0/115 cidr:2606-4700-4700--0/40 cidr:2606-4700-4700--0/41 cidr:2606-4700-4700--0/42 cidr:2606-4700-4700--0/43 cidr:2606-4700-4700--0/44 cidr:2606-4700-4700--0/45 cidr:2606-4700-4700--0/46 cidr:2606-4700-4700--0/47 cidr:2606-4700-4700--0/48 cidr:2606-4700-4700--0/49 cidr:2606-4700-4700--0/50 cidr:2606-4700-4700--0/51 cidr:2606-4700-4700--0/52 cidr:2606-4700-4700--0/53 cidr:2606-4700-4700--0/54 cidr:2606-4700-4700--0/55 cidr:2606-4700-4700--0/56 cidr:2606-4700-4700--0/57 cidr:2606-4700-4700--0/58 cidr:2606-4700-4700--0/59 cidr:2606-4700-4700--0/60 cidr:2606-4700-4700--0/61 cidr:2606-4700-4700--0/62 cidr:2606-4700-4700--0/63 cidr:2606-4700-4700--0/64 cidr:2606-4700-4700--0/65 cidr:2606-4700-4700--0/66 cidr:2606-4700-4700--0/67 cidr:2606-4700-4700--0/68 cidr:2606-4700-4700--0/69 cidr:2606-4700-4700--0/70 cidr:2606-4700-4700--0/71 cidr:2606-4700-4700--0/72 cidr:2606-4700-4700--0/73 cidr:2606-4700-4700--0/74 cidr:2606-4700-4700--0/75 cidr:2606-4700-4700--0/76 cidr:2606-4700-4700--0/77 cidr:2606-4700-4700--0/78 cidr:2606-4700-4700--0/79 cidr:2606-4700-4700--0/80 cidr:2606-4700-4700--0/81 cidr:2606-4700-4700--0/82 cidr:2606-4700-4700--0/83 cidr:2606-4700-4700--0/84 cidr:2606-4700-4700--0/85 cidr:2606-4700-4700--0/86 cidr:2606-4700-4700--0/87 cidr:2606-4700-4700--0/88 cidr:2606-4700-4700--0/89 cidr:2606-4700-4700--0/90 cidr:2606-4700-4700--0/91 cidr:2606-4700-4700--0/92 cidr:2606-4700-4700--0/93 cidr:2606-4700-4700--0/94 cidr:2606-4700-4700--0/95 cidr:2606-4700-4700--0/96 cidr:2606-4700-4700--0/97 cidr:2606-4700-4700--0/98 cidr:2606-4700-4700--0/99 cidr:2606-4700-4700--1000/116 cidr:2606-4700-4700--1000/117 cidr:2606-4700-4700--1000/118 cidr:2606-4700-4700--1000/119 cidr:2606-4700-4700--1100/120 cidr:2606-4700-4700--1100/121 cidr:2606-4700-4700--1100/122 cidr:2606-4700-4700--1100/123 cidr:2606-4700-4700--1110/124 cidr:2606-4700-4700--1110/125 cidr:2606-4700-4700--1110/126 cidr:2606-4700-4700--1110/127 cidr:2606-4700-4700--1111/128 reserved:world-ipv6]" subsys=policy
2024-01-02T10:54:29.963247661Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777422 labels="[cidr:0--0/0 cidr:0--0/1 cidr:0--0/2 cidr:2000--0/3 cidr:2000--0/4 cidr:2000--0/5 cidr:2400--0/6 cidr:2600--0/10 cidr:2600--0/11 cidr:2600--0/12 cidr:2600--0/13 cidr:2600--0/7 cidr:2600--0/8 cidr:2600--0/9 cidr:2604--0/14 cidr:2606--0/15 cidr:2606--0/16 cidr:2606--0/17 cidr:2606-4000--0/18 cidr:2606-4000--0/19 cidr:2606-4000--0/20 cidr:2606-4000--0/21 cidr:2606-4400--0/22 cidr:2606-4600--0/23 cidr:2606-4700--0/24 cidr:2606-4700--0/25 cidr:2606-4700--0/26 cidr:2606-4700--0/27 cidr:2606-4700--0/28 cidr:2606-4700--0/29 cidr:2606-4700--0/30 cidr:2606-4700--0/31 cidr:2606-4700--0/32 cidr:2606-4700--0/33 cidr:2606-4700-4000--0/34 cidr:2606-4700-4000--0/35 cidr:2606-4700-4000--0/36 cidr:2606-4700-4000--0/37 cidr:2606-4700-4400--0/38 cidr:2606-4700-4600--0/39 cidr:2606-4700-4700--0/100 cidr:2606-4700-4700--0/101 cidr:2606-4700-4700--0/102 cidr:2606-4700-4700--0/103 cidr:2606-4700-4700--0/104 cidr:2606-4700-4700--0/105 cidr:2606-4700-4700--0/106 cidr:2606-4700-4700--0/107 cidr:2606-4700-4700--0/108 cidr:2606-4700-4700--0/109 cidr:2606-4700-4700--0/110 cidr:2606-4700-4700--0/111 cidr:2606-4700-4700--0/112 cidr:2606-4700-4700--0/113 cidr:2606-4700-4700--0/114 cidr:2606-4700-4700--0/115 cidr:2606-4700-4700--0/40 cidr:2606-4700-4700--0/41 cidr:2606-4700-4700--0/42 cidr:2606-4700-4700--0/43 cidr:2606-4700-4700--0/44 cidr:2606-4700-4700--0/45 cidr:2606-4700-4700--0/46 cidr:2606-4700-4700--0/47 cidr:2606-4700-4700--0/48 cidr:2606-4700-4700--0/49 cidr:2606-4700-4700--0/50 cidr:2606-4700-4700--0/51 cidr:2606-4700-4700--0/52 cidr:2606-4700-4700--0/53 cidr:2606-4700-4700--0/54 cidr:2606-4700-4700--0/55 cidr:2606-4700-4700--0/56 cidr:2606-4700-4700--0/57 cidr:2606-4700-4700--0/58 cidr:2606-4700-4700--0/59 cidr:2606-4700-4700--0/60 cidr:2606-4700-4700--0/61 cidr:2606-4700-4700--0/62 cidr:2606-4700-4700--0/63 cidr:2606-4700-4700--0/64 cidr:2606-4700-4700--0/65 cidr:2606-4700-4700--0/66 cidr:2606-4700-4700--0/67 cidr:2606-4700-4700--0/68 cidr:2606-4700-4700--0/69 cidr:2606-4700-4700--0/70 cidr:2606-4700-4700--0/71 cidr:2606-4700-4700--0/72 cidr:2606-4700-4700--0/73 cidr:2606-4700-4700--0/74 cidr:2606-4700-4700--0/75 cidr:2606-4700-4700--0/76 cidr:2606-4700-4700--0/77 cidr:2606-4700-4700--0/78 cidr:2606-4700-4700--0/79 cidr:2606-4700-4700--0/80 cidr:2606-4700-4700--0/81 cidr:2606-4700-4700--0/82 cidr:2606-4700-4700--0/83 cidr:2606-4700-4700--0/84 cidr:2606-4700-4700--0/85 cidr:2606-4700-4700--0/86 cidr:2606-4700-4700--0/87 cidr:2606-4700-4700--0/88 cidr:2606-4700-4700--0/89 cidr:2606-4700-4700--0/90 cidr:2606-4700-4700--0/91 cidr:2606-4700-4700--0/92 cidr:2606-4700-4700--0/93 cidr:2606-4700-4700--0/94 cidr:2606-4700-4700--0/95 cidr:2606-4700-4700--0/96 cidr:2606-4700-4700--0/97 cidr:2606-4700-4700--0/98 cidr:2606-4700-4700--0/99 cidr:2606-4700-4700--1000/116 cidr:2606-4700-4700--1000/117 cidr:2606-4700-4700--1000/118 cidr:2606-4700-4700--1000/119 cidr:2606-4700-4700--1000/120 cidr:2606-4700-4700--1000/121 cidr:2606-4700-4700--1000/122 cidr:2606-4700-4700--1000/123 cidr:2606-4700-4700--1000/124 cidr:2606-4700-4700--1000/125 cidr:2606-4700-4700--1000/126 cidr:2606-4700-4700--1000/127 cidr:2606-4700-4700--1001/128 reserved:world-ipv6]" subsys=policy
2024-01-02T10:54:29.964383980Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[16777421 16777422]" policyID.Deleted="[]" subsys=policy
2024-01-02T10:54:29.964550059Z level=debug msg=AccumulateMapChanges AuthType=default EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" IsRedirect=true policyID.Added="[16777421 16777422]" policyID.Deleted="[]" port=53 protocol=17 subsys=policy trafficDirection=Egress
2024-01-02T10:54:29.965309225Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[16777421 16777422]" policyID.Deleted="[]" subsys=policy
2024-01-02T10:54:29.965414201Z level=debug msg=AccumulateMapChanges AuthType=default EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" IsRedirect=true policyID.Added="[16777421 16777422]" policyID.Deleted="[]" port=53 protocol=6 subsys=policy trafficDirection=Egress
2024-01-02T10:54:29.965516171Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[16777421 16777422]" policyID.Deleted="[]" subsys=policy
2024-01-02T10:54:29.965598866Z level=debug msg=AccumulateMapChanges AuthType=default EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" IsRedirect=true policyID.Added="[16777421 16777422]" policyID.Deleted="[]" port=53 protocol=17 subsys=policy trafficDirection=Egress
2024-01-02T10:54:29.965675328Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[16777421 16777422]" policyID.Deleted="[]" subsys=policy
2024-01-02T10:54:29.965822723Z level=debug msg=AccumulateMapChanges AuthType=default EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.world-ipv6: ,},MatchExpressions:[]LabelSelectorRequirement{},}" IsRedirect=true policyID.Added="[16777421 16777422]" policyID.Deleted="[]" port=53 protocol=6 subsys=policy trafficDirection=Egress
2024-01-02T10:54:29.965911959Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="MatchName: one.one.one.one, MatchPattern: " policyID.Added="[16777421 16777422]" policyID.Deleted="[]" subsys=policy
2024-01-02T10:54:29.965996087Z level=debug msg=AccumulateMapChanges AuthType=default EndpointSelector="MatchName: one.one.one.one, MatchPattern: " IsRedirect=true policyID.Added="[16777421 16777422]" policyID.Deleted="[]" port=80 protocol=6 subsys=policy trafficDirection=Egress
2024-01-02T10:54:29.967065430Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.967543182Z level=debug msg="cache unmodified by transaction; aborting" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.967807925Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.0010986328125
2024-01-02T10:54:29.971746480Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.0010986328125
2024-01-02T10:54:29.976910250Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.0010986328125
2024-01-02T10:54:29.977141592Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.0010986328125
2024-01-02T10:54:29.977386268Z level=debug msg="Applied policy map updates due identity changes" ciliumEndpointName=cilium-test/client-75bff5f5b9-5lfmd containerID=12289426c4 containerInterface= datapathPolicyRevision=236 desiredPolicyRevision=235 endpointID=2949 identity=42841 ipv4=10.244.2.240 ipv6="fd00:10:244:2::c316" k8sPodName=cilium-test/client-75bff5f5b9-5lfmd policyID.Added="map[Identity=16777421,DestPort=53,Nexthdr=6,TrafficDirection=1:{} Identity=16777421,DestPort=53,Nexthdr=17,TrafficDirection=1:{} Identity=16777422,DestPort=53,Nexthdr=6,TrafficDirection=1:{} Identity=16777422,DestPort=53,Nexthdr=17,TrafficDirection=1:{}]" policyID.Deleted="map[]" subsys=endpoint
2024-01-02T10:54:29.977544483Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.977709331Z level=debug msg="cache unmodified by transaction; aborting" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.977937526Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978085572Z level=debug msg="cache unmodified by transaction; aborting" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978189736Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978346569Z level=debug msg="cache unmodified by transaction; aborting" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978452426Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978544868Z level=debug msg="cache unmodified by transaction; aborting" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.978834739Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.979088923Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.979301820Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.979510740Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.979698069Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.981069827Z level=debug msg="EndpointManager policymap received event" subsys=endpoint-manager value=0.00146484375
2024-01-02T10:54:29.981317339Z level=debug msg="Applied policy map updates due identity changes" ciliumEndpointName=cilium-test/client2-88575dbb7-xztwc containerID=1c2c9118b5 containerInterface= datapathPolicyRevision=236 desiredPolicyRevision=236 endpointID=3057 identity=5137 ipv4=10.244.2.177 ipv6="fd00:10:244:2::23ca" k8sPodName=cilium-test/client2-88575dbb7-xztwc policyID.Added="map[Identity=16777421,DestPort=53,Nexthdr=6,TrafficDirection=1:{} Identity=16777421,DestPort=53,Nexthdr=17,TrafficDirection=1:{} Identity=16777421,DestPort=80,Nexthdr=6,TrafficDirection=1:{} Identity=16777422,DestPort=53,Nexthdr=6,TrafficDirection=1:{} Identity=16777422,DestPort=53,Nexthdr=17,TrafficDirection=1:{} Identity=16777422,DestPort=80,Nexthdr=6,TrafficDirection=1:{}]" policyID.Deleted="map[]" subsys=endpoint
2024-01-02T10:54:29.981473460Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[16777419 16777420 16777421 16777422]" port=80 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.981605156Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[27751]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.981744456Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[9 16777419 16777420]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.981907940Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[10 16777421 16777422]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.982055405Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[2]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.982190337Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=3057 policyID="[]" port=8080 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.982335408Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.982479636Z level=debug msg="updating resource in cache" subsys=xds xdsCachedVersion=588 xdsResourceName=3057 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.982573201Z level=debug msg="committing cache transaction and notifying of new version" subsys=xds xdsCachedVersion=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.982690340Z level=debug msg="getting 0 resources from set" subsys=xds xdsAckedVersion=587 xdsClientNode=127.0.0.1 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.982856960Z level=debug msg="no resource names requested, returning all 7 resources" subsys=xds xdsAckedVersion=587 xdsClientNode=127.0.0.1 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.983004656Z level=debug msg="sending xDS response with 7 resources" subsys=xds xdsCachedVersion=588 xdsCanary=false xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=588 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.986620318Z level=debug msg="Endpoint has no IP addresses" endpointID=2488 subsys=envoy-manager
2024-01-02T10:54:29.986632401Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=2949 policyID="[10 16777421 16777422]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.986637761Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=2949 policyID="[27751]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.986642199Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=2949 policyID="[2]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.986687363Z level=debug msg="PortNetworkPolicyRule matching remote IDs" endpointID=2949 policyID="[9 16777419 16777420]" port=53 serverNames="[]" subsys=envoy-manager trafficDirection=egress
2024-01-02T10:54:29.986790025Z level=debug msg="preparing new cache transaction: upserting 1 entries, deleting 0 entries" subsys=xds xdsCachedVersion=589 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.987005828Z level=debug msg="updating resource in cache" subsys=xds xdsCachedVersion=589 xdsResourceName=2949 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.987015154Z level=debug msg="committing cache transaction and notifying of new version" subsys=xds xdsCachedVersion=589 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:29.987019603Z level=debug msg="Waiting for proxy updates to complete..." subsys=endpoint-manager
2024-01-02T10:54:29.987321636Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 3" subsys=envoy-connection threadID=2004
2024-01-02T10:54:29.987391026Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:29.987475613Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read ready. dispatch_buffered_data=0" subsys=envoy-connection threadID=2004
2024-01-02T10:54:29.987538360Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read returns: 925" subsys=envoy-connection threadID=2004
2024-01-02T10:54:29.987626675Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read error: Resource temporarily unavailable" subsys=envoy-connection threadID=2004
2024-01-02T10:54:29.987697518Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatching 925 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:29.990569644Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=0, flags=0, stream_id=7" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:29.990770043Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:29.990781164Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=0 flags=0 length=916 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:29.990924591Z level=debug msg="[async http request response data (length=916 end_stream=false)" subsys=envoy-http threadID=2004
2024-01-02T10:54:29.990931704Z level=debug msg="[Received gRPC message for type.googleapis.com/cilium.NetworkPolicy at version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.990988484Z level=debug msg="[Pausing discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 0)" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991157169Z level=debug msg="[NetworkPolicyMap::onConfigUpdate(cilium.policymap.10.244.2.142.2.), 7 resources, version: 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991166647Z level=debug msg="[init manager NetworkPolicyMap manager for version 587 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:29.991171145Z level=debug msg="[Received Network Policy for endpoint 1155 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991175022Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991179240Z level=debug msg="[Received Network Policy for endpoint 3242 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991183448Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991262366Z level=debug msg="[Received Network Policy for endpoint 477 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991323600Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991475098Z level=debug msg="[Received Network Policy for endpoint 3363 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991483884Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991487842Z level=debug msg="[Received Network Policy for endpoint 1249 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991537524Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991788005Z level=debug msg="[Received Network Policy for endpoint 2949 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991796431Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991800048Z level=debug msg="[Received Network Policy for endpoint 3057 in onConfigUpdate() version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991803334Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP wildcard policy" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991806690Z level=debug msg="[Cilium L7 PortNetworkPolicyRules(): No rules, will allow everything." subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991810137Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP policy for port range 53-53" subsys=envoy-config threadID=2004
2024-01-02T10:54:29.991813483Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 2 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002476808Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 27751 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002495212Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 9 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002498768Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777419 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002501965Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777420 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002505090Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 10 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002508016Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777421 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002510871Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777422 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002513626Z level=debug msg="[Cilium L7 PortNetworkPolicy(): Adding rules for [53-53] to [53-53]" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002516401Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP policy for port range 80-80" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002519227Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777419 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002522102Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777420 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002524757Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777421 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002527622Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777422 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002530628Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule():" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002533674Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule(): HeaderData :method=<UNKNOWN>" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002536469Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule(): HeaderData :path=<UNKNOWN>" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002539184Z level=debug msg="[Cilium L7 PortNetworkPolicy(): Adding rules for [80-80] to [80-80]" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002542129Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP policy for port range 8080-8080" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002545065Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule():" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002547820Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule(): HeaderData :method=<UNKNOWN>" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002550535Z level=debug msg="[Cilium L7 HttpNetworkPolicyRule(): HeaderData :path=<UNKNOWN>" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002553560Z level=debug msg="[Cilium L7 PortNetworkPolicy(): Adding rules for [8080-8080] to [8080-8080]" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.002556667Z level=debug msg="[target NetworkPolicyMap manager for version 587 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.002559913Z level=debug msg="[added target NetworkPolicyMap manager for version 588 to init manager NetworkPolicyMap manager for version 588" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.004999624Z level=debug msg="[Pausing NPDS subscription" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005010384Z level=debug msg="[Pausing discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 1)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005014241Z level=debug msg="[NetworkPolicyMap manager for version 587 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.005026143Z level=debug msg="[init manager NetworkPolicyMap manager for version 588 initializing" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.005030261Z level=debug msg="[init manager NetworkPolicyMap manager for version 588 initializing target NetworkPolicyMap manager for version 588" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.005034038Z level=debug msg="[gRPC config for type.googleapis.com/cilium.NetworkPolicy accepted with 7 resources with version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005037344Z level=debug msg="[API type.googleapis.com/cilium.NetworkPolicy paused during queueDiscoveryRequest(), setting pending." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005040921Z level=debug msg="[Decreasing pause count on discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 2)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005044367Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatched 925 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.005047193Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 588" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.005050428Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::23ca" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.005053835Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.177" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.005057252Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 588" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.005060858Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::23ca" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.005063834Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.177" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.005066939Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 588" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.005070065Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::23ca" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.005072900Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.177" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.005076337Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 588" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.005079864Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::23ca" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.005082959Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.177" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.005086095Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the main thread for version 588" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005089451Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::23ca" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005092848Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.177" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.005096745Z level=debug msg="received request from xDS stream" subsys=xds xdsAckedVersion=588 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=588 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005099921Z level=debug msg="notifying observers of ACKs" subsys=xds xdsAckedVersion=588 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=588 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005107746Z level=debug msg="completing ACK: &{588 type.googleapis.com/cilium.NetworkPolicy map[]}" subsys=xds xdsAckedVersion=588 xdsClientNode=127.0.0.1 xdsNonce=588 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005111092Z level=debug msg="starting watch on 0 resources" subsys=xds xdsAckedVersion=588 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=588 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005114318Z level=debug msg="getting 0 resources from set" subsys=xds xdsAckedVersion=588 xdsClientNode=127.0.0.1 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005139465Z level=debug msg="no resource names requested, returning all 7 resources" subsys=xds xdsAckedVersion=588 xdsClientNode=127.0.0.1 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005146428Z level=debug msg="sending xDS response with 7 resources" subsys=xds xdsCachedVersion=589 xdsCanary=false xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=589 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.005150185Z level=debug msg="[target NetworkPolicyMap manager for version 588 initialized, notifying init manager NetworkPolicyMap manager for version 588" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.005153240Z level=debug msg="[init manager NetworkPolicyMap manager for version 588 initialized, notifying NetworkPolicyMap manager for version 588" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.005156256Z level=debug msg="[Resuming NPDS subscription" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.016683022Z level=debug msg="[Decreasing pause count on discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 1)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.016827482Z level=debug msg="[Resuming discovery requests for type.googleapis.com/cilium.NetworkPolicy" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.016900117Z level=debug msg="[Sending DiscoveryRequest for type.googleapis.com/cilium.NetworkPolicy: version_info: \"588\" type_url: \"type.googleapis.com/cilium.NetworkPolicy\" response_nonce: \"588\"" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.016973434Z level=debug msg="[[Tags: \"ConnectionId\":\"0\",\"StreamId\":\"4139120692945431400\"] proxying 57 bytes" subsys=envoy-router threadID=2004
2024-01-02T10:54:30.017037123Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] writing 66 bytes, end_stream false" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.017108085Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] sent frame type=0, stream_id=7, length=57" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.017175801Z level=debug msg="[[Tags: \"ConnectionId\":\"0\",\"StreamId\":\"4139120692945431400\"] decode data called: filter=envoy.filters.http.upstream_codec status=0" subsys=envoy-http threadID=2004
2024-01-02T10:54:30.017289413Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.017363972Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.018597072Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write returns: 66" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.018675468Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.018776236Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.018852568Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 3" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.019362509Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.019456454Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read ready. dispatch_buffered_data=0" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.019550670Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read returns: 964" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.019618687Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read error: Resource temporarily unavailable" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.019677076Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatching 964 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.019784997Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=8, flags=0, stream_id=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.019857853Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=8 flags=0 length=4 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.019927242Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=8" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.019991432Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=6, flags=0, stream_id=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020061613Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=6 flags=0 length=8 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020123288Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=6" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020191184Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=0, flags=0, stream_id=7" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020256166Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020324433Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=0 flags=0 length=925 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.020428507Z level=debug msg="[async http request response data (length=925 end_stream=false)" subsys=envoy-http threadID=2004
2024-01-02T10:54:30.020495322Z level=debug msg="[Received gRPC message for type.googleapis.com/cilium.NetworkPolicy at version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020566404Z level=debug msg="[Pausing discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 0)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020628590Z level=debug msg="[NetworkPolicyMap::onConfigUpdate(cilium.policymap.10.244.2.142.2.), 7 resources, version: 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020693782Z level=debug msg="[init manager NetworkPolicyMap manager for version 588 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.020797135Z level=debug msg="[Received Network Policy for endpoint 1249 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020860703Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020921667Z level=debug msg="[Received Network Policy for endpoint 2949 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.020983141Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP wildcard policy" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021041661Z level=debug msg="[Cilium L7 PortNetworkPolicyRules(): No rules, will allow everything." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021102925Z level=debug msg="[Cilium L7 PortNetworkPolicy(): installing TCP policy for port range 53-53" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021159450Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 2 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021234841Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 27751 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021289162Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 9 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021354664Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777419 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021412032Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777420 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021473987Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 10 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021536103Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777421 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021592097Z level=debug msg="[Cilium L7 PortNetworkPolicyRule(): Allowing remote 16777422 by rule: " subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021653852Z level=debug msg="[Cilium L7 PortNetworkPolicy(): Adding rules for [53-53] to [53-53]" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.021706711Z level=debug msg="[Received Network Policy for endpoint 3057 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.022210350Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.022285190Z level=debug msg="[Received Network Policy for endpoint 1155 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024326326Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024400775Z level=debug msg="[Received Network Policy for endpoint 3242 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024472589Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024536879Z level=debug msg="[Received Network Policy for endpoint 477 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024607450Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024674014Z level=debug msg="[Received Network Policy for endpoint 3363 in onConfigUpdate() version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024777067Z level=debug msg="[New policy is equal to old one, not updating." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.024843771Z level=debug msg="[target NetworkPolicyMap manager for version 588 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.024925363Z level=debug msg="[added target NetworkPolicyMap manager for version 589 to init manager NetworkPolicyMap manager for version 589" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.024991977Z level=debug msg="[Pausing NPDS subscription" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.025058091Z level=debug msg="[Pausing discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 1)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.025125266Z level=debug msg="[NetworkPolicyMap manager for version 588 destroyed" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.025181651Z level=debug msg="[init manager NetworkPolicyMap manager for version 589 initializing" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.025249879Z level=debug msg="[init manager NetworkPolicyMap manager for version 589 initializing target NetworkPolicyMap manager for version 589" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.025306895Z level=debug msg="[gRPC config for type.googleapis.com/cilium.NetworkPolicy accepted with 7 resources with version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.025383427Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 589" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.025444702Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::c316" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.025513149Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.240" subsys=envoy-config threadID=2012
2024-01-02T10:54:30.025576457Z level=debug msg="[API type.googleapis.com/cilium.NetworkPolicy paused during queueDiscoveryRequest(), setting pending." subsys=envoy-config threadID=2004
2024-01-02T10:54:30.025634546Z level=debug msg="[Decreasing pause count on discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 2)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.025699587Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatched 964 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.025827806Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to send frame type=6, flags=1" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.025891395Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] send data: bytes=17" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.025947009Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 589" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.025995599Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::c316" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.026048047Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.240" subsys=envoy-config threadID=2013
2024-01-02T10:54:30.026100094Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 589" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.026152272Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::c316" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.026205871Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.240" subsys=envoy-config threadID=2014
2024-01-02T10:54:30.026264831Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] writing 17 bytes, end_stream false" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026320315Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] sent frame type=6, stream_id=0, length=8" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.026368445Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026419519Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026466217Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write returns: 17" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026516641Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026562376Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.026626255Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the worker thread for version 589" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.026696447Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::c316" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.026819826Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.240" subsys=envoy-config threadID=2011
2024-01-02T10:54:30.026883515Z level=debug msg="[Cilium L7 NetworkPolicyMap::onConfigUpdate(): Starting updates on the main thread for version 589" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.026977290Z level=debug msg="[Cilium updating network policy for endpoint fd00:10:244:2::c316" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.027066867Z level=debug msg="[Cilium updating network policy for endpoint 10.244.2.240" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.027151535Z level=debug msg="[target NetworkPolicyMap manager for version 589 initialized, notifying init manager NetworkPolicyMap manager for version 589" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.027236553Z level=debug msg="[init manager NetworkPolicyMap manager for version 589 initialized, notifying NetworkPolicyMap manager for version 589" subsys=envoy-init threadID=2004
2024-01-02T10:54:30.027298980Z level=debug msg="[Resuming NPDS subscription" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.027361577Z level=debug msg="[Decreasing pause count on discovery requests for type.googleapis.com/cilium.NetworkPolicy (previous count 1)" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.027459800Z level=debug msg="[Resuming discovery requests for type.googleapis.com/cilium.NetworkPolicy" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.033766201Z level=error msg="Timed out waiting for datapath updates of FQDN IP information; returning response" subsys=daemon
2024-01-02T10:54:30.033881686Z level=debug msg="Waited for endpoints to regenerate due to a DNS response" duration=109.790463ms endpointID=2949 qname=one.one.one.one. subsys=daemon
2024-01-02T10:54:30.034054889Z level=debug msg="Responding to original DNS query" DNSRequestID=17959 dnsName=one.one.one.one. endpointID=2949 identity=42841 ipAddr="10.244.2.240:41167" subsys=fqdn/dnsproxy
2024-01-02T10:54:30.034251846Z level=debug msg="dnsproxy: Wrote DNS response (119/119 bytes) from 10.244.1.99:53 to 10.244.2.240:41167" subsys=fqdn/dnsproxy
2024-01-02T10:54:30.034350841Z level=debug msg="[Sending DiscoveryRequest for type.googleapis.com/cilium.NetworkPolicy: version_info: \"589\" type_url: \"type.googleapis.com/cilium.NetworkPolicy\" response_nonce: \"589\"" subsys=envoy-config threadID=2004
2024-01-02T10:54:30.034424839Z level=debug msg="[[Tags: \"ConnectionId\":\"0\",\"StreamId\":\"4139120692945431400\"] proxying 57 bytes" subsys=envoy-router threadID=2004
2024-01-02T10:54:30.034487566Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] writing 66 bytes, end_stream false" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.034555683Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] sent frame type=0, stream_id=7, length=57" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.034624932Z level=debug msg="[[Tags: \"ConnectionId\":\"0\",\"StreamId\":\"4139120692945431400\"] decode data called: filter=envoy.filters.http.upstream_codec status=0" subsys=envoy-http threadID=2004
2024-01-02T10:54:30.034700313Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.034805679Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.034859189Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write returns: 66" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.034914182Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.034959145Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035001905Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 3" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035039566Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035082686Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read ready. dispatch_buffered_data=0" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035130184Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read returns: 30" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035174667Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] read error: Resource temporarily unavailable" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035216345Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatching 30 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035259275Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=8, flags=0, stream_id=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035298699Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=8 flags=0 length=4 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035353080Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=8" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035404987Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to recv frame type=6, flags=0, stream_id=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035449119Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] track inbound frame type=6 flags=0 length=8 padding_length=0" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035494143Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] recv frame type=6" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035535781Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] dispatched 30 bytes" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035579682Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] about to send frame type=6, flags=1" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035616832Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] send data: bytes=17" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035658499Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] writing 17 bytes, end_stream false" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035696901Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] sent frame type=6, stream_id=0, length=8" subsys=envoy-http2 threadID=2004
2024-01-02T10:54:30.035795244Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035855337Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035908896Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write returns: 17" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.035972405Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] socket event: 2" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.036040682Z level=debug msg="[[Tags: \"ConnectionId\":\"0\"] write ready" subsys=envoy-connection threadID=2004
2024-01-02T10:54:30.036107958Z level=debug msg="received request from xDS stream" subsys=xds xdsAckedVersion=589 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=589 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.036195791Z level=debug msg="notifying observers of ACKs" subsys=xds xdsAckedVersion=589 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=589 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.036280970Z level=debug msg="completing ACK: &{589 type.googleapis.com/cilium.NetworkPolicy map[]}" subsys=xds xdsAckedVersion=589 xdsClientNode=127.0.0.1 xdsNonce=589 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.036511350Z level=debug msg="starting watch on 0 resources" subsys=xds xdsAckedVersion=589 xdsClientNode="host~127.0.0.1~no-id~localdomain" xdsNonce=589 xdsStreamID=4 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.036608501Z level=debug msg="current resource version is 589, waiting for it to become > 589" subsys=xds xdsAckedVersion=589 xdsClientNode=127.0.0.1 xdsTypeURL=type.googleapis.com/cilium.NetworkPolicy
2024-01-02T10:54:30.036687960Z level=debug msg="Wait time for proxy updates: 49.757673ms" subsys=endpoint-manager
2024-01-02T10:54:30.036821829Z level=debug msg="Upserting IP into ipcache layer" identity="{16777421 generated [] false true}" ipAddr="2606:4700:4700::1111/128" key=0 subsys=ipcache
2024-01-02T10:54:30.036920563Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777421 generated [] false true}" ipAddr="{2606:4700:4700::1111 ffffffffffffffffffffffffffffffff}" modification=Upsert subsys=datapath-ipcache
2024-01-02T10:54:30.037034376Z level=debug msg="Upserting IP into ipcache layer" identity="{16777422 generated [] false true}" ipAddr="2606:4700:4700::1001/128" key=0 subsys=ipcache
2024-01-02T10:54:30.037119504Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777422 generated [] false true}" ipAddr="{2606:4700:4700::1001 ffffffffffffffffffffffffffffffff}" modification=Upsert subsys=datapath-ipcache
2024-01-02T10:54:30.037215393Z level=debug msg="Controller func execution time: 93.926203ms" name=ipcache-inject-labels subsys=controller uuid=7661fcc7-fc9d-4311-a270-747277b6fabd
2024-01-02T10:54:30.037276377Z level=debug msg="Controller run succeeded; waiting for next controller update or stop" name=ipcache-inject-labels subsys=controller uuid=7661fcc7-fc9d-4311-a270-747277b6fabd
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment