bsr load
00000001 10/13/2020 14:47:56.555 [initRegistry] WDRBD_INFO<6>[0xFFFFE001458BC880] registry_path[\Registry\Machine\System\CurrentControlSet\Services\drbd] bypass_level=0, read_filter=0, use_volume_lock=1, netlink_tcp_port=5678, daemon_tcp_port=5679, ver=1.5 00000002 10/13/2020 14:47:56.555 [drbd_init] WDRBD_INFO<6>..\drbd\drbd_main.c: initialized. Version: 9.0.6 (api:2/proto:86-113) 00000003 10/13/2020 14:47:56.555 [drbd_init] WDRBD_INFO<6>..\drbd\drbd_main.c: 00000004 10/13/2020 14:47:56.555 [drbd_init] WDRBD_INFO<6>..\drbd\drbd_main.c: registered as block device major 147 00000005 10/13/2020 14:47:56.555 [DriverEntry] WDRBD_INFO<6>[0xFFFFE001458BC880] MVF Driver loaded.
cli command
00000087 10/13/2020 14:50:50.598 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_DOWN:27) begin -> 00000116 10/13/2020 14:50:50.598 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_DOWN:27) done (cmd_pending:0) <- 00000117 10/13/2020 14:51:34.520 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_NEW_RESOURCE:7) begin -> 00000119 10/13/2020 14:51:34.520 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <- 00000120 10/13/2020 14:51:34.535 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B880] drbd netlink cmd(DRBD_ADM_NEW_MINOR:5) begin -> 00000122 10/13/2020 14:51:34.535 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B880] drbd netlink cmd(DRBD_ADM_NEW_MINOR:5) done (cmd_pending:0) <- 00000123 10/13/2020 14:51:34.551 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_NEW_PEER:44) begin -> 00000126 10/13/2020 14:51:34.551 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_NEW_PEER:44) done (cmd_pending:0) <- 00000127 10/13/2020 14:51:34.551 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B880] drbd netlink cmd(DRBD_ADM_NEW_PATH:45) begin -> 00000128 10/13/2020 14:51:34.551 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B880] drbd netlink cmd(DRBD_ADM_NEW_PATH:45) done (cmd_pending:0) <- 00000129 10/13/2020 14:51:34.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CHG_PEER_DEVICE_OPTS:43) begin -> 00000131 10/13/2020 14:51:34.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CHG_PEER_DEVICE_OPTS:43) done (cmd_pending:0) <- 00000132 10/13/2020 14:51:34.613 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_ATTACH:12) begin -> 00000151 10/13/2020 14:51:34.613 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_ATTACH:12) done (cmd_pending:0) <- 00000152 10/13/2020 14:51:34.613 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) begin -> 00000155 10/13/2020 14:51:34.613 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) done (cmd_pending:0) <- 00000188 10/13/2020 14:51:44.754 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_DISCONNECT:11) begin -> 00000205 10/13/2020 14:51:44.754 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_DISCONNECT:11) done (cmd_pending:0) <- 00000206 10/13/2020 14:51:49.379 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) begin -> 00000212 10/13/2020 14:51:49.379 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) done (cmd_pending:0) <- 00000242 10/13/2020 14:53:50.473 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_PRIMARY:14) begin -> 00000255 10/13/2020 14:53:50.473 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_PRIMARY:14) done (cmd_pending:0) <-
state change
00000048 10/13/2020 14:48:17.644 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate ) 00000057 10/13/2020 14:48:17.660 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x0), scf(0x2a): conn_connect, conn( Unconnected -> Connecting ) 00000248 10/13/2020 14:53:50.473 [print_state_change] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0xa1c): change_role, role( Secondary -> Primary ) 00000254 10/13/2020 14:53:50.473 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Consistent), prpl(WFBitMapS), pdvflag(0x100600): receive_state, pdsk( Consistent -> Outdated ) 00000259 10/13/2020 14:53:50.473 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): drbd_start_resync, pdsk( Outdated -> Inconsistent ) repl( WFBitMapS -> SyncSource )
resource up
00000016 10/13/2020 14:48:17.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE001467C7880] drbd netlink cmd(DRBD_ADM_NEW_RESOURCE:7) begin -> 00000017 10/13/2020 14:48:17.566 [drbd_thread_start] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x0): Starting worker thread (from not_drbd_thread [0x0000000000000000]) 00000018 10/13/2020 14:48:17.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE001467C7880] drbd netlink cmd(DRBD_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <- 00000019 10/13/2020 14:48:17.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_NEW_MINOR:5) begin -> 00000020 10/13/2020 14:48:17.566 [drbd_create_device] WDRBD_INFO<6>[0xFFFFE00145F92040] device:FFFFE0014796F5F0 q->max_hw_sectors: 10967040 sectors, device->this_bdev->d_size: 5615124480 bytes 00000021 10/13/2020 14:48:17.566 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_NEW_MINOR:5) done (cmd_pending:0) <- 00000022 10/13/2020 14:48:17.582 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014691B880] drbd netlink cmd(DRBD_ADM_NEW_PEER:44) begin -> 00000023 10/13/2020 14:48:17.582 [drbd_create_peer_device_default_config] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): default, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k 00000024 10/13/2020 14:48:17.582 [drbd_thread_start] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x0), scf(0x0): Starting sender thread (from not_drbd_thread [0x0000000000000000]) 00000025 10/13/2020 14:48:17.582 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014691B880] drbd netlink cmd(DRBD_ADM_NEW_PEER:44) done (cmd_pending:0) <- 00000026 10/13/2020 14:48:17.582 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_NEW_PATH:45) begin -> 00000027 10/13/2020 14:48:17.582 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_NEW_PATH:45) done (cmd_pending:0) <- 00000028 10/13/2020 14:48:17.597 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014691B880] drbd netlink cmd(DRBD_ADM_CHG_PEER_DEVICE_OPTS:43) begin -> 00000029 10/13/2020 14:48:17.597 [drbd_adm_peer_device_opts] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): new, resync_rate : 614400k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k 00000030 10/13/2020 14:48:17.597 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014691B880] drbd netlink cmd(DRBD_ADM_CHG_PEER_DEVICE_OPTS:43) done (cmd_pending:0) <- 00000031 10/13/2020 14:48:17.644 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_ATTACH:12) begin -> 00000032 10/13/2020 14:48:17.644 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00145F92040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE00147372D20 00000033 10/13/2020 14:48:17.644 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Diskless), dvflag(0x0): change_disk_state, disk( Diskless -> Attaching ) 00000034 10/13/2020 14:48:17.644 [FsctlLockVolume] WDRBD_INFO<6>[0xFFFFE00145F92040] no lock. volume(\Device\HarddiskVolume2) already dismounted 00000035 10/13/2020 14:48:17.644 [FsctlFlushDismountVolume] WDRBD_INFO<6>[0xFFFFE00145F92040] no dismount. volume(\Device\HarddiskVolume2) already dismounted 00000036 10/13/2020 14:48:17.644 [FsctlUnlockVolume] WDRBD_INFO<6>[0xFFFFE00145F92040] volume(\Device\HarddiskVolume2) not locked 00000037 10/13/2020 14:48:17.644 [drbd_adm_attach] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): Maximum number of peer devices = 1 00000038 10/13/2020 14:48:17.644 [drbd_bump_write_ordering] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x1): Method to ensure write ordering: drain 00000039 10/13/2020 14:48:17.644 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): my node_id: 0 00000040 10/13/2020 14:48:17.644 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): node_id: 1 idx: 0 bm-uuid: 0x0 flags: 0x20010 max_size: 0 (DUnknown) 00000041 10/13/2020 14:48:17.644 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): my node_id: 0 00000042 10/13/2020 14:48:17.644 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): node_id: 1 idx: 0 bm-uuid: 0x0 flags: 0x20010 max_size: 0 (DUnknown) 00000043 10/13/2020 14:48:17.644 [drbd_bm_resize] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): drbd_bm_resize called with capacity == 10967040 00000044 10/13/2020 14:48:17.644 [drbd_bm_resize] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): resync bitmap: bits=1370880 words=42840 pages=42 00000045 10/13/2020 14:48:17.644 [drbd_determine_dev_size] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): size = 5355 MB (5483520 KB) 00000046 10/13/2020 14:48:17.644 [bm_rw_range] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): recounting of set bits took additional 0ms 00000047 10/13/2020 14:48:17.644 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00145F92040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE00147372D20 00000048 10/13/2020 14:48:17.644 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate ) 00000049 10/13/2020 14:48:17.644 [finish_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Attaching), dvflag(0x0): attached to current UUID: 233537F4119A9BFE 00000050 10/13/2020 14:48:17.644 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00145F92040] drbd netlink cmd(DRBD_ADM_ATTACH:12) done (cmd_pending:0) <- 00000051 10/13/2020 14:48:17.660 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE001464EF880] drbd netlink cmd(DRBD_ADM_CONNECT:10) begin -> 00000052 10/13/2020 14:48:17.660 [state_change_lock] WDRBD_WARN<4>[0xFFFFE001464EF880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE00147372D20 00000053 10/13/2020 14:48:17.660 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x0), scf(0x2a): drbd_adm_connect, conn( StandAlone -> Unconnected ) 00000054 10/13/2020 14:48:17.660 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE001464EF880] drbd netlink cmd(DRBD_ADM_CONNECT:10) done (cmd_pending:0) <-
resource down
00000087 10/13/2020 14:50:50.598 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_DOWN:27) begin -> 00000088 10/13/2020 14:50:50.598 [FsctlLockVolume] WDRBD_INFO<6>[0xFFFFE00146877040] no lock. volume(\Device\HarddiskVolume2) already dismounted 00000089 10/13/2020 14:50:50.598 [FsctlFlushDismountVolume] WDRBD_INFO<6>[0xFFFFE00146877040] no dismount. volume(\Device\HarddiskVolume2) already dismounted 00000090 10/13/2020 14:50:50.598 [FsctlUnlockVolume] WDRBD_INFO<6>[0xFFFFE00146877040] volume(\Device\HarddiskVolume2) not locked 00000091 10/13/2020 14:50:50.598 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00146877040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE00147372D20 00000092 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): Preparing cluster-wide state change 789940694 (0->1 496/16) 00000093 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:789940694] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 00000094 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:789940694] target_node_id(1) get_cluster_wide_reply (3) 00000095 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): State change 789940694: primary_nodes=0, weak_nodes=0 00000096 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x28): Cluster is now split 00000097 10/13/2020 14:50:50.598 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): Committing cluster-wide state change 789940694 (0ms) (0->1) 00000098 10/13/2020 14:50:50.598 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x208): conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown ) 00000099 10/13/2020 14:50:50.598 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off ) 00000100 10/13/2020 14:50:50.598 [drbd_recv] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x208): sock_recvmsg returned -15 00000101 10/13/2020 14:50:50.598 [drbd_ack_receiver] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated 00000102 10/13/2020 14:50:50.598 [drbd_thread_setup] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Terminating ack_recv thread 00000103 10/13/2020 14:50:50.598 [w_resync_timer] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): completed because it is not in the VERIFY_S or SYNC_TARGET replication state. 00000104 10/13/2020 14:50:50.598 [conn_disconnect] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Connection closed 00000105 10/13/2020 14:50:50.598 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone ) 00000106 10/13/2020 14:50:50.598 [drbd_thread_setup] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10e), scf(0x0): Terminating receiver thread 00000107 10/13/2020 14:50:50.598 [drbd_thread_setup] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10e), scf(0x0): Terminating sender thread 00000108 10/13/2020 14:50:50.598 [drbd_destroy_connection] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x110e), scf(0x0): drbd_destroy_connection 00000109 10/13/2020 14:50:50.598 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00146877040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE00147372D20 00000110 10/13/2020 14:50:50.598 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): change_disk_state, disk( UpToDate -> Detaching ) 00000111 10/13/2020 14:50:50.598 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Detaching), dvflag(0x1000): change_disk_state, disk( Detaching -> Diskless ) 00000112 10/13/2020 14:50:50.598 [adm_detach] WDRBD_INFO<6>[0xFFFFE00146877040] wait_event_interruptible_timeout timeo:3000 device->disk_state[NOW]:0 00000113 10/13/2020 14:50:50.598 [drbd_bm_resize] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Diskless), dvflag(0x0): drbd_bm_resize called with capacity == 0 00000114 10/13/2020 14:50:50.598 [drbd_thread_setup] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x0): Terminating worker thread 00000115 10/13/2020 14:50:50.598 [mvolWorkThread] WDRBD_INFO<6>[0xFFFFE00147830040] Terminating mvolWorkThread 00000116 10/13/2020 14:50:50.598 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE00146877040] drbd netlink cmd(DRBD_ADM_DOWN:27) done (cmd_pending:0) <-
resource connect
00000206 10/13/2020 14:51:49.379 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) begin -> 00000207 10/13/2020 14:51:49.379 [state_change_lock] WDRBD_WARN<4>[0xFFFFE0014688B040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE001476959A0 00000208 10/13/2020 14:51:49.379 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10c), scf(0x2a): drbd_adm_connect, conn( StandAlone -> Unconnected ) 00000209 10/13/2020 14:51:49.379 [drbd_thread_start] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x10c), scf(0x0): Starting receiver thread (from worker [0xFFFFE00147E45040]) 00000210 10/13/2020 14:51:49.379 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00146923880] worker should not initiate state changes with CS_SERIALIZE current:FFFFE00147638310 resource->worker.task:FFFFE001476959A0 00000211 10/13/2020 14:51:49.379 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0xc), scf(0x2a): conn_connect, conn( Unconnected -> Connecting ) 00000212 10/13/2020 14:51:49.379 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_CONNECT:10) done (cmd_pending:0) <- 00000213 10/13/2020 14:51:52.520 [drbd_do_features] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 113 00000214 10/13/2020 14:51:52.520 [drbd_do_features] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0x0): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME. 00000215 10/13/2020 14:51:52.520 [conn_connect] WDRBD_WARN<4>drbd r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0x0): send-buffering disabled nc->sndbuf_size:0 00000216 10/13/2020 14:51:52.520 [drbd_thread_start] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0x0): Starting ack_recv thread (from receiver [0xFFFFE00146923880]) 00000217 10/13/2020 14:51:52.535 [state_change_lock] WDRBD_WARN<4>[0xFFFFE00147972040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE00146F98630 resource->worker.task:FFFFE001476959A0 00000218 10/13/2020 14:51:52.535 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 1043930053 (0->1 499/146) 00000219 10/13/2020 14:51:52.535 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:1043930053] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (2058) 00000220 10/13/2020 14:51:52.535 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:1043930053] target_node_id(1) get_cluster_wide_reply (3) 00000221 10/13/2020 14:51:52.535 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x82a): State change 1043930053: primary_nodes=0, weak_nodes=0 00000222 10/13/2020 14:51:52.535 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 1043930053 (0ms) (0->1) 00000223 10/13/2020 14:51:52.535 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary ) 00000224 10/13/2020 14:51:52.535 [receive_SyncParam] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): sync, resync_rate : 614400k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k 00000225 10/13/2020 14:51:52.535 [receive_sizes] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): current_mydisk_size: 5615124480 bytes 00000226 10/13/2020 14:51:52.535 [receive_sizes] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): peer_current_size: 5615124480 bytes peer_user_size: 0 bytes peer_disk_size: 10807672832 bytes peer_max_size: 10807672832 bytes 00000227 10/13/2020 14:51:52.535 [receive_sizes] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): md_effective_size: 10967040 my_user_size: 0 my_max_size: 10967040 00000228 10/13/2020 14:51:52.535 [warn_if_differ_considerably] WDRBD_WARN<4>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): Considerable difference in lower level device sizes: 10807672832 bytes vs. 5615124480 bytes 00000229 10/13/2020 14:51:52.535 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): my node_id: 0 00000230 10/13/2020 14:51:52.535 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): node_id: 1 idx: 0 bm-uuid: 0x0 flags: 0x20010 max_size: 21108736 (DUnknown) 00000231 10/13/2020 14:51:52.535 [receive_sizes] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): calling drbd_determine_dev_size() 00000232 10/13/2020 14:51:52.535 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): my node_id: 0 00000233 10/13/2020 14:51:52.535 [get_max_agreeable_size] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): node_id: 1 idx: 0 bm-uuid: 0x0 flags: 0x20010 max_size: 21108736 (DUnknown)
resource disconnect
00000188 10/13/2020 14:51:44.754 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_DISCONNECT:11) begin -> 00000189 10/13/2020 14:51:44.754 [state_change_lock] WDRBD_WARN<4>[0xFFFFE0014688B040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801B127A040 resource->worker.task:FFFFE001476959A0 00000190 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): Preparing cluster-wide state change 1012019641 (0->1 496/16) 00000191 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:1012019641] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 00000192 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:1012019641] target_node_id(1) get_cluster_wide_reply (3) 00000193 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): State change 1012019641: primary_nodes=0, weak_nodes=0 00000194 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10c), scf(0x28): Cluster is now split 00000195 10/13/2020 14:51:44.754 [change_cluster_wide_state] WDRBD_INFO<6>drbd r0, r(Secondary), f(0x0), scf(0x28): Committing cluster-wide state change 1012019641 (0ms) (0->1) 00000196 10/13/2020 14:51:44.754 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10c), scf(0x208): conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown ) 00000197 10/13/2020 14:51:44.754 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off ) 00000198 10/13/2020 14:51:44.754 [drbd_recv] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10c), scf(0x208): sock_recvmsg returned -15 00000199 10/13/2020 14:51:44.754 [drbd_ack_receiver] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10c), scf(0x0): ack_receiver terminated 00000200 10/13/2020 14:51:44.754 [drbd_thread_setup] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10c), scf(0x0): Terminating ack_recv thread 00000201 10/13/2020 14:51:44.754 [w_resync_timer] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): completed because it is not in the VERIFY_S or SYNC_TARGET replication state. 00000202 10/13/2020 14:51:44.754 [conn_disconnect] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10c), scf(0x0): Connection closed 00000203 10/13/2020 14:51:44.754 [print_state_change] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10c), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone ) 00000204 10/13/2020 14:51:44.754 [drbd_thread_setup] WDRBD_INFO<6>drbd r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10c), scf(0x0): Terminating receiver thread 00000205 10/13/2020 14:51:44.754 [NetlinkWorkThread] WDRBD_INFO<6>[0xFFFFE0014688B040] drbd netlink cmd(DRBD_ADM_DISCONNECT:11) done (cmd_pending:0) <-
syncsource
resync start
00000305 10/13/2020 14:54:51.505 [__receive_uuids] WDRBD_WARN<4>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): receive new current but not update UUID: 233537F4119A9BFE 00000306 10/13/2020 14:54:51.505 [log_handshake] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): drbd_sync_handshake: 00000307 10/13/2020 14:54:51.505 [drbd_uuid_dump_self] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): self BA6151025D30A885:233537F4119A9BFF:238A851C11C54292:1DD3312D0EE9989A bits:17 flags:120 00000308 10/13/2020 14:54:51.505 [drbd_uuid_dump_peer] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): peer 233537F4119A9BFE:0000000000000000:B43F1BF5DA1F8DFE:B66081A55B3040D6 bits:0 flags:0 00000309 10/13/2020 14:54:51.505 [drbd_handshake] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): uuid_compare()=2 by rule 70 00000310 10/13/2020 14:54:51.505 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive new repl state "WFBitMapS" 00000311 10/13/2020 14:54:51.505 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive_state, pdsk( DUnknown -> Outdated ) repl( Off -> WFBitMapS ) 00000312 10/13/2020 14:54:51.505 [drbd_queue_bitmap_io] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): send_bitmap (WFBitMapS), worker.task(FFFFE001476959A0), current(FFFFE001476959A0) .. 00000322 10/13/2020 14:54:51.505 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): receive new repl state "WFBitMapS" 00000323 10/13/2020 14:54:51.505 [INFO_bm_xfer_stats] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): send bitmap stats [Bytes(packets)]: plain 0(0), RLE 45(1), total 45; compression: 100.0% 00000324 10/13/2020 14:54:51.505 [INFO_bm_xfer_stats] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 45(1), total 45; compression: 100.0% 00000325 10/13/2020 14:54:51.505 [receive_bitmap_finished] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): send that bitmap exchange has been completed 00000326 10/13/2020 14:54:51.505 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): drbd_start_resync, pdsk( Outdated -> Inconsistent ) repl( WFBitMapS -> SyncSource ) 00000327 10/13/2020 14:54:51.505 [drbd_start_resync] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): Began resync as SyncSource (will sync 68 KB [17 bits set]).
resync finished
00000329 10/13/2020 14:54:51.536 [__receive_uuids] WDRBD_WARN<4>drbd r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): receive new current but not update UUID: BA6151025D30A884 00000330 10/13/2020 14:54:51.536 [drbd_print_uuids] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): drbd_uuid_detect_finished_resyncs, updated UUIDs BA6151025D30A885:0000000000000000:233537F4119A9BFE:238A851C11C54292 00000331 10/13/2020 14:54:51.536 [drbd_uuid_detect_finished_resyncs] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x4): Clearing bitmap UUID for node 2 00000332 10/13/2020 14:54:51.536 [drbd_resync_finished] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): Resync done (total 1 sec; paused 0 sec; 68 K/sec), hit bit (in sync 0; marked rl 0) 00000333 10/13/2020 14:54:51.536 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): drbd_resync_finished, pdsk( Inconsistent -> UpToDate ) repl( SyncSource -> Established ) 00000334 10/13/2020 14:54:51.536 [drbd_queue_bitmap_io] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x0): write from resync_finished, worker.task(FFFFE001476959A0), current(FFFFE001476959A0) 00000335 10/13/2020 14:54:51.536 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): receive new repl state "Established"
synctarget
resync start
00000080 10/13/2020 14:54:51.300 [__receive_uuids] WDRBD_WARN<4>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive new current but not update UUID: BA6151025D30A885 00000081 10/13/2020 14:54:51.300 [log_handshake] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): drbd_sync_handshake: 00000082 10/13/2020 14:54:51.300 [drbd_uuid_dump_self] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): self 233537F4119A9BFE:0000000000000000:B43F1BF5DA1F8DFE:B66081A55B3040D6 bits:0 flags:0 00000083 10/13/2020 14:54:51.300 [drbd_uuid_dump_peer] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): peer BA6151025D30A885:233537F4119A9BFF:238A851C11C54292:1DD3312D0EE9989A bits:17 flags:1120 00000084 10/13/2020 14:54:51.300 [drbd_handshake] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): uuid_compare()=-2 by rule 50 00000085 10/13/2020 14:54:51.300 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive new repl state "WFBitMapT" 00000086 10/13/2020 14:54:51.300 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive_state, pdsk( DUnknown -> UpToDate ) repl( Off -> WFBitMapT ) 00000087 10/13/2020 14:54:51.300 [w_after_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): not sending state because of old repl_state(Off) 00000088 10/13/2020 14:54:51.316 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): receive new repl state "WFBitMapT" 00000089 10/13/2020 14:54:51.316 [w_after_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): not sending state because of old repl_state(WFBitMapT) 00000090 10/13/2020 14:54:51.316 [INFO_bm_xfer_stats] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 45(1), total 45; compression: 100.0% 00000091 10/13/2020 14:54:51.316 [receive_bm_exchange_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): bitmap exchange complete 00000092 10/13/2020 14:54:51.316 [INFO_bm_xfer_stats] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): send bitmap stats [Bytes(packets)]: plain 0(0), RLE 45(1), total 45; compression: 100.0% 00000093 10/13/2020 14:54:51.316 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Outdated), dvflag(0x0): drbd_start_resync, disk( Outdated -> Inconsistent ) 00000094 10/13/2020 14:54:51.316 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): drbd_start_resync, repl( WFBitMapT -> SyncTarget ) 00000095 10/13/2020 14:54:51.316 [drbd_start_resync] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): Began resync as SyncTarget (will sync 68 KB [17 bits set]). 00000096 10/13/2020 14:54:51.316 [receive_state] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): receive new repl state "SyncTarget" 00000097 10/13/2020 14:54:51.331 [make_resync_request] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): DRBD_END_OF_BITMAP(25802666), device->bm_resync_fo : 1370880, bm_set : 8
resync finished
00000098 10/13/2020 14:54:51.331 [drbd_resync_finished] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): Resync done (total 1 sec; paused 0 sec; 68 K/sec), hit bit (in sync 0; marked rl 0) 00000099 10/13/2020 14:54:51.331 [drbd_print_uuids] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): drbd_resync_finished, updated UUIDs BA6151025D30A884:0000000000000000:233537F4119A9BFE:B43F1BF5DA1F8DFE 00000100 10/13/2020 14:54:51.331 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2, ds(Inconsistent), dvflag(0x20004): drbd_resync_finished, disk( Inconsistent -> UpToDate ) 00000101 10/13/2020 14:54:51.331 [print_state_change] WDRBD_INFO<6>drbd r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): drbd_resync_finished, repl( SyncTarget -> Established ) 00000102 10/13/2020 14:54:51.331 [drbd_queue_bitmap_io] WDRBD_INFO<6>drbd r0/0 minor 2, ds(UpToDate), dvflag(0x20000): write from resync_finished, worker.task(FFFFE0007414EEC0), current(FFFFE0007414EEC0)