Skip to content

kube-apiserver IP adresses disappear from bpf ipcache 10 minutes after restarting cilium-agent #24502

Closed
#24875
Closed
kube-apiserver IP adresses disappear from bpf ipcache 10 minutes after restarting cilium-agent#24502
#24875
Assignees
squeed
Labels
area/agentCilium agent related.kind/bugThis is a bug in the Cilium logic.kind/community-reportThis was reported by a user in the Cilium community, eg via Slack.kind/regressionThis functionality worked fine before, but was broken in a newer release of Cilium.needs/triageThis issue requires triaging to establish severity and next steps.priority/highThis is considered vital to an upcoming release.sig/policyImpacts whether traffic is allowed or denied based on user-defined policies.
@svanschie

Description

@svanschie
svanschie
opened on Mar 21, 2023

Is there an existing issue for this?

  • I have searched the existing issues

What happened?

When I restart the cilium agent, everything works fine for 10 minutes. After that connectivity to kube-apiserver breaks. I expect this happens due to the IP adresses of the API no longer being in the ipcache. The IP addresses seem to be removed from this cache as part of the functionality behind the --identity-restore-grace-period flag, which is set to the default of 10 minutes.

The IP addresses of my API server are:

  • 10.102.3.28
  • 10.102.3.42

After a restart, they both show up twice in the output of cilium identity list:

16777219   cidr:10.102.3.28/32
           reserved:world
16777220   cidr:10.102.3.42/32
           reserved:world
16777222   cidr:10.102.3.42/32
           reserved:kube-apiserver
           reserved:world
16777223   cidr:10.102.3.28/32
           reserved:kube-apiserver
           reserved:world

The corresponding entries in cilium bpf ipcache list:

10.102.3.28/32                  identity=16777223 encryptkey=0 tunnelendpoint=0.0.0.0 nodeid=0
10.102.3.42/32                  identity=16777222 encryptkey=0 tunnelendpoint=0.0.0.0 nodeid=0

After 10 minutes, identities 16777219 and 16777220 are removed:

2023-03-21T12:48:07.411157839Z level=debug msg="UpdateIdentities: Deleting identity" identity=16777219 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.0/27 cidr:10.102.3.16/28 cidr:10.102.3.24/29 cidr:10.102.3.28/30 cidr:10.102.3.28/31 cidr:10.102.3.28/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy
2023-03-21T12:48:07.411168359Z level=debug msg="UpdateIdentities: Deleting identity" identity=16777220 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.32/27 cidr:10.102.3.32/28 cidr:10.102.3.40/29 cidr:10.102.3.40/30 cidr:10.102.3.42/31 cidr:10.102.3.42/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy

And entries from ipcache for the API server IP addresses are also removed:

2023-03-21T12:48:07.411224640Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.28/32 subsys=ipcache
2023-03-21T12:48:07.411231711Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777223 generated false}" ipAddr="{10.102.3.28 ffffffff}" modification=Delete subsys=datapath-ipcache
2023-03-21T12:48:07.411240471Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.42/32 subsys=ipcache
2023-03-21T12:48:07.411242771Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777222 generated false}" ipAddr="{10.102.3.42 ffffffff}" modification=Delete subsys=datapath-ipcache

No new entries are added to the ipcache for the API server IP addresses.

When allowing outbound traffic to port 443 anywhere it works fine, but with a policy that allows traffic to the cluster (or kube-apiserver specifically) entities the traffic is dropped:

apiVersion: cilium.io/v2
kind: CiliumClusterwideNetworkPolicy
metadata:
  name: default-allow-cluster-only
spec:
  endpointSelector: {}
  egress:
    - toEntities:
        - cluster

Example of a dropped request:

{
  "flow": {
    "time": "2023-03-21T12:58:09.767376425Z",
    "verdict": "DROPPED",
    "drop_reason": 133,
    "ethernet": {
      "source": "4a:7c:ea:1f:d8:40",
      "destination": "c2:ef:b0:d0:23:9a"
    },
    "IP": {
      "source": "10.102.4.59",
      "destination": "10.102.3.28",
      "ipVersion": "IPv4"
    },
    "l4": {
      "TCP": {
        "source_port": 59884,
        "destination_port": 443,
        "flags": {
          "SYN": true
        }
      }
    },
    "source": {
      "ID": 156,
      "identity": 55508,
      "namespace": "external-dns",
      "labels": [
        "k8s:app.kubernetes.io/instance=external-dns",
        "k8s:app.kubernetes.io/name=external-dns",
        "k8s:io.cilium.k8s.namespace.labels.kubernetes.io/metadata.name=external-dns",
        "k8s:io.cilium.k8s.policy.cluster=default",
        "k8s:io.cilium.k8s.policy.serviceaccount=external-dns",
        "k8s:io.kubernetes.pod.namespace=external-dns"
      ],
      "pod_name": "external-dns-659779cd66-jt4ck",
      "workloads": [
        {
          "name": "external-dns",
          "kind": "Deployment"
        }
      ]
    },
    "destination": {
      "identity": 2,
      "labels": [
        "reserved:world"
      ]
    },
    "Type": "L3_L4",
    "node_name": "ip-10-102-5-6.eu-west-1.compute.internal",
    "event_type": {
      "type": 1,
      "sub_type": 133
    },
    "traffic_direction": "EGRESS",
    "drop_reason_desc": "POLICY_DENIED",
    "Summary": "TCP Flags: SYN"
  },
  "node_name": "ip-10-102-5-6.eu-west-1.compute.internal",
  "time": "2023-03-21T12:58:09.767376425Z"
}

Cilium Version

1.13.1

Kernel Version

5.15.79

Kubernetes Version

v1.24.8-eks-ffeb93d

Sysdump

No response

Relevant log output

2023-03-21T12:38:01.379721686Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.28/32,reserved:world" subsys=identity-cache
2023-03-21T12:38:01.379730526Z level=debug msg="Reallocated restored CIDR identity: 16777219" subsys=identity-cache
2023-03-21T12:38:01.379806618Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.42/32,reserved:world" subsys=identity-cache
2023-03-21T12:38:01.379815458Z level=debug msg="Reallocated restored CIDR identity: 16777220" subsys=identity-cache
2023-03-21T12:38:01.381765715Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777219 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.0/27 cidr:10.102.3.16/28 cidr:10.102.3.24/29 cidr:10.102.3.28/30 cidr:10.102.3.28/31 cidr:10.102.3.28/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy
2023-03-21T12:38:01.382198643Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777220 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.32/27 cidr:10.102.3.32/28 cidr:10.102.3.40/29 cidr:10.102.3.40/30 cidr:10.102.3.42/31 cidr:10.102.3.42/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy
2023-03-21T12:38:01.388316588Z level=debug msg="Upserting IP into ipcache layer" identity="{16777220 generated false}" ipAddr=10.102.3.42/32 key=0 subsys=ipcache
2023-03-21T12:38:01.388350159Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777220 generated false}" ipAddr="{10.102.3.42 ffffffff}" modification=Upsert subsys=datapath-ipcache
2023-03-21T12:38:01.388976990Z level=debug msg="Upserting IP into ipcache layer" identity="{16777219 generated false}" ipAddr=10.102.3.28/32 key=0 subsys=ipcache
2023-03-21T12:38:01.388994991Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777219 generated false}" ipAddr="{10.102.3.28 ffffffff}" modification=Upsert subsys=datapath-ipcache
2023-03-21T12:38:01.389687974Z level=debug msg="Restoring backend" backendID=3 backendPreferred=false backendState=0 l3n4Addr="10.102.3.28:443" subsys=service
2023-03-21T12:38:01.389712834Z level=debug msg="Restoring backend" backendID=4 backendPreferred=false backendState=0 l3n4Addr="10.102.3.42:443" subsys=service
2023-03-21T12:38:02.522004786Z level=debug msg="Kubernetes service definition changed" action=service-updated endpoints="10.102.3.28:443/TCP,10.102.3.42:443/TCP" k8sNamespace=default k8sSvcName=kubernetes old-service=nil service="frontends:[172.16.0.1]/ports=[https]/selector=map[]" subsys=k8s-watcher
2023-03-21T12:38:02.522043487Z level=debug msg="Upserting service" backends="[10.102.3.28:443 10.102.3.42:443]" l7LBFrontendPorts="[]" l7LBProxyPort=0 loadBalancerSourceRanges="[]" serviceIP="{172.16.0.1 {TCP 443} 0}" serviceName=kubernetes serviceNamespace=default sessionAffinity=false sessionAffinityTimeout=0 subsys=service svcExtTrafficPolicy=Cluster svcHealthCheckNodePort=0 svcIntTrafficPolicy=Cluster svcType=ClusterIP
2023-03-21T12:38:02.522087977Z level=debug msg="Acquired service ID" backends="[10.102.3.28:443 10.102.3.42:443]" l7LBFrontendPorts="[]" l7LBProxyPort=0 loadBalancerSourceRanges="[]" serviceID=4 serviceIP="{172.16.0.1 {TCP 443} 0}" serviceName=kubernetes serviceNamespace=default sessionAffinity=false sessionAffinityTimeout=0 subsys=service svcExtTrafficPolicy=Cluster svcHealthCheckNodePort=0 svcIntTrafficPolicy=Cluster svcType=ClusterIP
2023-03-21T12:38:02.537470738Z level=info msg="Policy Add Request" ciliumNetworkPolicy="[&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[] IngressDeny:[] Egress:[{EgressCommonRule:{ToEndpoints:[] ToRequires:[] ToCIDR:[169.254.169.254/32] ToCIDRSet:[] ToEntities:[] ToServices:[] ToGroups:[] aggregatedSelectors:[{LabelSelector:0xc00051b7e0 requirements:0xc0016edea8 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{cidr.169.254.169.254/32: ,},MatchExpressions:[]LabelSelectorRequirement{},}}]} ToPorts:[{Ports:[{Port:80 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ToFQDNs:[] ICMPs:[] Auth:<nil>}] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Egress to metadata server},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[] IngressDeny:[] Egress:[{EgressCommonRule:{ToEndpoints:[{\"matchLabels\":{\"k8s:io.kubernetes.pod.namespace\":\"kube-system\",\"k8s:k8s-app\":\"kube-dns\"}}] ToRequires:[] ToCIDR: ToCIDRSet:[] ToEntities:[] ToServices:[] ToGroups:[] aggregatedSelectors:[]} ToPorts:[{Ports:[{Port:53 Protocol:ANY}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:0xc0001e53b0}] ToFQDNs:[] ICMPs:[] Auth:<nil>}] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Egress to DNS},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[] IngressDeny:[] Egress:[{EgressCommonRule:{ToEndpoints:[] ToRequires:[] ToCIDR: ToCIDRSet:[] ToEntities:[] ToServices:[] ToGroups:[] aggregatedSelectors:[{LabelSelector:0xc00051b9e0 requirements:0xc00050cdb0 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{reserved.none: ,},MatchExpressions:[]LabelSelectorRequirement{},}}]} ToPorts:[{Ports:[{Port:443 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ToFQDNs:[{MatchName:app.datadoghq.eu MatchPattern:} {MatchName: MatchPattern:*-app.agent.datadoghq.eu} {MatchName:orchestrator.datadoghq.eu MatchPattern:}] ICMPs:[] Auth:<nil>}] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Egress to Datadog intake},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[] IngressDeny:[] Egress:[{EgressCommonRule:{ToEndpoints:[] ToRequires:[] ToCIDR: ToCIDRSet:[10.102.3.42/32 10.102.3.28/32] ToEntities:[] ToServices:[{K8sServiceSelector:<nil> K8sService:0xc00051aee0}] ToGroups:[] aggregatedSelectors:[{LabelSelector:0xc00051b8a0 requirements:0xc0016edf08 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{cidr.10.102.3.42/32: ,},MatchExpressions:[]LabelSelectorRequirement{},}} {LabelSelector:0xc00051b900 requirements:0xc0016edf68 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{cidr.10.102.3.28/32: ,},MatchExpressions:[]LabelSelectorRequirement{},}}]} ToPorts:[] ToFQDNs:[] ICMPs:[] Auth:<nil>} {EgressCommonRule:{ToEndpoints:[] ToRequires:[] ToCIDR: ToCIDRSet:[] ToEntities:[host remote-node] ToServices:[] ToGroups:[] aggregatedSelectors:[{LabelSelector:0xc00051b940 requirements:0xc00050cbd0 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{reserved.host: ,},MatchExpressions:[]LabelSelectorRequirement{},}} {LabelSelector:0xc00051b9a0 requirements:0xc00050ccf0 cachedLabelSelectorString:&LabelSelector{MatchLabels:map[string]string{reserved.remote-node: ,},MatchExpressions:[]LabelSelectorRequirement{},}}]} ToPorts:[{Ports:[{Port:443 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ToFQDNs:[] ICMPs:[] Auth:<nil>}] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Egress to Kube API server},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[{IngressCommonRule:{FromEndpoints:[{\"matchLabels\":{\"any:app\":\"datadog\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}}] FromRequires:[] FromCIDR: FromCIDRSet:[] FromEntities:[] aggregatedSelectors:[]} ToPorts:[{Ports:[{Port:5005 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ICMPs:[] Auth:<nil>}] IngressDeny:[] Egress:[] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Ingress from cluster agent},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[] IngressDeny:[] Egress:[{EgressCommonRule:{ToEndpoints:[{\"matchLabels\":{\"any:app\":\"datadog\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}}] ToRequires:[] ToCIDR: ToCIDRSet:[] ToEntities:[] ToServices:[] ToGroups:[] aggregatedSelectors:[]} ToPorts:[{Ports:[{Port:5005 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ToFQDNs:[] ICMPs:[] Auth:<nil>}] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Egress to cluster agent},\n&{EndpointSelector:{\"matchLabels\":{\"any:app\":\"datadog-cluster-agent\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}} NodeSelector:{} Ingress:[{IngressCommonRule:{FromEndpoints:[{\"matchLabels\":{\"any:app\":\"datadog\",\"k8s:io.kubernetes.pod.namespace\":\"datadog\"}}] FromRequires:[] FromCIDR: FromCIDRSet:[] FromEntities:[] aggregatedSelectors:[]} ToPorts:[{Ports:[{Port:5000 Protocol:TCP} {Port:5005 Protocol:TCP}] TerminatingTLS:<nil> OriginatingTLS:<nil> ServerNames:[] Listener:<nil> Rules:<nil>}] ICMPs:[] Auth:<nil>}] IngressDeny:[] Egress:[] EgressDeny:[] Labels:[k8s:io.cilium.k8s.policy.derived-from=CiliumNetworkPolicy k8s:io.cilium.k8s.policy.name=datadog-cluster-agent k8s:io.cilium.k8s.policy.namespace=datadog k8s:io.cilium.k8s.policy.uid=8c470cd3-6f44-493f-9e7b-0587a55a859d] Description:Ingress from agent}]" policyAddRequest=7740f4e2-df0f-4753-ab7a-2fd6ba8613fd subsys=daemon
2023-03-21T12:38:02.537482319Z level=debug msg="Policy imported via API, found CIDR prefixes..." policyAddRequest=7740f4e2-df0f-4753-ab7a-2fd6ba8613fd prefixes="[169.254.169.254/32 10.102.3.42/32 10.102.3.28/32]" subsys=daemon
2023-03-21T12:38:02.537488979Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.42/32,reserved:kube-apiserver,reserved:world" subsys=identity-cache
2023-03-21T12:38:02.537491849Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.28/32,reserved:kube-apiserver,reserved:world" subsys=identity-cache
2023-03-21T12:38:02.537501589Z level=debug msg="Upserting IP into ipcache layer" identity="{16777222 generated false}" ipAddr=10.102.3.42/32 key=0 subsys=ipcache
2023-03-21T12:38:02.537505019Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777222 generated false}" ipAddr="{10.102.3.42 ffffffff}" modification=Upsert subsys=datapath-ipcache
2023-03-21T12:38:02.537511709Z level=debug msg="Upserting IP into ipcache layer" identity="{16777223 generated false}" ipAddr=10.102.3.28/32 key=0 subsys=ipcache
2023-03-21T12:38:02.537513599Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777223 generated false}" ipAddr="{10.102.3.28 ffffffff}" modification=Upsert subsys=datapath-ipcache
2023-03-21T12:38:02.537518019Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777222 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.32/27 cidr:10.102.3.32/28 cidr:10.102.3.40/29 cidr:10.102.3.40/30 cidr:10.102.3.42/31 cidr:10.102.3.42/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:kube-apiserver reserved:world]" subsys=policy
2023-03-21T12:38:02.537519549Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777223 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.0/27 cidr:10.102.3.16/28 cidr:10.102.3.24/29 cidr:10.102.3.28/30 cidr:10.102.3.28/31 cidr:10.102.3.28/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:kube-apiserver reserved:world]" subsys=policy
2023-03-21T12:38:03.283568317Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:03.293190788Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:03.315919687Z level=debug msg="Injecting CIDR labels for prefix" cidr=10.102.3.28/32 labels="reserved:kube-apiserver" subsys=ipcache
2023-03-21T12:38:03.316049329Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.28/32,reserved:kube-apiserver,reserved:world" subsys=identity-cache
2023-03-21T12:38:03.316098860Z level=debug msg="Injecting CIDR labels for prefix" cidr=10.102.3.42/32 labels="reserved:kube-apiserver" subsys=ipcache
2023-03-21T12:38:03.316174742Z level=debug msg="Resolving identity" identityLabels="cidr:10.102.3.42/32,reserved:kube-apiserver,reserved:world" subsys=identity-cache
2023-03-21T12:38:04.206800560Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:04.208662435Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.299388052Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.299391722Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.299399042Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.299402912Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.304862465Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.304876056Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.341891184Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:05.341915855Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.284295199Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.298362225Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.356223898Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.371419664Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.421476170Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.422089272Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.431103502Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.434927684Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.451099640Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.558145501Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.614780770Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.635244646Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.708572662Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.780494170Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.887803976Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:38:06.914983419Z level=debug msg="stale identity observed" identity=16777219 ipAddr=10.102.3.28 oldIdentity=16777223 subsys=hubble
2023-03-21T12:38:06.960803665Z level=debug msg="ToMapState: Allowed remote IDs" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{reserved.kube-apiserver: ,},MatchExpressions:[]LabelSelectorRequirement{},}" policyID="[kube-apiserver 16777222 16777223]" port=0 portName= protocol=0 subsys=policy trafficDirection=Egress
2023-03-21T12:48:07.411157839Z level=debug msg="UpdateIdentities: Deleting identity" identity=16777219 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.0/27 cidr:10.102.3.16/28 cidr:10.102.3.24/29 cidr:10.102.3.28/30 cidr:10.102.3.28/31 cidr:10.102.3.28/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy
2023-03-21T12:48:07.411168359Z level=debug msg="UpdateIdentities: Deleting identity" identity=16777220 labels="[cidr:0.0.0.0/0 cidr:0.0.0.0/1 cidr:0.0.0.0/2 cidr:0.0.0.0/3 cidr:0.0.0.0/4 cidr:10.0.0.0/7 cidr:10.0.0.0/8 cidr:10.0.0.0/9 cidr:10.100.0.0/14 cidr:10.102.0.0/15 cidr:10.102.0.0/16 cidr:10.102.0.0/17 cidr:10.102.0.0/18 cidr:10.102.0.0/19 cidr:10.102.0.0/20 cidr:10.102.0.0/21 cidr:10.102.0.0/22 cidr:10.102.2.0/23 cidr:10.102.3.0/24 cidr:10.102.3.0/25 cidr:10.102.3.0/26 cidr:10.102.3.32/27 cidr:10.102.3.32/28 cidr:10.102.3.40/29 cidr:10.102.3.40/30 cidr:10.102.3.42/31 cidr:10.102.3.42/32 cidr:10.64.0.0/10 cidr:10.96.0.0/11 cidr:10.96.0.0/12 cidr:10.96.0.0/13 cidr:8.0.0.0/5 cidr:8.0.0.0/6 reserved:world]" subsys=policy
2023-03-21T12:48:07.411172319Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[]" policyID.Deleted="[16777219 16777220]" subsys=policy
2023-03-21T12:48:07.411175119Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[]" policyID.Deleted="[16777219 16777220]" subsys=policy
2023-03-21T12:48:07.411177510Z level=debug msg="identities selected by L4Filter updated" EndpointSelector="&LabelSelector{MatchLabels:map[string]string{},MatchExpressions:[]LabelSelectorRequirement{},}" policyID.Added="[]" policyID.Deleted="[16777219 16777220]" subsys=policy
2023-03-21T12:48:07.411224640Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.28/32 subsys=ipcache
2023-03-21T12:48:07.411231711Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777223 generated false}" ipAddr="{10.102.3.28 ffffffff}" modification=Delete subsys=datapath-ipcache
2023-03-21T12:48:07.411240471Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.42/32 subsys=ipcache
2023-03-21T12:48:07.411242771Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777222 generated false}" ipAddr="{10.102.3.42 ffffffff}" modification=Delete subsys=datapath-ipcache

Anything else?

When it's in a "broken" state and I restart cilium agent, it will work again. After this restart it will also keep working after the 10 minutes. If cilium agent is restarted again after that, it will break after 10 minutes again.

I was unable to reproduce the issue with Cilium v1.12.7. I compared the debug logging between v1.12.7 and v.13.1 for what happened after 10 minutes. The primary differences are as follows:

v1.12.7:

2023-03-21T12:30:05.711083450Z level=debug msg="Deleting CIDR shadowed by endpoint IP" ipAddr=10.102.3.28/32 subsys=ipcache
2023-03-21T12:30:05.711091211Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.28/32 subsys=ipcache
2023-03-21T12:30:05.711129211Z level=debug msg="Deleting CIDR shadowed by endpoint IP" ipAddr=10.102.3.42/32 subsys=ipcache
2023-03-21T12:30:05.711188562Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.42/32 subsys=ipcache

v1.13.1:

2023-03-21T12:48:07.411224640Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.28/32 subsys=ipcache
2023-03-21T12:48:07.411231711Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777223 generated false}" ipAddr="{10.102.3.28 ffffffff}" modification=Delete subsys=datapath-ipcache
2023-03-21T12:48:07.411240471Z level=debug msg="Deleting IP from ipcache layer" ipAddr=10.102.3.42/32 subsys=ipcache
2023-03-21T12:48:07.411242771Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777222 generated false}" ipAddr="{10.102.3.42 ffffffff}" modification=Delete subsys=datapath-ipcache

Code of Conduct

  • I agree to follow this project's Code of Conduct

Metadata

Metadata

Assignees

Labels

area/agentCilium agent related.kind/bugThis is a bug in the Cilium logic.kind/community-reportThis was reported by a user in the Cilium community, eg via Slack.kind/regressionThis functionality worked fine before, but was broken in a newer release of Cilium.needs/triageThis issue requires triaging to establish severity and next steps.priority/highThis is considered vital to an upcoming release.sig/policyImpacts whether traffic is allowed or denied based on user-defined policies.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions