Widen the log wait in the diskless loading short read test

[madolson]

diskless loading short read gives the replica ~5s to log the outcome after the master kills the replication link, but the replica cannot report anything until it has parsed through the RDB bytes already sitting in its socket receive buffer and reached the EOF. That takes 6-25ms on an idle machine and seconds on an oversubscribed sanitizer or TLS runner, so the budget has no headroom and the test flakes. This raises the try count from 500 to 6000 (~60s) at the same 10ms poll delay. Tracked upstream as valkey-io/valkey#4325.

Details

Problem

tests/integration/replication.tcl:826 on upstream/unstable (d6415e766):

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.

The wait is not waiting for a network event. rioConnEnsureBuffered turns connRead() == 0 into immediate failure (src/rio.c:261-268, src/connection.h:350-352) and rdbReportError logs Internal error in RDB (src/rdb.c:122-160), so the only thing standing between the kill and the log line is replica-side RDB parse throughput over the already-buffered bytes. The budget is a throughput bet on the runner.

The 5s came verbatim from Redis 03406fcb6 (redis#9763, 2021), before sanitizer jobs existed and before this job started passing --accurate (500 iterations instead of 100, tests/integration/replication.tcl:945-947).

Reproduction

The knob is key-load-delay (src/config.c:3582, applied per top-level RDB opcode at src/rdb.c:3949). Two things have to be right or it does nothing:

1. Set it only at the kill, not at test start. With the parser slow from the beginning, receive-window autotuning keeps the replica's rcvbuf small, so less is buffered and the wait does not lengthen. key-load-delay of 20000, 100000 and 200000 from test start all still passed (14s / 37s / 177s runtime, assertion never tripped). The CI shape is a replica that read at full speed, filled a large autotuned rcvbuf, and then lost its CPU.
2. Many small keys. The stock dataset's opcodes run up to 1MB, so a 2MB buffered window is ~2 opcodes and per-opcode delay barely accumulates. debug populate 100000 puts thousands of opcodes in that window.

Also set loading-process-events-interval-bytes 16384 on the replica (src/config.c:3657, default 2MB) so the mid-load CONFIG SET lands promptly; during loading the replica only processes events at those boundaries (src/rdb.c:3374).

Copy the test to tests/integration/repro-issue-44.tcl with attempts 5 and:

# after "$replica config set hz 500"
set repro_delay [expr {[info exists ::env(REPRO44_DELAY)] ? $::env(REPRO44_DELAY) : 0}]
$replica config set loading-process-events-interval-bytes 16384

# after the data-fill loop
r debug populate 100000

# immediately before "set killed [$master client kill type replica]"
$replica config set key-load-delay $repro_delay

# around the assertion
set t0 [clock clicks -milliseconds]
set res [wait_for_log_messages -1 {...} $loglines 500 10]
puts "REPRO44 iter $i: kill -> outcome in [expr {[clock clicks -milliseconds]-$t0}] ms"
$replica config set key-load-delay 0

REPRO44_DELAY=2000 ./runtest --single integration/repro-issue-44 --loops 5

Measured kill-to-outcome window:

key-load-delay (us, set at kill)	window	result
0	14, 2, 14, 2, 2 ms	pass
500	5867, 2, 1119, 2, 4613 ms	pass, grazing the budget
1000	145, 2, 2, 169, >5000 ms	1/5 loops fail
2000	first iteration exceeds	4/5 loops fail

Testing

Before, budget 500 10:

########## BEFORE (budget 500x10ms = ~5s), delay=2000us, 5 loops ##########
REPRO44 iter 0: kill -> outcome in 2 ms
REPRO44 iter 1: kill -> outcome in 15 ms
REPRO44 iter 2: kill -> outcome in 3 ms
REPRO44 iter 0: kill -> outcome in 5953 ms
REPRO44 iter 1: kill -> outcome in 2 ms
[err]: repro44 diskless loading short read in tests/integration/repro-issue-44.tcl
log message of '"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"' not found in ./tests/tmp/server.17917.1/stdout after line: 44 till line: 48
[err]: repro44 diskless loading short read in tests/integration/repro-issue-44.tcl
log message of '"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"' not found in ./tests/tmp/server.17919.1/stdout after line: 44 till line: 48
REPRO44 iter 2: kill -> outcome in 13 ms
[err]: repro44 diskless loading short read in tests/integration/repro-issue-44.tcl
log message of '"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"' not found in ./tests/tmp/server.17929.1/stdout after line: 44 till line: 48
REPRO44 iter 3: kill -> outcome in 3 ms
REPRO44 iter 4: kill -> outcome in 2 ms
[err]: repro44 diskless loading short read in tests/integration/repro-issue-44.tcl
log message of '"*Internal error in RDB*" "*Finished with success*" "*Successful partial resynchronization*"' not found in ./tests/tmp/server.17924.1/stdout after line: 108 till line: 112
[ok]: repro44 diskless loading short read (17082 ms)
                   The End
Test Summary: 1 passed, 4 failed

After, budget 6000 10:

########## AFTER (budget 6000x10ms = ~60s), delay=2000us, 5 loops ##########
REPRO44 iter 0: kill -> outcome in 1953 ms
REPRO44 iter 0: kill -> outcome in 2287 ms
REPRO44 iter 0: kill -> outcome in 3326 ms
REPRO44 iter 1: kill -> outcome in 2 ms
REPRO44 iter 2: kill -> outcome in 14 ms
REPRO44 iter 1: kill -> outcome in 2 ms
REPRO44 iter 1: kill -> outcome in 2 ms
REPRO44 iter 3: kill -> outcome in 2 ms
REPRO44 iter 4: kill -> outcome in 3 ms
[ok]: repro44 diskless loading short read (14657 ms)
REPRO44 iter 0: kill -> outcome in 7881 ms
REPRO44 iter 1: kill -> outcome in 14 ms
REPRO44 iter 2: kill -> outcome in 2 ms
REPRO44 iter 3: kill -> outcome in 13 ms
REPRO44 iter 4: kill -> outcome in 2 ms
REPRO44 iter 0: kill -> outcome in 11735 ms
[ok]: repro44 diskless loading short read (18662 ms)
REPRO44 iter 1: kill -> outcome in 2 ms
REPRO44 iter 2: kill -> outcome in 10372 ms
REPRO44 iter 3: kill -> outcome in 2 ms
REPRO44 iter 4: kill -> outcome in 2 ms
[ok]: repro44 diskless loading short read (23631 ms)
REPRO44 iter 2: kill -> outcome in 10348 ms
REPRO44 iter 2: kill -> outcome in 20390 ms
REPRO44 iter 3: kill -> outcome in 2 ms
REPRO44 iter 4: kill -> outcome in 244 ms
[ok]: repro44 diskless loading short read (34978 ms)
REPRO44 iter 3: kill -> outcome in 3198 ms
REPRO44 iter 4: kill -> outcome in 2 ms
[ok]: repro44 diskless loading short read (37635 ms)
                   The End
Test Summary: 5 passed, 0 failed

20.4s observed under the artificial slowdown, against 60s of budget and the 6.6s the UBSan runner needed.

--only "diskless loading short read" cannot isolate this test: later wait_for_sync calls in the file sit outside any test body and depend on a replicaof that a skipped test performs, so the run aborts with replica didn't sync in time at tests/integration/replication.tcl:250. The 5-loop evidence above therefore comes from the extracted copy, which carries the identical assertion. The full file was run separately with the fix.

Not verified against a real UBSan build; the slowdown above stands in for the runner.

Decisions

• Raise the try count, not the poll delay. Raising the delay would add up to 90ms of latency to each of the 500 --accurate iterations even when nothing is wrong. Raising the count costs nothing on a healthy run because wait_for_log_messages returns on first match.
• Not a product bug. Detection is correct and prompt in the other 499 iterations of the failing CI run, and no path blocks after connRead returns 0.
• Left out of scope: 66f9618f4 (#3853) added two abort paths that emit none of the three grepped-for strings, Failed to initialize RDB stream reader from primary (src/replication.c:2782-2785) and Compressed RDB stream from primary was truncated; will resync (src/replication.c:2812). The test does not enable repl-compression, so this is latent rather than the observed cause, and it wants its own change.

Fixes #44

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