[DRBD-user] Online verification skipped verify, too busy

Denis drbdsys at made.net
Mon Jun 29 10:03:37 CEST 2020 

Hello,

I have this setup with two replica, primary on lvm (datacenter ssd)
and secondary on zfs (datacenter ssd)

All works well but I want to verify it.

So I found some OOS and some skipped, I suspect that the OSS
was a false positive due to the high activity at the time... any idea?
Anyway I did a drbdadm disconnect and connect

The question is why some sectors was skipped and what shoud I do?

Below the logs, thanks for your attention!

Denis


version: 9.0.22-2 (api:2/proto:86-116)
GIT-hash: 719792f2cc1360c65c848ffdb66090959e27fde5 build by root at node2, 
2020-04-24 14:04:55
Transports (api:16): tcp (9.0.22-2)


[Sun Jun 28 16:22:31 2020] drbd stor-node2 node2: Preparing remote state 
change 2866147247
[Sun Jun 28 16:22:31 2020] drbd stor-node2 node2: Committing remote 
state change 2866147247 (primary_nodes=1)
[Sun Jun 28 16:22:31 2020] drbd stor-node2/0 drbd1222 node2: repl( 
Established -> VerifyT )
[Sun Jun 28 16:22:31 2020] drbd stor-node2/0 drbd1222: Online Verify 
start sector: 0
[Sun Jun 28 17:17:39 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=47073208, size=25712 (sectors)
[Sun Jun 28 17:24:29 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=132786072, size=8 (sectors)
[Sun Jun 28 17:31:02 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=113871928, size=17848 (sectors)
[Sun Jun 28 17:33:15 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=154119224, size=23024 (sectors)
[Sun Jun 28 17:41:25 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=160350504, size=19600 (sectors)
[Sun Jun 28 17:41:27 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=183804632, size=24264 (sectors)
[Sun Jun 28 17:56:02 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=183893160, size=21120 (sectors)
[Sun Jun 28 17:56:03 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=227313536, size=17944 (sectors)
[Sun Jun 28 18:08:39 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=227364904, size=35936 (sectors)
[Sun Jun 28 18:08:44 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=259563408, size=6720 (sectors)
[Sun Jun 28 19:33:34 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=259758128, size=18488 (sectors)
[Sun Jun 28 19:34:15 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=502827808, size=6912 (sectors)
[Sun Jun 28 20:03:40 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=504813152, size=21168 (sectors)
[Sun Jun 28 20:34:25 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=664642232, size=8 (sectors)
[Sun Jun 28 20:34:37 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=664979448, size=8 (sectors)
[Sun Jun 28 20:34:42 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665139496, size=8 (sectors)
[Sun Jun 28 20:34:42 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665139664, size=8 (sectors)
[Sun Jun 28 20:34:42 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665139752, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665258560, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665258584, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665258904, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665258944, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665259248, size=8 (sectors)
[Sun Jun 28 20:34:49 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665259336, size=8 (sectors)
[Sun Jun 28 20:34:50 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665287312, size=8 (sectors)
[Sun Jun 28 20:34:50 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665287592, size=8 (sectors)
[Sun Jun 28 20:34:53 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=665322400, size=8 (sectors)
[Sun Jun 28 20:41:49 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=584780824, size=35536 (sectors)
[Sun Jun 28 20:48:35 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=685446824, size=23176 (sectors)
[Sun Jun 28 20:53:10 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=707061680, size=19912 (sectors)
[Sun Jun 28 22:08:11 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=718457776, size=21208 (sectors)
[Sun Jun 28 22:21:43 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=973231480, size=8 (sectors)
[Sun Jun 28 22:22:12 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=974514408, size=8 (sectors)
[Sun Jun 28 22:22:15 2020] drbd stor-node2/0 drbd1222 node2: Out of 
sync: start=974654160, size=8 (sectors)
[Sun Jun 28 22:39:05 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=936978880, size=17888 (sectors)
[Sun Jun 28 22:45:56 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=1028544008, size=20664 (sectors)
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: Skipped 
verify, too busy: start=1049394256, size=19880 (sectors)
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: Online 
verify done but 49625 4k blocks skipped (total 34281 sec; paused 0 sec; 
24468 K/sec)
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: Online 
verify found 17 4k blocks out of sync!
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: repl( 
VerifyT -> Established )
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm out-of-sync
[Mon Jun 29 01:53:54 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm out-of-sync exit code 0



[Mon Jun 29 09:24:39 2020] drbd stor-node2: Preparing cluster-wide state 
change 3568948431 (1->0 496/16)
[Mon Jun 29 09:24:39 2020] drbd stor-node2: State change 3568948431: 
primary_nodes=1, weak_nodes=FFFFFFFFFFFFFFFE
[Mon Jun 29 09:24:39 2020] drbd stor-node2 node2: Cluster is now split
[Mon Jun 29 09:24:39 2020] drbd stor-node2: Committing cluster-wide 
state change 3568948431 (0ms)
[Mon Jun 29 09:24:39 2020] drbd stor-node2 node2: conn( Connected -> 
Disconnecting ) peer( Primary -> Unknown )
[Mon Jun 29 09:24:39 2020] drbd stor-node2/0 drbd1222: disk( UpToDate -> 
Outdated )
[Mon Jun 29 09:24:39 2020] drbd stor-node2/0 drbd1222 node2: pdsk( 
UpToDate -> DUnknown ) repl( Established -> Off )
[Mon Jun 29 09:24:39 2020] drbd stor-node2 node2: ack_receiver terminated
[Mon Jun 29 09:24:39 2020] drbd stor-node2 node2: Terminating ack_recv 
thread
[Mon Jun 29 09:24:40 2020] drbd stor-node2 node2: Aborting remote state 
change 0 commit not possible
[Mon Jun 29 09:24:40 2020] drbd stor-node2 node2: Restarting sender thread
[Mon Jun 29 09:24:40 2020] drbd stor-node2 node2: Connection closed
[Mon Jun 29 09:24:40 2020] drbd stor-node2 node2: conn( Disconnecting -> 
StandAlone )
[Mon Jun 29 09:24:40 2020] drbd stor-node2 node2: Terminating receiver 
thread
[Mon Jun 29 09:24:48 2020] drbd stor-node2 node2: conn( StandAlone -> 
Unconnected )
[Mon Jun 29 09:24:48 2020] drbd stor-node2 node2: Starting receiver 
thread (from drbd_w_stor-pve [11351])
[Mon Jun 29 09:24:48 2020] drbd stor-node2 node2: conn( Unconnected -> 
Connecting )
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Handshake to peer 0 
successful: Agreed network protocol version 116
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Feature flags enabled 
on protocol level: 0xf TRIM THIN_RESYNC WRITE_SAME WRITE_ZEROES.
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Peer authenticated 
using 20 bytes HMAC
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Starting ack_recv 
thread (from drbd_r_stor-pve [9095])
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Preparing remote state 
change 1327599887
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: Committing remote 
state change 1327599887 (primary_nodes=1)
[Mon Jun 29 09:24:49 2020] drbd stor-node2 node2: conn( Connecting -> 
Connected ) peer( Unknown -> Primary )
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: 
drbd_sync_handshake:
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: self 
A46181A69F5B2C5E:0000000000000000:646F7C83E8FFC96A:59AF1EFB1F88F6C6 
bits:17 flags:120
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: peer 
CBB75ACDAB4ED177:A46181A69F5B2C5F:508441C732E4D840:73F4F74963135314 
bits:4529 flags:120
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: 
uuid_compare()=target-use-bitmap by rule 50
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: pdsk( 
DUnknown -> UpToDate ) repl( Off -> WFBitMapT )
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: receive 
bitmap stats [Bytes(packets)]: plain 0(0), RLE 1590(1), total 1590; 
compression: 100.0%
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: send bitmap 
stats [Bytes(packets)]: plain 0(0), RLE 1590(1), total 1590; 
compression: 100.0%
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm before-resync-target
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm before-resync-target exit code 0
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222: disk( Outdated -> 
Inconsistent )
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: repl( 
WFBitMapT -> SyncTarget )
[Mon Jun 29 09:24:49 2020] drbd stor-node2/0 drbd1222 node2: Began 
resync as SyncTarget (will sync 18120 KB [4530 bits set]).
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222 node2: Resync done 
(total 8 sec; paused 0 sec; 2308 K/sec)
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222 node2: updated 
UUIDs CBB75ACDAB4ED176:0000000000000000:646F7C83E8FFC96A:59AF1EFB1F88F6C6
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222: disk( 
Inconsistent -> UpToDate )
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222 node2: repl( 
SyncTarget -> Established )
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm after-resync-target
[Mon Jun 29 09:24:58 2020] drbd stor-node2/0 drbd1222 node2: helper 
command: /sbin/drbdadm after-resync-target exit code 0

More information about the drbd-user mailing list