Split brain recovery

General
1

I have an issue here I’m not sure how to proceed with. I’m currently on drbd 9.2.15 and linstor 1.32.3 on PVE8, and trying to make sure everything is clean before upgrading.

Everything looks fine except there is one linstor/drbd resource set in a weird state:

╭──────────────────────────────────────────────────────────────────────────────────────────╮
│ ResourceName │ Node     │ Layers       │ Usage  │ Conns                │    State │ Vote │
╞══════════════════════════════════════════════════════════════════════════════════════════╡
│ pm-a565d280  │ virtual1 │ DRBD,STORAGE │ Unused │ Ok                   │ UpToDate │ Yes  │
│ pm-a565d280  │ virtual5 │ DRBD,STORAGE │ Unused │ StandAlone(virtual6) │ UpToDate │ Yes  │
│ pm-a565d280  │ virtual6 │ DRBD,STORAGE │ InUse  │ StandAlone(virtual5) │ UpToDate │ Yes  │
╰──────────────────────────────────────────────────────────────────────────────────────────╯

This is a Proxmox VM running on node virtual6.

Here’s the info from drbdadm status:

brian@virtual1:~$ sudo drbdadm status | grep -A6 pm-a565d280
pm-a565d280 role:Secondary
  disk:UpToDate open:no
  virtual5 role:Secondary
    peer-disk:UpToDate
  virtual6 role:Primary
    peer-disk:UpToDate

brian@virtual5:~$ sudo drbdadm status | grep -A6 pm-a565d280
pm-a565d280 role:Secondary
  disk:UpToDate open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:StandAlone

brian@virtual6:~$ sudo drbdadm status | grep -A6 pm-a565d280
pm-a565d280 role:Primary
  disk:UpToDate open:yes
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual5 connection:StandAlone

ss shows tcp connections between virtual1 and virtual6, and virtual1 and virtual5, but not virtual5 and virtual6

brian@virtual1:~$ linstor resource list -o rsc_name,drbd_ports -r pm-a565d280
╭───────────────────────────╮
│ ResourceName │ DRBD Ports │
╞═══════════════════════════╡
│ pm-a565d280  │ 7001       │
│ pm-a565d280  │ 7001       │
│ pm-a565d280  │ 7001       │
╰───────────────────────────╯

brian@virtual1:~$ ss -ntp sport 7001 or dport 7001
State              Recv-Q              Send-Q                            Local Address:Port                              Peer Address:Port               Process
ESTAB              0                   0                                      10.0.0.1:7001                                  10.0.0.5:38249
ESTAB              0                   0                                      10.0.0.1:7001                                  10.0.0.6:42305
ESTAB              0                   0                                      10.0.0.1:43279                                 10.0.0.6:7001
ESTAB              0                   0                                      10.0.0.1:45159                                 10.0.0.5:7001

brian@virtual5:~$ ss -ntp sport 7001 or dport 7001
State              Recv-Q              Send-Q                            Local Address:Port                              Peer Address:Port               Process
ESTAB              0                   0                                      10.0.0.5:7001                                  10.0.0.1:45159
ESTAB              0                   0                                      10.0.0.5:38249                                 10.0.0.1:7001

brian@virtual6:~$ ss -ntp sport 7001 or dport 7001
State              Recv-Q              Send-Q                            Local Address:Port                              Peer Address:Port               Process
ESTAB              0                   0                                      10.0.0.6:42305                                 10.0.0.1:7001
ESTAB              0                   0                                      10.0.0.6:7001                                  10.0.0.1:43279

Here are dmesg logs from virtual6:

[7391908.443059] drbd pm-a565d280: Preparing cluster-wide state change 1727548113: 2->all role( Primary )
[7391908.443969] drbd pm-a565d280: State change 1727548113: primary_nodes=5, weak_nodes=FFFFFFFFFFFFFFF8
[7391908.444342] drbd pm-a565d280: Committing cluster-wide state change 1727548113 (2ms)
[7391908.444644] drbd pm-a565d280: role( Secondary -> Primary ) [kvm:2987951 auto-promote]
[7720329.599402] drbd pm-a565d280 virtual5: [drbd_s_pm-a565d/1661603] sending time expired, ko = 6
[7720335.743416] drbd pm-a565d280 virtual5: [drbd_s_pm-a565d/1661603] sending time expired, ko = 5
[7720341.887428] drbd pm-a565d280 virtual5: [drbd_s_pm-a565d/1661603] sending time expired, ko = 4
[7720348.031452] drbd pm-a565d280 virtual5: [drbd_s_pm-a565d/1661603] sending time expired, ko = 3
[7720353.151488] drbd pm-a565d280/0 drbd1001 virtual1: We did not send a P_BARRIER for 42184ms > ko-count (7) * timeout (60 * 0.1s); drbd kernel thread blocked?
[7720353.152061] drbd pm-a565d280/0 drbd1001 virtual5: Remote failed to finish a request within 42281ms > ko-count (7) * timeout (60 * 0.1s)
[7720353.152585] drbd pm-a565d280 virtual5: conn( Connected -> Timeout ) peer( Primary -> Unknown ) [timeout]
[7720353.152853] drbd pm-a565d280/0 drbd1001 virtual5: pdsk( UpToDate -> DUnknown ) repl( Established -> Off ) [timeout]
[7720353.153307] drbd pm-a565d280 tcp:virtual5: dtt_send_page: size=4096 len=2212 sent=-4
[7720353.153655] drbd pm-a565d280 virtual5: Terminating sender thread
[7720353.153945] drbd pm-a565d280 virtual5: Starting sender thread (peer-node-id 0)
[7720353.161890] drbd pm-a565d280: Preparing cluster-wide state change 4067492453: 2->all empty
[7720353.171013] drbd pm-a565d280: Declined by peer virtual1 (id: 1), see the kernel log there
[7720353.171018] drbd pm-a565d280/0 drbd1001: new current UUID: CE19EB05CD99195F weak: FFFFFFFFFFFFFFF9
[7720353.171300] drbd pm-a565d280: Aborting cluster-wide state change 4067492453 (9ms) rv = -10
[7720353.172472] drbd pm-a565d280 virtual5: Connection closed
[7720353.172789] drbd pm-a565d280 virtual5: helper command: /sbin/drbdadm disconnected
[7720353.228058] drbd pm-a565d280: Preparing remote state change 1522374807: 0->all empty
[7720353.277079] drbd pm-a565d280 virtual1: Committing remote state change 1522374807 (primary_nodes=5)
[7720353.277386] drbd pm-a565d280: State change failed: Refusing to be Outdated while Connected (-6)
[7720353.277657] drbd pm-a565d280/0 drbd1001: Failed: disk( UpToDate -> Outdated ) [far-away]
[7720353.277920] drbd pm-a565d280/0 drbd1001 virtual5: Failed: pdsk( DUnknown -> Outdated ) [far-away]
[7720353.278189] drbd pm-a565d280: FATAL: Local commit of prepared 1522374807 failed!
[7720353.287781] drbd pm-a565d280 virtual5: helper command: /sbin/drbdadm disconnected exit code 0
[7720353.288063] drbd pm-a565d280 virtual5: conn( Timeout -> Unconnected ) [disconnected]
[7720353.314766] drbd pm-a565d280 virtual5: Restarting receiver thread
[7720353.315047] drbd pm-a565d280 virtual5: conn( Unconnected -> Connecting ) [connecting]
[7720353.370393] drbd pm-a565d280: Preparing remote state change 1168424474: 0->all role( Secondary )
[7720353.370690] drbd pm-a565d280: State change failed: Refusing to be Outdated while Connected (-6)
[7720353.370985] drbd pm-a565d280/0 drbd1001: Failed: disk( UpToDate -> Outdated ) [far-away]
[7720353.380993] drbd pm-a565d280 virtual1: Aborting remote state change 1168424474
[7720353.831514] drbd pm-a565d280 virtual5: Handshake to peer 0 successful: Agreed network protocol version 123
[7720353.831920] drbd pm-a565d280 virtual5: Feature flags enabled on protocol level: 0x7f TRIM THIN_RESYNC WRITE_SAME WRITE_ZEROES RESYNC_DAGTAG
[7720353.841633] drbd pm-a565d280 virtual5: Peer authenticated using 20 bytes HMAC
[7720353.851273] drbd pm-a565d280: Preparing remote state change 1752104334: 0->2 role( Primary ) conn( Connected )
[7720353.860352] drbd pm-a565d280/0 drbd1001 virtual5: drbd_sync_handshake:
[7720353.860706] drbd pm-a565d280/0 drbd1001 virtual5: self CE19EB05CD99195F:5F3737112A90D0EE:7049016D775874D6:A45AC845BE96E2AE bits:44533 flags:120
[7720353.861410] drbd pm-a565d280/0 drbd1001 virtual5: peer 7049016D775874D7:5F3737112A90D0EF:CE19EB05CD99195E:66A717399223FE36 bits:1040 flags:1120
[7720353.862094] drbd pm-a565d280/0 drbd1001 virtual5: uuid_compare()=split-brain-auto-recover by rule=bitmap-both
[7720353.862428] drbd pm-a565d280/0 drbd1001 virtual5: helper command: /sbin/drbdadm initial-split-brain
[7720353.871428] drbd pm-a565d280/0 drbd1001 virtual5: helper command: /sbin/drbdadm initial-split-brain exit code 0
[7720353.871773] drbd pm-a565d280/0 drbd1001 virtual5: Split-Brain detected but unresolved, dropping connection!
[7720353.872155] drbd pm-a565d280/0 drbd1001 virtual5: helper command: /sbin/drbdadm split-brain
[7720353.881154] drbd pm-a565d280/0 drbd1001 virtual5: helper command: /sbin/drbdadm split-brain exit code 0
[7720353.895588] drbd pm-a565d280 virtual5: Aborting remote state change 1752104334
[7720353.895927] drbd pm-a565d280 virtual5: conn( Connecting -> Disconnecting ) [receive-disconnect]
[7720353.904890] drbd pm-a565d280 virtual5: Terminating sender thread
[7720353.905266] drbd pm-a565d280 virtual5: Starting sender thread (peer-node-id 0)
[7720353.915173] drbd pm-a565d280 virtual5: Connection closed
[7720353.915526] drbd pm-a565d280 virtual5: helper command: /sbin/drbdadm disconnected
[7720353.924578] drbd pm-a565d280 virtual5: helper command: /sbin/drbdadm disconnected exit code 0
[7720353.924909] drbd pm-a565d280 virtual5: conn( Disconnecting -> StandAlone ) [disconnected]
[7720353.925256] drbd pm-a565d280 virtual5: Terminating receiver thread
[7720358.785579] drbd pm-a565d280: Preparing remote state change 2156534139: 0->all role( Secondary )
[7720358.812901] drbd pm-a565d280 virtual1: Committing remote state change 2156534139 (primary_nodes=4)

and virtual5:

[25077768.314400] drbd pm-a565d280: Preparing remote state change 1727548113: 2->all role( Primary )
[25077768.323836] drbd pm-a565d280 virtual6: Committing remote state change 1727548113 (primary_nodes=5)
[25077768.324126] drbd pm-a565d280 virtual6: peer( Secondary -> Primary ) [remote]
[25406213.797687] drbd pm-a565d280 virtual6: meta connection shut down by peer.
[25406213.798011] drbd pm-a565d280 virtual6: conn( Connected -> NetworkFailure ) peer( Primary -> Unknown )
[25406213.798363] drbd pm-a565d280/0 drbd1001 virtual6: pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
[25406213.798763] drbd pm-a565d280: Preparing remote state change 4067492453: 2->all empty
[25406213.798801] drbd pm-a565d280 virtual6: meta connection shut down by peer.
[25406213.799033] drbd pm-a565d280: State change failed: Refusing to be Outdated while Connected (-6)
[25406213.799509] drbd pm-a565d280/0 drbd1001: Failed: disk( UpToDate -> Outdated ) [far-away]
[25406213.799802] drbd pm-a565d280/0 drbd1001 virtual6: Failed: pdsk( DUnknown -> Outdated ) [far-away]
[25406213.800149] drbd pm-a565d280 virtual6: Terminating sender thread
[25406213.800410] drbd pm-a565d280 virtual6: Starting sender thread (peer-node-id 2)
[25406213.816452] drbd pm-a565d280 virtual1: Aborting remote state change 4067492453
[25406213.817886] drbd pm-a565d280: Preparing cluster-wide state change 1522374807: 0->all empty
[25406213.831456] drbd pm-a565d280/0 drbd1001: new current UUID: 7049016D775874D7 weak: FFFFFFFFFFFFFFFC
[25406213.845505] drbd pm-a565d280 virtual6: Connection closed
[25406213.845835] drbd pm-a565d280 virtual6: helper command: /sbin/drbdadm disconnected
[25406213.854933] drbd pm-a565d280 virtual6: helper command: /sbin/drbdadm disconnected exit code 0
[25406213.855263] drbd pm-a565d280 virtual6: conn( NetworkFailure -> Unconnected ) [disconnected]
[25406213.855571] drbd pm-a565d280 virtual6: Restarting receiver thread
[25406213.855831] drbd pm-a565d280 virtual6: conn( Unconnected -> Connecting ) [connecting]
[25406213.872384] drbd pm-a565d280: State change 1522374807: primary_nodes=5, weak_nodes=FFFFFFFFFFFFFFFD
[25406213.872733] drbd pm-a565d280: Committing cluster-wide state change 1522374807 (55ms)
[25406213.873024] drbd pm-a565d280: State change failed: Refusing to be Outdated while Connected (-6)
[25406213.873285] drbd pm-a565d280/0 drbd1001: Failed: disk( UpToDate -> Outdated ) [lost-peer]
[25406213.873574] drbd pm-a565d280: FATAL: Local commit of already committed 1522374807 failed!
[25406214.004183] drbd pm-a565d280: Preparing cluster-wide state change 1168424474: 0->all role( Secondary )
[25406214.013692] drbd pm-a565d280: Aborting cluster-wide state change 1168424474 (9ms) rv = -10
[25406214.014231] drbd pm-a565d280: Declined by peer virtual1 (id: 1), see the kernel log there
[25406214.014236] drbd pm-a565d280: Auto-demote failed: State change was refused by peer node (-10)
[25406214.466708] drbd pm-a565d280 virtual6: Handshake to peer 2 successful: Agreed network protocol version 123
[25406214.467071] drbd pm-a565d280 virtual6: Feature flags enabled on protocol level: 0x7f TRIM THIN_RESYNC WRITE_SAME WRITE_ZEROES RESYNC_DAGTAG
[25406214.476716] drbd pm-a565d280 virtual6: Peer authenticated using 20 bytes HMAC
[25406214.485983] drbd pm-a565d280: Preparing cluster-wide state change 1752104334: 0->2 role( Primary ) conn( Connected )
[25406214.509194] drbd pm-a565d280/0 drbd1001 virtual6: drbd_sync_handshake:
[25406214.509568] drbd pm-a565d280/0 drbd1001 virtual6: self 7049016D775874D7:5F3737112A90D0EF:CE19EB05CD99195E:66A717399223FE36 bits:1040 flags:120
[25406214.510172] drbd pm-a565d280/0 drbd1001 virtual6: peer CE19EB05CD99195F:5F3737112A90D0EE:7049016D775874D6:A45AC845BE96E2AE bits:44533 flags:1120
[25406214.510811] drbd pm-a565d280/0 drbd1001 virtual6: uuid_compare()=split-brain-auto-recover by rule=bitmap-both
[25406214.511125] drbd pm-a565d280/0 drbd1001 virtual6: helper command: /sbin/drbdadm initial-split-brain
[25406214.520200] drbd pm-a565d280/0 drbd1001 virtual6: helper command: /sbin/drbdadm initial-split-brain exit code 0
[25406214.520543] drbd pm-a565d280/0 drbd1001 virtual6: Split-Brain detected but unresolved, dropping connection!
[25406214.520912] drbd pm-a565d280/0 drbd1001 virtual6: helper command: /sbin/drbdadm split-brain
[25406214.529946] drbd pm-a565d280/0 drbd1001 virtual6: helper command: /sbin/drbdadm split-brain exit code 0
[25406214.530347] drbd pm-a565d280: Aborting cluster-wide state change 1752104334 (45ms) rv = -27
[25406214.530729] drbd pm-a565d280 virtual6: conn( Connecting -> Disconnecting ) [connect-failed]
[25406214.531100] drbd pm-a565d280 virtual6: Terminating sender thread
[25406214.531498] drbd pm-a565d280 virtual6: Starting sender thread (peer-node-id 2)
[25406214.547701] drbd pm-a565d280 virtual6: Connection closed
[25406214.548089] drbd pm-a565d280 virtual6: helper command: /sbin/drbdadm disconnected
[25406214.557252] drbd pm-a565d280 virtual6: helper command: /sbin/drbdadm disconnected exit code 0
[25406214.557621] drbd pm-a565d280 virtual6: conn( Disconnecting -> StandAlone ) [disconnected]
[25406214.557952] drbd pm-a565d280 virtual6: Terminating receiver thread
[25406219.419456] drbd pm-a565d280: Preparing cluster-wide state change 2156534139: 0->all role( Secondary )
[25406219.421233] drbd pm-a565d280: State change 2156534139: primary_nodes=4, weak_nodes=FFFFFFFFFFFFFFF9
[25406219.422197] drbd pm-a565d280: Committing cluster-wide state change 2156534139 (3ms)
[25406219.423131] drbd pm-a565d280: role( Primary -> Secondary ) [vgs:4029233 auto-demote]

Those timestamps correspond to the time the VM was created - i.e. it has been in some sort of split-brain state all this time, just nobody noticed.

Aside: I already had prometheus alerting rules which noticed states other than “UpToDate”, but in this case, all three think they are “UpToDate”. I don’t understand how all replicas can be “UpToDate” when two of the connections are “StandAlone”. I have now added extra alerting rules to detect drbd_connection_state!="Connected"

Anyway, given that it says clearly “Split-Brain detected but unresolved”, and the primary is on virtual6, I thought all I would need to do is force a resync on virtual5. But sadly, this was not the case:

brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:UpToDate open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:StandAlone

brian@virtual5:~$ sudo drbdadm disconnect pm-a565d280
brian@virtual5:~$ sudo drbdadm connect pm-a565d280 --discard-my-data
brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    replication:SyncTarget peer-disk:UpToDate done:4.39
  virtual6 connection:Connecting

brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    replication:SyncTarget peer-disk:UpToDate done:49.01
  virtual6 connection:Connecting

brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    replication:SyncTarget peer-disk:UpToDate done:87.33
  virtual6 connection:Connecting

brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:Connecting

(How did it replicate from the primary on virtual6, when not connected? Did it replicate from virtual5 instead?)

The new dmesg messages on virtual6:

[13078405.292216] drbd pm-a565d280: Preparing remote state change 3246810944: 0->1 conn( Disconnecting )
[13078405.301812] drbd pm-a565d280 virtual1: Committing remote state change 3246810944 (primary_nodes=4)
[13078414.556180] drbd pm-a565d280: Preparing remote state change 2384590131: 0->1 role( Secondary ) conn( Connected )
[13078414.587058] drbd pm-a565d280 virtual1: Committing remote state change 2384590131 (primary_nodes=4)

and on virtual5:

[30764278.064499] drbd pm-a565d280: Preparing cluster-wide state change 3246810944: 0->1 conn( Disconnecting )
[30764278.066005] drbd pm-a565d280: State change 3246810944: primary_nodes=4, weak_nodes=FFFFFFFFFFFFFFF9
[30764278.066398] drbd pm-a565d280 virtual1: Cluster is now split
[30764278.066785] drbd pm-a565d280: Committing cluster-wide state change 3246810944 (2ms)
[30764278.067187] drbd pm-a565d280 virtual1: conn( Connected -> Disconnecting ) peer( Secondary -> Unknown ) [disconnect]
[30764278.067584] drbd pm-a565d280/0 drbd1001: disk( UpToDate -> Outdated ) quorum( yes -> no ) [disconnect]
[30764278.067967] drbd pm-a565d280/0 drbd1001 virtual1: pdsk( UpToDate -> DUnknown ) repl( Established -> Off ) [disconnect]
[30764278.068501] drbd pm-a565d280 virtual1: Terminating sender thread
[30764278.068894] drbd pm-a565d280 virtual1: Starting sender thread (peer-node-id 1)
[30764278.082632] drbd pm-a565d280 virtual1: Connection closed
[30764278.083011] drbd pm-a565d280 virtual1: helper command: /sbin/drbdadm disconnected
[30764278.085511] drbd pm-a565d280 virtual1: helper command: /sbin/drbdadm disconnected exit code 0
[30764278.085848] drbd pm-a565d280 virtual1: conn( Disconnecting -> StandAlone ) [disconnected]
[30764278.086214] drbd pm-a565d280 virtual1: Terminating receiver thread
[30764278.087406] drbd pm-a565d280: State change failed: Can not disconnect a StandAlone device (-9)
[30764278.087890] drbd pm-a565d280 virtual6: Failed: conn( StandAlone -> Disconnecting ) [disconnect]
[30764286.800923] drbd pm-a565d280 virtual1: conn( StandAlone -> Unconnected ) [connect]
[30764286.801460] drbd pm-a565d280 virtual1: Starting receiver thread (peer-node-id 1)
[30764286.802040] drbd pm-a565d280 virtual1: conn( Unconnected -> Connecting ) [connecting]
[30764286.802499] drbd pm-a565d280 virtual6: conn( StandAlone -> Unconnected ) [connect]
[30764286.802909] drbd pm-a565d280 virtual6: Starting receiver thread (peer-node-id 2)
[30764286.803360] drbd pm-a565d280 virtual6: conn( Unconnected -> Connecting ) [connecting]
[30764287.310290] drbd pm-a565d280 virtual1: Handshake to peer 1 successful: Agreed network protocol version 123
[30764287.310873] drbd pm-a565d280 virtual1: Feature flags enabled on protocol level: 0x7f TRIM THIN_RESYNC WRITE_SAME WRITE_ZEROES RESYNC_DAGTAG
[30764287.320352] drbd pm-a565d280 virtual1: Peer authenticated using 20 bytes HMAC
[30764287.322209] drbd pm-a565d280: Preparing cluster-wide state change 2384590131: 0->1 role( Secondary ) conn( Connected )
[30764287.339225] drbd pm-a565d280/0 drbd1001 virtual1: drbd_sync_handshake:
[30764287.339602] drbd pm-a565d280/0 drbd1001 virtual1: self 7049016D775874D6:0000000000000000:CE19EB05CD99195E:66A717399223FE36 bits:1893 flags:121
[30764287.340212] drbd pm-a565d280/0 drbd1001 virtual1: peer CE19EB05CD99195E:7049016D775874D6:5F3737112A90D0EE:66A717399223FE36 bits:1481801 flags:1100
[30764287.340848] drbd pm-a565d280/0 drbd1001 virtual1: uuid_compare()=target-use-bitmap by rule=bitmap-peer
[30764287.349848] drbd pm-a565d280: State change 2384590131: primary_nodes=4, weak_nodes=FFFFFFFFFFFFFFF8
[30764287.350208] drbd pm-a565d280: Committing cluster-wide state change 2384590131 (28ms)
[30764287.350553] drbd pm-a565d280 virtual1: conn( Connecting -> Connected ) peer( Unknown -> Secondary ) [connected]
[30764287.350881] drbd pm-a565d280/0 drbd1001: quorum( no -> yes ) [connected]
[30764287.351209] drbd pm-a565d280/0 drbd1001 virtual1: pdsk( DUnknown -> UpToDate ) repl( Off -> WFBitMapT ) [connected]
[30764287.351548] drbd pm-a565d280/0 drbd1001: Setting exposed data uuid: CE19EB05CD99195E
[30764287.364345] drbd pm-a565d280/0 drbd1001 virtual1: receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 6587(2), total 6587; compression: 99.8%
[30764287.376106] drbd pm-a565d280/0 drbd1001 virtual1: send bitmap stats [Bytes(packets)]: plain 0(0), RLE 6587(2), total 6587; compression: 99.8%
[30764287.376840] drbd pm-a565d280/0 drbd1001 virtual1: helper command: /sbin/drbdadm before-resync-target
[30764287.385925] drbd pm-a565d280/0 drbd1001 virtual1: helper command: /sbin/drbdadm before-resync-target exit code 0
[30764287.386375] drbd pm-a565d280/0 drbd1001: disk( Outdated -> Inconsistent ) [receive-bitmap]
[30764287.386712] drbd pm-a565d280/0 drbd1001 virtual6: resync-susp( no -> connection dependency ) [receive-bitmap]
[30764287.387065] drbd pm-a565d280/0 drbd1001 virtual1: repl( WFBitMapT -> SyncTarget ) [receive-bitmap]
[30764287.387561] drbd pm-a565d280/0 drbd1001 virtual1: Began resync as SyncTarget (will sync 5927204 KB [1481801 bits set]).
[30764347.623288] drbd pm-a565d280/0 drbd1001 virtual1: Resync done (total 60 sec; paused 0 sec; 98796 K/sec)
[30764347.623756] drbd pm-a565d280/0 drbd1001 virtual1: Peer was unstable during resync
[30764347.624159] drbd pm-a565d280/0 drbd1001 virtual6: resync-susp( connection dependency -> no ) [resync-finished]
[30764347.624508] drbd pm-a565d280/0 drbd1001 virtual1: repl( SyncTarget -> Established ) [resync-finished]
[30764347.624906] drbd pm-a565d280/0 drbd1001 virtual1: helper command: /sbin/drbdadm after-resync-target
[30764347.634214] drbd pm-a565d280/0 drbd1001 virtual1: helper command: /sbin/drbdadm after-resync-target exit code 0

And now I’m in a different, and possibly worse state: the disks are “inconsistent” and there’s still no connection between virtual5 and virtual6.

brian@virtual1:~$ sudo drbdadm status pm-a565d280
[sudo] password for brian:
pm-a565d280 role:Secondary
  disk:UpToDate open:no
  virtual5 role:Secondary
    peer-disk:Inconsistent
  virtual6 role:Primary
    peer-disk:UpToDate

brian@virtual5:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:Connecting

brian@virtual6:~$ sudo drbdadm status pm-a565d280
pm-a565d280 role:Primary
  disk:UpToDate open:yes
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual5 connection:StandAlone

Oddly, linstor shows virtual5 “connecting” to virtual6, and shows 94% sync even though there’s no sync going on (and it’s quite a while since the forced resync completed)

brian@virtual1:~$ linstor r l -r pm-a565d280
╭────────────────────────────────────────────────────────────────────────────────────────────────────╮
│ ResourceName │ Node     │ Layers       │ Usage  │ Conns                │              State │ Vote │
╞════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ pm-a565d280  │ virtual1 │ DRBD,STORAGE │ Unused │ Ok                   │           UpToDate │ Yes  │
│ pm-a565d280  │ virtual5 │ DRBD,STORAGE │ Unused │ Connecting(virtual6) │ SyncTarget(94.94%) │ Yes  │
│ pm-a565d280  │ virtual6 │ DRBD,STORAGE │ InUse  │ StandAlone(virtual5) │           UpToDate │ Yes  │
╰────────────────────────────────────────────────────────────────────────────────────────────────────╯

Anyway… I’m not really sure how to proceed here, and so I’m looking for advice before I risk any further changes.

Thanks in advance,

Brian Candler.

P.S. there are 14 replicated resource definitions in total and none of the others have problem (indeed, 6 of them have InUse status on virtual6). Therefore I have a high degree of confidence that it’s not an issue with networking between the nodes.

2

Additional info: now that I note virtual5 says “Connecting…” to virtual6, I see tcpdump activity: connections are being rejected by virtual6.

root@virtual6:/home/brian# tcpdump -i ens1f1.99 -nn -s0 -v tcp port 7001
tcpdump: listening on ens1f1.99, link-type EN10MB (Ethernet), snapshot length 262144 bytes
06:15:30.685620 IP (tos 0x0, ttl 64, id 47681, offset 0, flags [DF], proto TCP (6), length 60)
    10.0.0.5.42779 > 10.0.0.6.7001: Flags [S], cksum 0x8365 (correct), seq 3901440830, win 62720, options [mss 8960,sackOK,TS val 78031710 ecr 0,nop,wscale 7], length 0
06:15:30.685643 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 40)
    10.0.0.6.7001 > 10.0.0.5.42779: Flags [R.], cksum 0xad86 (correct), seq 0, ack 3901440831, win 0, length 0
06:15:34.067188 IP (tos 0x0, ttl 64, id 7312, offset 0, flags [DF], proto TCP (6), length 68)
    10.0.0.6.7001 > 10.0.0.1.43279: Flags [P.], cksum 0x143d (incorrect -> 0xe0f8), seq 1919727865:1919727881, ack 224561524, win 23481, options [nop,nop,TS val 2965645164 ecr 1427832743], length 16
06:15:34.067299 IP (tos 0x0, ttl 64, id 24047, offset 0, flags [DF], proto TCP (6), length 52)
    10.0.0.1.43279 > 10.0.0.6.7001: Flags [.], cksum 0x0c4b (correct), ack 16, win 31747, options [nop,nop,TS val 1427842663 ecr 2965645164], length 0
06:15:34.067312 IP (tos 0x0, ttl 64, id 24048, offset 0, flags [DF], proto TCP (6), length 68)
    10.0.0.1.43279 > 10.0.0.6.7001: Flags [P.], cksum 0x99dd (correct), seq 1:17, ack 16, win 31747, options [nop,nop,TS val 1427842663 ecr 2965645164], length 16
06:15:34.067320 IP (tos 0x0, ttl 64, id 7313, offset 0, flags [DF], proto TCP (6), length 52)
    10.0.0.6.7001 > 10.0.0.1.43279: Flags [.], cksum 0x142d (incorrect -> 0x2c85), ack 17, win 23481, options [nop,nop,TS val 2965645164 ecr 1427842663], length 0
06:15:42.461674 IP (tos 0x0, ttl 64, id 46034, offset 0, flags [DF], proto TCP (6), length 60)

And virtual6 doesn’t have a listening socket on this port:

root@virtual6:/home/brian# ss -natp sport 7001 or dport 7001
State              Recv-Q              Send-Q                            Local Address:Port                              Peer Address:Port               Process
ESTAB              0                   0                                      10.0.0.6:42305                                 10.0.0.1:7001
ESTAB              0                   0                                      10.0.0.6:7001                                  10.0.0.1:43279

whereas virtual5 does:

root@virtual5:/home/brian# ss -natp sport 7001 or dport 7001
State               Recv-Q              Send-Q                           Local Address:Port                              Peer Address:Port               Process
LISTEN              0                   0                                     10.0.0.5:7001                                   0.0.0.0:*
ESTAB               0                   0                                     10.0.0.5:7001                                  10.0.0.1:42623
ESTAB               0                   0                                     10.0.0.5:51749                                 10.0.0.1:7001

In fact, virtual5 is the only machine listening on any port 7XXX:

root@virtual5:/home/brian# ss -nltp | grep ':7[0-9][0-9][0-9]'
LISTEN 0      0           10.0.0.5:7001      0.0.0.0:*

The other two machines show empty to that query: I guess drbd stops listening for further incoming connections once it has received all those it expects?

3

Just tried again: on virtual5 (the victim)

root@virtual5:/home/brian# drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:Connecting

root@virtual5:/home/brian# drbdadm disconnect pm-a565d280
root@virtual5:/home/brian# drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent quorum:no open:no
  virtual1 connection:StandAlone
  virtual6 connection:StandAlone

root@virtual5:/home/brian# drbdadm secondary pm-a565d280
root@virtual5:/home/brian# drbdadm connect --discard-my-data pm-a565d280
root@virtual5:/home/brian# drbdadm status pm-a565d280
pm-a565d280 role:Secondary
  disk:Inconsistent open:no
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual6 connection:Connecting

I realised I hadn’t done the extra step on the other side virtual6 (the survivor):

root@virtual6:/home/brian# drbdadm status pm-a565d280
pm-a565d280 role:Primary
  disk:UpToDate open:yes
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual5 connection:StandAlone

root@virtual6:/home/brian# drbdadm disconnect pm-a565d280
pm-a565d280: State change failed: (-25) No quorum
additional info from kernel:
1 of 3 nodes visible, need 2 for quorum
Command 'drbdsetup disconnect pm-a565d280 1' terminated with exit code 11
root@virtual6:/home/brian# drbdadm connect pm-a565d280
pm-a565d280: Failure: (125) Device has a net-config (use disconnect first)
Command 'drbdsetup connect pm-a565d280 1' terminated with exit code 10

Ah… but I don’t want to connect from both, just from one, and I see from the manpage that connections are named as resource:connection-name:

root@virtual6:/home/brian# drbdadm disconnect pm-a565d280:virtual5
root@virtual6:/home/brian# drbdadm connect pm-a565d280:virtual5
root@virtual6:/home/brian#

root@virtual6:/home/brian# drbdadm status pm-a565d280
pm-a565d280 role:Primary
  disk:UpToDate open:yes
  virtual1 role:Secondary
    peer-disk:UpToDate
  virtual5 role:Secondary
    peer-disk:UpToDate

Yay! Problem solved.

Sorry for the noise, but hopefully this helps someone another time (or myself, when I search for the same problem in the future!)