Skip to content

Moar test fixes - #685

Open
kolyshkin wants to merge 3 commits into
containers:mainfrom
kolyshkin:test-log-rotate-race
Open

Moar test fixes#685
kolyshkin wants to merge 3 commits into
containers:mainfrom
kolyshkin:test-log-rotate-race

Conversation

@kolyshkin

@kolyshkin kolyshkin commented Aug 24, 2026

Copy link
Copy Markdown
Collaborator

The coverage job hit this on #684, which touches nothing but the cri-o test selection:

not ok 120 ctrl: rotate logs with --log-rotate
  in test file test/10-ctrl.bats, line 192
  `assert "${output}" =~ "before rotation"' failed

The race

ctrl: rotate logs with --log-rotate starts a container that writes before rotation, sends 2 1 1 to the control fifo to rotate the log, and then checks that the line is in the rotated file $LOG_PATH.1 and that what comes after is in the new $LOG_PATH.

The test waits for the container to be running before rotating, but that says nothing about conmon having written the first line to the log yet. Lose that race and the rotation moves a log that does not contain the line, before rotation lands in the fresh log along with after rotation, and $LOG_PATH.1 is there -- so the assert_file_exists above passes -- but empty. The coverage job is the slowest one, which is where this turns up.

So the test now waits for the line to be logged before rotating.

The helper

While adding the fourth "poll until X" helper to test_helper.bash, the loop -- deadline from $SECONDS, check, sleep, die -- was written out three times already. It is now

retry <how_long> <interval> <command ...>

which returns non-zero instead of dying: it does not know what it was waiting for, the callers do, and they keep their own messages. wait_for_runtime_status, wait_for_conmon_exit and wait_for_syncpipe_output are converted to it, and the new wait_for_log_line uses it too.

No functional change from the conversion, other than the status check in wait_for_runtime_status no longer printing expr's match count into the test log.

Ran the full suite locally: 120/120.

The unrelated CI breakage

Also here, since the cri-o job was red for a reason of its own: go 1.27 (which go-version: stable started resolving to) does not build cri-o main.

In golang.org/x/net v0.54.0, which cri-o vendors, http2 switches to a thin wrapper around net/http under go 1.27 (server.go is //go:build !(go1.27 && !http2legacy)), and http2.TrailerPrefix -- used by the vendored grpc -- is only defined in the non-wrapped build:

vendor/google.golang.org/grpc/internal/transport/handler_server.go:271:18: undefined: http2.TrailerPrefix

Upstream fixes this by vendoring x/net v0.55.0, which moves TrailerPrefix into a file built either way; see cri-o/cri-o#10103 (comment). Until that lands, go is pinned to 1.26 here.

kolyshkin and others added 3 commits August 24, 2026 10:21
Three helpers here poll for something with the same loop written out
three times: a deadline computed from $SECONDS, a check, a sleep, and a
die at the end. A fourth one is about to be added.

Factor the loop out as

	retry <how_long> <interval> <command ...>

which returns non-zero rather than dying, as it does not know what it
was waiting for -- the callers do, and they keep their own messages.

No functional change, save for the status check in wait_for_runtime_status
no longer printing expr's match count to the test log.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
"ctrl: rotate logs with --log-rotate" starts a container that writes
"before rotation", rotates the log by writing to the control fifo, and
then checks that the line ended up in the rotated file:

	not ok 120 ctrl: rotate logs with --log-rotate
	  in test file test/10-ctrl.bats, line 192
	  `assert "${output}" =~ "before rotation"' failed

Between the container being reported as running and conmon writing that
line to the log there is a gap, and the test rotates without waiting for
it. Lose the race and the rotation moves a log that does not have the
line yet, so it lands in the new log instead, leaving the rotated one
there but empty. The coverage job, being the slowest, is where this
shows up.

Wait for the line to be logged before rotating.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Go 1.27 broke building cri-o main: in golang.org/x/net v0.54.0 (which
cri-o vendors) the http2 package switches to a wrapper around net/http
under go 1.27, and http2.TrailerPrefix, used by the vendored grpc, is
only defined in the non-wrapped build. This makes the cri-o job fail
with:

	vendor/google.golang.org/grpc/internal/transport/handler_server.go:271:18: undefined: http2.TrailerPrefix

The fix upstream is to vendor x/net v0.55.0, which moves TrailerPrefix
to a file built in both cases. Until that lands, pin go to 1.26.

See cri-o/cri-o#10103 (comment)

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@kolyshkin kolyshkin changed the title test: fix the log rotation race, add a retry helper Moar test fixes Aug 24, 2026
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