[daily-ci] FLAKY-TEST: diskless loading short read 5s log wait too tight under UBSan

[madolson]

diskless loading short read gives the replica a fixed ~5s to report the outcome after the master kills the replication link, and on the UBSan job that budget ran out. When the master closed the connection the replica still had a couple of MB of RDB buffered in its socket receive buffer, and it has to parse through that before it reaches the EOF and logs Internal error in RDB. It normally does this in 6-25ms, but this runner was giving it about 4% of normal throughput, so it was still parsing 6.6s later when the test gave up. The code is fine; the assertion at tests/integration/replication.tcl:960 has no headroom.

Upstream valkey-io/valkey#4325 already tracks this same assertion on the TLS jobs. My verdict agrees with it being a test problem, and adds the mechanism.

Details

Job links

• https://github.com/valkey-io/valkey/actions/runs/35039408935/job/104615694145 (test-sanitizer-undefined (gcc), 2026-09-16, hit twice in the run)

Source read at upstream/unstable = d6415e766.

Assertion

[err]: diskless loading short read in tests/integration/replication.tcl
log message of '"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"' not found in ./tests/tmp/server.7143.495/stdout after line: 3201 till line: 3205

tests/integration/replication.tcl:960 is the failing wait:

set res [wait_for_log_messages -1 {"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"} $loglines 500 10]

tests/support/util.tcl:285-307 makes that 500 tries at 10ms, so ~5s plus one exec tail per try.

What happened

From --dump-logs (replica pid 70398, master pid 70418), final iteration:

70418:M 00:32:01.280 * Background RDB transfer started by pid 71991 to pipe through parent process
70398:S 00:32:01.285 * PRIMARY <-> REPLICA sync: Loading DB in memory
70398:S 00:32:01.285 * RDB memory usage when created 72.45 Mb
70418:M 00:32:01.337 * Connection with replica 127.0.0.1:24864 lost.      <-- the test's client kill
70418:M 00:32:01.347 # Background RDB transfer terminated by signal 10
   ... replica silent for 6.6s, test gives up ~00:32:07.2 ...
70398:signal-handler (1789518727) Received shutdown signal during loading, scheduling shutdown.
70398:S 00:32:07.959 * User requested shutdown...

Every other iteration in the same run went from Loading DB in memory to
Internal error in RDB reading offset ... rdb.c:4006 -> Unexpected EOF reading RDB file in 6-25ms,
and a full successful load of this dataset took ~280ms (00:32:00.523 -> 00:32:00.805).

Slow, not hung

The replica exited through whileBlockedCron (src/server.c:1886,
if (server.shutdown_asap && server.loading) prepareForShutdown(...)). On a non-dual-channel
diskless load the only caller reaching that check is rdbLoadProgressCallback ->
processEventsWhileBlocked() (src/rdb.c:3374), which fires only when parsing crosses a
loading-process-events-interval-bytes boundary (default 2MB, src/config.c:3657). So at
00:32:07.959 the replica was still inside the parse loop and had just crossed a 2MB boundary.

A blocked read is ruled out: rioConnEnsureBuffered retries only on EINTR
(src/rio.c:261-268, src/connection.h:350-352) and turns connRead() == 0 into immediate
failure, which rdbReportError (src/rdb.c:122-160) logs as Internal error in RDB ... assuming connection error, resuming operation.. Had the replica been parked in connRead when SIGTERM
arrived, the EINTR retry would have hit EOF and logged that line instead of shutting down.

Runner was heavily oversubscribed: same job has GEOSEARCH fuzzy test - bybox (249533 ms) and
(249511 ms) running concurrently, on a UBSan -O3 build with the suite at 16 parallel clients
(.github/workflows/daily.yml:1256, :1262).

Origin

The 5s budget comes verbatim from Redis 03406fcb6 ("fix short timeout in replication short read
tests", redis#9763, 2021), long before sanitizer jobs existed and before this job started passing
--accurate (500 iterations instead of 100, tests/integration/replication.tcl:945-947). Not a
recent regression: the last commits touching this file (66f9618f4, 6ae7eb488, acba5ddd0) did
not change the wait or the log strings on the path taken.

Latent second flake source in the same assertion

The streaming-compression work (66f9618f4, #3853, plus 4be324e88) added abort paths that emit
none of the three grepped-for messages: rdbInitStreamReader failing on a torn envelope probe logs
Failed to initialize RDB stream reader from primary (src/replication.c:2782-2785), and
compressed truncation logs Compressed RDB stream from primary was truncated; will resync
(src/replication.c:2812). This run took the plaintext path (rdb.c:4006 -> Unexpected EOF), so
this is not the observed cause, but the test would fail differently once repl-compression is
enabled.

Ruled out

• Defect in the diskless-load abort path. Detection is correct and prompt in the other 499
  iterations of the same run, and no path blocks after connRead returns 0.
• Recent regression. See Origin above.
• Infra in the narrow sense. No runner timeout, network error, or toolchain failure. The runner was
  just slow and the test has no tolerance for that.

This was generated by AI but verified, with love, by a human.

[madolson]

Duplicate of valkey-io/valkey#4325, which the Test Failure Detector opened for this same assertion and has recorded 3 times on test-ubuntu-tls, test-almalinux8-tls-module and test-centosstream9-tls-module. Reproduction and the throughput knob are posted there. Test bug, not a product bug: the ~5s budget at tests/integration/replication.tcl:826 is a bet on replica-side RDB parse throughput, and it has no headroom.

Fix in #65, which raises the try count from 500 to 6000 at the same 10ms poll delay.

This was generated by AI but verified, with love, by a human.