Skip to content

Disable repl-timeout in dual channel buffer memory test - #57

Open
madolson wants to merge 1 commit into
unstablefrom
ai/issue-41
Open

madolson wants to merge 1 commit into
unstablefrom
ai/issue-41

Conversation

@madolson

Copy link
Copy Markdown
Owner

Dual channel replication buffer memory fields freezes the primary's socket-target BGSAVE with rdb-key-save-delay 2000000 so the replica stays in REPL_STATE_TRANSFER while the test pushes 50MB down the main channel, but rioConnset buffers the child's output so the replica's RDB socket reads nothing and repl_transfer_lastio never advances. The default 60s repl-timeout therefore aborts the sync, cancelReplicationHandshake frees the pending buffer the test is measuring, and the reconnect is parked behind the still-running BGSAVE, so mem_total_replication_buffers can never reach the 40MB the wait loop needs. That gives the test a hard 60s wall-clock budget for the 50MB write loop, and on the TLS jobs a Tcl client pushing 1MB values only manages about 180KB/s. This sets repl-timeout 3600 on both servers, since the stall is injected by the test and the timeout should not fire at all.

Details

Problem

Upstream record: valkey-io/valkey#3923 (open, 5 occurrences, all *-tls-module jobs). Latest: test-almalinux9-tls-module run 34727724387.

[err]: Dual channel replication buffer memory fields in tests/integration/dual-channel-replication.tcl
replica didn't receive the data in time

Chain, at agents/unstable:

  1. tests/integration/dual-channel-replication.tcl:1542 sets rdb-key-save-delay 2000000 over 1000 keys, so the BGSAVE child emits one 20 byte key every 2s. rioConnset buffers, so the replica's RDB socket gets nothing after the $EOF: preamble.
  2. server.repl_transfer_lastio only advances on a real RDB-channel read (src/replication.c:3248), so it stays pinned at sync start.
  3. src/replication.c:5374-5379 trips the bulk-transfer timeout. repl-timeout defaults to 60 (src/config.c:3500) and this test never overrides it, unlike 20 other repl-timeout calls in the same file.
  4. cancelReplicationHandshake calls freePendingReplDataBuf (src/replication.c:3070), which zeroes server.pending_repl_data.mem (src/replication.c:3022). That field is exactly what backs mem_total_replication_buffers and mem_replicas_repl_buffer (src/server.c:6418-6419).
  5. The reconnect hits src/replication.c:1286 "Current BGSAVE has socket target. Waiting for next BGSAVE for SYNC", so no new stream arrives and the buffer cannot refill. Unrecoverable once the timeout fires.

The failing CI run's main-channel client shows tot-net-out=11264508 and omem=20504 at disconnect: 11MB of the intended 51MB in 61s, with no write backlog on the primary. The bottleneck is the Tcl TLS client, about 180KB/s.

Reproduction

The knob is repl-timeout. The test's budget is repl-timeout seconds; squeeze it below the write loop's duration and the CI failure appears verbatim. No test edit needed, --config supplies it, and the target test is extracted to its own file because --only cannot skip the out-of-test wait_process_paused scaffolding at line 832.

sed -n '1520,1610p' tests/integration/dual-channel-replication.tcl > tests/integration/repro-41.tcl
./runtest --single integration/repro-41 --config repl-timeout 1 --loops 5

Before, 5/5 fail:

[err]: Dual channel replication buffer memory fields in tests/integration/repro-41.tcl
replica didn't receive the data in time
[err]: Dual channel replication buffer memory fields in tests/integration/repro-41.tcl
replica didn't receive the data in time
[err]: Dual channel replication buffer memory fields in tests/integration/repro-41.tcl
replica didn't receive the data in time
[err]: Dual channel replication buffer memory fields in tests/integration/repro-41.tcl
replica didn't receive the data in time
[err]: Dual channel replication buffer memory fields in tests/integration/repro-41.tcl
replica didn't receive the data in time
Test Summary: 0 passed, 5 failed

Server logs match the CI timeline exactly. Primary:

32347:M 16 Sep 2026 04:49:14.249 * Starting BGSAVE for SYNC with target: replicas sockets using: dual-channel
32347:M 16 Sep 2026 04:49:16.177 * Current BGSAVE has socket target. Waiting for next BGSAVE for SYNC

Replica:

32403:S 16 Sep 2026 04:49:14.249 * Dual channel replication: PSYNC is not possible, initialize RDB channel.
32403:S 16 Sep 2026 04:49:16.177 # Timeout receiving bulk data from PRIMARY... If the problem persists try to set the 'repl-timeout' parameter in valkey.conf to a larger value.
32403:S 16 Sep 2026 04:49:16.177 * Dual channel replication: Aborting dual channel sync
32403:S 16 Sep 2026 04:49:16.177 * Dual channel replication: PSYNC is not possible, initialize RDB channel.

After, with --config repl-timeout 1 still applied so the test's own config set is what wins, 5/5 pass:

[ok]: Dual channel replication buffer memory fields (3175 ms)
[ok]: Dual channel replication buffer memory fields (3178 ms)
[ok]: Dual channel replication buffer memory fields (3281 ms)
[ok]: Dual channel replication buffer memory fields (3282 ms)
[ok]: Dual channel replication buffer memory fields (3288 ms)
Test Summary: 5 passed, 0 failed

TLS could not be exercised locally, package require tls is unavailable on this host, so the throughput half of the diagnosis rests on the CI tot-net-out figure rather than a local measurement.

Why not the alternative fixes

valkey-io/valkey#4309 replaces the fixed 50 writes with a loop that sends until the replica buffer reaches the threshold. It does not fix this failure. The constraint is wall clock, not write count: at 180KB/s the 40MB target is unreachable inside 60s regardless of loop shape, and once the timeout fires the buffer is zeroed with no path to refill.

Scaling the 40MB and 10MB thresholds down would also work, but it weakens what the test checks and still leaves a wall-clock budget that a slow enough runner can blow.

Testing

The test suite has no repl-timeout state to leak here, both config set calls are scoped to servers this test starts.

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

The test freezes the socket-target BGSAVE with rdb-key-save-delay 2000000
so the replica stays in REPL_STATE_TRANSFER while 50MB is pushed through
the main channel. rioConnset buffers the child's output, so the replica's
RDB socket receives nothing and server.repl_transfer_lastio never advances
(src/replication.c:3248). The default 60s repl-timeout then aborts the sync
(src/replication.c:5374-5379), cancelReplicationHandshake frees the pending
buffer being measured (src/replication.c:3070), and the reconnect is parked
behind the still-running BGSAVE (src/replication.c:1286), so
mem_total_replication_buffers can never reach the 40MB threshold.

That gives the test a hard repl-timeout-second wall clock budget for the
50MB write loop. On the TLS jobs a Tcl client pushing 1MB values manages
about 180KB/s, so the loop needs minutes and the test fails.

Set repl-timeout to 3600 on both servers. The stall is injected by the
test, so the timeout should not fire at all.

Fixes valkey-io/valkey#3923

Signed-off-by: Madelyn Olson <matolson@amazon.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant