Versions Compared

Old Version 8

changes.mady.by.user 한성원

Saved on

compared with

New Version Current

changes.mady.by.user SungEun Kim

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

...

Table of Contents

개요

개별 동작에 따라 발생하는 일련의 로그 패턴들에 대해 분석하고 설명합니다.

동작

Info

windwos bsr 1.6.1 버전의 로그를 기준으로 합니다.

드라이버 기동

다음은 windows 에서 bsr 커널 드라이버가 기동할 때의 로그 입니다.

  • 드라이버 버전과 드라이버에서 사용하는 port 정보등을 출력합니다.

    • 윈도우즈 커널 드라이버는 시스템이 시작하는 시점에 기동합니다. 기동 시점의 로그 시간을 보면 시스템이 시작한 시간을 유추할 수 있습니다.

Code Block
00000001 10/1326/2020 16:0924:0342.11439587079617 [wait_for_add_deviceinitRegistry] [LOGDRIVER:1063] bsr_info<6> [0xFFFFE000CBDC18800xFFFFE0012A6BD880] Wait for device to be connected for log file generation.(C:\Program Files\bsr)
00000002 10/13/2020 16:09:03.1144175 [initRegistry] [DRIVER:63] bsr_info<6> [0xFFFFE000CBABD880] registry_path[\Registry\Machine\System\CurrentControlSet\Services\bsr]
00000003 10/13/2020 16:09:03.1144212 [initRegistryregistry_path[\Registry\Machine\System\CurrentControlSet\Services\bsr]
00000002 10/26/2020 16:24:42.7079678 [initRegistry] [DRIVER:64] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] bypass_level=0, read_filter=0, use_volume_lock=1, netlink_tcp_port=5678, daemon_tcp_port=5679, ver=1.5
0000000400000003 10/1326/2020 16:0924:0342.11448267080324 [bsr_initwait_for_add_device] [DRIVERLOG:7710] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A9DC300] Wait initialized.for Version: 1.6-A4 (api:device to be connected for log file generation.(C:\Program Files\bsr)
00000004 10/26/2020 16:24:42.7080346 [bsr_init] [DRIVER:77] bsr_info<6> [0xFFFFE0012A6BD880] BSR driver loaded and initialized successfully. Version: 1.6.1 (api:2/proto:86-114)
00000005 10/1326/2020 16:0924:0342.11448507080380 [bsr_init] [DRIVER:78] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] 1.6.1(2020.910.0113_A4A1) GIT-hash: f52eea3 build by DEV3-KBLD+Administrator@dev3-kbld, Tue SepOct 13 1 15:19:41 2020 
00000006 10/1326/2020 16:0924:0342.11448687080400 [bsr_init] [DRIVER:79] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] registered as block device major 147

cli command

Code Block
00000018
00000007 10/1326/2020 16:0924:2942.00581647080424 [NetlinkWorkThreadDriverEntry] [NETLINKDRIVER:184] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012A6BD880] BSR bsrMVF netlink cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
00000020 Driver loaded.

상태 변경

다음은 bsr 커널의 disk, peer disk, replication, connection, role의 상태가 변경될 때 발생하는 로그 입니다.

  • 복수의 상태 변경이 하나의 로그에 출력 될 수 있습니다.

  • 연결 상태가 connected 에서 connecting 또는 standalone 으로 변경 될 경우, 연결 상태 변경 로그를 중심으로 분석합니다.

  • 로그에는 해당 상태 변경을 수행한 호출자 함수의 이름이 같이 출력됩니다. 함수의 호출 흐름을 추적하여 디버깅 정보로 활용할 수 있습니다.

    • 다음 로그에서 상태 변경을 수행한 호출자는 change_disk_state, recevie_state, change_role, connect_work 가 됩니다.

Code Block
00000053 10/13/2020 16:09:29.06122103583295 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:20] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <-
00000021bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )
00000091 10/13/2020 16:09:2948.09027722615732 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:1821] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) begin ->
00000023 10/13/2020 16:09:29.0906385 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) done (cmd_pending:0) <-
00000024 r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive_state, pdsk( DUnknown -> UpToDate ) repl( Off -> Established )
00000099 10/13/2020 16:0910:2914.10119073457504 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:18] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_PEER:44) begin ->
00000027bsr r0, r(Secondary), f(0x0), scf(0xa1c): change_role, role( Secondary -> Primary )
00000583 10/13/2020 16:0914:2901.10146845270141 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:2019] bsr_info<6> bsr [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done (cmd_pending:0) <-
00000028 10/13/2020 16:09:29.1124180 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CC6EF880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) begin ->
00000029 10/13/2020 16:09:29.1140515 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CC6EF880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done (cmd_pending:0) <-

state change

Code Block
00000053 10/13/2020 16:09:29.3583295 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )
00000091 10/13/2020 16:09:48.2615732 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive_state, pdsk( DUnknown -> UpToDate ) repl( Off -> Established )
00000099 10/13/2020 16:10:14.3457504 [print_state_change] [STATE:18] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0xa1c): change_role, role( Secondary -> Primary )
00000583 10/13/2020 16:14:01.5270141 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )

resource up

Code Block

00000722 10/13/2020 16:16:12.6266106 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
00000723 10/13/2020 16:16:12.6266252 [bsr_thread_start] [THREAD:12] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x0): Starting worker thread (from not_bsr_thread [0])
00000724 10/13/2020 16:16:12.6268449 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <-
00000725 10/13/2020 16:16:12.6346292 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) begin ->
00000726 10/13/2020 16:16:12.6346651 [bsr_create_device] [VOLUME:10] bsr_info<6> [0xFFFFE000CCAAC040] device(FFFFE000CE6C8890) max sectors(21211136), size(10860101632 bytes)
00000727 10/13/2020 16:16:12.6348421r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )

Netlink 명령

다음은 bsr 유틸리티로 명령을 수행했을 때의 로그와 설명입니다.

  • Netlink 를 통한 유틸리티 명령은 커널로그로 기록되며 명령의 시작과 끝은 인식할 수 있도록 아래의 로그와 같이 기록하고 있습니다.

    • 명령의 시작은 command has been received. Execute the command. 로 기록됩니다.

    • 명령의 끝은 command execution terminated. 로 기록됩니다.

    • 명령의 시작과 끝을 하나의 쌍으로 보고 하나의 명령단위로 간주하면 됩니다.

  • 다음의 로그 예는 Netlink 명령의 시작과 끝 로그 만을 중점으로 기록한 내용입니다. 시작과 끝 사이에 명령을 수행한 내역의 로그들은 가독성을 위해 생략하였습니다.

Code Block
00000018 10/26/2020 16:25:03.2195574 [NetlinkWorkThread] [NETLINK:2018] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) done (cmd_pending:0) <-
00000728 10/13RESOURCE:7 command has been received. Execute the command.
...//명령 수행
00000020 10/26/2020 16:1625:1203.64307012197637 [NetlinkWorkThread] [NETLINK:1820] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PEER:44RESOURCE:7 command execution terminated. (pending command:0)
begin
->
0000072900000021 10/1326/2020 16:1625:1203.64308892278267 [bsr_create_peer_device_default_configNetlinkWorkThread] [GENLNETLINK:4518] bsr_info<6> bsr 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, ov_req_num : 10b, ov_req_interval : 100ms
00000730 10/13/2020 16:16:12.6431084 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x0), scf(0x0): Starting sender thread (from not_bsr_thread [0])
00000731 10/13/2020 16:16:12.6433056[0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command has been received. Execute the command.
...//명령 수행
00000023 10/26/2020 16:25:03.2280254 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command execution terminated. (pending command:0)

00000024 10/26/2020 16:25:03.2352395 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44 command has been received. Execute the command.
...//명령 수행
00000027 10/26/2020 16:25:03.2354514 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done command execution terminated. (cmd_pending command:0)
<-
0000073200000028 10/1326/2020 16:1625:1203.65194822442056 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_PATH:45) begin ->
00000733 command has been received. Execute the command.
...//명령 수행
00000029 10/1326/2020 16:1625:1203.65215982444816 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done command execution terminated. (cmd_pending command:0)
<-
0000073400000030 10/1326/2020 16:1625:1203.70334752884146 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] bsr netlink cmd(BSR_ADM_ATTACH:12) begin ->
00000735 10/13_ATTACH:12 command has been received. Execute the command.
...//명령 수행
00000055 10/26/2020 16:1625:1203.70377193033626 [state_change_lockNetlinkWorkThread] [STATENETLINK:4020] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000736 10/13BSR_ADM_ATTACH:12 command execution terminated. (pending command:0)

00000056 10/26/2020 16:1625:1203.70378833136502 [print_state_changeNetlinkWorkThread] [STATENETLINK:2018] bsr_info<6> bsr r0/0 minor 2, ds(Diskless), dvflag(0x0): change_disk_state, disk( Diskless -> Attaching )
00000737 10/13[0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command has been received. Execute the command.
...//명령 수행
00000059 10/26/2020 16:1625:1203.70383823139110 [FsctlLockVolumeNetlinkWorkThread] [VOLUMENETLINK:20] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] no lockBSR_ADM_CONNECT:10 command execution terminated. volume(\Device\HarddiskVolume2) already dismounted
00000738 10/13(pending command:0)

connect

  • connect 명령을 수행했을 때의 시작 로그입니다.

Code Block
00000056 10/26/2020 16:1625:1203.70384143136502 [FsctlFlushDismountVolumeNetlinkWorkThread] [VOLUMENETLINK:1518] bsr_info<6> [0xFFFFE000CCAC4880] no dismount. volume(\Device\HarddiskVolume2) already dismounted
00000739 10/13/2020 16:16:12.7038441 [FsctlUnlockVolume] [VOLUME:24] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) not locked
00000740 10/130xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command has been received. Execute the command.
00000057 10/26/2020 16:1625:1203.70384603136604 [bsrstate_admchange_attachlock] [GENLSTATE:3640] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Maximum number of bitmap peer devices 1
00000741 10/13[0xFFFFE0012B2F9880] Worker should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C513C60
00000058 10/26/2020 16:1625:1203.70478593136765 [bsrprint_bumpstate_write_orderingchange] [VOLUMESTATE:6619] bsr_info<6> bsr r0 pnode-id:1, r(Secondarycs(StandAlone), prole(Unknown), fcflag(0x0), scf(0x10x2a): Method to ensure write ordering: drain
00000742bsr_adm_connect, conn( StandAlone -> Unconnected )
00000059 10/1326/2020 16:1625:1203.70478913139110 [get_max_agreeable_sizeNetlinkWorkThread] [GENLNETLINK:1620] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000743 10/13[0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command execution terminated. (pending command:0)
00000060 10/26/2020 16:1625:1203.70479133139464 [getbsr_maxthread_agreeable_sizestart] [GENLTHREAD:1711] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000744 10/13:1, cs(Unconnected), prole(Unknown), cflag(0x0), scf(0x0): Starting receiver thread (from worker [2928])
00000061 10/26/2020 16:1625:1203.70481033140159 [getstate_maxchange_agreeable_sizelock] [GENLSTATE:1640] bsr_info<6> [0xFFFFE0012C706040] bsrWorker r0/0should minornot 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000745 10/13initiate state changes with CS_SERIALIZE current:FFFFE0012C707160 resource->worker.task:FFFFE0012C513C60
00000062 10/26/2020 16:1625:1203.70481233140398 [getprint_maxstate_agreeable_sizechange] [GENLSTATE:1719] bsr_info<6> bsr r0/0 minor 2 r0 pnode-id:1, pdskcs(DUnknownUnconnected), prplprole(OffUnknown), pdvflagcflag(0x0):, node idscf(10x2a): bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000746 10/13conn_connect, conn( Unconnected -> Connecting )

  • 00000063 .. [PROTOCOL:55] 연결 후 로컬이 허용하는 protocol version을 출력하며 protocol version은 하위호환을 지원합니다.

Code Block
00000063 10/26/2020 16:1625:1206.70481593224961 [bsr_bmdo_resizefeatures] [BITMAPPROTOCOL:2355] bsr_info<6> bsr r0/0 minor 2, ds(Attaching pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), dvflag(0x0): bitmap resize called with capacity(21211136)
00000747 10/13scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000064 10/26/2020 16:1625:1206.70540153225110 [bsr_bmdo_resizefeatures] [BITMAPPROTOCOL:2556] bsr_info<6> bsr r0/0 minor 2, ds(Attaching pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), dvflagscf(0x0): resize bitmap, bits(2651392) words(82856) pages(81)
00000748 10/13 Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.

  • 00000065 .. [SEND BUFFER:27] 로컬 send-buffer 사용 여부와 사용할 경우 send-buffer 할당 크기를 출력합니다. 만약 버퍼 할당을 위한 메모리가 부족하면 send-buffer가 할당에 실패하고 버퍼링 없이 동작합니다.

Code Block
00000065 10/26/2020 16:1625:1206.70540543231473 [bsr_determine_dev_sizeconn_connect] [GENLSEND BUFFER:1327] bsr_info<6>warn<4> bsr r0/0 minor 2, ds(Attaching pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), dvflagscf(0x0): Updatesend-buffering diskdisabled nc->sndbuf_size:0
10 GB (10605568 KB)
00000749 00000066 10/1326/2020 16:1625:1206.70929933231590 [bmbsr_rwthread_rangestart] [BITMAPTHREAD:2911] bsr_info<6> bsr r0/0 minor 2, ds(Attaching pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), dvflagscf(0x0): recountingStarting ofack_recv set bits took additional 1ms
00000750thread (from receiver [1700])
00000067 10/1326/2020 16:1625:1206.70930793374818 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012CBD2040] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFE0012C7CCC20 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000075100000068 10/1326/2020 16:1625:1206.70932403375354 [printchange_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 177619259 (0->1 499/146)
00000069 10/26/2020 16:25:06.3375466 [change_cluster_wide_state] [STATETWOPC:2035] bsr_info<6> bsr r0/0 minor 2, r(Secondary), dsf(Attaching0x0), dvflagscf(0x00x82a): change_disk_state,[TWOPC:177619259] target_node_id(1) conn(Connected) repl(-) disk( Attaching -> UpToDate )
00000752 10/13-) pdsk(-) role(Secondary) peer(-) flags (2058) 
00000070 10/26/2020 16:1625:1206.70932883384621 [finishchange_cluster_wide_state_change] [UUIDTWOPC:1436] bsr_info<6> bsr r0/0 minor 2, dsr(AttachingSecondary), dvflagf(0x0): attached to current UUID: 83F530CA41FA9868
00000753 10/13/2020 16:16:12.7097657 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_ATTACH:12) done (cmd_pending:0) <-
00000754 10/13, scf(0x82a): [TWOPC:177619259] target_node_id(1) get_cluster_wide_reply (3) 
00000071 10/26/2020 16:1625:1206.71867773384814 [NetlinkWorkThreadchange_cluster_wide_state] [NETLINKTWOPC:1837] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) begin ->
00000755 10/13bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 177619259: primary_nodes=0, weak_nodes=0
00000072 10/26/2020 16:1625:1206.71868943384904 [statechange_cluster_changewide_lockstate] [STATETWOPC:4039] bsr_info<6> [0xFFFFE000CCAAC040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000756 10/13bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 177619259 (1ms) (0->1)
00000073 10/26/2020 16:1625:1206.71871023389819 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(StandAloneConnecting), prole(Unknown), cflag(0x00xc), scf(0x2a0xa0a): bsrconnect_adm_connectwork, conn( StandAloneConnecting -> UnconnectedConnected ) 00000757 10/13/2020 16:16:12.7189150 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) done (cmd_pending:0) <-
00000758 10/13peer( Unknown -> Secondary )

  • 00000074 .. [PROTOCOL:29] 피어 노드에게 수신 받은 peer device의 설정 정보가 출력됩니다.

Code Block
00000074 10/26/2020 16:1625:1206.71903223391141 [bsrreceive_thread_startSyncParam] [THREADPROTOCOL:1129] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(UnconnectedDUnknown), proleprpl(UnknownOff), cflagpdvflag(0x0), scf(0x0): Startingrecv receiverpeer threaddevice (from worker [2108])
00000759 10/13/2020 16:16:12.7191149 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CDDA5880] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CE0F9170 resource->worker.task:FFFFE000CDE0B820
00000760 10/13/2020 16:16:12.7191349 [print_state_change] [STATE:19option, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms

  • 00000075 .. [PROTOCOL:32] 로컬 노드의 현재 설정 되어 있는 복제 디스크 크기가 출력됩니다.

Code Block
00000075 10/26/2020 16:25:06.3396005 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown/0 minor 2, ds(UpToDate), cflagdvflag(0x0), scf(0x2a): conn_connect, conn( Unconnected -> Connecting )
00000761 10/13: current_mydisk_size: 10860101632 bytes

  • 00000076 .. [PROTOCOL:33] 피어 노드의 현재 설정 되어 있는 복제 디스크 크기와 최대로 설정 할 수 있는 복제 디스크 크기가 출력됩니다.

Code Block
00000076 10/26/2020 16:1625:1506.72248483396102 [bsrreceive_do_featuressizes] [PROTOCOL:5533] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(ConnectingDUnknown), proleprpl(UnknownOff), cflagpdvflag(0x0), scf(0x0): peer_current_size: Handshake10860101632 tobytes peer 1 successful: Agreed network protocol version 114
00000762 10/13_user_size: 0 bytes peer_disk_size: 10860101632 bytes peer_max_size: 10860101632 bytes

  • 00000077 .. [PROTOCOL:34] 로그는 최근 노드간 연결 후 협의로 설정 되어 있는 복제 디스크 크기가 출력됩니다.

Code Block
00000077 10/26/2020 16:1625:1506.72249163396215 [bsrreceive_do_featuressizes] [PROTOCOL:5634] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(ConnectingDUnknown), proleprpl(UnknownOff), cflagpdvflag(0x00x100000), scf(0x0): md_effective_size: Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000763 10/1321211136 my_user_size: 0 my_max_size: 21211136
00000078 10/26/2020 16:1625:1506.72273323396295 [conn_connectget_max_agreeable_size] [SEND BUFFERVOLUME:2798] bsr_warn<4>info<6> bsr r0 pnode-id:1/0 minor 2, csds(ConnectingUpToDate), proledvflag(Unknown), cflag(0x0), scf(0x0): send-buffering disabled nc->sndbuf_size:0
00000764 10/130x0): Skip the replication volume size comparison because it is a local node id(0)
00000079 10/26/2020 16:1625:1506.72274373396358 [bsrget_max_threadagreeable_startsize] [THREADVOLUME:1199] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(ConnectingDUnknown), proleprpl(UnknownOff), cflag(0x0), scf pdvflag(0x100000): node id(1) bitmap index(0) bitmap uuid(0x0): Starting ack_recv thread (from receiver [2808])
00000765 10/13flags(0x10) max size(21211136) disk state(DUnknown)
00000080 10/26/2020 16:1625:1506.77704043396463 [statereceive_change_locksizes] [STATEPROTOCOL:4039] bsr_info<6> [0xFFFFE000CDA1A040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CDAA58C0 resource->worker.task:FFFFE000CDE0B820
00000766 10/13 bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): Proceed with device size setting
00000081 10/26/2020 16:1625:1506.77706283397114 [changeget_clustermax_wideagreeable_statesize] [TWOPCVOLUME:3498] bsr_info<6> bsr r0/0 minor 2, rds(SecondaryUpToDate), fdvflag(0x0), scf(0x82a): Preparing cluster-wide state change 1853056548 (0->1 499/146)
00000767 10/13: Skip the replication volume size comparison because it is a local node id(0)
00000082 10/26/2020 16:1625:1506.77706643397234 [changeget_clustermax_wideagreeable_statesize] [TWOPCVOLUME:3599] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, rpdsk(SecondaryDUnknown), fprpl(0x0Off), scfpdvflag(0x82a0x100000): [TWOPC:1853056548] target_node_node id(1) bitmap connindex(Connected0) repl(-) disk(-bitmap uuid(0x0) pdskflags(-0x10) role(Secondary) peer(-max size(21211136) flagsdisk state(2058) 
00000768 10/13/2020 16:16:15.7776058 [change_cluster_wide_state] [TWOPC:36] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:1853056548] target_node_id(1) get_cluster_wide_reply (3) 
00000769 10/13/2020 16:16:15.7776109 [change_cluster_wide_state] [TWOPC:37DUnknown)

disconnect

  • disconnect 명령의 시작 로그 입니다.

Code Block
00000093 10/26/2020 16:37:52.2808432 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_DISCONNECT:11 command has been received. Execute the command.
00000094 10/26/2020 16:37:52.2808549 [state_change_lock] [STATE:40] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 1853056548: primary_nodes=0, weak_nodes=0
00000770 10/13[0xFFFFE0012B69D880] Worker should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C513C60
00000095 10/26/2020 16:1637:1552.77761452808836 [change_cluster_wide_state] [TWOPC:3934] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a0x28): CommittingPreparing cluster-wide state change 18530565483319182627 (1ms) (0->1 496/16)
0000077100000096 10/1326/2020 16:1637:1552.77784712808878 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000772 10/13/2020 16:16:15.7779527 [receive_SyncParam] [PROTOCOL:29_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x0), pdvflagscf(0x00x28): sync, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000773 10/13[TWOPC:3319182627] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000097 10/26/2020 16:1637:1552.77812602812432 [receive_sizeschange_cluster_wide_state] [PROTOCOLTWOPC:3236] bsr_info<6> bsr r0/0 minor 2, r(Secondary), dsf(UpToDate0x0), dvflagscf(0x00x28): current_mydisk_size: 10860101632 bytes
00000774 10/13 [TWOPC:3319182627] target_node_id(1) get_cluster_wide_reply (3) 
00000098 10/26/2020 16:1637:1552.77812922812481 [receive_sizeschange_cluster_wide_state] [PROTOCOLTWOPC:3337] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off), pdvflag(0x0): peer_current_size: 10860101632 bytes peer_user_size: 0 bytes peer_disk_size: 10860101632 bytes peer_max_size: 10860101632 bytes
00000775 10/130x0), scf(0x28): State change 3319182627: primary_nodes=0, weak_nodes=0
00000099 10/26/2020 16:1637:1552.77813342812511 [receive_sizeschange_cluster_wide_state] [PROTOCOLTWOPC:3438] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskcs(DUnknownConnected), prplprole(OffSecondary), pdvflagcflag(0x1000000x10e): md_effective_size, scf(0x28): 21211136 my_user_size: 0 my_max_size: 21211136
00000776Cluster is now split
00000100 10/1326/2020 16:1637:1552.77813652812540 [getchange_maxcluster_agreeablewide_sizestate] [GENLTWOPC:1639] bsr_info<6> bsr r0/0 minor 2, dsr(UpToDateSecondary), dvflagf(0x0), scf(0x28): local node_id: 0
00000777 10/13 Committing cluster-wide state change 3319182627 (1ms) (0->1)

  • 00000101 .. [STATE:19] disconnect 명령으로 연결을 직접 종료할 경우 연결 상태가 StandAlone으로 변경됩니다.

Code Block
00000101 10/26/2020 16:1637:1552.77813872813798 [getprint_maxstate_agreeable_sizechange] [GENLSTATE:1719] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknowncs(Connected), prole(Secondary), prplcflag(Off0x10e), pdvflagscf(0x1000000x208): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)
00000778 10/13conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown )
00000102 10/26/2020 16:1637:1552.77814292813842 [receiveprint_state_sizeschange] [PROTOCOLSTATE:3921] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknownUpToDate), prpl(OffEstablished), pdvflag(0x1000000x100600): Proceed with device size setting
00000779 10/13/2020 16:16:15.7782072 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): local node_id: 0
00000780 10/13conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000103 10/26/2020 16:1637:1552.77821092814295 [get_max_agreeable_sizebsr_recv] [GENLSOCKET:1715] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskcs(DUnknownConnected), prplprole(OffSecondary), pdvflagcflag(0x1000000x10e):, node idscf(10x208): bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)

resource down

Code Block
00000617 10/13Data stream socket receive error(-15)
00000104 10/26/2020 16:1637:1152.21368052814897 [NetlinkWorkThreadbsr_ack_receiver] [NETLINKCONNECTION:1816] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) begin ->
00000618 10/13bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated
00000105 10/26/2020 16:1637:1152.21373442814968 [FsctlLockVolumebsr_thread_setup] [VOLUMETHREAD:659] bsr_info<6> [0xFFFFE000CCAC4880] try lock volume(\Device\HarddiskVolume2)
00000680 10/13bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Terminating ack_recv thread
00000106 10/26/2020 16:1637:1152.25348832817384 [FsctlLockVolumew_resync_timer] [VOLUMERESYNC/OV:23105] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) locked. handle(0xFFFFFFFF80000DC8)
00000683 10/13/2020 16:16:11.2535024 [FsctlFlushDismountVolume] [VOLUME:62] bsr_info<6> [0xFFFFE000CCAC4880] try flush volume(\Device\HarddiskVolume2)
00000684 10/13/2020 16:16:11.2535729 [FsctlFlushDismountVolume] [VOLUME:63] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) flushed
00000685 10/13/2020 16:16:11.2535766 [FsctlFlushDismountVolume] [VOLUME:64] bsr_info<6> [0xFFFFE000CCAC4880] try dismount volume(\Device\HarddiskVolume2)
00000686 10/13/2020 16:16:11.2559822 [FsctlFlushDismountVolume] [VOLUMEbsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): The resync is complete because it is not in VerifyS or SyncTarget replication state.
00000107 10/26/2020 16:37:52.2820403 [conn_disconnect] [CONNECTION:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Connection closed
00000108 10/26/2020 16:37:52.2820944 [print_state_change] [STATE:19] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) dismounted
00000687 10/13 bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone )
00000109 10/26/2020 16:1637:1152.25601782821351 [printbsr_statethread_changesetup] [STATETHREAD:189] bsr_info<6> bsr r0 pnode-id:1, rcs(PrimaryStandAlone), fprole(0x11Unknown), scfcflag(0x83c0x10e): change_role, rolescf(0x0): Primary -> Secondary )
00000688Terminating receiver thread
00000110 10/1326/2020 16:1637:1152.25682562823823 [__receive_uuidsNetlinkWorkThread] [UUIDNETLINK:1620] bsr_warn<4>info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): receive new current but not update UUID: 83F530CA41FA9868
00000689 10/13[0xFFFFE0012B69D880] BSR_ADM_DISCONNECT:11 command execution terminated. (pending command:0)

up

다음은 bsradm up 명령에 따른 일련의 로그의 예 이며, 순차적으로 수행되는 개별 동작 로그에 대해 설명합니다.

Info

up 명령은 리소스를 기동하는 명령으로 리소스를 기동하기 위해 필요한 여러 단계의 명령을 순차적으로 수행합니다. new-resource, new-minor, new-peer, new-path, attach, connect 명령들이 순차적으로 수행됩니다.

Code Block
00000018 10/26/2020 16:1625:1103.25683172195574 [bsr_uuid_compareNetlinkWorkThread] [RESYNC/OVNETLINK:19718] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): Local and peer current UUIDs are the same. rule(40), res(0)
00000690 10/13[0xFFFFE0012B69D880] BSR_ADM_NEW_RESOURCE:7 command has been received. Execute the command.
00000019 10/26/2020 16:1625:1103.25698572195696 [FsctlUnlockVolumebsr_thread_start] [VOLUMETHREAD:6112] bsr_info<6> [0xFFFFE000CCAC4880] unlock volume(\Device\HarddiskVolume2)
00000691 10/13/2020 16:16:11.2576899 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) unlocked
00000692 10/13bsr r0, r(Secondary), f(0x0), scf(0x0): Starting worker thread (from not_bsr_thread [0])
00000020 10/26/2020 16:1625:1103.25771792197637 [state_change_lockNetlinkWorkThread] [STATENETLINK:4020] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B69D880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDB38300
00000693 10/13BSR_ADM_NEW_RESOURCE:7 command execution terminated. (pending command:0)
00000021 10/26/2020 16:1625:1103.25773282278267 [change_cluster_wide_stateNetlinkWorkThread] [TWOPCNETLINK:34] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): Preparing cluster-wide state change 1834520240 (0->1 496/16)
00000694 10/1318] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command has been received. Execute the command.
00000022 10/26/2020 16:1625:1103.25773552278667 [changebsr_clustercreate_wide_statedevice] [TWOPCVOLUME:3510] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): [TWOPC:1834520240] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000695 10/13[0xFFFFE0012A786040] The capacity of the create device(FFFFE0012CAD1AB0) is max sectors(21211136), size(10860101632 bytes)
00000023 10/26/2020 16:1625:1103.25802122280254 [change_cluster_wide_stateNetlinkWorkThread] [TWOPCNETLINK:3620] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): [TWOPC:1834520240] target_node_id(1) get_cluster_wide_reply (3) 
00000696 10/13 [0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command execution terminated. (pending command:0)
00000024 10/26/2020 16:25:03.2352395 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44 command has been received. Execute the command.
00000025 10/26/2020 16:1625:1103.25802512352568 [change_cluster_wide_statebsr_create_peer_device_default_config] [TWOPCGENL:3745] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, rpdsk(SecondaryDUnknown), fprpl(0x11Off), scfpdvflag(0x28): State change 1834520240: primary_nodes=0, weak_nodes=0
00000697 10/130x0): default peer device option. resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000026 10/26/2020 16:1625:1103.25802752352753 [changebsr_clusterthread_wide_statestart] [TWOPCTHREAD:3811] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectedStandAlone), prole(SecondaryUnknown), cflag(0x210e0x0), scf(0x280x0): Starting sender Clusterthread is now split
00000698(from not_bsr_thread [0])
00000027 10/1326/2020 16:1625:1103.25803002354514 [change_cluster_wide_stateNetlinkWorkThread] [TWOPCNETLINK:3920] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): Committing cluster-wide state change 1834520240 (0ms) (0->1)
00000699 10/13[0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44 command execution terminated. (pending command:0)
00000028 10/26/2020 16:1625:1103.25843882442056 [ReceiveNetlinkWorkThread] [SOCKETNETLINK:6618] bsr_info<6> [0xFFFFE000CDB668800xFFFFE0012A786040] receiver => Recv multiWait error. err(STATUS_CONNECTION_RESET) wsk(0xFFFFE000CE2A8198) size(16)
00000700 10/13BSR_ADM_NEW_PATH:45 command has been received. Execute the command.
00000029 10/26/2020 16:1625:1103.25845792444816 [bsr_recvNetlinkWorkThread] [SOCKETNETLINK:1420] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x210e), scf(0x28): socket reset due to peer.
00000701 10/13 [0xFFFFE0012A786040] BSR_ADM_NEW_PATH:45 command execution terminated. (pending command:0)
00000030 10/26/2020 16:25:03.2884146 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B2FC880] BSR_ADM_ATTACH:12 command has been received. Execute the command.
00000031 10/26/2020 16:1625:1103.25847572889320 [print_state_change_lock] [STATE:1940] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x210e), scf(0x21): bsr_recv, conn( Connected -> BrokenPipe ) peer( Secondary -> Unknown )
00000702 10/13[0xFFFFE0012B2FC880] Worker should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C513C60
00000032 10/26/2020 16:1625:1103.25848052889474 [print_state_change] [STATE:2120] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskds(UpToDateDiskless), prpldvflag(Established), pdvflag(0x100600)0x0): bsrchange_disk_recvstate, pdskdisk( UpToDateDiskless -> DUnknownAttaching ) repl( Established -> Off )
00000703 10/13
00000033 10/26/2020 16:25:03.2890049 [FsctlLockVolume] [VOLUME:65] bsr_info<6> [0xFFFFE0012B2FC880] try lock volume(\Device\HarddiskVolume2)
00000034 10/26/2020 16:1625:1103.25850712959696 [bsr_recv_all_warnFsctlLockVolume] [PROTOCOLVOLUME:6423] bsr_warn<4>info<6> bsr r0 pnode-id:1, cs(BrokenPipe), prole(Unknown), cflag(0x211e), scf(0x0): short read (expected size 16)
00000704 10/13[0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) locked. handle(0xFFFFFFFF80000AFC)
00000035 10/26/2020 16:25:03.2959798 [FsctlFlushDismountVolume] [VOLUME:62] bsr_info<6> [0xFFFFE0012B2FC880] try flush volume(\Device\HarddiskVolume2)
00000036 10/26/2020 16:1625:1103.25852472959854 [print_state_changeFsctlFlushDismountVolume] [STATEVOLUME:1917] bsr_info<6> bsr r0 pnode-id:1, cs(BrokenPipe), prole(Unknown), cflag(0x211e), scf(0x208): conn_try_disconnect, conn( BrokenPipe -> Disconnecting )
00000705 10/13[0xFFFFE0012B2FC880] Failed to flush volume. status(0xc000026e)
00000037 10/26/2020 16:25:03.2959874 [FsctlFlushDismountVolume] [VOLUME:63] bsr_info<6> [0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) flushed
00000038 10/26/2020 16:1625:1103.25864952959893 [bsr_ack_receiverFsctlFlushDismountVolume] [CONNECTIONVOLUME:1664] bsr_info<6> bsr[0xFFFFE0012B2FC880] r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x0): ack_receiver terminated
00000706 10/13try dismount volume(\Device\HarddiskVolume2)
00000039 10/26/2020 16:1625:1103.25865322965893 [bsr_thread_setupFsctlFlushDismountVolume] [THREADVOLUME:919] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x0): Terminating ack_recv thread
00000707 10/13[0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) dismounted
00000040 10/26/2020 16:1625:1103.25876922965979 [w_resync_timerFsctlUnlockVolume] [RESYNC/OVVOLUME:10561] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): completed because it is not in the VerifyS or SyncTarget replication state.
00000708 10/13[0xFFFFE0012B2FC880] unlock volume(\Device\HarddiskVolume2)
00000041 10/26/2020 16:25:03.2969597 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) unlocked
00000042 10/26/2020 16:1625:1103.25911572969738 [connbsr_adm_disconnectattach] [CONNECTIONGENL:936] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown/0 minor 2, ds(Attaching), cflag(0x211e), scf(dvflag(0x0): Connection closed
00000709 The maximum number of bitmap peer devices is 1.
00000043 10/1326/2020 16:1625:1103.25916882979413 [printbsr_bump_statewrite_changeordering] [STATEVOLUME:1966] bsr_info<6> bsr r0 pnode-id:1, csr(DisconnectingSecondary), prole(Unknown), cflag(0x211ef(0x0), scf(0x230x1): conn_disconnect, conn( Disconnecting -> StandAlone )
00000710Method to ensure write ordering: drain
00000044 10/1326/2020 16:1625:1103.25919812979447 [bsrget_max_threadagreeable_setupsize] [THREADVOLUME:998] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x211e), scf(0x0): Terminating receiver thread
00000711 10/13/0 minor 2, ds(Attaching), dvflag(0x0): Skip the replication volume size comparison because it is a local node id(0)
00000045 10/26/2020 16:1625:1103.25924682979474 [bsrget_max_threadagreeable_setupsize] [THREADVOLUME:999] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(StandAloneDUnknown), proleprpl(UnknownOff), cflag(0x211e), scf(0x0): Terminating sender thread
00000712 10/13 pdvflag(0x0): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000046 10/26/2020 16:1625:1103.25930362979681 [bsrget_max_destroyagreeable_connectionsize] [CONNECTIONVOLUME:198] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x311e), scf/0 minor 2, ds(Attaching), dvflag(0x0): bsr_destroy_connection
00000713 10/13/2020 16:16:11.2593241 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDB38300
00000714 10/13Skip the replication volume size comparison because it is a local node id(0)
00000047 10/26/2020 16:1625:1103.25933392979705 [printget_max_stateagreeable_changesize] [STATEVOLUME:2099] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, ds(UpToDatepdsk(DUnknown), prpl(Off), dvflagpdvflag(0x20x0): change_disk_state, disk( UpToDate -> Detaching )
00000715 10/13 node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000048 10/26/2020 16:1625:1103.25933782979742 [finishbsr_statebm_changeresize] [UUIDBITMAP:1923] bsr_info<6> bsr r0/0 minor 2, ds(UpToDateAttaching), dvflag(0x100020x0): detachingStart resizing the bitmap size to disk currentcapacity. UUID: 83F530CA41FA9868
00000716capacity sector(21211136)
00000049 10/1326/2020 16:1625:1103.25938632985588 [printbsr_statebm_changeresize] [STATEBITMAP:2025] bsr_info<6> bsr r0/0 minor 2, ds(DetachingAttaching), dvflag(0x10020x0): change_disk_state, disk( Detaching -> Diskless )
00000717 10/13/2020 16:16:11.2593963 [adm_detach] [GENL:42] bsr_info<6> [0xFFFFE000CCAC4880] wait event interruptible timeout. time out(3000) disk state(Diskless)
00000718 10/13The bitmap size has been resized to disk capacity. bits(2651392) words(82856) pages(81)

  • 00000050 .. [VOLUME:96] attach 대상 복제 볼륨의 크기가 출력됩니다.

Code Block
00000050 10/26/2020 16:1625:1103.25991582985622 [bsr_bmdetermine_dev_resizesize] [BITMAPVOLUME:2396] bsr_info<6> bsr r0/0 minor 2, ds(DisklessAttaching), dvflag(0x20x0): bitmap resize called with capacity(0)
00000719 10/13Update the disk size in the meta. 10 GB (10605568 KB)
00000051 10/26/2020 16:1625:1103.26011413028170 [bsrbm_threadrw_setuprange] [THREADBITMAP:1029] bsr_info<6> bsr r0, r(Secondary)/0 minor 2, fds(0x11Attaching), scfdvflag(0x0): Terminating worker thread
00000720 Recounting of set bits took additional 0ms
00000052 10/1326/2020 16:1625:1103.26015623028240 [mvolWorkThreadstate_change_lock] [THREADSTATE:2040] bsr_info<6> [0xFFFFE000CDC92880] Terminating mvolWorkThread
00000721 10/130xFFFFE0012B2FC880] Worker should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C513C60
00000053 10/26/2020 16:1625:1103.26038183028465 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:20] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) done (cmd_pending:0) <-

resource connect

Code Block
00000791 10/13 bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )

  • 00000054 .. [UUID:14] attach 대상 복제 볼륨의 current UUID가 출력됩니다.

Code Block
00000054 10/26/2020 16:1825:2003.97619143028511 [NetlinkWorkThreadfinish_state_change] [NETLINKUUID:1814] bsr_info<6> [0xFFFFE000CCAFB880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) begin ->
00000792 10/13 bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): attached to current UUID: A95D18E8D4AE8C78
00000055 10/26/2020 16:1825:2003.97620233033626 [state_change_lockNetlinkWorkThread] [STATENETLINK:4020] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012B2FC880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000793 10/13BSR_ADM_ATTACH:12 command execution terminated. (pending command:0)

  • connect 명령을 수행합니다.

Code Block
00000059 10/26/2020 16:1825:2003.97622183139110 [change_cluster_wide_stateNetlinkWorkThread] [TWOPCNETLINK:3420] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): Preparing cluster-wide state change 2366568536 (0->1 496/16)
00000794 10/13[0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command execution terminated. (pending command:0)
00000060 10/26/2020 16:1825:2003.97622523139464 [changebsr_clusterthread_wide_statestart] [TWOPCTHREAD:3511] bsr_info<6> bsr r0 pnode-id:1, r(Secondarycs(Unconnected), prole(Unknown), fcflag(0x0), scf(0x280x0): [TWOPC:2366568536] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000795 10/13Starting receiver thread (from worker [2928])
00000061 10/26/2020 16:1825:2003.97663563140159 [state_change_cluster_wide_statelock] [TWOPCSTATE:3640] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:2366568536] target_node_id(1) get_cluster_wide_reply (3) 
00000796 10/13info<6> [0xFFFFE0012C706040] Worker should not initiate state changes with CS_SERIALIZE current:FFFFE0012C707160 resource->worker.task:FFFFE0012C513C60
00000062 10/26/2020 16:1825:2003.97664123140398 [changeprint_clusterstate_wide_statechange] [TWOPCSTATE:3719] bsr_info<6> bsr r0 pnode-id:1, r(Secondarycs(Unconnected), prole(Unknown), fcflag(0x0), scf(0x280x2a): State change 2366568536: primary_nodes=0, weak_nodes=0
00000797 10/13conn_connect, conn( Unconnected -> Connecting )
00000063 10/26/2020 16:1825:2006.97664633224961 [changebsr_clusterdo_wide_statefeatures] [TWOPCPROTOCOL:3855] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectedConnecting), prole(SecondaryUnknown), cflag(0x10e0x0), scf(0x28): Cluster is now split
00000798 10/130x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000064 10/26/2020 16:1825:2006.97664973225110 [changebsr_clusterdo_wide_statefeatures] [TWOPCPROTOCOL:3956] bsr_info<6> bsr r0 pnode-id:1, r(Secondarycs(Connecting), prole(Unknown), fcflag(0x0), scf(0x280x0): Committing cluster-wide state change 2366568536 (0ms) (0->1)
00000799 10/13Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000065 10/26/2020 16:1825:2006.97677703231473 [printconn_state_changeconnect] [STATESEND BUFFER:1927] bsr_info<6>warn<4> bsr r0 pnode-id:1, cs(ConnectedConnecting), prole(SecondaryUnknown), cflag(0x10e0x0), scf(0x2080x0): conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown )
00000800 10/13send-buffering disabled nc->sndbuf_size:0
00000066 10/26/2020 16:1825:2006.97678313231590 [printbsr_statethread_changestart] [STATETHREAD:2111] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cs(Connecting), prole(Unknown), pdskcflag(UpToDate0x0), prpl(Established), pdvflag(0x100600): conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000801 10/13 scf(0x0): Starting ack_recv thread (from receiver [1700])
00000067 10/26/2020 16:25:06.3374818 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE0012CBD2040] Worker should not initiate state changes with CS_SERIALIZE current:FFFFE0012C7CCC20 resource->worker.task:FFFFE0012C513C60
00000068 10/26/2020 16:1825:2006.97682113375354 [bsr_recvchange_cluster_wide_state] [SOCKETTWOPC:1534] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(r(Secondary), cflagf(0x10e0x0), scf(0x2080x82a): socket data receive error(-15)
00000802 10/13 Preparing cluster-wide state change 177619259 (0->1 499/146)
00000069 10/26/2020 16:1825:2006.97689743375466 [bsrchange_cluster_ackwide_receiverstate] [CONNECTIONTWOPC:1635] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated
00000803 10/13, r(Secondary), f(0x0), scf(0x82a): [TWOPC:177619259] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (2058) 
00000070 10/26/2020 16:1825:2006.97690283384621 [bsrchange_cluster_threadwide_setupstate] [THREADTWOPC:936] bsr_info<6> bsr r0 pnode-id:1, r(Secondary), csf(Disconnecting0x0), prolescf(Unknown), cflag(0x10e), scf(0x0): Terminating ack_recv thread
00000804 10/130x82a): [TWOPC:177619259] target_node_id(1) get_cluster_wide_reply (3) 
00000071 10/26/2020 16:1825:2006.97719903384814 [wchange_cluster_resyncwide_timerstate] [RESYNC/OVTWOPC:10537] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x0), pdvflagscf(0x00x82a): completedState becausechange it is not in the VerifyS or SyncTarget replication state.
00000805 10/13177619259: primary_nodes=0, weak_nodes=0
00000072 10/26/2020 16:1825:2006.97743973384904 [conn_disconnectchange_cluster_wide_state] [CONNECTIONTWOPC:939] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting) r0, proler(UnknownSecondary), cflagf(0x10e0x0), scf(0x00x82a): Connection closed
00000806 Committing cluster-wide state change 177619259 (1ms) (0->1)
00000073 10/1326/2020 16:1825:2006.97749283389819 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(DisconnectingConnecting), prole(Unknown), cflag(0x10e0xc), scf(0x230xa0a): connconnect_disconnectwork, conn( Connecting -> Connected ) peer( DisconnectingUnknown -> StandAloneSecondary )
0000080700000074 10/1326/2020 16:1825:2006.97753353391141 [bsrreceive_thread_setupSyncParam] [THREADPROTOCOL:929] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(StandAloneDUnknown), proleprpl(UnknownOff), cflagpdvflag(0x10e), scf(0x0): Terminating receiver thread
00000808 10/13/2020 16:18:20.9777552 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) done (cmd_pending:0) <-
00000809 10/13/2020 16:18:22.9478253 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) begin ->
00000810 10/13/2020 16:18:22.9478355 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAAC040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000811 10/13/2020 16:18:22.9478519 [print_state_change] [STATE:190x0): recv peer device option, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000075 10/26/2020 16:25:06.3396005 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): current_mydisk_size: 10860101632 bytes
00000076 10/26/2020 16:25:06.3396102 [receive_sizes] [PROTOCOL:33] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): peer_current_size: 10860101632 bytes peer_user_size: 0 bytes peer_disk_size: 10860101632 bytes peer_max_size: 10860101632 bytes
00000077 10/26/2020 16:25:06.3396215 [receive_sizes] [PROTOCOL:34] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(StandAloneDUnknown), proleprpl(UnknownOff), cflagpdvflag(0x10e), scf(0x2a)0x100000): bsrmd_admeffective_connect, conn( StandAlone -> Unconnected )
00000812 10/13size: 21211136 my_user_size: 0 my_max_size: 21211136
00000078 10/26/2020 16:1825:2206.94789043396295 [bsrget_max_threadagreeable_startsize] [THREADVOLUME:1198] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x10e), scf/0 minor 2, ds(UpToDate), dvflag(0x0): StartingSkip receiver thread (from worker [2108])
00000813 10/13/2020 16:18:22.9480150 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) done (cmd_pending:0) <-
00000814 10/13the replication volume size comparison because it is a local node id(0)
00000079 10/26/2020 16:1825:2206.94802653396358 [stateget_max_changeagreeable_locksize] [STATEVOLUME:4099] bsr_info<6> [0xFFFFE000CE728040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CE0F9170 resource->worker.task:FFFFE000CDE0B820
00000815 10/13 bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)
00000080 10/26/2020 16:1825:2206.94804163396463 [printreceive_state_changesizes] [STATEPROTOCOL:1939] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(UnconnectedDUnknown), proleprpl(UnknownOff), cflagpdvflag(0xe), scf(0x2a)0x100000): conn_connect, conn( Unconnected -> Connecting )
00000816Proceed with device size setting
00000081 10/1326/2020 16:1825:2506.95669413397114 [bsrget_max_doagreeable_featuressize] [PROTOCOLVOLUME:5598] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown/0 minor 2, ds(UpToDate), cflag(0xe), scf(dvflag(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000817 10/13 Skip the replication volume size comparison because it is a local node id(0)
00000082 10/26/2020 16:1825:2506.95670173397234 [bsrget_max_doagreeable_featuressize] [PROTOCOLVOLUME:5699] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0x0): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000818 10/13/2020 16:18:25.9568141 [conn_connect] [SEND BUFFER:27] bsr_warn<4> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0x0): send-buffering disabled nc->sndbuf_size:0
00000819 10/13/2020 16:18:25.9568180 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0x0): Starting ack_recv thread (from receiver [1676])
00000820 10/13/2020 16:18:26.0424367 [state_change_lock] [STATE:40 pdsk(DUnknown), prpl(Off), pdvflag(0x100000): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)

down

bsradm down 명령에서 순차적으로 수행하는 개별 동작 로그에 대해 설명합니다.

Info

down 은 리소스를 볼륨에 대한 베타적 락 획득, Flush, dismount, 연결 해제, 볼륨 잠금의 순서로 수행합니다.

Code Block
00000398 10/26/2020 16:49:10.2436929 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B2F9880] BSR_ADM_DOWN:27 command has been received. Execute the command.

  • 00000399 .. [VOLUME:65], 00000680 .. [VOLUME:23] 복제 볼륨에 대한 베타적 락 획득을 시도합니다. 베타적 락이 다른 프로세스에 의해 이미 획득된 상태이면 이 시도는 실패할 수 있습니다. 이 시도가 실패되더라도 무시하고 다음 단계로 넘어갑니다.

Code Block
00000399 10/26/2020 16:49:10.2437390 [FsctlLockVolume] [VOLUME:65] bsr_info<6> [0xFFFFE0012B2F9880] try lock volume(\Device\HarddiskVolume2)
00000472 10/26/2020 16:49:10.2864430 [FsctlLockVolume] [VOLUME:23] bsr_info<6> [0xFFFFE000CDA1A0400xFFFFE0012B2F9880] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CDAA58C0 resource->worker.task:FFFFE000CDE0B820
00000821 10/13volume(\Device\HarddiskVolume2) locked. handle(0xFFFFFFFF80000C20)

  • 00000473 .. [VOLUME:62], 00000474 .. [VOLUME:63] 복제 볼륨에 대한 캐쉬 flush 를 수행합니다.

Code Block
00000473 10/26/2020 16:1849:2610.04245862864535 [change_cluster_wide_stateFsctlFlushDismountVolume] [TWOPCVOLUME:3462] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 2387348015 (0->1 499/146)
00000822 10/13[0xFFFFE0012B2F9880] try flush volume(\Device\HarddiskVolume2)
00000474 10/26/2020 16:1849:2610.04247332864915 [change_cluster_wide_stateFsctlFlushDismountVolume] [TWOPCVOLUME:3563] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:2387348015] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (2058) 
00000823 10/13[0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) flushed

  • 00000475 .. [VOLUME:64], 00000476 .. [VOLUME:19] 복제 볼륨 dismount 를 수행합니다.

Code Block
00000475 10/26/2020 16:1849:2610.04304892864954 [change_cluster_wide_stateFsctlFlushDismountVolume] [TWOPCVOLUME:3664] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:2387348015] target_node_id(1) get_cluster_wide_reply (3) 
00000824 10/13[0xFFFFE0012B2F9880] try dismount volume(\Device\HarddiskVolume2)
00000479 10/26/2020 16:1849:2610.04305602871632 [change_cluster_wide_stateFsctlFlushDismountVolume] [TWOPCVOLUME:3719] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 2387348015: primary_nodes=0, weak_nodes=0
00000825 10/13[0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) dismounted

  • 00000480 .. [STATE:18] role이 primary 이면 secondary 로 먼저 강등합니다.

Code Block
00000480 10/26/2020 16:1849:2610.04306112871910 [changeprint_clusterstate_wide_statechange] [TWOPCSTATE:3918] bsr_info<6> bsr r0, r(SecondaryPrimary), f(0x00x1), scf(0x82a0x83c): Committing cluster-wide state change 2387348015 (0ms) (0->1)
00000826 10/13change_role, role( Primary -> Secondary )
00000481 10/26/2020 16:1849:2610.04323172879558 [print__statereceive_changeuuids] [STATEUUID:1916] bsr_info<6>warn<4> bsr r0/0 minor 2 pnode-id:1, cspdsk(ConnectingUpToDate), proleprpl(UnknownEstablished), cflag(0xe), scf(0xa0apdvflag(0x100600): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000827 10/13receive new current but not update UUID: CE5CC8B0672E645C
00000482 10/26/2020 16:1849:2610.04349602879607 [receivebsr_uuid_SyncParamcompare] [PROTOCOLRESYNC/OV:29197] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, ds(UpToDate), pdskdvflag(DUnknown), prpl(Off0x2): Local and peer current UUIDs are the same. rule(40), pdvflagres(0x0): sync, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000828 10/13/2020 16:18:26.0435080 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): current_mydisk_size: 10860101632 bytes
00000829 10/13/2020 16:18:26.0435114 [receive_sizes] [PROTOCOL:330)

  • 00000483 .. [VOLUME:61], 00000691 .. [VOLUME:26] 복제 볼륨에 대한 베타적 락을 가지고 있었다면 반환합니다.

Code Block
00000483 10/26/2020 16:49:10.2881069 [FsctlUnlockVolume] [VOLUME:61] bsr_info<6> [0xFFFFE0012B2F9880] unlock volume(\Device\HarddiskVolume2)
00000484 10/26/2020 16:49:10.2889783 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) unlocked
00000485 10/26/2020 16:49:10.2890044 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE0012B2F9880] Worker should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C7D29A0

  • disconnect 를 수행합니다.

Code Block
00000486 10/26/2020 16:49:10.2890183 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x1), pdvflagscf(0x00x28): peer_current_size: 10860101632 bytes peer_user_size: 0 bytes peer_disk_size: 10860101632 bytes peer_max_size: 10860101632 bytes
00000830 10/13 Preparing cluster-wide state change 1805107054 (0->1 496/16)
00000487 10/26/2020 16:1849:2610.04351682890209 [receive_sizeschange_cluster_wide_state] [PROTOCOLTWOPC:3435] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x1), pdvflagscf(0x1000000x28): [TWOPC:1805107054] mdtarget_effective_size: 21211136 my_user_size: 0 my_max_size: 21211136
00000831 10/13node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000488 10/26/2020 16:1849:2610.04352092893052 [getchange_maxcluster_agreeablewide_sizestate] [GENLTWOPC:1636] bsr_info<6> bsr r0/0 minor 2, r(Secondary), dsf(UpToDate0x1), dvflagscf(0x00x28): local [TWOPC:1805107054] target_node_id: 0
00000832(1) get_cluster_wide_reply (3) 
00000489 10/1326/2020 16:1849:2610.04352362893089 [getchange_maxcluster_agreeablewide_sizestate] [GENLTWOPC:1737] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x1), pdvflagscf(0x1000000x28): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)
00000833 10/13State change 1805107054: primary_nodes=0, weak_nodes=0
00000490 10/26/2020 16:1849:2610.04352922893113 [receive_sizeschange_cluster_wide_state] [PROTOCOLTWOPC:3938] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknowncs(Connected), prole(Secondary), prplcflag(Off0x10e), pdvflagscf(0x1000000x28): ProceedCluster withis devicenow sizesplit
setting
0000083400000491 10/1326/2020 16:1849:2610.04364432893140 [getchange_maxcluster_agreeablewide_sizestate] [GENLTWOPC:1639] bsr_info<6> bsr r0/0 minor 2, r(Secondary), dsf(UpToDate0x1), dvflagscf(0x00x28): local node_id: 0
00000835 Committing cluster-wide state change 1805107054 (1ms) (0->1)
00000492 10/1326/2020 16:1849:2610.04364742895017 [getprint_maxstate_agreeable_sizechange] [GENLSTATE:1719] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskcs(DUnknownConnected), prplprole(OffSecondary), pdvflagcflag(0x1000000x10e):, node idscf(10x208) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)

resource disconnect

Code Block
00000791 10/13/2020 16:18:20.9761914 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAFB880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) begin ->
00000792 10/13: conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown )
00000493 10/26/2020 16:1849:2010.97620232895061 [print_state_change_lock] [STATE:4021] bsr_info<6> [0xFFFFE000CCAFB880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000793 10/13bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000494 10/26/2020 16:1849:2010.97622182895371 [change_cluster_wide_statebsr_recv] [TWOPCSOCKET:3415] bsr_info<6> bsr r0 pnode-id:1, rcs(Connected), prole(Secondary), fcflag(0x00x10e), scf(0x280x208): PreparingData cluster-widestream statesocket changereceive 2366568536 error(0->1 496/1615)
0000079400000495 10/1326/2020 16:1849:2010.97622522895990 [changebsr_clusterack_wide_statereceiver] [TWOPCCONNECTION:3516] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:2366568536] target_node_id(1) conn pnode-id:1, cs(Disconnecting), replprole(-Unknown), diskcflag(-0x10e), pdskscf(-0x0) role(-) peer(-) flags (8) 
00000795 10/13: ack_receiver terminated
00000496 10/26/2020 16:1849:2010.97663562896039 [changebsr_clusterthread_wide_statesetup] [TWOPCTHREAD:369] bsr_info<6> bsr r0 pnode-id:1, r(Secondarycs(Disconnecting), prole(Unknown), fcflag(0x00x10e), scf(0x280x0): [TWOPC:2366568536] target_node_id(1) get_cluster_wide_reply (3) 
00000796Terminating ack_recv thread
00000497 10/1326/2020 16:1849:2010.97664122897546 [changew_clusterresync_wide_statetimer] [TWOPCRESYNC/OV:37105] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, rpdsk(SecondaryDUnknown), fprpl(0x0Off), scfpdvflag(0x280x0): State change 2366568536: primary_nodes=0, weak_nodes=0
00000797 10/13 The resync is complete because it is not in VerifyS or SyncTarget replication state.
00000498 10/26/2020 16:1849:2010.97664632900523 [change_cluster_wide_stateconn_disconnect] [TWOPCCONNECTION:389] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectedDisconnecting), prole(SecondaryUnknown), cflag(0x10e), scf(0x280x0): ClusterConnection is now split
00000798closed
00000499 10/1326/2020 16:1849:2010.97664972900922 [changeprint_clusterstate_wide_statechange] [TWOPCSTATE:3919] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), rprole(SecondaryUnknown), fcflag(0x00x10e), scf(0x280x23): Committing cluster-wide state change 2366568536 (0ms) (0->1)
00000799 10/13conn_disconnect, conn( Disconnecting -> StandAlone )
00000500 10/26/2020 16:1849:2010.97677702901181 [printbsr_statethread_changesetup] [STATETHREAD:199] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectedStandAlone), prole(SecondaryUnknown), cflag(0x10e), scf(0x208): conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown )
00000800 10/13(0x10e), scf(0x0): Terminating receiver thread
00000501 10/26/2020 16:1849:2010.97678312901744 [printbsr_statethread_changesetup] [STATETHREAD:219] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskcs(UpToDateStandAlone), prplprole(EstablishedUnknown), pdvflagcflag(0x100600): conn_try_disconnect0x10e), pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000801 10/13scf(0x0): Terminating sender thread
00000502 10/26/2020 16:1849:2010.97682112902522 [bsr_destroy_recvconnection] [SOCKETCONNECTION:151] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectedStandAlone), prole(SecondaryUnknown), cflag(0x10e0x110e), scf(0x2080x0): The socketconnection dataobject receive error(-15)
00000802is removed.
00000503 10/1326/2020 16:1849:2010.97689742902683 [bsrstate_ackchange_receiverlock] [CONNECTIONSTATE:1640] bsr_info<6> [0xFFFFE0012B2F9880] bsrWorker r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated
00000803 10/13should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C7D29A0

  • 00000504 .. [STATE:20] detaching 상태 변경이 출력됩니다.

Code Block
00000504 10/26/2020 16:1849:2010.97690282902780 [bsrprint_threadstate_setupchange] [THREADSTATE:920] bsr_info<6> bsr r0 pnode-id:1/0 minor 2, csds(DisconnectingUpToDate), proledvflag(Unknown0x2), cflag(0x10e), scf(0x0): Terminating ack_recv thread
00000804 10/13: change_disk_state, disk( UpToDate -> Detaching )

  • 00000715 .. [UUID?:19] detaching 시 복제 볼륨의 current UUID 가 출력됩니다.

Code Block
00000505 10/26/2020 16:1849:2010.97719902902819 [wfinish_resyncstate_timerchange] [RESYNC/OVUUID:10519] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskds(DUnknownUpToDate), prpldvflag(Off), pdvflag(0x0)0x10002): completeddetaching becauseto itcurrent isUUID: not in the VerifyS or SyncTarget replication state.
00000805CE5CC8B0672E645C
00000506 10/1326/2020 16:1849:2010.97743972903353 [connprint_state_disconnectchange] [CONNECTIONSTATE:920] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown/0 minor 2, ds(Detaching), cflagdvflag(0x10e)0x1002): change_disk_state, scf(0x0): Connection closed
00000806disk( Detaching -> Diskless )
00000507 10/1326/2020 16:1849:2010.97749282909946 [printbsr_statebm_changeresize] [STATEBITMAP:1923] bsr_info<6> bsr r0 pnode-id:1/0 minor 2, csds(DisconnectingDiskless), proledvflag(Unknown), cflag(0x10e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone )
00000807 10/130x2): Start resizing the bitmap size to disk capacity. capacity sector(0)
00000508 10/26/2020 16:1849:2010.97753352912038 [bsr_thread_setup] [THREAD:910] bsr_info<6> bsr r0 pnode-id:1, csr(StandAloneSecondary), prole(Unknown), cflag(0x10ef(0x1), scf(0x0): Terminating receiverworker thread
0000080800000509 10/1326/2020 16:18:20.9777552:49:10.2912489 [mvolWorkThread] [THREAD:20] bsr_info<6> [0xFFFFE0012CBCF880] Terminating mvolWorkThread
00000510 10/26/2020 16:49:10.2914483 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012B2F9880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) done (cmd_pending:0) <-

syncsource

resync start

...

DOWN:27 command execution terminated. (pending command:0)

동기화

syncsource

다음은 syncsource 의 동기화 시작 로그입니다.

Code Block
00000322 10/26/2020 16:

...

48:

...

53.

...

1027626 [__receive_uuids] [UUID:16] bsr_warn<4> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): receive new current but not update UUID:

...

A95D18E8D4AE8C78

...

00000323 10/

...

26/2020 16:

...

48:

...

53.

...

1027665 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(

...

0x0): Peer UUID and local bitmap UUID are the same. rule(70), res(2)

...

  • 00000324 .. [RESYNC/OV:73] 로컬 노드와 피어 노드의 동기화 핸드쉐이크를 시작합니다.
 Code Block
00000324 10/
...
26/2020 16:
...
48:
...
53.
...
1029289 [log_handshake] [RESYNC/OV:73] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): bsr_sync_handshake:
...
  • 00000325 .. [RESYNC/OV:65] 로컬의 UUID가 출력됩니다.
 Code Block
00000325 10/26/2020 16:
...
48:
...
53.
...
1029330 [bsr_uuid_dump_self] [RESYNC/OV:65] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): self 
...
CE5CC8B0672E645D:
...
A95D18E8D4AE8C78:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:
...
0 flags
...
:20
  • 00000326 .. [RESYNC/OV:66] 피어의 UUID가 출력됩니다.
 Code Block
00000326 10/
...
26/2020 16:
...
48:
...
53.
...
1029384 [bsr_uuid_dump_peer] [RESYNC/OV:66] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): peer 
...
A95D18E8D4AE8C78:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags
...
:100
  • 00000327 .. [RESYNC/OV:202], 00000599 .. [RESYNC/OV:75] 로컬과 피어의 uuid compare 결과가 출력됩니다.
 Code Block
00000327 10/26/2020 16:
...
48:
...
53.
...
1029433 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(
...
0x0): Peer UUID and local bitmap UUID are the same. rule(70), res(2)

...
00000328 10/
...
26/2020 16:
...
48:
...
53.
...
1029467 [bsr_handshake] [RESYNC/OV:75] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): uuid_compare(2) by rule 70

...
00000329 10/
...
26/2020 16:
...
48:
...
53.
...
1029713 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): 
...
Receive new repl state "WFBitMapS"

...
00000330 10/
...
26/2020 16:
...
48:
...
53.
...
1029830 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): receive_state, pdsk( DUnknown -> 
...
Consistent ) repl( Off -> WFBitMapS )

...
00000331 10/
...
26/2020 16:
...
48:
...
53.
...
1030835 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(
...
0x0): send_bitmap (WFBitMapS), worker.task(
...
FFFFE0012C7D29A0), current(
...
FFFFE0012C7D29A0)

...
00000332 10/
...
26/2020 16:
...
48:
...
53.
...
1048104 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(
...
Consistent), prpl(WFBitMapS), pdvflag(0x100600): 
...
Receive new repl
...
 state "WFBitMapS"
00000333 10/26/2020 16:48:53.1048248 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Consistent), prpl(WFBitMapS), pdvflag(0x100600): receive_state, pdsk( Consistent -> Outdated )
  • 00000334 .. [BITMAP:50] 로컬의 비트맵이 피어 노드에 전송 완료 되었습니다.
 Code Block
00000334 10/26/2020 16:
...
48:
...
53.
...
1049603 [INFO_bm_xfer_stats] [BITMAP:50] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): send bitmap stats [Bytes(packets)]: plain 0(0), RLE 
...
23(1), total 
...
23; compression: 100.0%
...
  • 00000335 .. [BITMAP:50] 피어 노드의 비트맵이 로컬에서 수신 완료 되었습니다.
 Code Block
00000335 10/
...
26/2020 16:
...
48:
...
53.
...
1065768 [INFO_bm_xfer_stats] [BITMAP:50] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 
...
23(1), total 
...
23; compression: 100.0%
...
  • 00000336 .. [BITMAP:52] 비트맵 교환이 완료되었습니다.
 Code Block
00000336 10/26/2020 16:
...
48:
...
53.
...
1065812 [receive_bitmap_finished] [BITMAP:52] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): 
...
Send that bitmap exchange has been completed

...
00000337 10/
...
26/2020 16:
...
48:
...
53.
...
1066753 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): bsr_start_resync, pdsk( Outdated -> Inconsistent ) repl
...
( WFBitMapS -> SyncSource )
  • 00000338 .. [RESYNC/OV:144] 동기화가 시작되고 동기화 해야할 데이터 크기가 출력됩니다.
 Code Block
00000338 10/26/2020 16:
...
48:
...
53.
...
1067116 [bsr_start_resync] [RESYNC/OV:144] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): Began resync as SyncSource (will sync 
...
0 KB [
...
0 bits set]).

...
00000339 10/
...
26/2020 16:
...
48:
...
53.
...
1087501 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): 
...
Receive new repl state "SyncSource"

...
00000340 10/
...
26/2020 16:
...
48:
...
53.
...
1170857 [__receive_uuids] [UUID:16] bsr_warn<4> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): receive new current but not update UUID: 
...
CE5CC8B0672E645C

...
00000341 10/
...
26/2020 16:
...
48:
...
53.
...
1170913 [bsr_uuid_compare] [RESYNC/OV:197] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(
...
0x0): Local and peer current UUIDs are the same. rule(40), res(0)
  • resync finished00000342 .. [UUID:1] 동기화 완료 후 새로 지정되는 UUID 정보가 출력됩니다.
 Code Block
...
00000342 10/
...
26/2020 16:
...
48:
...
53.
...
1170949 [bsr_print_uuids] [UUID:1] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): bsr_uuid_detect_finished_resyncs, updated UUIDs 
...
CE5CC8B0672E645D:0000000000000000:
...
A95D18E8D4AE8C78:3DF87D1E1EFC3E92
...
  • 00000613 .. [RESYNC/OV:116] 동기화 완료 후 동기화 진행 시간 및 속도가 출력됩니다.
 Code Block
00000343 10/
...
26/2020 16:
...
48:
...
53.
...
1180660 [bsr_resync_finished] [RESYNC/OV:116] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): Resync done (total 
...
1 sec; paused 0 sec; 
...
0 K/sec), hit bit (in sync 0; marked rl 0)

...
00000344 10/
...
26/2020 16:
...
48:
...
53.
...
1180792 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): bsr_resync_finished, pdsk( Inconsistent -> UpToDate ) repl( SyncSource -> Established )

...
00000345 10/
...
26/2020 16:
...
48:
...
53.
...
1181716 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(
...
0x0): write from resync_finished, worker.task(
...
FFFFE0012C7D29A0), current
...
(FFFFE0012C7D29A0)
00000346 10/26/2020 16:48:53.1182718 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): Receive new repl state "Established"
synctarget
다음은 synctarget에서 동기화 시작 로그입니다.
 Info
syncsource와 중복되는 로그는 설명하지 않습니다.
  • 비트맵 교환 과정은 syncsource와 동일합니다.
 Code Block
00000210 10/26/2020 16:
...
48:
...
52.
...
7780270 [
...
bsr_uuid_
...
compare] [
...
RESYNC/OV:
...
198] bsr_info<6> bsr r0/0 minor 2
...
, 
...
ds(UpToDate), 
...
dvflag(
...
synctarget
resync start
...
0x20000): The local current UUID is the same as the peer bitmap UUID. rule(50), res(-2)
00000211 10/26/2020 16:
...
48:
...
52.
...
7780426 [print_state_
...
change] [
...
STATE:
...
20] bsr_
...
info<6> bsr r0/0 minor 2
...
, 
...
ds(
...
UpToDate), 
...
dvflag(0x20000): __receive_uuids, 
...
disk( 
...
UpToDate 
...
-> 
...
Outdated 
...
)

...
00000212 10/
...
26/2020 16:
...
48:
...
52.
...
7789223 [log_handshake] [RESYNC/OV:73] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): bsr_sync_handshake:

...
00000213 10/
...
26/2020 16:
...
48:
...
52.
...
7789252 [bsr_uuid_dump_self] [RESYNC/OV:65] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): self 
...
A95D18E8D4AE8C78:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags:
...
100

...
00000214 10/
...
26/2020 16:
...
48:
...
52.
...
7789291 [bsr_uuid_dump_peer] [RESYNC/OV:66] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): peer 
...
CE5CC8B0672E645D:
...
A95D18E8D4AE8C78:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:
...
0 flags:
...
20

...
00000215 10/
...
26/2020 16:
...
48:
...
52.
...
7789328 [bsr_uuid_compare] [RESYNC/OV:198] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(
...
0x20000): The local current UUID is the same as the peer bitmap UUID. rule(50), res(-2)

...
00000216 10/
...
26/2020 16:
...
48:
...
52.
...
7789352 [bsr_handshake] [RESYNC/OV:75] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): uuid_compare(-2) by rule 50

...
00000217 10/
...
26/2020 16:
...
48:
...
52.
...
7789384 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): 
...
Receive new repl state "WFBitMapT"

...
00000218 10/
...
26/2020 16:
...
48:
...
52.
...
7789491 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive_state, pdsk( DUnknown -> UpToDate ) repl( Off -> WFBitMapT )

...
00000219 10/
...
26/2020 16:
...
48:
...
52.
...
7790130 [w_after_state_change] [STATE:28] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): 
...
Not sending state because of old 
...
replication state(Off)

...
00000220 10/
...
26/2020 16:
...
48:
...
52.
...
7791844 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): 
...
Receive new repl state "WFBitMapT"

...
00000221 10/
...
26/2020 16:
...
48:
...
52.
...
7797620 [w_after_state_change] [STATE:28] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): 
...
Not sending state because of old replication 
...
state(WFBitMapT)

...
00000222 10/
...
26/2020 16:
...
48:
...
52.
...
7798480 [INFO_bm_xfer_stats] [BITMAP:50] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 
...
23(1), total 
...
23; compression: 100.0%

...
00000223 10/
...
26/2020 16:
...
48:
...
52.
...
7815593 [INFO_bm_xfer_stats] [BITMAP:50] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): send bitmap stats [Bytes(packets)]: plain 0(0), RLE 
...
23(1), total 
...
23; compression: 100.0%

...
00000224 10/
...
26/2020 16:
...
48:
...
52.
...
7815876 [receive_bm_exchange_state] [BITMAP:44] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): bitmap exchange complete

...
00000225 10/
...
26/2020 16:
...
48:
...
52.
...
7817559 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): 
...
Receive new repl state "WFBitMapT"

...
00000226 10/
...
26/2020 16:
...
48:
...
52.
...
7832750 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(0x0): bsr_start_resync, disk( Outdated -> Inconsistent )

...
00000227 10/
...
26/2020 16:
...
48:
...
52.
...
7832782 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): bsr_start_resync, repl( WFBitMapT -> SyncTarget )

...
00000228 10/
...
26/2020 16:
...
48:
...
52.
...
7833043 [bsr_start_resync] [RESYNC/OV:144] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): Began resync as SyncTarget (will sync 
...
0 KB [
...
0 bits set]).

...
00000229 10/
...
26/2020 16:
...
48:
...
52.
...
7838039 [__receive_uuids] [UUID:16] bsr_warn<4> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): receive new current but
...
 not update UUID: CE5CC8B0672E645D
  • 00000230 .. [RESYNC/OV:107]  synctarget에서 동기화 데이터 요청을 syncsource에 모두 전송 했을때 출력됩니다.
 Code Block
00000230 10/26/2020 16:
...
48:
...
52.
...
7915051 [make_resync_request] [RESYNC/OV:
...
107] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600):
...
resync finished
...
 Finished the resync. resync target area does not exist.
  • 다음은 synctarget의 동기화 완료 로그입니다.
 Code Block
00000231 10/26/2020 16:
...
48:
...
52.
...
7918471 [bsr_resync_finished] [RESYNC/OV:116] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): Resync done (total 
...
1 sec; paused 0 sec; 
...
0 K/sec), hit bit (in sync 0; marked rl 0)

...
00000232 10/
...
26/2020 16:
...
48:
...
52.
...
7918549 [bsr_print_uuids] [UUID:1] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): bsr_resync_finished, updated UUIDs 
...
CE5CC8B0672E645C:0000000000000000:
...
A95D18E8D4AE8C78:3DF87D1E1EFC3E92

...
00000233 10/
...
26/2020 16:
...
48:
...
52.
...
7918808 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Inconsistent), dvflag(0x20004): bsr_resync_finished, disk( Inconsistent -> UpToDate )

...
00000234 10/
...
26/2020 16:
...
48:
...
52.
...
7918840 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): bsr_resync_finished, repl( SyncTarget -> Established )

...
00000235 10/
...
26/2020 16:
...
48:
...
52.
...
7927024 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20000): write from resync_finished, worker.task(
...
FFFFE000E4CD8CF0), current(
...
FFFFE000E4CD8CF0)