awsnodeagent_policy_programming_latency_seconds records inaccurate observations due to stale last-change-trigger-time annotation

[mharmer-canva]

What happened:

The end-to-end policy programming latency histograms awsnodeagent_policy_programming_latency_seconds and awsnodeagent_cluster_policy_programming_latency_seconds (added in #516) record large numbers of multi-minute observations on clusters whose dataplane is demonstrably healthy. Mechanism, confirmed against the code in both repos:

• The Network Policy Controller stamps networking.k8s.aws/last-change-trigger-time on a PolicyEndpoint in setLastChangeTriggerTime() (pkg/policyendpoints/manager.go, added change timestamp in PE and CPE annotation amazon-network-policy-controller-k8s#213) only when processing a genuine change — but PolicyEndpoints are also rewritten at other times (background rewrites, mass rewrites during node churn) without the annotation being refreshed.
• The agent's observePolicyProgrammingLatency() (controllers/policyendpoints_controller.go, emitting latency metrics based on PE and CPE updates in NPC #516) computes time.Since(triggerTime) and calls Observe() on every PE reconcile. The only guard is trackerStartTime (annotations predating agent start are skipped); there is no per-PE comparison against the previously-seen annotation value. Since every agent watches every PE, each rewrite of a PE carrying an old annotation produces one observation of (now − old annotation) per agent, landing in the top (≥300s / +Inf) buckets.

What you expected to happen:

An observation should be emitted only when a PE write actually carries a new trigger annotation: the agent should compare the annotation to the previously-seen value for that PE and skip unchanged ones. And/or the controller should refresh or clear the annotation on non-trigger rewrites so it never accompanies a write it did not trigger. kube-proxy's network_programming_duration_seconds handling of EndpointsLastChangeTriggerTime — which is cited as the pattern being followed — is the prior art: it only measures when the trigger time changes.

How to reproduce it (as minimally and precisely as possible):

1. EKS Kubernetes 1.35, VPC CNI v1.22.3 with network policy enabled (aws-network-policy-agent v1.3.7, EKS-managed network policy controller).
2. Create a NetworkPolicy whose selector membership rarely changes (e.g. a static ingress policy for a stable Deployment).
3. Wait for, or induce, PolicyEndpoint rewrites that involve no selector-membership change (node churn / controller rewrite cycle).
4. Observe resourceVersion advances while the annotation stays fixed:

kubectl get policyendpoint <pe> -o jsonpath='{.metadata.resourceVersion} {.metadata.annotations.networking\.k8s\.aws/last-change-trigger-time}'

5. Scrape awsnodeagent_policy_programming_latency_seconds on any node: each such rewrite adds one observation of (now − annotation) per agent.

Environment:
Kubernetes version (use kubectl version): 1.35
CNI Version: 1.22.3
Network Policy Agent Version: 1.3.7

[viveksb007]

@mharmer-canva thanks for the details in this issue.

During node churn, the target pods will be updated (selected by NP podSelector ), hence PE will be updated. PE might have static ingress/egress membership rules but the target pods are dynamic and those will still result in PE change.

From details in this issue, it seems resourceVersion is being increased without the corresponding annotation last-change-trigger-time change. The network-policy-controller always updates the annotation on the PE write path. I did basic test based on repro steps above and didn't saw resourceVersion bump with same last time stamp.

Can you double check if resourceVersion is being bumped with stale annotation time? if its happening, maybe share the scale of test being done, so I can try that on my side.

[mharmer-canva]

Hey @viveksb007, thanks for looking into this.

I was able to reproduce this on on one of our clusters (scale: ~360 PEs, ~110 nodes / ~45 agents, steady pod churn), polling PolicyEndpoints over a 6 hour period, capturing (resourceVersion, generation, last-change-trigger-time) per PE:

• Every resourceVersion change carried a fresh annotation change. There were zero writes with an unchanged last-change-trigger-time. "resourceVersion is being increased without the corresponding annotation last-change-trigger-time change" doesn't seem to be the issue here.
• We saw incorrect observations over this period, without any writes that could legitimately produce them.

My theory is that these observations are coming from agent reconciles not triggered by writes eg workqueue requeues, RequeueAfter, or informer resync - re-delivering PEs with old timestamps. Agentic analysis points to this mechanism: "observePolicyProgrammingLatency() observes on every reconcile with only the trackerStartTime (agent-restart) guard, so any such re-delivery of a PE with a post-agent-start annotation emits time.Since(annotation) again".

The minimal repro is probably to make an agent reconcile a PE without any write happening.

Thanks again for your help!

[viveksb007]

@mharmer-canva From my understanding, informer re-sync will happen when agent will re-start and when the agent re-starts, it only emits metrics if getting PE tagged after its re-start. Curious to know what multi-minute observations are you seeing?

it could be tricky to translate those metrics directly to the dataplane impact as reconciliation updates the rules but based on the older rules DP traffic might be working just fine.

Are you running in strict mode or standard mode for this testing?

[mharmer-canva]

From my understanding, informer re-sync will happen when agent will re-start and when the agent re-starts, it only emits metrics if getting PE tagged after its re-start. Curious to know what multi-minute observations are you seeing?

It seems there are other ways that a reconcile can be triggered without a corresponding write - notably reflector relists after watch errors or apiserver watch cache expiry (eg due to apiserver restart/rebalance). In our tests we saw that the count of incorrect observations is a multiple of the number of PEs in the cluster, which implies ~all PEs are being re-observed when this happens.

it could be tricky to translate those metrics directly to the dataplane impact as reconciliation updates the rules but based on the older rules DP traffic might be working just fine.

Correct, no DP impact in this case, however this is the recommended metric for enforcement-latency monitoring, and we currently can't alert on it due to this noise. To give a sense of how prevalent this is, here's the p99 over 24 hours for 1 cluster:

Are you running in strict mode or standard mode for this testing?

Strict mode.

[viveksb007]

yeah, it seems Agent side metric observation needs to handle cases like

• Periodic informer resync
• Watch relist after API-server disconnect/restart
• ...

Agent is missing the "consume-once semantics" today. I will raise a PR to fix this. Thanks for the details

[viveksb007]

@mharmer-canva I have merged the fix, this should be available on the next release. I will update with the exact release tag.

[mharmer-canva]

Thanks @viveksb007 , appreciate the speedy fix!