Skip to end of metadata
Go to start of metadata

You are viewing an old version of this page. View the current version.

Compare with Current View Page History

« Previous Version 40 Next »

목적

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

주요 동작 로그를 읽기전 전 https://mantech.jira.com/wiki/spaces/BSRUG , 로그 을 숙지해주세요.

동작

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

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

커널 로드

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

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

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

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” 입니다.

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” 이 없다면 명령이 완료되지 않은 상황임을 알 수 있습니다.

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

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

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 명령 실행 시 연결되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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

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은 하위호환을 지원합니다.

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가 할당되지 않아 사용되지 않습니다.

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

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] 로그는 로컬 노드의 현재 설정되어있는 복제 디스크 크기가 출력됩니다.

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

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] 로그는 최근 노드간 연결 후 협의로 설정되어있는 복제 디스크 크기가 출력됩니다.

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 명령 실행 시 연결 종료되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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

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으로 상태 변경 시 출력됩니다.

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되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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

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 대상 복제 디스크의 크기가 출력됩니다.

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

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 명령이 실행됩니다.

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되는 과정의 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

bsradm down 명령은 볼륨 lock, 볼륨 flush, 볼륨 dismount, 연결 종료, 볼륨 잠금 순서로 실행됩니다.

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] 로그들은 복제 볼륨 베타적 락 획득 시 출력됩니다.

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 시 출력됩니다.

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 실행 시 출력됩니다.

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을 변결 할때 출력됩니다.

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] 로그들은 복제 볼륨 베타적 락 반환 시 출력됩니다.

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 명령과 동일한 동작을 실행합니다.

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 상태 변경이 출력됩니다.

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

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에서 동기화 시작 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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 정보 교환을 시작하기 전에 출력됩니다.

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

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

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 비교 후 결과가 출력됩니다.

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] 로그는 로컬 노드의 비트맵을 피어 노드에 전송 완료 시 출력됩니다.

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] 로그는 피어 노드의 비트맵을 로컬 노드가 수신 완료 시 출력됩니다.

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] 로그는 비트맵 교환이 완료되면 출력됩니다.

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] 로그는 동기화 시작과 동기화 데이터 크기가 출력됩니다.

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

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] 로그는 동기화 진행 시간 및 초당 동기화 속도가 출력됩니다.

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에서 동기화 시작 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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

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

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에 모두 전송 했을때 출력됩니다.

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에서 동기화 완료 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다.

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)
  • No labels