Versions Compared

Old Version 37

changes.mady.by.user 한성원

Saved on

compared with

New Version 38

changes.mady.by.user 한성원

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.
Table of Contents

목적

주요 동작 로그는 사용자의 bsr 커널 로그 접근성을 높이기 위해 주요 동작에 대한 bsr 커널 출력 로그와 설명을 제공합니다.

Info

주요 동작 로그를 읽기전 전에 https://mantech.jira.com/wiki/spaces/BSRUG , 로그 를 먼저 읽어주세요.

동작

Info

출력 로그는 windwos bsr 1.6.1 설치 후 1:1 연결 환경에서 수집한 로그로 작성되었습니다.

  • 작성 된 주요 동작 로그는 성공 시 출력되는 로그이며 실패 시 다른 로그가 출력됩니다.

커널 로드

다음은 windows 에서 bsr 커널 드라이버 로드 시 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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

  • 시스템 로그가 없는 상황에서는 커널 로드 로그 출력 시간을 통해 시스템 시작 시간을 짐작하기도 합니다.

Code Block
00000001 10/13/2020 16:09:03.1143958 [wait_for_add_device] [LOG:10] bsr_info<6> [0xFFFFE000CBDC1880] 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 [initRegistry] [DRIVER:64] bsr_info<6> [0xFFFFE000CBABD880] bypass_level=0, read_filter=0, use_volume_lock=1, netlink_tcp_port=5678, daemon_tcp_port=5679, ver=1.5
00000004 10/13/2020 16:09:03.1144826 [bsr_init] [DRIVER:77] bsr_info<6> [0xFFFFE000CBABD880] initialized. Version: 1.6.1-A1 (api:2/proto:86-114)
00000005 10/13/2020 16:09:03.1144850 [bsr_init] [DRIVER:78] bsr_info<6> [0xFFFFE000CBABD880] 1.6.1(2020.10.13_A1) GIT-hash: f52eea3 build by DEV3-KBLD+Administrator@dev3-kbld, Tue Oct 13 15:19:41 2020
00000006 10/13/2020 16:09:03.1144868 [bsr_init] [DRIVER:79] bsr_info<6> [0xFFFFE000CBABD880] registered as block device major 147

상태 변경

다음은 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.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 )

명령 실행

다음은 bsradm.exe, bsrsetup.exe, bsrmeta.exe, bsrcon.exe 으로 명령 실행 시 bsr 커널에서 해당 명령 실행 전 실행 후 로그 출려과 분석 시 주로 참고하는 로그의 설명입니다.

  • 명령 실행 시 “bsr netlink cmd(~) begin”, 명령 실행 후 “bsr netlink cmd(~) done” 로그를 출력하며 실행되는 명령은 cmd()안에 표시됩니다.

    • 예를들어 명령 실행 시 “cmd(~) begin” 은 있으나 매칭되는 “cmd(~) done” 이 없다면 명령이 완료되지 않은 상황임을 알 수 있습니다.

  • 명령에따라 실행 완료까지 대기 또는 대기하지 않을 수 있습니다.

  • 명령 실행으로 출력되는 로그는 “..” 으로 작성했으며 다른 주요 동작 로그에서 작성하고 설명합니다.

Code Block
00000018 10/13/2020 16:09:29.0058164 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
..
00000020 10/13/2020 16:09:29.0612210 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <-
..
00000021 10/13/2020 16:09:29.0902772 [NetlinkWorkThread] [NETLINK:18] 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 10/13/2020 16:09:29.1011907 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_PEER:44) begin ->
..
00000027 10/13/2020 16:09:29.1014684 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [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) <-

connect 실행

다음은 bsradm, bsrsetup 으로 connect 명령 실행 시 연결되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

Info

시스템 또는 네트워크 상황등으로 재연결 시 connect 명령 실행과 동일한 과정의 로그가 출력됩니다.

Code Block
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:19] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10e), scf(0x2a): bsr_adm_connect, conn( StandAlone -> Unconnected )
00000812 10/13/2020 16:18:22.9478904 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x10e), scf(0x0): Starting 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/13/2020 16:18:22.9480265 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CE728040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CE0F9170 resource->worker.task:FFFFE000CDE0B820
00000815 10/13/2020 16:18:22.9480416 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0xe), scf(0x2a): conn_connect, conn( Unconnected -> Connecting )

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

Code Block
00000816 10/13/2020 16:18:25.9566941 [bsr_do_features] [PROTOCOL:55] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000817 10/13/2020 16:18:25.9567017 [bsr_do_features] [PROTOCOL:56] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0x0): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.

  • 00000818 .. [SEND BUFFER:27] 로그는 로컬 send-buffer 사용 유무와 사용 시 send-buffer 할당 크기를 출력하며 만약 메모리가 부족하면 send-buffer가 할당되지 않아 사용되지 않습니다.

Code Block
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] bsr_info<6> [0xFFFFE000CDA1A040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CDAA58C0 resource->worker.task:FFFFE000CDE0B820
00000821 10/13/2020 16:18:26.0424586 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 2387348015 (0->1 499/146)
00000822 10/13/2020 16:18:26.0424733 [change_cluster_wide_state] [TWOPC:35] 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/2020 16:18:26.0430489 [change_cluster_wide_state] [TWOPC:36] 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/2020 16:18:26.0430560 [change_cluster_wide_state] [TWOPC:37] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 2387348015: primary_nodes=0, weak_nodes=0
00000825 10/13/2020 16:18:26.0430611 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 2387348015 (0ms) (0->1)
00000826 10/13/2020 16:18:26.0432317 [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 )

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

Code Block
00000827 10/13/2020 16:18:26.0434960 [receive_SyncParam] [PROTOCOL:29] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(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 .. [PROTOCOL:32] 로그는 로컬 노드의 현재 설정되어있는 복제 디스크 크기가 출력됩니다.

Code Block
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 .. [PROTOCOL:33] 로그는 피어 노드의 현재 설정되어있는 복제 디스크 크기와 최대 설정 할 수 있는 복제 디스크 크기가 출력됩니다.

Code Block
00000829 10/13/2020 16:18:26.0435114 [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

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

Code Block
00000830 10/13/2020 16:18:26.0435168 [receive_sizes] [PROTOCOL:34] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): md_effective_size: 21211136 my_user_size: 0 my_max_size: 21211136
00000831 10/13/2020 16:18:26.0435209 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): local node_id: 0
00000832 10/13/2020 16:18:26.0435236 [get_max_agreeable_size] [GENL:17] bsr_info<6> 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)
00000833 10/13/2020 16:18:26.0435292 [receive_sizes] [PROTOCOL:39] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): Proceed with device size setting
00000834 10/13/2020 16:18:26.0436443 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): local node_id: 0
00000835 10/13/2020 16:18:26.0436474 [get_max_agreeable_size] [GENL:17] bsr_info<6> 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)

disconnect 실행

다음은 bsradm, bsrsetup 으로 disconnect 명령 실행 시 연결 종료되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

Info

시스템 또는 네트워크 상황등으로 연결 종료 시 동일한 과정의 로그가 출력되나 연결 상태가 standalone으로 설정되지 않습니다.

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/2020 16:18:20.9762023 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAFB880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000793 10/13/2020 16:18:20.9762218 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): Preparing cluster-wide state change 2366568536 (0->1 496/16)
00000794 10/13/2020 16:18:20.9762252 [change_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:2366568536] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000795 10/13/2020 16:18:20.9766356 [change_cluster_wide_state] [TWOPC:36] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:2366568536] target_node_id(1) get_cluster_wide_reply (3) 
00000796 10/13/2020 16:18:20.9766412 [change_cluster_wide_state] [TWOPC:37] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): State change 2366568536: primary_nodes=0, weak_nodes=0
00000797 10/13/2020 16:18:20.9766463 [change_cluster_wide_state] [TWOPC:38] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x28): Cluster is now split
00000798 10/13/2020 16:18:20.9766497 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): Committing cluster-wide state change 2366568536 (0ms) (0->1)

  • 00000799 .. [STATE:19] 로그는 disconnect 명령으로 연결 종료 시 연결 상태가 standalone으로 상태 변경 시 출력됩니다.

Code Block
00000799 10/13/2020 16:18:20.9767770 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x208): conn_try_disconnect, conn( Connected -> Disconnecting ) peer( Secondary -> Unknown )
00000800 10/13/2020 16:18:20.9767831 [print_state_change] [STATE:21] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): conn_try_disconnect, pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000801 10/13/2020 16:18:20.9768211 [bsr_recv] [SOCKET:15] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x208): socket data receive error(-15)
00000802 10/13/2020 16:18:20.9768974 [bsr_ack_receiver] [CONNECTION:16] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated
00000803 10/13/2020 16:18:20.9769028 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Terminating ack_recv thread
00000804 10/13/2020 16:18:20.9771990 [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.
00000805 10/13/2020 16:18:20.9774397 [conn_disconnect] [CONNECTION:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Connection closed
00000806 10/13/2020 16:18:20.9774928 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone )
00000807 10/13/2020 16:18:20.9775335 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(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) <-

up 실행

다음은 bsradm up 명령 실행 시 up되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

Info

bsradm up 명령 실행 시 new-resource, new-minor, new-peer, new-path, attach, connect 명령이 순차적으로 실행됩니다.

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.6348421 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) done (cmd_pending:0) <-
00000728 10/13/2020 16:16:12.6430701 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_PEER:44) begin ->
00000729 10/13/2020 16:16:12.6430889 [bsr_create_peer_device_default_config] [GENL:45] 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 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done (cmd_pending:0) <-
00000732 10/13/2020 16:16:12.6519482 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAFB880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) begin ->
00000733 10/13/2020 16:16:12.6521598 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done (cmd_pending:0) <-
00000734 10/13/2020 16:16:12.7033475 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_ATTACH:12) begin ->
00000735 10/13/2020 16:16:12.7037719 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000736 10/13/2020 16:16:12.7037883 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Diskless), dvflag(0x0): change_disk_state, disk( Diskless -> Attaching )
00000737 10/13/2020 16:16:12.7038382 [FsctlLockVolume] [VOLUME:20] bsr_info<6> [0xFFFFE000CCAC4880] no lock. volume(\Device\HarddiskVolume2) already dismounted
00000738 10/13/2020 16:16:12.7038414 [FsctlFlushDismountVolume] [VOLUME:15] 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/13/2020 16:16:12.7038460 [bsr_adm_attach] [GENL:36] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Maximum number of bitmap peer devices 1
00000741 10/13/2020 16:16:12.7047859 [bsr_bump_write_ordering] [VOLUME:66] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x1): Method to ensure write ordering: drain
00000742 10/13/2020 16:16:12.7047891 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000743 10/13/2020 16:16:12.7047913 [get_max_agreeable_size] [GENL:17] 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/2020 16:16:12.7048103 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000745 10/13/2020 16:16:12.7048123 [get_max_agreeable_size] [GENL:17] 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)
00000746 10/13/2020 16:16:12.7048159 [bsr_bm_resize] [BITMAP:23] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): bitmap resize called with capacity(21211136)
00000747 10/13/2020 16:16:12.7054015 [bsr_bm_resize] [BITMAP:25] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): resize bitmap, bits(2651392) words(82856) pages(81)

  • 00000748 .. [GENL:13] 로그는 attach 대상 복제 디스크의 크기가 출력됩니다.

Code Block
00000748 10/13/2020 16:16:12.7054054 [bsr_determine_dev_size] [GENL:13] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Update disk size 10 GB (10605568 KB)
00000749 10/13/2020 16:16:12.7092993 [bm_rw_range] [BITMAP:29] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): recounting of set bits took additional 1ms
00000750 10/13/2020 16:16:12.7093079 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000751 10/13/2020 16:16:12.7093240 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )

  • 00000752 .. [UUID:14] 로그는 attach 대상 복제 디스크의 설정되어있는 current UUID가 출력됩니다.

Code Block
00000752 10/13/2020 16:16:12.7093288 [finish_state_change] [UUID:14] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(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) <-

  • connect 명령이 실행됩니다.

Code Block
00000754 10/13/2020 16:16:12.7186777 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) begin ->
00000755 10/13/2020 16:16:12.7186894 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAAC040] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000756 10/13/2020 16:16:12.7187102 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x0), scf(0x2a): bsr_adm_connect, conn( StandAlone -> Unconnected )
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/13/2020 16:16:12.7190322 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x0), scf(0x0): Starting receiver thread (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:19] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x0), scf(0x2a): conn_connect, conn( Unconnected -> Connecting )
00000761 10/13/2020 16:16:15.7224848 [bsr_do_features] [PROTOCOL:55] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000762 10/13/2020 16:16:15.7224916 [bsr_do_features] [PROTOCOL:56] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000763 10/13/2020 16:16:15.7227332 [conn_connect] [SEND BUFFER:27] bsr_warn<4> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): send-buffering disabled nc->sndbuf_size:0
00000764 10/13/2020 16:16:15.7227437 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): Starting ack_recv thread (from receiver [2808])
00000765 10/13/2020 16:16:15.7770404 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CDA1A040] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CDAA58C0 resource->worker.task:FFFFE000CDE0B820
00000766 10/13/2020 16:16:15.7770628 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 1853056548 (0->1 499/146)
00000767 10/13/2020 16:16:15.7770664 [change_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:1853056548] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (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:37] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 1853056548: primary_nodes=0, weak_nodes=0
00000770 10/13/2020 16:16:15.7776145 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 1853056548 (1ms) (0->1)
00000771 10/13/2020 16:16:15.7778471 [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] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(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
00000773 10/13/2020 16:16:15.7781260 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): current_mydisk_size: 10860101632 bytes
00000774 10/13/2020 16:16:15.7781292 [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
00000775 10/13/2020 16:16:15.7781334 [receive_sizes] [PROTOCOL:34] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): md_effective_size: 21211136 my_user_size: 0 my_max_size: 21211136
00000776 10/13/2020 16:16:15.7781365 [get_max_agreeable_size] [GENL:16] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): local node_id: 0
00000777 10/13/2020 16:16:15.7781387 [get_max_agreeable_size] [GENL:17] bsr_info<6> 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)
00000778 10/13/2020 16:16:15.7781429 [receive_sizes] [PROTOCOL:39] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): 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/13/2020 16:16:15.7782109 [get_max_agreeable_size] [GENL:17] bsr_info<6> 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)

down 실행

다음은 bsradm down 명령 실행 시 down되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

Info

bsradm down 명령은 볼륨 lock, 볼륨 flush, 볼륨 dismount, 연결 종료, 디스크 제거 순서로 실행됩니다.

Code Block
00000617 10/13/2020 16:16:11.2136805 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) begin ->

  • 00000618 .. [VOLUME:65], 00000680 .. [VOLUME:23] 로그들은 복제 볼륨 베타적 락 획득 시 출력됩니다.

Code Block
00000618 10/13/2020 16:16:11.2137344 [FsctlLockVolume] [VOLUME:65] bsr_info<6> [0xFFFFE000CCAC4880] try lock volume(\Device\HarddiskVolume2)
00000680 10/13/2020 16:16:11.2534883 [FsctlLockVolume] [VOLUME:23] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) locked. handle(0xFFFFFFFF80000DC8)

  • 00000683 .. [VOLUME:62], 00000684 .. [VOLUME:63] 로그들은 복제 볼륨 flush 시 출력됩니다.

Code Block
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 .. [VOLUME:64], 00000686 .. [VOLUME:19] 로그들은 복제 볼륨 dismount 실행 시 출력됩니다.

Code Block
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] [VOLUME:19] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) dismounted

  • 00000687 .. [STATE:18] 로그는 down 시 role이 primary 일때 secondary 로 role을 변결 할때 출력됩니다.

Code Block
00000687 10/13/2020 16:16:11.2560178 [print_state_change] [STATE:18] bsr_info<6> bsr r0, r(Primary), f(0x11), scf(0x83c): change_role, role( Primary -> Secondary )
00000688 10/13/2020 16:16:11.2568256 [__receive_uuids] [UUID:16] bsr_warn<4> 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/2020 16:16:11.2568317 [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)

  • 00000690 .. [VOLUME:61], 00000691 .. [VOLUME:26] 로그들은 복제 볼륨 베타적 락 반환 시 출력됩니다.

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

  • 00000714 .. [STATE:20] 로그는 detaching 상태 변경이 출력됩니다.

Code Block
00000714 10/13/2020 16:16:11.2593339 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): change_disk_state, disk( UpToDate -> Detaching )

  • 00000715 .. [UUID?:19] 로그는 detaching 시 대상 복제 볼륨에 설정되어있는 current UUID 가 출력됩니다.

Code Block
00000715 10/13/2020 16:16:11.2593378 [finish_state_change] [UUID:19] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x10002): detaching to current UUID: 83F530CA41FA9868
00000716 10/13/2020 16:16:11.2593863 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Detaching), dvflag(0x1002): 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/13/2020 16:16:11.2599158 [bsr_bm_resize] [BITMAP:23] bsr_info<6> bsr r0/0 minor 2, ds(Diskless), dvflag(0x2): bitmap resize called with capacity(0)
00000719 10/13/2020 16:16:11.2601141 [bsr_thread_setup] [THREAD:10] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x0): Terminating worker thread
00000720 10/13/2020 16:16:11.2601562 [mvolWorkThread] [THREAD:20] bsr_info<6> [0xFFFFE000CDC92880] Terminating mvolWorkThread
00000721 10/13/2020 16:16:11.2603818 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) done (cmd_pending:0) <-

동기화

syncsource

다음은 syncsource에서 동기화 시작 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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)

  • 00000595 .. [RESYNC/OV:73] 로그는 연결이 완료되면 로컬 노드와 피어 노드의 UUID 정보 교환을 시작하기 전에 출력됩니다.

Code Block
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:

  • 00000596 .. [RESYNC/OV:65] 로그는 로컬 노드에 설정되어있는 UUID 정보가 출력됩니다.

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

  • 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 .. [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)
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"

  • 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%

  • 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%

  • 00000606 .. [BITMAP:52] 로그는 비트맵 교환이 완료되면 출력됩니다.

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 )

  • 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 정보가 출력됩니다.

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

  • 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

다음은 synctarget에서 동기화 시작 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

Info

syncsource와 중복되는 로그는 설명하지 않습니다.

  • 비트밉 교환 과정은 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"
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"
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에서 동기화 데이터 요청을 syncsource에 모두 전송 했을때 출력됩니다.

Code Block
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

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

Code Block
00000104 10/13/2020 16:14:10.6436530 [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 9 sec; paused 0 sec; 3868 K/sec), hit bit (in sync 0; marked rl 0)
00000105 10/13/2020 16:14:10.6436613 [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 83F530CA41FA9868:0000000000000000:7B326D963D9936CE:3DF87D1E1EFC3E92
00000106 10/13/2020 16:14:10.6436766 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Inconsistent), dvflag(0x20004): bsr_resync_finished, disk( Inconsistent -> UpToDate )
00000107 10/13/2020 16:14:10.6436796 [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 )
00000108 10/13/2020 16:14:10.6441781 [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(FFFFE0016F4E7770), current(FFFFE0016F4E7770)