Cilium-Agent bootstrap time varies significantly on empty cluster

[marseel]

I've been playing with spinning up 400 node cluster with Cilium on the main branch.
I've noticed quite a significant variance of bootstrap time - based on bootstrap "overall" metric.
With a bit of more logging added, I was able to pin point it to "Creating host endpoint":

cilium/daemon/cmd/daemon_main.go

Line 1877 in b1317f3

err := d.endpointManager.AddHostEndpoint(

In a "good" bootstrap latency, it doesn't block and exits instantly.
In a "worse" bootstrap latency case, it can take up to 15s.
Both nodes are totally fresh nodes joining cluster.

"good" bootstrap logs:

time="2024-09-20T14:19:09.850855533Z" level=info msg="Creating host endpoint" subsys=daemon
time="2024-09-20T14:19:09.852644572Z" level=info msg="New endpoint" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=1 ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:09.85350633Z" level=info msg="Resolving identity labels (blocking)" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=1 identityLabels="k8s:node.kubernetes.io/instance-type=e2-medium,k8s:topology.gke.io/zone=us-west1-a,k8s:topology.kubernetes.io/region=us-west1,k8s:topology.kubernetes.io/zone=us-west1-a,reserved:host" ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:09.854139025Z" level=info msg="Identity of endpoint changed" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=1 identity=1 identityLabels="k8s:node.kubernetes.io/instance-type=e2-medium,k8s:topology.gke.io/zone=us-west1-a,k8s:topology.kubernetes.io/region=us-west1,k8s:topology.kubernetes.io/zone=us-west1-a,reserved:host" ipv4= ipv6= k8sPodName=/ oldIdentity="no identity" subsys=endpoint
time="2024-09-20T14:19:09.854538725Z" level=info msg="Exited Creating host endpoint" subsys=daemon

"bad" bootstrap logs:

time="2024-09-20T14:19:06.32758278Z" level=info msg="Creating host endpoint" subsys=daemon
time="2024-09-20T14:19:06.328056064Z" level=info msg="New endpoint" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=422 ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:06.328406025Z" level=info msg="Resolving identity labels (blocking)" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=422 identityLabels="k8s:node.kubernetes.io/instance-type=e2-medium,k8s:topology.gke.io/zone=us-west1-a,k8s:topology.kubernetes.io/region=us-west1,k8s:topology.kubernetes.io/zone=us-west1-a,reserved:host" ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:06.32854293Z" level=info msg="Identity of endpoint changed" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=0 endpointID=422 identity=1 identityLabels="k8s:node.kubernetes.io/instance-type=e2-medium,k8s:topology.gke.io/zone=us-west1-a,k8s:topology.kubernetes.io/region=us-west1,k8s:topology.kubernetes.io/zone=us-west1-a,reserved:host" ipv4= ipv6= k8sPodName=/ oldIdentity="no identity" subsys=endpoint
time="2024-09-20T14:19:06.329062633Z" level=info msg="Finished regenerating restored endpoints" regenerated=0 subsys=daemon total=0
time=2024-09-20T14:19:06Z level=info msg="Start hook executed" function="datapath.initDatapath.func1 (pkg/datapath/cells.go:183) (agent.datapath)" duration=269.676805ms
time="2024-09-20T14:19:06.332084473Z" level=info msg="Kernel config file not found: if the agent fails to start, check the system requirements at https://docs.cilium.io/en/stable/operations/system_requirements" subsys=probes
time=2024-09-20T14:19:06Z level=info msg=Started duration=8.812676001s
time="2024-09-20T14:19:06.335209791Z" level=info msg="Deleted orphan backends" orphanBackends=0 subsys=service
time="2024-09-20T14:19:06.381445195Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-l3vj spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.389705481Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-mj0k spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.573808689Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-b55h spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.57440312Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-rgzb spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.576726435Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-81cq spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.589857339Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-m7r0 spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.830825362Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-lb0q spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.83217526Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-h9jq spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.833458752Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-f4z4 spi=0 subsys=nodemanager
time="2024-09-20T14:19:06.846097133Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-l3vj spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.014960102Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_connect for program cil_sock6_connect" subsys=socketlb
time="2024-09-20T14:19:07.015217143Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_sendmsg for program cil_sock6_sendmsg" subsys=socketlb
time="2024-09-20T14:19:07.01542215Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_recvmsg for program cil_sock6_recvmsg" subsys=socketlb
time="2024-09-20T14:19:07.015557226Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_getpeername for program cil_sock6_getpeername" subsys=socketlb
time="2024-09-20T14:19:07.015685461Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_connect for program cil_sock4_connect" subsys=socketlb
time="2024-09-20T14:19:07.015824077Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_sendmsg for program cil_sock4_sendmsg" subsys=socketlb
time="2024-09-20T14:19:07.015946028Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_recvmsg for program cil_sock4_recvmsg" subsys=socketlb
time="2024-09-20T14:19:07.016085432Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_post_bind for program cil_sock6_post_bind" subsys=socketlb
time="2024-09-20T14:19:07.016234444Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_getpeername for program cil_sock4_getpeername" subsys=socketlb
time="2024-09-20T14:19:07.016350076Z" level=info msg="No existing link found at /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_post_bind for program cil_sock4_post_bind" subsys=socketlb
time="2024-09-20T14:19:07.02210362Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-qzqv spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.046527819Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-m7r0 spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.080088967Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cj3m spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.193214145Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-ql8b spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.194264326Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-5n4x spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.3400804Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-h9jq spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.380391805Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-fg4b spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.48653844Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cj3m spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.494380178Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-m7n8 spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.580981807Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-1t1x spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.63309521Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-tmrc spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.699243788Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cck6 spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.78009809Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-fg4b spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.782738647Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-bnvd spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.861341303Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-hfg8 spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.942270259Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-1c2n spi=0 subsys=nodemanager
time="2024-09-20T14:19:07.967426411Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-m7n8 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.002492154Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-tmrc spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.017726903Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-sbl3 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.028715994Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-1t1x spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.065547061Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-mhx0 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.111735843Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-n556 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.146702226Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-7pr7 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.147799165Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cck6 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.148198687Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-bnvd spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.190915633Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-jq8k spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.208391127Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-hfg8 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.24275886Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-65rd spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.274289475Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-tpxs spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.298358347Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-1c2n spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.309023024Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-zhg1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.449984834Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-sbl3 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.459604292Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-mhx0 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.482544061Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-x2nh spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.523075616Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-7pr7 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.621029755Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-tpxs spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.642461168Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-65rd spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.718483636Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-zhg1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.757340938Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-n7s1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:08.991273753Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-90xp spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.280126038Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-qzqv spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.314570014Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-n7s1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.357693886Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-3rzn spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.425718275Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-59kz spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.503736775Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-jq8k spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.664356074Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-qzqv spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.702539496Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-m7n8 spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.72272843Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-n7s1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.747550508Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-3rzn spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.884758856Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-59kz spi=0 subsys=nodemanager
time="2024-09-20T14:19:09.980256205Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-lgl1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:10.187826424Z" level=info msg="Program cil_from_overlay attached to device cilium_vxlan using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:10.188084004Z" level=info msg="Program cil_to_overlay attached to device cilium_vxlan using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:10.294478959Z" level=info msg="regenerating all endpoints" reason="Configuration or devices changed" subsys=endpoint-manager
time="2024-09-20T14:19:10.906010759Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-fkf2 spi=0 subsys=nodemanager
time="2024-09-20T14:19:11.976953308Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-70w7 spi=0 subsys=nodemanager
time="2024-09-20T14:19:12.876722765Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-rp03 spi=0 subsys=nodemanager
time="2024-09-20T14:19:12.929443904Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-b5pc spi=0 subsys=nodemanager
time="2024-09-20T14:19:13.540527356Z" level=info msg="Compiled new BPF template" BPFCompilationTime=3.243172505s file-path=/var/run/cilium/state/templates/0a76e1d08e4117196272b05b14c75598adf2872ec2e8399545b61ec7a0b5db8d/bpf_host.o subsys=datapath-loader
time="2024-09-20T14:19:13.609109218Z" level=info msg="Program cil_to_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.609354731Z" level=info msg="Program cil_from_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.67230992Z" level=info msg="Program cil_to_host attached to device cilium_net using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.760669522Z" level=info msg="Program cil_from_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.760924878Z" level=info msg="Program cil_to_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.761321814Z" level=info msg="Reloaded endpoint BPF program" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=0 desiredPolicyRevision=1 endpointID=422 identity=1 ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:13.766011863Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-tkjx spi=0 subsys=nodemanager
time="2024-09-20T14:19:13.807569277Z" level=info msg="Program cil_to_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.807794508Z" level=info msg="Program cil_from_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.848915836Z" level=info msg="Program cil_to_host attached to device cilium_net using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.87823959Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-l3vj spi=0 subsys=nodemanager
time="2024-09-20T14:19:13.948470038Z" level=info msg="Program cil_from_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.948682139Z" level=info msg="Program cil_to_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:13.949215189Z" level=info msg="Reloaded endpoint BPF program" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=1 desiredPolicyRevision=1 endpointID=422 identity=1 ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:14.331332687Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-lkg1 spi=0 subsys=nodemanager
time="2024-09-20T14:19:14.655429561Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_sendmsg for program cil_sock4_sendmsg" subsys=socketlb
time="2024-09-20T14:19:14.655489673Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_recvmsg for program cil_sock4_recvmsg" subsys=socketlb
time="2024-09-20T14:19:14.655623207Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_getpeername for program cil_sock4_getpeername" subsys=socketlb
time="2024-09-20T14:19:14.655731084Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_connect for program cil_sock6_connect" subsys=socketlb
time="2024-09-20T14:19:14.655845925Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_getpeername for program cil_sock6_getpeername" subsys=socketlb
time="2024-09-20T14:19:14.655930374Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_post_bind for program cil_sock6_post_bind" subsys=socketlb
time="2024-09-20T14:19:14.656072876Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_connect for program cil_sock4_connect" subsys=socketlb
time="2024-09-20T14:19:14.656140255Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock4_post_bind for program cil_sock4_post_bind" subsys=socketlb
time="2024-09-20T14:19:14.656224855Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_sendmsg for program cil_sock6_sendmsg" subsys=socketlb
time="2024-09-20T14:19:14.656274634Z" level=info msg="Updated link /sys/fs/bpf/cilium/socketlb/links/cgroup/cil_sock6_recvmsg for program cil_sock6_recvmsg" subsys=socketlb
time="2024-09-20T14:19:14.747161488Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-qjtc spi=0 subsys=nodemanager
time="2024-09-20T14:19:14.97833227Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-bnvd spi=0 subsys=nodemanager
time="2024-09-20T14:19:15.654360878Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-wrb7 spi=0 subsys=nodemanager
time="2024-09-20T14:19:15.68298843Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-q8zv spi=0 subsys=nodemanager
time="2024-09-20T14:19:16.380472077Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-mj0k spi=0 subsys=nodemanager
time="2024-09-20T14:19:16.607248261Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cvg9 spi=0 subsys=nodemanager
time="2024-09-20T14:19:17.079087224Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-xngj spi=0 subsys=nodemanager
time="2024-09-20T14:19:17.547944196Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-8lk3 spi=0 subsys=nodemanager
time="2024-09-20T14:19:17.760951426Z" level=info msg="Program cil_from_overlay attached to device cilium_vxlan using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:17.761167233Z" level=info msg="Program cil_to_overlay attached to device cilium_vxlan using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:17.764466771Z" level=info msg="regenerating all endpoints" reason="Configuration or devices changed" subsys=endpoint-manager
time="2024-09-20T14:19:18.480600681Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-cl9j spi=0 subsys=nodemanager
time="2024-09-20T14:19:18.523552726Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-v9wm spi=0 subsys=nodemanager
time="2024-09-20T14:19:19.327733759Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-j4fn spi=0 subsys=nodemanager
time="2024-09-20T14:19:19.558019303Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-8xfw spi=0 subsys=nodemanager
time="2024-09-20T14:19:20.58772248Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-8kg2 spi=0 subsys=nodemanager
time="2024-09-20T14:19:21.01921114Z" level=info msg="Compiled new BPF template" BPFCompilationTime=3.253157964s file-path=/var/run/cilium/state/templates/d8c631d52d9bf7c06d08b254f09160a722787e7a6fbde8f08a20c706de95eda4/bpf_host.o subsys=datapath-loader
time="2024-09-20T14:19:21.032954218Z" level=info msg="Node updated" clusterName=10960602554-1 nodeName=workloads2-1777 spi=0 subsys=nodemanager
time="2024-09-20T14:19:21.071516121Z" level=info msg="Program cil_to_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:21.071663712Z" level=info msg="Program cil_from_host attached to device cilium_host using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:21.115318418Z" level=info msg="Program cil_to_host attached to device cilium_net using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:21.210100422Z" level=info msg="Program cil_from_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:21.210468649Z" level=info msg="Program cil_to_netdev attached to device ens4 using legacy tc" subsys=datapath-loader
time="2024-09-20T14:19:21.210940089Z" level=info msg="Reloaded endpoint BPF program" ciliumEndpointName=/ containerID= containerInterface= datapathPolicyRevision=1 desiredPolicyRevision=1 endpointID=422 identity=1 ipv4= ipv6= k8sPodName=/ subsys=endpoint
time="2024-09-20T14:19:21.211747565Z" level=info msg="Exited Creating host endpoint" subsys=daemon

This makes me think that there must be some kind of interplay with how we initialize a daemon and sometimes AddHostEndpoint seems to be blocking.

I will keep investigating this further, but maybe there is already some "known" problem. Any advice appreciated ❤️

[marseel]

I've talked offline a little bit with @joestringer
and it seems like we are compiling/attaching host programs after we report bootstrap finished in a "fast" bootstrap case.
They are also compiled and attached after we start serving cilium API.
I've checked all the way back to v1.13 and it seems it was always like that 🤔
Example logs from v1.13 running on the kind cluster:

2024-09-24T09:42:07.298435402Z time="2024-09-24T09:42:07Z" level=info msg="Initializing Cilium API" subsys=daemon
2024-09-24T09:42:07.304603026Z time="2024-09-24T09:42:07Z" level=info msg="Daemon initialization completed" bootstrapTime=2.033771362s subsys=daemon
2024-09-24T09:42:07.306139095Z time="2024-09-24T09:42:07Z" level=info msg="Serving cilium API at unix:///var/run/cilium/cilium.sock" subsys=daemon
2024-09-24T09:42:07.645577340Z time="2024-09-24T09:42:07Z" level=debug msg="Successfully attached program to interface" device=cilium_host direction=ingress ifindex=3 objPath=3949_next/bpf_host.o progName=cil_to_host subsys=datapath-loader
2024-09-24T09:42:07.645587626Z time="2024-09-24T09:42:07Z" level=debug msg="Successfully attached program to interface" device=cilium_host direction=egress ifindex=3 objPath=3949_next/bpf_host.o progName=cil_from_host subsys=datapath-loader
2024-09-24T09:42:07.647723769Z time="2024-09-24T09:42:07Z" level=debug msg="Successfully attached program to interface" device=cilium_net direction=ingress ifindex=2 objPath=3949_next/bpf_host_cilium_net.o progName=cil_to_host subsys=datapath-loader

This shows that we start serving Cilium API after bootstrap claims to be completed, but before host eBPF programs are attached.