Versions Compared

Old Version 33

changes.mady.by.user 한성원

Saved on

compared with

New Version 34

changes.mady.by.user 한성원

Saved on

Key

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

...

Code Block
00000690 10/13/2020 16:16:11.2569857 [FsctlUnlockVolume] [VOLUME:61] 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/13/2020 16:16:11.2577179 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDB38300

  • disconnect 명령이 실행됩니다명령과 동일한 동작을 실행합니다.

Code Block
00000693 10/13/2020 16:16:11.2577328 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): Preparing cluster-wide state change 1834520240 (0->1 496/16)
00000694 10/13/2020 16:16:11.2577355 [change_cluster_wide_state] [TWOPC:35] 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/2020 16:16:11.2580212 [change_cluster_wide_state] [TWOPC:36] 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/2020 16:16:11.2580251 [change_cluster_wide_state] [TWOPC:37] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): State change 1834520240: primary_nodes=0, weak_nodes=0
00000697 10/13/2020 16:16:11.2580275 [change_cluster_wide_state] [TWOPC:38] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x210e), scf(0x28): Cluster is now split
00000698 10/13/2020 16:16:11.2580300 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): Committing cluster-wide state change 1834520240 (0ms) (0->1)
00000699 10/13/2020 16:16:11.2584388 [Receive] [SOCKET:66] bsr_info<6> [0xFFFFE000CDB66880] receiver => Recv multiWait error. err(STATUS_CONNECTION_RESET) wsk(0xFFFFE000CE2A8198) size(16)
00000700 10/13/2020 16:16:11.2584579 [bsr_recv] [SOCKET:14] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x210e), scf(0x28): socket reset due to peer.
00000701 10/13/2020 16:16:11.2584757 [print_state_change] [STATE:19] 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/2020 16:16:11.2584805 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): bsr_recv, pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000703 10/13/2020 16:16:11.2585071 [bsr_recv_all_warn] [PROTOCOL:64] bsr_warn<4> bsr r0 pnode-id:1, cs(BrokenPipe), prole(Unknown), cflag(0x211e), scf(0x0): short read (expected size 16)
00000704 10/13/2020 16:16:11.2585247 [print_state_change] [STATE:19] 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/2020 16:16:11.2586495 [bsr_ack_receiver] [CONNECTION:16] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x0): ack_receiver terminated
00000706 10/13/2020 16:16:11.2586532 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x0): Terminating ack_recv thread
00000707 10/13/2020 16:16:11.2587692 [w_resync_timer] [RESYNC/OV:105] 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/2020 16:16:11.2591157 [conn_disconnect] [CONNECTION:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x0): Connection closed
00000709 10/13/2020 16:16:11.2591688 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone )
00000710 10/13/2020 16:16:11.2591981 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x211e), scf(0x0): Terminating receiver thread
00000711 10/13/2020 16:16:11.2592468 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x211e), scf(0x0): Terminating sender thread
00000712 10/13/2020 16:16:11.2593036 [bsr_destroy_connection] [CONNECTION:1] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x311e), scf(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

...

Code Block
00000593 10/13/2020 16:14:01.5273798 [__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: 7B326D963D9936CE
00000594 10/13/2020 16:14:01.5273852 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): Peer UUID and local bitmap UUID are the same. rule(70), res(2)

  • 연결이 완료되면 동기화 시작 전 로컬 노드와 피어 노드의 UUID 정보를 교환합니다.

// 피어 노드의 UUID, FLAG 정보 로그
Code Block
// 피어 노드와 동기화 여부를 확인하기 위해 교환한 UUID, FLAG 정보 로그 [RESYNC/OV:73] 
00000595 10/13/2020 16:14:01.5275442 [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:
Code Block

  • 00000596 .. [RESYNC/OV:65]

...

  • 로그는 로컬 노드에 설정되어있는 UUID 정보입니다.

// 피어 노드의 UUID, FLAG 정보 로그
Code Block
00000596 10/13/2020 16:14:01.5275481 [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 83F530CA41FA9869:7B326D963D9936CF:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:8711 flags:120
Code Block

  • 00000597 .. [RESYNC/OV:66]

...

  • 로그는 피어 노드에 설정되어있는 UUID 정보입니다.

Code Block
00000597 10/13/2020 16:14:01.5275527 [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 7B326D963D9936CE:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags:0
00000598 10/13/2020 16:14:

  • 00000598 .. [RESYNC/OV:202], 00000599 .. [RESYNC/OV:75] 로그는 로컬 노드와 피어 노드의 UUID 비교 후 결과입니다.

// 피어 노드에 비트맵 전송 로그
Code Block
00000598 10/13/2020 16:14:01.5275568 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): Peer UUID and local bitmap UUID are the same. rule(70), res(2)
Code Block
// 로컬 노드와 피어 노드의 비교 결과 로그 [RESYNC/OV:75]
00000599 10/13/2020 16:14:01.5275593 [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
00000600 10/13/2020 16:14:01.5275634 [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"
00000601 10/13/2020 16:14:01.5275781 [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 -> Outdated ) repl( Off -> WFBitMapS )
00000602 10/13/2020 16:14:01.5277419 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): send_bitmap (WFBitMapS), worker.task(FFFFE000CDB38300), current(FFFFE000CDB38300)
00000603 10/13/2020 16:14:01.5297955 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): receive new repl state "WFBitMapS"
Code Block

  • 00000604 .. [BITMAP:50]

...

  • 로그는 로컬 노드 비트맵 전송에 대한 결과입니다.

// 피어 노드의 비트맵 수신 로그
Code Block
00000604 10/13/2020 16:14:01.5299369 [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 56(1), total 56; compression: 100.0%
Code Block

  • 00000605 .. [BITMAP:50]

...

  • 로그는 피어 노드 비트맵 수신에 대한 결과입니다.

// 비트맵 교환 완료 로그
Code Block
00000605 10/13/2020 16:14:01.5321829 [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 56(1), total 56; compression: 100.0%
Code Block

  • 00000606 .. [BITMAP:52]

...

  • 로그는 비트맵 교환 완료 결과입니다.

// 동기화 데이터 크기(34844 KB) 및 동기화 시작 로그
Code Block
00000606 10/13/2020 16:14:01.5321885 [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
00000607 10/13/2020 16:14:01.5323570 [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 )
Code Block

  • 00000608 .. [RESYNC/OV:144]

...

  • 로그는 동기화 시작과 동기화 데이터 크기입니다.

Code Block
00000608 10/13/2020 16:14:01.5324087 [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 34844 KB [8711 bits set]).
00000609 10/13/2020 16:14:01.5332003 [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"
00000610 10/13/2020 16:14:10.7932817 [__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: 83F530CA41FA9868
00000611 10/13/2020 16:14:10.7932881 [bsr_uuid_compare] [RESYNC/OV:197] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): Local and peer current UUIDs are the same. rule(40), res(0)

다음은 syncsource에서 동기화 완료 로그 출력과 분석 시 주로 확인하는 로그의 설명입니다.

...

  • 00000612 .. [UUID:1] 로그는 동기화 완료로 갱신되는 UUID 입니다.

// 동기화 진행 시간 및 초당 동기화 진행 데이터 크기(3868 K/sec) 로그 [RESYNC/OV:116]
Code Block
00000612 10/13/2020 16:14:10.7932922 [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 83F530CA41FA9869:0000000000000000:7B326D963D9936CE:3DF87D1E1EFC3E92
Code Block

  • 00000613 .. [RESYNC/OV:116] 로그는 동기화 진행 시간 및 초당 동기화 속도 입니다.

Code Block
00000613 10/13/2020 16:14:10.7939134 [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 9 sec; paused 0 sec; 3868 K/sec), hit bit (in sync 0; marked rl 0)
00000614 10/13/2020 16:14:10.7939295 [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 )
00000615 10/13/2020 16:14:10.7940275 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): write from resync_finished, worker.task(FFFFE000CDB38300), current(FFFFE000CDB38300)
00000616 10/13/2020 16:14:10.7941994 [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에서 동기화 시작 로그 출력과 분석 시 주로 확인하는 로그의 설명입니다.

  • 비트밉 교환 과정은 syncsource와 동일합니다.

Code Block
00000084 10/13/2020 16:14:01.3783975 [__receive_uuids] [UUID:16] bsr_warn<4> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receive new current but not update UUID: 83F530CA41FA9869
00000085 10/13/2020 16:14:01.3784433 [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:
00000086 10/13/2020 16:14:01.3784484 [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 7B326D963D9936CE:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags:0
00000087 10/13/2020 16:14:01.3784535 [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 83F530CA41FA9869:7B326D963D9936CF:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:8711 flags:120
00000088 10/13/2020 16:14:01.3784589 [bsr_uuid_compare] [RESYNC/OV:198] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(0x0): The local current UUID is the same as the peer bitmap UUID. rule(50), res(-2)
00000089 10/13/2020 16:14:01.3784626 [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
00000090 10/13/2020 16:14:01.3784682 [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"
Code Block
//
UUID, FLAG 비교 결과에 대한 상태 변경 로그 [STATE:21]
00000091 10/13/2020 16:14:01.3784857 [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 )
00000092 10/13/2020 16:14:01.3785440 [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 repl_state(Off)
00000093 10/13/2020 16:14:01.3787983 [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"
Code Block
//
비트맵 교환 과정 및 동기화 시작 로그 (syncsource 동일)
00000094 10/13/2020 16:14:01.3788417 [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 repl_state(WFBitMapT)
00000095 10/13/2020 16:14:01.3807180 [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 56(1), total 56; compression: 100.0%
00000096 10/13/2020 16:14:01.3830286 [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 56(1), total 56; compression: 100.0%
00000097 10/13/2020 16:14:01.3831040 [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
00000098 10/13/2020 16:14:01.3833661 [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"
00000099 10/13/2020 16:14:01.3834175 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(0x0): bsr_start_resync, disk( Outdated -> Inconsistent )
00000100 10/13/2020 16:14:01.3834212 [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 )
00000101 10/13/2020 16:14:01.3834682 [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 34844 KB [8711 bits set]).
00000102 10/13/2020 16:14:01.3841175 [__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: 83F530CA41FA9869

  • 00000103 .. [RESYNC/OV:109] 로그는 synctarget에서 동기화 데이터 요청을 모두 전송 했을때 입니다.

Code Block
// 동기화 요청 완료 로그 [RESYNC/OV:109]
00000103 10/13/2020 16:14:10.6370316 [make_resync_request] [RESYNC/OV:109] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(SyncTarget), pdvflag(0x100600): BSR_END_OF_BITMAP(25786753), device->bm_resync_fo : 2651392, bm_set : 132

...