Skip to content

[high] fix: wait for the publish worker in test_search_publish_timestamp - #1482

Open
elhoim wants to merge 1 commit into
MISP:mainfrom
elhoim:fix/publish-timestamp-race
Open

[high] fix: wait for the publish worker in test_search_publish_timestamp#1482
elhoim wants to merge 1 commit into
MISP:mainfrom
elhoim:fix/publish-timestamp-race

Conversation

@elhoim

@elhoim elhoim commented Sep 3, 2026

Copy link
Copy Markdown
Member

BLUF — test_search_publish_timestamp races the publish worker and fails whenever the server answers faster.

  • Problem — It asserts that a publish_timestamp='5s' search returns exactly one event immediately after creating it, but since MISP 2.5.40 the publish timestamp is set by a background worker rather than during add_event. The assertion only ever passed because the three invalid-query searches before it happened to take longer than the worker's tick.
  • Fix — Waits for the worker to actually publish instead of relying on that incidental latency, and drops a fixed 10-second sleep that was both slow and still insufficient.
  • Effect — The test becomes deterministic rather than a race, and stops reporting a server-side speed-up as a test failure.

How this surfaced

MISP/MISP#11081 removes a bcrypt verification from every authenticated REST request. On that branch this test fails reproducibly on both CI legs:

FAILED tests/testlive_comprehensive.py::TestComprehensive::test_search_publish_timestamp
  - AssertionError: 0 != 1

The runtime of this very suite is the evidence that nothing is actually broken:

branch testlive_comprehensive (same 85 tests) result
the faster-auth branch 145.6s, 146.9s fails this test
six other MISP PRs, 12 runs 190.3s – 216.7s all pass

The faster the server answers, the sooner the three invalid queries return, and the less time the publish worker has had. 0 is the correct answer to the search at that moment — the event genuinely is not published yet.

Why it is a race

second = self.pub_misp_connector.add_event(second, pythonify=True)
# three invalid publish_timestamp queries, each asserting []
events = self.pub_misp_connector.search(publish_timestamp='5s', pythonify=True)
self.assertEqual(len(events), 1)

Nothing between add_event and the assertion waits for publication. The three invalid queries are load-bearing purely as a delay, which is not what they were written for. The test's own comment a few lines further down already acknowledges the 2.5.40 change and sleeps for it — but only after the assertion that needs it.

The change

  • _wait_until_published() — polls until the event reports published with a non-zero publish_timestamp, then returns the re-fetched event. On timeout it fails with event <id> was not published within <n>s rather than letting a later assertion fail obscurely. It accepts publish_timestamp as either the int 0 that add_event returns or the datetime that pythonify produces once the worker has run.
  • Wait for the first event before creating the second. The interval assertion at the end compares the two publish timestamps, but the previous sleep only separated their creation times.
  • Wait for the second event before the 5-second-window assertion.
  • Drop the fixed time.sleep(10) that preceded the re-fetch. It slowed the suite down and still raised AttributeError on int.timestamp() whenever the worker was slower than the guess.
  • Assert the two publish timestamps are more than 5s apart, so a violation reports the real gap instead of an opaque count mismatch.

Verification

The helper's control flow was exercised against a stubbed connector, since the surrounding suite needs a live MISP instance:

case result
unpublished, then published returns after 3 polls (~1.0s)
published=True but publish_timestamp == 0 keeps waiting, does not return early
never publishes fails after the timeout with event 42 was not published within 2s

The test is now driven by the worker's actual progress, so it neither races a faster server nor pays a fixed delay on a slower one.

MISP/MISP#11081 is blocked on this change and should go green once it is merged and MISP's PyMISP submodule picks it up.

🤖 Generated with Claude Code

The test asserts that a search for publish_timestamp='5s' returns exactly
one event immediately after creating it. Since 2.5.40 MISP sets the publish
timestamp in a background worker rather than during add_event, so this only
passed because the three invalid-query searches in between happened to take
longer than the worker's tick.

That makes the test sensitive to unrelated server-side performance. It fails
reproducibly against a MISP branch that removes a bcrypt verification from
every authenticated REST request: the same 85-test suite drops from 190-217s
to 146s, the three queries return before the worker has published, and the
search correctly matches nothing - "AssertionError: 0 != 1".

Wait for publication instead of relying on incidental latency:

  - add _wait_until_published(), which polls until the event reports
    published with a non-zero publish_timestamp, and fails with a clear
    message on timeout rather than letting a later assertion fail obscurely.
    It accepts publish_timestamp as either the int 0 add_event returns or the
    datetime pythonify produces once the worker has run.
  - wait for the first event before creating the second, so the two publish
    timestamps are genuinely separated. The previous sleep separated only the
    creation times, which is not what the interval assertion compares.
  - wait for the second event before the 5-second window assertion.
  - drop the fixed 10s sleep that preceded the re-fetch. It slowed the suite
    down and still raised AttributeError on int.timestamp() whenever the
    worker was slower than the guess.
  - assert the two publish timestamps are more than 5s apart, so a violation
    reports the real gap instead of an opaque count mismatch.

The test is now driven by the worker's actual progress, so it neither races a
faster server nor pays a fixed delay on a slower one.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant