Skip to content

fix(tests): Make EventCorrelatorTest timestamps deterministic - #4927

Open
flrnd wants to merge 1 commit into
kubernetes-client:masterfrom
flrnd:fix-remove-thread-sleep-from-event-correlator-test
Open

flrnd wants to merge 1 commit into
kubernetes-client:masterfrom
flrnd:fix-remove-thread-sleep-from-event-correlator-test

Conversation

@flrnd

@flrnd flrnd commented Sep 29, 2026 •

Copy link
Copy Markdown

Notes

Remove Thread.sleep(100) from EventCorrelatorTest and make timestamp generation deterministic without depending on elapsed wall-clock time.

The investigation identified two timestamp paths: timestamps supplied by the test for ordinary duplicate events, and timestamps generated internally by EventAggregator for aggregated events.

CI failures

The initial change used now.plusNanos(10) to separate the input timestamps. It passed on Linux and macOS across JDK 11, 17, and 21, and initially on Windows with JDK 11, but intermittent failures appeared on Windows with JDK 17 and 21. Later CI runs also failed on Windows with JDK 11 and 21, specifically in parameterized case [6] (repeated aggregation of similar events).

The failures were not consistently reproducible locally, including on a Windows 10 VM running Eclipse Temurin JDK 11, 17, and 21 with the same Bazel version and --config ci.

Investigation

Instrumenting EventCorrelatorTest and tracing the flow through EventCorrelator, EventAggregator, and EventLogger revealed two different behaviours:

  • Duplicate events: EventAggregator returns the original event. EventLogger restores the first observation's firstTimestamp while preserving the incoming lastTimestamp. Explicitly advancing the input timestamp makes these cases deterministic. Increasing the increment to 1 ms addressed the initial failures.
  • Aggregated events: When the distinct-message threshold is reached, EventAggregator creates a new event with both timestamps set from its own OffsetDateTime.now() call. On repeated aggregation, EventLogger restores the previous firstTimestamp and retains the new aggregated event's lastTimestamp. If both clock reads return the same value, the assertion fails even though the event is correctly aggregated and counted.

This explains why increasing the input timestamp alone did not fix case [6]: the aggregator replaces those timestamps.

Windows / JDK investigation

After inspecting the OpenJDK source, the failures appear consistent with coarse system-clock resolution on some Windows environments.

  • The OpenJDK 11 and 17 Windows implementations inspected use GetSystemTimeAsFileTime(). Its timestamps are represented in 100-nanosecond units, but that representation does not guarantee that successive calls produce distinct values.
  • I reproduced the same case [6] assertion failure locally on Linux by temporarily truncating the aggregator's OffsetDateTime.now() values to seconds.

This reproduces the suspected failure mechanism, although the effective clock resolution on the CI runners was not measured directly. It also helps explain why Thread.sleep(100) reduced the failures: it made separate clock readings more likely without guaranteeing them.

Solution

Comparing the Java implementation with Kubernetes' Go client revealed that the Go correlator receives an injectable clock, and its tests use SimpleIntervalClock to advance time predictably. The Java implementation follows similar aggregation logic but read the system clock directly in EventAggregator.

The Java implementation now accepts a Supplier<OffsetDateTime> for aggregation timestamps, while retaining the existing constructors and production behaviour. The default supplier is evaluated on each call:

OffsetDateTime::now

The test supplies an incrementing source instead:

AtomicReference<OffsetDateTime> time =
    new AtomicReference<>(OffsetDateTime.now());

Supplier<OffsetDateTime> advancingTime =
    () -> time.getAndUpdate(t -> t.plusSeconds(1));

EventCorrelator passes the supplier to EventAggregator; EventLogger remains unchanged. The original timestamp assertions are preserved, and the test no longer relies on separate system-clock reads in the aggregation path.

This follows the testability principle used by the Go client without introducing a custom Clock class or changing how production obtains time.

Validation

  • Reproduced the intermittent CI assertion locally by simulating a coarse-resolution aggregator clock.
  • Verified that EventCorrelatorTest passes with the injected incrementing timestamp source.
  • Reverted the temporary clock-truncation experiment.
  • Ran the full Bazel test suite locally: 113 test targets passed.

The remaining input-timestamp increment is intentional: ordinary duplicate events preserve the input timestamps, whereas aggregated events use the injected timestamp supplier.

@linux-foundation-easycla

linux-foundation-easycla Bot commented Sep 29, 2026 •

Copy link
Copy Markdown

CLA Signed
The committers listed above are authorized under a signed CLA.

  • ✅ login: flrnd / name: flrnd (fd34a69)

@kubernetes-prow

Copy link
Copy Markdown
Contributor

Welcome @flrnd!

It looks like this is your first PR to kubernetes-client/java 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes-client/java has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

@kubernetes-prow kubernetes-prow Bot added cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. and removed cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. labels Sep 29, 2026
@brendandburns

Copy link
Copy Markdown
Contributor

/lgtm
/approve

@kubernetes-prow kubernetes-prow Bot added lgtm "Looks good to me", indicates that a PR is ready to be merged. approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Sep 30, 2026
@flrnd

flrnd commented Sep 30, 2026 •

Copy link
Copy Markdown
Author

The same failure occurs on Java 11, 17, and 21 in the Windows Bazel build.
In Java 21, two parameterized cases fail because firstTimestamp and lastTimestamp are equal after removing the Thread.sleep(100). It seems that OffsetDateTime.now() calls can produce the same timestamp in this environment.

In this case, I now wonder if it is worth finding a deterministic way to generate the timestamps, or if leaving the sleep in place makes sense.

@flrnd

flrnd commented Sep 30, 2026

Copy link
Copy Markdown
Author

Another alternative to Thread.sleep(100) would be to explicitly advance the timestamp used by the test:

@@ -144,8 +138,8 @@ class EventCorrelatorTest {
       Boolean expectedSkip)
       throws Exception {
     EventCorrelator correlator = new EventCorrelator();
+    OffsetDateTime now = OffsetDateTime.now();
     for (CoreV1Event event : previousEvents) {
-      OffsetDateTime now = OffsetDateTime.now();
       event.setFirstTimestamp(now);
       event.setLastTimestamp(now);
       Optional<MutablePair<CoreV1Event, V1Patch>> result = correlator.correlate(event);
@@ -153,7 +147,7 @@ class EventCorrelatorTest {
         correlator.updateState(event);
       }
     }
-    OffsetDateTime now = OffsetDateTime.now();
+    now = now.plusNanos(10);
     newEvent.setFirstTimestamp(now);
     newEvent.setLastTimestamp(now);

@brendandburns

Copy link
Copy Markdown
Contributor

Feel free to try that alternate fix and update this PR.

@kubernetes-prow kubernetes-prow Bot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 6, 2026
@flrnd flrnd changed the title fix(tests): remove unnecessary Thread.sleep from EventCorrelatorTest fix(tests): Make EventCorrelatorTest timestamps deterministic Oct 6, 2026
@flrnd
flrnd force-pushed the fix-remove-thread-sleep-from-event-correlator-test branch from bd1ce4a to 9f9dcc7 Compare October 6, 2026 23:23
@brendandburns

Copy link
Copy Markdown
Contributor

/lgtm
/approve

@kubernetes-prow kubernetes-prow Bot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 13, 2026
@kubernetes-prow

Copy link
Copy Markdown
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: brendandburns, flrnd

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@brendandburns

Copy link
Copy Markdown
Contributor

There are now test failures in this test in some CI/CD runs.

@flrnd
flrnd force-pushed the fix-remove-thread-sleep-from-event-correlator-test branch from 9f9dcc7 to 95b4da2 Compare October 16, 2026 11:32
@kubernetes-prow kubernetes-prow Bot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 16, 2026
@kubernetes-prow

Copy link
Copy Markdown
Contributor

New changes are detected. LGTM label has been removed.

@flrnd

flrnd commented Oct 16, 2026 •

Copy link
Copy Markdown
Author

Looking at both failing jobs, I think we're dealing with two separate timestamp issues. The first appears to have been addressed by increasing the timestamp increment to 1 ms, but the latest failures point to a second issue in EventAggregator, as highlighted in the earlier review comment.
Both Windows jobs (JDK 11 and 21) failed on the same parameterized case, [6], which tests counting aggregated similar events.

Tracing the execution through EventCorrelator, EventAggregator, and EventLogger suggests the following:

  • When the aggregation threshold is reached, EventAggregator creates a new event and assigns both timestamps using its own OffsetDateTime.now().
  • On subsequent aggregation, EventLogger restores the previous firstTimestamp while preserving the new lastTimestamp.
  • If those two calls to OffsetDateTime.now() return identical values, the assertion fails.
    This would explain why increasing the input timestamp by 1 ms addressed the earlier failures but doesn't resolve this case.

Reproducing this locally may be tricky, since the failure appears to depend on the environment's clock resolution and timing. Managed to reproduce the same failure locally now

Update: Windows / JDK investigation

After discussing this with folks on IRC and looking into the OpenJDK source, the issue seems more likely related to Windows clock resolution than to OffsetDateTime itself.

The investigation revealed a few interesting details:

  • OpenJDK 11 and 17 (the versions I inspected) use the Windows GetSystemTimeAsFileTime() API to obtain system time, which provides timestamps in 100-nanosecond units but doesn't guarantee that the underlying clock updates at that resolution.
  • The failing GitHub Actions jobs run on Azure-hosted Windows Server 2025 VMs (windows-2025-vs2026).
  • On some Windows environments, particularly VMs, consecutive clock reads may return identical timestamps. This is consistent with the intermittent failures across different JDK versions.
  • I managed to reproduce the exact case [6] failure locally on Linux by temporarily truncating OffsetDateTime.now() to seconds inside EventAggregator.

This supports the hypothesis that the test relies on a clock-resolution guarantee that isn't available across all environments. It also explains why Thread.sleep(100) was helping with the aggregated events. The next step is to find a way to make the tests independent of the underlying system clock resolution.

Replace Thread.sleep(100) with explicit timestamp increments in
EventCorrelatorTest. Duplicate events preserve their input timestamps,
so advancing those timestamps is sufficient to verify compression.

Aggregated events, however, generate their own timestamps using
OffsetDateTime.now(). Consecutive calls can return identical values
depending on system clock resolution, causing intermittent CI failures
on Windows.

Following the approach used by the Go client, introduce an injectable
timestamp source in EventAggregator using Supplier<OffsetDateTime>.
Add a corresponding EventCorrelator constructor to pass the supplier
through, while preserving the existing constructors and production
behaviour with OffsetDateTime::now.

Use an incrementing timestamp supplier in the test to control
aggregation timestamps independently of the system clock.

This preserves the existing timestamp assertions, removes the timing
dependency, and avoids changes to EventLogger.
@flrnd
flrnd force-pushed the fix-remove-thread-sleep-from-event-correlator-test branch from 95b4da2 to 8c7c91f Compare October 17, 2026 10:43
@kubernetes-prow kubernetes-prow Bot removed the size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. label Oct 17, 2026
@kubernetes-prow kubernetes-prow Bot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Oct 17, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants