Skip to content

[TEST-FAILURE] Primaries will not time out then they are elected in the same epoch in tests/unit/cluster/failover2.tcl #3932

Closed
#3946
Closed
[TEST-FAILURE] Primaries will not time out then they are elected in the same epoch in tests/unit/cluster/failover2.tcl#3932
#3946
Labels
test-failureAn issue indicating a test failure

Description

@github-actions
github-actions
bot
opened on Jun 7, 2026

Summary

Primaries will not time out then they are elected in the same epoch in tests/unit/cluster/failover2.tcl is failing in CI.

Failing test(s)

  • Test name: Primaries will not time out then they are elected in the same epoch
  • Test file: tests/unit/cluster/failover2.tcl
  • CI link(s):
  • test-sanitizer-address-gcc: CI link

Error stack trace

expected pattern not found in srv -7 log file: *Failover attempt expired*, but instead got: ### Starting server for test 
48923:M 07 Jun 2026 00:48:57.768 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
48923:M 07 Jun 2026 00:48:57.768 * oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo
48923:M 07 Jun 2026 00:48:57.768 * Valkey version=255.255.255, bits=64, commit=c8c38e77, modified=0, pid=48923, just started
48923:M 07 Jun 2026 00:48:57.768 * Configuration loaded
48923:M 07 Jun 2026 00:48:57.810 * monotonic clock: X86 TSC @ 2595.89 ticks/us
48923:M 07 Jun 2026 00:48:57.812 # Failed to write PID file: Permission denied
                .+^+.                                                
            .+#########+.                                            
        .+########+########+.           Valkey 255.255.255 (c8c38e77/0) 64 bit
    .+########+'     '+########+.                                    
 .########+'     .+.     '+########.    Running in cluster mode
 |####+'     .+#######+.     '+####|    Port: 28224
 |###|   .+###############+.   |###|    PID: 48923                     
 |###|   |#####*'' ''*#####|   |###|                                 
 |###|   |####'  .-.  '####|   |###|                                 
 |###|   |###(  (@@@)  )###|   |###|          https://valkey.io      
 |###|   |####.  '-'  .####|   |###|                                 
 |###|   |#####*.   .*#####|   |###|                                 
 |###|   '+#####|   |#####+'   |###|                                 
 |####+.     +##|   |#+'     .+####|                                 
 '#######+   |##|        .+########'                                 
    '+###|   |##|    .+########+'                                    
        '|   |####+########+'                                        
             +#########+'                                            
                '+v+'                                                

48923:M 07 Jun 2026 00:48:57.812 * No cluster configuration found, I'm 1b3c638fcb56a6cd722066fe21800a06956aed22
48923:M 07 Jun 2026 00:48:57.835 * Static Module 'lua' successfully loaded
48923:M 07 Jun 2026 00:48:57.839 * Server initialized
48923:M 07 Jun 2026 00:48:57.840 * Ready to accept connections tcp
48923:M 07 Jun 2026 00:48:57.840 * Ready to accept connections unix
48923:M 07 Jun 2026 00:48:57.877 - Accepted 127.0.0.1:43131
48923:M 07 Jun 2026 00:48:57.880 - Client closed connection id=3 addr=127.0.0.1:43131 laddr=127.0.0.1:28224 fd=12 name= age=0 idle=0 flags=N capa= db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=0 qbuf-free=16384 argv-mem=0 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=33350 events=r cmd=ping user=default redir=-1 resp=2 lib-name= lib-ver= tot-net-in=7 tot-net-out=7 tot-cmds=1
48923:M 07 Jun 2026 00:48:57.898 - Accepted 127.0.0.1:41771
48923:M 07 Jun 2026 00:48:59.860 # Cluster is currently down: I am part of a minority partition.
48923:M 07 Jun 2026 00:48:59.924 * configEpoch set to 8 via CLUSTER SET-CONFIG-EPOCH
48923:M 07 Jun 2026 00:49:00.086 - Accepting cluster node connection from 127.0.0.1:47760
48923:M 07 Jun 2026 00:49:00.086 * IP address for this node updated to 127.0.0.1
48923:M 07 Jun 2026 00:49:00.086 - Bound cluster node 5d79adeb17d03cce3be5534c517f68ad7b283a94 (127.0.0.1:28231) to connection of client 127.0.0.1:47760
48923:M 07 Jun 2026 00:49:00.361 - Accepting cluster node connection from 127.0.0.1:47774
48923:M 07 Jun 2026 00:49:00.437 - Accepting cluster node connection from 127.0.0.1:47778
48923:M 07 Jun 2026 00:49:00.704 - Accepting cluster node connection from 127.0.0.1:47782
48923:M 07 Jun 2026 00:49:00.737 - Accepting cluster node connection from 127.0.0.1:47796
48923:M 07 Jun 2026 00:49:00.776 * Mismatch in topology information for sender node ef6ca2e183773b4f09a27cff227bc03fe50c2327 (127.0.0.1:28231) in shard b5b820a8321ef68ccd0b2452eb52deaf6a6adf36
48923:M 07 Jun 2026 00:49:00.783 # Cluster is currently down: At least one hash slot is not served by any available node. Please check the 'cluster-require-full-coverage' configuration.
48923:M 07 Jun 2026 00:49:00.799 - Accepting cluster node connection from 127.0.0.1:47804
48923:M 07 Jun 2026 00:49:00.799 - Accepting cluster node connection from 127.0.0.1:47816
48923:M 07 Jun 2026 00:49:00.889 * Mismatch in topology information for sender node 0c53885e1af926cda930879e7d009f59bd8c9022 (127.0.0.1:28229) in shard 84e6fd47b684b0de9379d0d96abcac88061389e2
48923:M 07 Jun 2026 00:49:00.909 * Mismatch in topology information for sender node c2767c8e7750d3c058786a4921e581c699796df7 (127.0.0.1:28228) in shard 8c7350de952f3ef538fdd3e74d4f90f8d4fac59a
48923:M 07 Jun 2026 00:49:00.911 - Accepting cluster node connection from 127.0.0.1:47830
48923:M 07 Jun 2026 00:49:00.946 - Bound cluster node c2767c8e7750d3c058786a4921e581c699796df7 (R3) to connection of client 127.0.0.1:47830
48923:M 07 Jun 2026 00:49:00.987 * Mismatch in topology information for sender node 7de67e27b710cdf120bb275f12ce1673153e1618 (127.0.0.1:28227) in shard f31e559dafa21aa1365372812327cfefe16540a7
48923:M 07 Jun 2026 00:49:01.020 * Mismatch in topology information for sender node 952b2f770893843fc03d7349b32f21a9dff7baae (127.0.0.1:28226) in shard d9650bb0c3ffc2477443cc8f0e23f1a8ce7a43f8
48923:M 07 Jun 2026 00:49:01.111 * Mismatch in topology information for sender node e0e1754bdfa4a968b402ccbcf74ec89b3d74af0f (127.0.0.1:28225) in shard d7b628594771624c9396becb1067be07906b419d
48923:M 07 Jun 2026 00:49:01.138 - Accepting cluster node connection from 127.0.0.1:47836
48923:M 07 Jun 2026 00:49:01.138 - Bound cluster node e0e1754bdfa4a968b402ccbcf74ec89b3d74af0f (R6) to connection of client 127.0.0.1:47836
48923:M 07 Jun 2026 00:49:01.387 - Bound cluster node 952b2f770893843fc03d7349b32f21a9dff7baae (R5) to connection of client 127.0.0.1:47774
48923:M 07 Jun 2026 00:49:01.898 * Mismatch in topology information for sender node 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (127.0.0.1:28230) in shard f8b7f263c11b9782a51a4a9d1f15c944416ded06
48923:M 07 Jun 2026 00:49:02.005 - Bound cluster node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) to connection of client 127.0.0.1:47816
48923:M 07 Jun 2026 00:49:02.024 - Bound cluster node 0c53885e1af926cda930879e7d009f59bd8c9022 (R2) to connection of client 127.0.0.1:47782
48923:M 07 Jun 2026 00:49:02.056 - Bound cluster node 7de67e27b710cdf120bb275f12ce1673153e1618 (R4) to connection of client 127.0.0.1:47796
48923:M 07 Jun 2026 00:49:02.068 - Bound cluster node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) to connection of client 127.0.0.1:47778
48923:M 07 Jun 2026 00:49:02.108 - Bound cluster node 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1) to connection of client 127.0.0.1:47804
48923:M 07 Jun 2026 00:49:02.212 # Missing implement of connection type tls
48923:S 07 Jun 2026 00:49:02.267 * Connecting to PRIMARY 127.0.0.1:28231
48923:S 07 Jun 2026 00:49:02.268 * PRIMARY <-> REPLICA sync started
48923:S 07 Jun 2026 00:49:02.268 * Cluster state changed: ok
48923:S 07 Jun 2026 00:49:02.276 * Non blocking connect for SYNC fired the event.
48923:S 07 Jun 2026 00:49:02.279 * Primary replied to PING, replication can continue...
48923:S 07 Jun 2026 00:49:02.294 * Node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) is no longer primary of shard 0004ac1b825cf213240fed542a85d47ddc9122d8; removed all 0 slot(s) it used to own
48923:S 07 Jun 2026 00:49:02.294 * Node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) is now part of shard cd784d82c205fd34587fd968d20e05357fd0c809
48923:S 07 Jun 2026 00:49:02.294 * Node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) is now a replica of node 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1) in shard cd784d82c205fd34587fd968d20e05357fd0c809
48923:S 07 Jun 2026 00:49:02.295 * Node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) is no longer primary of shard 64cbfbd99be698498d82e254e6417cb7e3747474; removed all 0 slot(s) it used to own
48923:S 07 Jun 2026 00:49:02.295 * Node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) is now part of shard 35146bc48122a2a97c40c92b7b034e43fa0fff01
48923:S 07 Jun 2026 00:49:02.295 * Node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) is now a replica of node 0c53885e1af926cda930879e7d009f59bd8c9022 (R2) in shard 35146bc48122a2a97c40c92b7b034e43fa0fff01
48923:S 07 Jun 2026 00:49:02.325 * Partial resynchronization not possible (no cached primary)
48923:S 07 Jun 2026 00:49:02.330 * Full resync from primary: d1ebc14a4ed83a1e9320a9d0510b9a10bab6f8a9:0
48923:S 07 Jun 2026 00:49:02.340 * Replica main thread creating Bio thread to save RDB to disk
48923:S 07 Jun 2026 00:49:02.345 * Replica bio thread: PRIMARY <-> REPLICA sync: receiving streamed RDB from primary with EOF to disk
48923:S 07 Jun 2026 00:49:02.346 * Replica bio thread: Done downloading RDB
48923:S 07 Jun 2026 00:49:02.351 # DEBUG LOG: ========== I am replica 7 ==========
48923:S 07 Jun 2026 00:49:02.927 * Replica main thread detected RDB download completion in Bio thread
48923:S 07 Jun 2026 00:49:02.927 * Loading the RDB and finalizing primary-replica sync...
48923:S 07 Jun 2026 00:49:02.928 * PRIMARY <-> REPLICA sync: Loading DB in memory
48923:S 07 Jun 2026 00:49:02.928 * Cleaning slot migration log in anticipation of a load operation.
48923:S 07 Jun 2026 00:49:02.928 * RDB signature and version check passed. Flushing old data
48923:S 07 Jun 2026 00:49:02.929 * Loading RDB produced by Valkey version 255.255.255
48923:S 07 Jun 2026 00:49:02.929 * RDB age 0 seconds
48923:S 07 Jun 2026 00:49:02.929 * RDB memory usage when created 2.63 Mb
48923:S 07 Jun 2026 00:49:02.929 * Done loading RDB, keys loaded: 0, keys expired: 0, all fields expired hashes: 0.
48923:S 07 Jun 2026 00:49:02.929 * PRIMARY <-> REPLICA sync: Finished with success
### Starting test Primaries will not time out then they are elected in the same epoch in tests/unit/cluster/failover2.tcl
48923:S 07 Jun 2026 00:49:09.147 - Node 7de67e27b710cdf120bb275f12ce1673153e1618 (R4) reported node 0c53885e1af926cda930879e7d009f59bd8c9022 (R2) as not reachable.
48923:S 07 Jun 2026 00:49:09.147 - Node 7de67e27b710cdf120bb275f12ce1673153e1618 (R4) reported node 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1) as not reachable.
48923:S 07 Jun 2026 00:49:09.148 - Node e0e1754bdfa4a968b402ccbcf74ec89b3d74af0f (R6) reported node ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0) as not reachable.
48923:S 07 Jun 2026 00:49:09.161 * NODE ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0) possibly failing.
48923:S 07 Jun 2026 00:49:09.161 * NODE 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1) possibly failing.
48923:S 07 Jun 2026 00:49:09.219 - Node c2767c8e7750d3c058786a4921e581c699796df7 (R3) reported node 0c53885e1af926cda930879e7d009f59bd8c9022 (R2) as not reachable.
48923:S 07 Jun 2026 00:49:09.219 - Node c2767c8e7750d3c058786a4921e581c699796df7 (R3) reported node ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0) as not reachable.
48923:S 07 Jun 2026 00:49:09.491 * FAIL message received from a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) about 0c53885e1af926cda930879e7d009f59bd8c9022 (R2)
48923:S 07 Jun 2026 00:49:09.491 # Cluster state changed: fail
48923:S 07 Jun 2026 00:49:09.491 # Cluster is currently down: At least one hash slot is not served by any available node. Please check the 'cluster-require-full-coverage' configuration.
48923:S 07 Jun 2026 00:49:09.642 * Reconfiguring node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) as primary for shard 35146bc48122a2a97c40c92b7b034e43fa0fff01
48923:S 07 Jun 2026 00:49:09.642 * Mismatch in topology information for sender node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) in shard 35146bc48122a2a97c40c92b7b034e43fa0fff01
48923:S 07 Jun 2026 00:49:09.643 - Node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) reported node ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0) as not reachable.
48923:S 07 Jun 2026 00:49:09.643 - Node a2a09a5cc00cbcfbc832e63639c4a7adead8cb38 (R9) reported node 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1) as not reachable.
48923:S 07 Jun 2026 00:49:09.643 * Cluster state changed: ok
48923:S 07 Jun 2026 00:49:09.714 * FAIL message received from 952b2f770893843fc03d7349b32f21a9dff7baae (R5) about ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0)
48923:S 07 Jun 2026 00:49:09.714 # Cluster state changed: fail
48923:S 07 Jun 2026 00:49:09.714 # Cluster is currently down: At least one hash slot is not served by any available node. Please check the 'cluster-require-full-coverage' configuration.
48923:S 07 Jun 2026 00:49:09.714 * This is the best ranked replica and can initiate the election immediately.
48923:S 07 Jun 2026 00:49:09.714 * Start of election delayed for 0 milliseconds (rank #0, primary rank #0, offset 14).
48923:S 07 Jun 2026 00:49:09.714 * Starting a failover election for epoch 12, node config epoch is 1
48923:S 07 Jun 2026 00:49:09.740 * FAIL message received from 7de67e27b710cdf120bb275f12ce1673153e1618 (R4) about 1bbba6ad9b94fc81bb49bb6bab11f01a072c5b95 (R1)
48923:S 07 Jun 2026 00:49:09.759 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:09.759 * Needed quorum: 4. Number of votes received so far: 1
48923:S 07 Jun 2026 00:49:10.096 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:10.096 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:11.023 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:11.023 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:12.060 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:12.060 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:13.095 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:13.095 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:14.012 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:14.012 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:15.036 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:15.048 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:15.782 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:15.782 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:16.086 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:16.086 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:17.019 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:17.019 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:18.061 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:18.061 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:19.091 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:19.091 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:20.014 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:20.014 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:21.051 * Currently unable to failover: Failover attempt expired.
48923:S 07 Jun 2026 00:49:21.051 * Needed quorum: 4. Number of votes received so far: 2
48923:S 07 Jun 2026 00:49:21.765 * This is the best ranked replica and can initiate the election immediately.
48923:S 07 Jun 2026 00:49:21.765 * Start of election delayed for 0 milliseconds (rank #0, primary rank #0, offset 14).
48923:S 07 Jun 2026 00:49:21.765 * Starting a failover election for epoch 13, node config epoch is 1
48923:S 07 Jun 2026 00:49:21.801 * Currently unable to failover: Waiting for votes, but majority still not reached.
48923:S 07 Jun 2026 00:49:21.801 * Needed quorum: 4. Number of votes received so far: 1
48923:S 07 Jun 2026 00:49:21.805 * Failover election won: I'm the new primary.
48923:S 07 Jun 2026 00:49:21.805 * configEpoch set to 13 after successful failover
48923:S 07 Jun 2026 00:49:21.805 * Setting myself to primary in shard c6c9393654a5c0403aea3d10aede331d2c8ec458 after failover; my old primary is ef6ca2e183773b4f09a27cff227bc03fe50c2327 (R0)
48923:S 07 Jun 2026 00:49:21.805 * Reconfiguring node 1b3c638fcb56a6cd722066fe21800a06956aed22 (R7) as primary for shard c6c9393654a5c0403aea3d10aede331d2c8ec458
48923:M 07 Jun 2026 00:49:21.805 * Connection with primary lost.
48923:M 07 Jun 2026 00:49:21.805 * Caching the disconnected primary state.
48923:M 07 Jun 2026 00:49:21.805 * Discarding previously cached primary state.
48923:M 07 Jun 2026 00:49:21.805 * Setting secondary replication ID to d1ebc14a4ed83a1e9320a9d0510b9a10bab6f8a9, valid up to offset: 15. New replication ID is 1d50e1f774f24da91672c0a1d88b8867d7bdd6a7
48923:M 07 Jun 2026 00:49:21.870 * Failover auth granted to 9e01f186876271dc64a2cd4837d6e03783925601 (R8) for epoch 14
48923:M 07 Jun 2026 00:49:21.924 * Reconfiguring node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) as primary for shard cd784d82c205fd34587fd968d20e05357fd0c809
48923:M 07 Jun 2026 00:49:21.924 * Mismatch in topology information for sender node 9e01f186876271dc64a2cd4837d6e03783925601 (R8) in shard cd784d82c205fd34587fd968d20e05357fd0c809
48923:M 07 Jun 2026 00:49:21.926 * Cluster state changed: ok

Environments: test-sanitizer-address-gcc

Auto-created by Test Failure Detector

Metadata

Metadata

Assignees

No one assigned

    Labels

    test-failureAn issue indicating a test failure

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions