Add time wrapper to test agent delays in CI

[joestringer]

Cilium's internal business logic relies on a highly parallel combination of reactive handlers for incoming information, "triggers" that ratelimit requests for processing to ensure Cilium does not over-consume resources, and "controllers" that periodically perform updates or resiliency checks of configured state. While in general most things are "eventually consistent", the presence of time-based triggers and controllers can introduce challenges when evaluating how Cilium will perform once the "eventual consistency" is resolved.

Taking an example of a situation where this eventual consistency caused issues that were not identified during pre-release testing, consider the issue fixed by #27327 . Cilium v1.14.0 was released with a bug where Cilium appeared to work correctly for the first several minutes following startup, then afterwards introduced connectivity disruption to specific peers. This was traced down to a logic delay tied to a 10 minute timer following startup which caused some state to be recomputed & configured in the system, ultimately causing the packet loss.

While better unit testing for the individual package could have caught this issue earlier, the issue was also triggered by the integration between the specific package and other logic in other packages. It is quite difficult to systematically identify time-based errors across the entire agent by relying purely on such testing in each package. This PR attempts to provide a more systematic safety net for timer-based issues by providing a hidden flag to override all timers within Cilium and ensuring that Cilium's CI runs with these timers set to a minimal value.

One of the interesting challenges with this PR is that it can be tempting for developers to rely on time-based tricks in order to ensure the execution order of specific pieces of logic. However, when the system is highly loaded, such mechanisms can become unreliable as an ordering enforcement mechanism. As a side-objective, this PR also hopes to make such tricks less viable on order to incentivize implementing better ordering mechanisms.

Review tips: The treewide commit has about 2/3 of the changes but is generated almost entirely from a script, so can be overlooked for initial review:

    treewide: Wrap time package with internal wrapper
...
178 files changed, 186 insertions(+), 191 deletions(-)

Related: #28844

[joestringer]

/ci-ginkgo

[joestringer]

🎣 f04-agent-policy-multi-node-1 seems to be failing consistently across k8s platforms:

• Failure in Spec Teardown (AfterEach) [130.273 seconds]
K8sAgentPolicyTest
/home/runner/work/cilium/cilium/test/ginkgo-ext/scopes.go:461
  Multi-node policy test
  /home/runner/work/cilium/cilium/test/ginkgo-ext/scopes.go:461
    validates fromEntities policies
    /home/runner/work/cilium/cilium/test/ginkgo-ext/scopes.go:461
      with remote-node identity enabled [AfterEach]
      /home/runner/work/cilium/cilium/test/ginkgo-ext/scopes.go:461
        Validates fromEntities remote-node policy
        /home/runner/work/cilium/cilium/test/ginkgo-ext/scopes.go:515

        Found 1 k8s-app=cilium logs matching list of errors that must be investigated:
        2023-08-03T21:42:49.751308617Z level=error msg="Unable to find identity of previously used CIDR 172.18.0.2/32" subsys=ipcache

EDIT: The referred IP address is one of the k8s nodes. The fact that releaseCIDRIdentities is being called with that prefix is a bit of a weird observation, since it should be considered as a "remote node" and hence should not have a CIDR identity in the current implementation.

In this scenario where all timers are set to 5s, for some reason the daemon allocates an identity for remote nodes on startup and seems to even insert it into the ipcache before it learns about the remote node IPs. This can cause temporary traffic disruption during startup, and should not happen. Furthermore it appears that the identity is released and then later on the ipcache gets confused that it was released.

2023-08-03T21:42:38.093177787Z level=debug msg="Resolving identity" identityLabels="cidr:172.18.0.2/32,reserved:world" subsys=identity-cache
2023-08-03T21:42:38.094183031Z level=debug msg="Upserting IP into ipcache layer" identity="{16777217 generated [] false false}" ipAddr=172.18.0.2/32 key=0 subsys=ipcache
2023-08-03T21:42:38.094192168Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{16777217 generated [] false false}" ipAddr="{172.18.0.2 ffffffff}" modification=Upsert subsys=datapath-ipcache
...
2023-08-03T21:42:38.098477940Z level=debug msg="UpdateIdentities: Adding a new identity" identity=16777217 labels="[cidr:0.0.0.0/0 cidr:128.0.0.0/1 cidr:128.0.0.0/2 cidr:160.0.0.0/3 cidr:160.0.0.0/4 cidr:168.0.0.0/5 cidr:172.0.0.0/10 cidr:172.0.0.0/11 cidr:172.0.0.0/6 cidr:172.0.0.0/7 cidr:172.0.0.0/8 cidr:172.0.0.0/9 cidr:172.16.0.0/12 cidr:172.16.0.0/13 cidr:172.16.0.0/14 cidr:172.18.0.0/15 cidr:172.18.0.0/16 cidr:172.18.0.0/17 cidr:172.18.0.0/18 cidr:172.18.0.0/19 cidr:172.18.0.0/20 cidr:172.18.0.0/21 cidr:172.18.0.0/22 cidr:172.18.0.0/23 cidr:172.18.0.0/24 cidr:172.18.0.0/25 cidr:172.18.0.0/26 cidr:172.18.0.0/27 cidr:172.18.0.0/28 cidr:172.18.0.0/29 cidr:172.18.0.0/30 cidr:172.18.0.2/31 cidr:172.18.0.2/32 reserved:world]" subsys=policy
...
2023-08-03T21:42:39.133189307Z level=debug msg="Kubernetes service definition changed" action=service-updated endpoints="172.18.0.2:6443/TCP" k8sNamespace=default k8sSvcName=kubernetes old-endpoints="172.18.0.2:6443/TCP" old-service=nil service="frontends:[10.96.0.1]/ports=[https]/selector=map[]" subsys=k8s-watcher
...
2023-08-03T21:42:40.004022127Z level=debug msg="Updating tunnel map entry" endpoint=172.18.0.2 key=0 prefix=10.0.0.0 subsys=map-tunnel
2023-08-03T21:42:40.210928109Z level=debug msg="Upserting IP into ipcache layer" identity="{kube-apiserver kube-apiserver [] false true}" ipAddr=172.18.0.2/32 key=0 subsys=ipcache
2023-08-03T21:42:40.210936205Z level=debug msg="Daemon notified of IP-Identity cache state change" identity="{kube-apiserver kube-apiserver [] false false}" ipAddr="{172.18.0.2 ffffffff}" modification=Upsert subsys=datapath-ipcache
2023-08-03T21:42:40.211844718Z level=debug msg="UpdateIdentities: Deleting identity" identity=16777217 labels="[cidr:0.0.0.0/0 cidr:128.0.0.0/1 cidr:128.0.0.0/2 cidr:160.0.0.0/3 cidr:160.0.0.0/4 cidr:168.0.0.0/5 cidr:172.0.0.0/10 cidr:172.0.0.0/11 cidr:172.0.0.0/6 cidr:172.0.0.0/7 cidr:172.0.0.0/8 cidr:172.0.0.0/9 cidr:172.16.0.0/12 cidr:172.16.0.0/13 cidr:172.16.0.0/14 cidr:172.18.0.0/15 cidr:172.18.0.0/16 cidr:172.18.0.0/17 cidr:172.18.0.0/18 cidr:172.18.0.0/19 cidr:172.18.0.0/20 cidr:172.18.0.0/21 cidr:172.18.0.0/22 cidr:172.18.0.0/23 cidr:172.18.0.0/24 cidr:172.18.0.0/25 cidr:172.18.0.0/26 cidr:172.18.0.0/27 cidr:172.18.0.0/28 cidr:172.18.0.0/29 cidr:172.18.0.0/30 cidr:172.18.0.2/31 cidr:172.18.0.2/32 reserved:world]" subsys=policy
...
2023-08-03T21:42:43.843942352Z level=debug msg="stale identity observed" identity=16777217 ipAddr=172.18.0.2 oldIdentity=7 subsys=hubble
2023-08-03T21:42:49.751308617Z level=error msg="Unable to find identity of previously used CIDR 172.18.0.2/32" subsys=ipcache

Full agent log:
logs-cilium-qc62c-cilium-agent-20230803-214347.log

EDIT2: 💡 OK so the previous test was with --enable-remote-node-identity=false, which explains why the remote node's identity previously corresponded to a CIDR identity in the ipcache map and why it was restored that way. So the transition there from a CIDR identity to using the remote-node identity likely makes sense. However that doesn't fully explain the reference counting dynamic that introduces the error log. Cilium should have been able to detect that it had allocated the identity newly once, then it should be able to release the final reference once. There's currently a double-free. That sounds a lot like the error reported against v1.14.0.

EDIT3: This was useful to catch the regression, and the bug is now fixed. I think it's still worth pursuing this testing strategy as a backup to try to catch this class of error in CI in future, ideally before we release such bugs.

[github-actions]

This pull request has been automatically marked as stale because it
has not had recent activity. It will be closed if no further activity
occurs. Thank you for your contributions.

[github-actions]

This pull request has not seen any activity since it was marked stale.
Closing.

[joestringer]

/test

[joestringer]

/test

[joestringer]

/test

[joestringer]

/test

[derailed]

@joestringer Nice work! Just wish there was a better way to handle this ;(

[joestringer]

/test