Versions Compared

Old Version 16

changes.mady.by.user 한성원

Saved on

compared with

New Version Current

changes.mady.by.user SungEun Kim

Saved on

Key

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

목적

...

개요

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

동작

Info

windwos bsr 1.6.1 설치 및 1:1 연결의 주요 동작 로그로 작성되었습니다.

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

동작

커널 로드

windows 에서 bsr 커널 드라이버는 시스템 시작 시 로드되며 로드 시 출력 되는 로그입니다.

...

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

드라이버 기동

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

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

    • 시스템 로그가 없는 상황에서는 커널 로드 로그 출력 시간을 통해 시스템 시작 시간을 짐작하기도 합니다윈도우즈 커널 드라이버는 시스템이 시작하는 시점에 기동합니다. 기동 시점의 로그 시간을 보면 시스템이 시작한 시간을 유추할 수 있습니다.

Code Block
00000001 10/1326/2020 16:0924:0342.11439587079617 [wait_for_add_deviceinitRegistry] [LOGDRIVER:1063] 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[\0xFFFFE0012A6BD880] registry_path[\Registry\Machine\System\CurrentControlSet\Services\bsr]
0000000300000002 10/1326/2020 16:0924:0342.11442127079678 [initRegistry] [DRIVER:64] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] bypass_level=0, read_filter=0, use_volume_lock=1, netlink_tcp_port=5678, daemon_tcp_port=5679, ver=1.5
0000000400000003 10/1326/2020 16:0924:0342.11448267080324 [bsr_initwait_for_add_device] [DRIVERLOG:7710] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A9DC300] initialized. Version: 1.6.1-A1 (api:2/proto:86-114)
00000005 10/13Wait for device to be connected for log file generation.(C:\Program Files\bsr)
00000004 10/26/2020 16:24:42.7080346 [bsr_init] [DRIVER:77] bsr_info<6> [0xFFFFE0012A6BD880] BSR driver loaded and initialized successfully. Version: 1.6.1 (api:2/proto:86-114)
00000005 10/26/2020 16:0924:0342.11448507080380 [bsr_init] [DRIVER:78] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] 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/1326/2020 16:0924:0342.11448687080400 [bsr_init] [DRIVER:79] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] registered as block device major 147

명령 실행

  • bsradm.exe, bsrsetup.exe, bsrmeta.exe, bsrcon.exe 으로 명령 실행 시 bsr 커널에서 실행되는 명령의 경우 bsr 커널 명령 실행 전 실행 후 로그를 출력합니다.

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

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

    • 명령에따라 실행 시 완료까지 대기하거고 완료되거나 대기하지 않고 완료될 수 있습니다.

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

Code Block
00000018
00000007 10/26/2020 16:24:42.7080424 [DriverEntry] [DRIVER:4] bsr_info<6> [0xFFFFE0012A6BD880] BSR MVF Driver loaded.

상태 변경

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

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

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

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

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

Code Block
00000053 10/13/2020 16:09:29.00581643583295 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:1820] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
..
00000020 bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )
00000091 10/13/2020 16:09:2948.06122102615732 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:2021] bsr_info<6> [0xFFFFE000CCAA5040] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done (cmd_pending:0) <-
..
00000021 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:0910:2914.09027723457504 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:18] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlinkr0, cmd(BSR_ADM_NEW_MINOR:5) begin ->
..
00000023r(Secondary), f(0x0), scf(0xa1c): change_role, role( Secondary -> Primary )
00000583 10/13/2020 16:0914:2901.09063855270141 [NetlinkWorkThreadprint_state_change] [NETLINKSTATE:2019] bsr_info<6> [0xFFFFE000CCAC4880]bsr 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.1014684r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )

Netlink 명령

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

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

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

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

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

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

Code Block
00000018 10/26/2020 16:25:03.2195574 [NetlinkWorkThread] [NETLINK:2018] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done (cmd_pending:0) <-
..
00000028 10/13RESOURCE:7 command has been received. Execute the command.
...//명령 수행
00000020 10/26/2020 16:0925:2903.11241802197637 [NetlinkWorkThread] [NETLINK:1820] bsr_info<6> [0xFFFFE000CC6EF8800xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PATHRESOURCE:45)7 begincommand ->execution ..
00000029terminated. (pending command:0)

00000021 10/1326/2020 16:0925:2903.11405152278267 [NetlinkWorkThread] [NETLINK:2018] bsr_info<6> [0xFFFFE000CC6EF8800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done (cmd_pending:0) <-

상태 변경

  • 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] [STATEMINOR:5 command has been received. Execute the command.
...//명령 수행
00000023 10/26/2020 16:25:03.2280254 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command execution terminated. (pending command:0)

00000024 10/26/2020 16:25:03.2352395 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44 command has been received. Execute the command.
...//명령 수행
00000027 10/26/2020 16:25:03.2354514 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44 command execution terminated. (pending command:0)

00000028 10/26/2020 16:25:03.2442056 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_PATH:45 command has been received. Execute the command.
...//명령 수행
00000029 10/26/2020 16:25:03.2444816 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_PATH:45 command execution terminated. (pending command:0)

00000030 10/26/2020 16:25:03.2884146 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012B2FC880] BSR_ADM_ATTACH:12 command has been received. Execute the command.
...//명령 수행
00000055 10/26/2020 16:25:03.3033626 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012B2FC880] BSR_ADM_ATTACH:12 command execution terminated. (pending command:0)

00000056 10/26/2020 16:25:03.3136502 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0xa1c): change_role, role( Secondary -> Primary )
00000583 10/13[0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command has been received. Execute the command.
...//명령 수행
00000059 10/26/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 )

노드 연결

Code Block
00000809 10/13/2020 16:18:22.947825325:03.3139110 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command execution terminated. (pending command:0)

connect

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

Code Block
00000056 10/26/2020 16:25:03.3136502 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B2F9880] bsr netlink cmd(BSR_ADM_CONNECT:10) begin ->
00000810 command has been received. Execute the command.
00000057 10/1326/2020 16:1825:2203.94783553136604 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B2F9880] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFF800A6319BD0 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000081100000058 10/1326/2020 16:1825:2203.94785193136765 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10e0x0), scf(0x2a): bsr_adm_connect, conn( StandAlone -> Unconnected )
00000812
00000059 10/26/2020 16:25:03.3139110 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command execution terminated. (pending command:0)
00000060 10/1326/2020 16:1825:2203.94789043139464 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x10e0x0), 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/132928])
00000061 10/26/2020 16:1825:2203.94802653140159 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CE7280400xFFFFE0012C706040] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFE000CE0F9170FFFFE0012C707160 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000081500000062 10/1326/2020 16:1825:2203.94804163140398 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0xe0x0), scf(0x2a): conn_connect, conn( Unconnected -> Connecting )
00000816

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

Code Block
00000063 10/1326/2020 16:1825:2506.95669413224961 [bsr_do_features] [PROTOCOL:55] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe0x0), scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
0000081700000064 10/1326/2020 16:1825:2506.95670173225110 [bsr_do_features] [PROTOCOL:56] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe0x0), scf(0x0): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000818

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

Code Block
00000065 10/1326/2020 16:18:25:06.95681413231473 [conn_connect] [SEND BUFFER:27] bsr_warn<4> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe0x0), scf(0x0): send-buffering disabled nc->sndbuf_size:0
0000081900000066 10/1326/2020 16:1825:2506.95681803231590 [bsr_thread_start] [THREAD:11] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe0x0), scf(0x0): Starting ack_recv thread (from receiver [16761700])
0000082000000067 10/1326/2020 16:1825:2606.04243673374818 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CDA1A0400xFFFFE0012CBD2040] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFE000CDAA58C0FFFFE0012C7CCC20 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000082100000068 10/1326/2020 16:1825:2606.04245863375354 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Preparing cluster-wide state change 2387348015177619259 (0->1 499/146)
0000082200000069 10/1326/2020 16:1825:2606.04247333375466 [change_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:2387348015177619259] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (2058) 
0000082300000070 10/1326/2020 16:1825:2606.04304893384621 [change_cluster_wide_state] [TWOPC:36] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:2387348015177619259] target_node_id(1) get_cluster_wide_reply (3) 
0000082400000071 10/1326/2020 16:1825:2606.04305603384814 [change_cluster_wide_state] [TWOPC:37] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State change 2387348015177619259: primary_nodes=0, weak_nodes=0
0000082500000072 10/1326/2020 16:1825:2606.04306113384904 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 2387348015177619259 (0ms1ms) (0->1)
0000082600000073 10/1326/2020 16:1825:2606.04323173389819 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xe0xc), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000827 10/13 -> Secondary )

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

Code Block
00000074 10/26/2020 16:1825:2606.04349603391141 [receive_SyncParam] [PROTOCOL:29] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): syncrecv peer device option, resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000828

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

Code Block
00000075 10/1326/2020 16:1825:2606.04350803396005 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): current_mydisk_size: 10860101632 bytes
00000829

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

Code Block
00000076 10/1326/2020 16:1825:2606.04351143396102 [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 10/13max_size: 10860101632 bytes

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

Code Block
00000077 10/26/2020 16:1825:2606.04351683396215 [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
0000083100000078 10/1326/2020 16:1825:2606.04352093396295 [get_max_agreeable_size] [GENLVOLUME:1698] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): Skip the replication volume size comparison because it is a local node_ id: (0)
0000083200000079 10/1326/2020 16:1825:2606.04352363396358 [get_max_agreeable_size] [GENLVOLUME:1799] 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)
0000083300000080 10/1326/2020 16:1825:2606.04352923396463 [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
0000083400000081 10/1326/2020 16:1825:2606.04364433397114 [get_max_agreeable_size] [GENLVOLUME:1698] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0):, ds(UpToDate), dvflag(0x0): Skip the replication volume size comparison because it is a local node_ id: (0)
0000083500000082 10/1326/2020 16:1825:2606.04364743397234 [get_max_agreeable_size] [GENLVOLUME:1799] 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

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

Code Block
0000079100000093 10/1326/2020 16:1837:2052.97619142808432 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) begin ->
00000792 command has been received. Execute the command.
00000094 10/1326/2020 16:1837:2052.97620232808549 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012B69D880] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFF800A6319BD0 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000079300000095 10/1326/2020 16:1837:2052.97622182808836 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): Preparing cluster-wide state change 23665685363319182627 (0->1 496/16)
0000079400000096 10/1326/2020 16:1837:2052.97622522808878 [change_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:23665685363319182627] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
0000079500000097 10/1326/2020 16:1837:2052.97663562812432 [change_cluster_wide_state] [TWOPC:36] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): [TWOPC:23665685363319182627] target_node_id(1) get_cluster_wide_reply (3) 
0000079600000098 10/1326/2020 16:1837:2052.97664122812481 [change_cluster_wide_state] [TWOPC:37] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): State change 23665685363319182627: primary_nodes=0, weak_nodes=0
0000079700000099 10/1326/2020 16:1837:2052.97664632812511 [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
0000079800000100 10/1326/2020 16:1837:2052.97664972812540 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x28): Committing cluster-wide state change 23665685363319182627 (0ms1ms) (0->1)
00000799

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

Code Block
00000101 10/1326/2020 16:1837:2052.97677702813798 [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 )
0000080000000102 10/1326/2020 16:1837:2052.97678312813842 [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 )
0000080100000103 10/1326/2020 16:1837:2052.97682112814295 [bsr_recv] [SOCKET:15] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x10e), scf(0x208): Data stream socket data receive error(-15)
0000080200000104 10/1326/2020 16:1837:2052.97689742814897 [bsr_ack_receiver] [CONNECTION:16] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): ack_receiver terminated
0000080300000105 10/1326/2020 16:1837:2052.97690282814968 [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
0000080400000106 10/1326/2020 16:1837:2052.97719902817384 [w_resync_timer] [RESYNC/OV:105] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): completed: The resync is complete because it is not in the VerifyS or SyncTarget replication state.
0000080500000107 10/1326/2020 16:1837:2052.97743972820403 [conn_disconnect] [CONNECTION:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x10e), scf(0x0): Connection closed
0000080600000108 10/1326/2020 16:1837:2052.97749282820944 [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 )
0000080700000109 10/1326/2020 16:1837:2052.97753352821351 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x10e), scf(0x0): Terminating receiver thread
0000080800000110 10/1326/2020 16:1837:2052.97775522823823 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_DISCONNECT:11) done command execution terminated. (cmd_pending command:0) <-

리소스 up 명령 실행

Code Block
00000722 10/13

up

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

Info

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

Code Block
00000018 10/26/2020 16:1625:1203.62661062195574 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
00000723 command has been received. Execute the command.
00000019 10/1326/2020 16:1625:1203.62662522195696 [bsr_thread_start] [THREAD:12] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x0): Starting worker thread (from not_bsr_thread [0])
0000072400000020 10/1326/2020 16:1625:1203.62684492197637 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done command execution terminated. (cmd_pending command:0)
<-00000021 00000725 10/1326/2020 16:1625:1203.63462922278267 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) begin ->
00000726 command has been received. Execute the command.
00000022 10/1326/2020 16:1625:1203.63466512278667 [bsr_create_device] [VOLUME:10] bsr_info<6> [0xFFFFE000CCAAC040]0xFFFFE0012A786040] The capacity of the create device(FFFFE000CE6C8890FFFFE0012CAD1AB0) is max sectors(21211136), size(10860101632 bytes)
0000072700000023 10/1326/2020 16:1625:1203.63484212280254 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) done command execution terminated. (cmd_pending command:0)
<-00000024 00000728 10/1326/2020 16:1625:1203.64307012352395 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) begin ->
00000729 command has been received. Execute the command.
00000025 10/1326/2020 16:1625:1203.64308892352568 [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, peer device option. resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
0000073000000026 10/1326/2020 16:1625:1203.64310842352753 [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])
0000073100000027 10/1326/2020 16:1625:1203.64330562354514 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done (cmd_pending command execution terminated. (pending command:0)
<-00000028 00000732 10/1326/2020 16:1625:1203.65194822442056 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_PATH:45) begin ->
00000733 command has been received. Execute the command.
00000029 10/1326/2020 16:1625:1203.65215982444816 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAFB8800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done command execution terminated. (cmd_pending command:0)
<-
0000073400000030 10/1326/2020 16:1625:1203.70334752884146 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] bsr netlink cmd(BSR_ADM_ATTACH:12) begin ->
00000735 command has been received. Execute the command.
00000031 10/1326/2020 16:1625:1203.70377192889320 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFF800A6319BD0 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000073600000032 10/1326/2020 16:1625:1203.70378832889474 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Diskless), dvflag(0x0): change_disk_state, disk( Diskless -> Attaching )
0000073700000033 10/1326/2020 16:1625:1203.70383822890049 [FsctlLockVolume] [VOLUME:2065] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] notry lock. volume(\Device\HarddiskVolume2)
already00000034 dismounted
00000738 10/1326/2020 16:1625:1203.70384142959696 [FsctlFlushDismountVolumeFsctlLockVolume] [VOLUME:1523] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] no dismount. volume(\Device\HarddiskVolume2) already dismounted
00000739locked. handle(0xFFFFFFFF80000AFC)
00000035 10/1326/2020 16:1625:1203.70384412959798 [FsctlUnlockVolumeFsctlFlushDismountVolume] [VOLUME:2462] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2FC880] try flush volume(\Device\HarddiskVolume2)
not00000036 locked
00000740 10/1326/2020 16:1625:1203.70384602959854 [bsr_adm_attachFsctlFlushDismountVolume] [GENLVOLUME:3617] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Maximum number of bitmap peer devices 1
00000741 10/13[0xFFFFE0012B2FC880] Failed to flush volume. status(0xc000026e)
00000037 10/26/2020 16:1625:1203.70478592959874 [bsr_bump_write_orderingFsctlFlushDismountVolume] [VOLUME:6663] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x1): Method to ensure write ordering: drain
00000742 10/13[0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) flushed
00000038 10/26/2020 16:25:03.2959893 [FsctlFlushDismountVolume] [VOLUME:64] bsr_info<6> [0xFFFFE0012B2FC880] try dismount volume(\Device\HarddiskVolume2)
00000039 10/26/2020 16:1625:1203.70478912965893 [get_max_agreeable_sizeFsctlFlushDismountVolume] [GENLVOLUME:1619] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000743 10/13[0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) dismounted
00000040 10/26/2020 16:1625:1203.70479132965979 [get_max_agreeable_sizeFsctlUnlockVolume] [GENLVOLUME:1761] 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[0xFFFFE0012B2FC880] unlock volume(\Device\HarddiskVolume2)
00000041 10/26/2020 16:25:03.2969597 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) unlocked
00000042 10/26/2020 16:1625:1203.70481032969738 [getbsr_maxadm_agreeable_sizeattach] [GENL:1636] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000745 The maximum number of bitmap peer devices is 1.
00000043 10/1326/2020 16:1625:1203.70481232979413 [getbsr_maxbump_agreeablewrite_sizeordering] [GENLVOLUME:1766] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x0), pdvflagscf(0x00x1): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000746 10/13Method to ensure write ordering: drain
00000044 10/26/2020 16:1625:1203.70481592979447 [bsrget_max_bmagreeable_resizesize] [BITMAPVOLUME:2398] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): bitmap resize called with capacity(21211136)
00000747 10/13Skip the replication volume size comparison because it is a local node id(0)
00000045 10/26/2020 16:1625:1203.70540152979474 [bsrget_max_bmagreeable_resizesize] [BITMAPVOLUME:2599] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), dsprpl(AttachingOff), dvflagpdvflag(0x0): resize bitmap, bits(2651392) words(82856) pages(81)
00000748 10/13 node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000046 10/26/2020 16:1625:1203.70540542979681 [bsrget_determinemax_devagreeable_size] [GENLVOLUME:1398] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Skip Updatethe replication diskvolume size 10 GB (10605568 KB)
00000749 comparison because it is a local node id(0)
00000047 10/1326/2020 16:1625:1203.70929932979705 [bmget_max_rwagreeable_rangesize] [BITMAPVOLUME:2999] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, ds(Attachingpdsk(DUnknown), prpl(Off), dvflagpdvflag(0x0): recounting of set bits took additional 1ms
00000750 10/13 node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000048 10/26/2020 16:1625:1203.70930792979742 [statebsr_changebm_lockresize] [STATEBITMAP:4023] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDE0B820
00000751 10/13 bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Start resizing the bitmap size to disk capacity. capacity sector(21211136)
00000049 10/26/2020 16:1625:1203.70932402985588 [printbsr_statebm_changeresize] [STATEBITMAP:2025] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )
00000752 10/13The bitmap size has been resized to disk capacity. bits(2651392) words(82856) pages(81)

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

Code Block
00000050 10/26/2020 16:1625:1203.70932882985622 [finishbsr_determine_statedev_changesize] [UUIDVOLUME:1496] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): attached to current UUID: 83F530CA41FA9868
00000753 10/13Update the disk size in the meta. 10 GB (10605568 KB)
00000051 10/26/2020 16:1625:1203.70976573028170 [NetlinkWorkThreadbm_rw_range] [NETLINKBITMAP:2029] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_ATTACH:12) done (cmd_pending:0) <-
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/13r0/0 minor 2, ds(Attaching), dvflag(0x0): Recounting of set bits took additional 0ms
00000052 10/26/2020 16:1625:1203.71868943028240 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAAC0400xFFFFE0012B2FC880] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFF800A6319BD0 resource->worker.task:FFFFE000CDE0B820FFFFE0012C513C60
0000075600000053 10/1326/2020 16:1625:1203.71871023028465 [print_state_change] [STATE:1920] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown/0 minor 2, ds(Attaching), cflagdvflag(0x0), scf(0x2a): bsrchange_admdisk_connectstate, conndisk( StandAloneAttaching -> UnconnectedUpToDate )
00000757

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

Code Block
00000054 10/1326/2020 16:1625:1203.71891503028511 [NetlinkWorkThreadfinish_state_change] [NETLINKUUID:2014] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) done (cmd_pending:0) <-
00000758 10/13 bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): attached to current UUID: A95D18E8D4AE8C78
00000055 10/26/2020 16:1625:1203.71903223033626 [bsr_thread_startNetlinkWorkThread] [THREADNETLINK:1120] 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[0xFFFFE0012B2FC880] BSR_ADM_ATTACH:12 command execution terminated. (pending command:0)

  • connect 명령을 수행합니다.

Code Block
00000059 10/26/2020 16:1625:1203.71911493139110 [state_change_lockNetlinkWorkThread] [STATENETLINK:4020] bsr_info<6> [0xFFFFE000CDDA58800xFFFFE0012B2F9880] worker should not initiate state changes with CS_SERIALIZE current:FFFFE000CE0F9170 resource->worker.task:FFFFE000CDE0B820
00000760 10/13BSR_ADM_CONNECT:10 command execution terminated. (pending command:0)
00000060 10/26/2020 16:1625:1203.71913493139464 [printbsr_statethread_changestart] [STATETHREAD:1911] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown), cflag(0x0), scf(0x2a0x0): conn_connect, conn( Unconnected -> Connecting )
00000761 10/13Starting receiver thread (from worker [2928])
00000061 10/26/2020 16:1625:1503.72248483140159 [bsrstate_dochange_featureslock] [PROTOCOLSTATE:5540] bsr_info<6> bsr[0xFFFFE0012C706040] r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): Handshake to peer 1 successful: Agreed network protocol version 114
00000762 10/13Worker should not initiate state changes with CS_SERIALIZE current:FFFFE0012C707160 resource->worker.task:FFFFE0012C513C60
00000062 10/26/2020 16:1625:1503.72249163140398 [bsrprint_dostate_featureschange] [PROTOCOLSTATE:5619] bsr_info<6> bsr r0 pnode-id:1, cs(ConnectingUnconnected), prole(Unknown), cflag(0x0), scf(0x00x2a): Feature flags enabled on protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000763 10/13conn_connect, conn( Unconnected -> Connecting )
00000063 10/26/2020 16:1625:1506.72273323224961 [connbsr_do_connectfeatures] [SEND BUFFERPROTOCOL:2755] bsr_warn<4>info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): send-buffering disabled nc->sndbuf_size:0
00000764 10/13 Handshake to peer 1 successful: Agreed network protocol version 114
00000064 10/26/2020 16:1625:1506.72274373225110 [bsr_threaddo_startfeatures] [THREADPROTOCOL:1156] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): StartingFeature ack_recvflags threadenabled (fromon 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/13protocol level: 0x7 TRIM THIN_RESYNC WRITE_SAME.
00000065 10/26/2020 16:1625:1506.77706283231473 [change_cluster_wide_stateconn_connect] [TWOPCSEND BUFFER:3427] bsr_info<6>warn<4> bsr r0 pnode-id:1, r(Secondarycs(Connecting), prole(Unknown), fcflag(0x0), scf(0x82a0x0): Preparing clustersend-widebuffering state change 1853056548 (0->1 499/146)
00000767disabled nc->sndbuf_size:0
00000066 10/1326/2020 16:1625:1506.77706643231590 [changebsr_clusterthread_wide_statestart] [TWOPCTHREAD:3511] 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 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0x0), scf(0x0): Starting ack_recv thread (from receiver [1700])
00000067 10/26/2020 16:1625:1506.77760583374818 [state_change_cluster_wide_statelock] [TWOPCSTATE:3640] 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[0xFFFFE0012CBD2040] Worker should not initiate state changes with CS_SERIALIZE current:FFFFE0012C7CCC20 resource->worker.task:FFFFE0012C513C60
00000068 10/26/2020 16:1625:1506.77761093375354 [change_cluster_wide_state] [TWOPC:3734] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): State Preparing cluster-wide state change 1853056548: primary_nodes=0, weak_nodes=0
00000770177619259 (0->1 499/146)
00000069 10/1326/2020 16:1625:1506.77761453375466 [change_cluster_wide_state] [TWOPC:3935] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 1853056548 (1ms) (0->1)
00000771 10/13[TWOPC:177619259] target_node_id(1) conn(Connected) repl(-) disk(-) pdsk(-) role(Secondary) peer(-) flags (2058) 
00000070 10/26/2020 16:1625:1506.77784713384621 [printchange_cluster_wide_state_change] [STATETWOPC:1936] bsr_info<6> bsr r0 pnode-id:1, cs(Connecting) r0, proler(UnknownSecondary), cflagf(0xc0x0), scf(0xa0a0x82a): [TWOPC:177619259] connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000772 10/13target_node_id(1) get_cluster_wide_reply (3) 
00000071 10/26/2020 16:1625:1506.77795273384814 [receive_SyncParamchange_cluster_wide_state] [PROTOCOLTWOPC:2937] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskr(DUnknownSecondary), prplf(Off0x0), pdvflagscf(0x00x82a): 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:32State change 177619259: primary_nodes=0, weak_nodes=0
00000072 10/26/2020 16:25:06.3384904 [change_cluster_wide_state] [TWOPC:39] bsr_info<6> bsr r0, r(Secondary), f(0x0), scf(0x82a): Committing cluster-wide state change 177619259 (1ms) (0->1)
00000073 10/26/2020 16:25:06.3389819 [print_state_change] [STATE:19] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), dvflagscf(0x00xa0a): current_mydisk_size: 10860101632 bytes
00000774 10/13connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000074 10/26/2020 16:1625:1506.77812923391141 [receive_sizesSyncParam] [PROTOCOL:3329] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): recv peer_current_size: 10860101632device bytesoption, peer_user_sizeresync_rate : 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:16250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000075 10/26/2020 16:25:06.3396005 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): local node_id: 0
00000777current_mydisk_size: 10860101632 bytes
00000076 10/1326/2020 16:1625:1506.77813873396102 [get_max_agreeable_sizereceive_sizes] [GENLPROTOCOL:1733] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000)0x0): peer_current_size: node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)
00000778 10/1310860101632 bytes peer_user_size: 0 bytes peer_disk_size: 10860101632 bytes peer_max_size: 10860101632 bytes
00000077 10/26/2020 16:1625:1506.77814293396215 [receive_sizes] [PROTOCOL:3934] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): md_effective_size: Proceed with device size setting
0000077921211136 my_user_size: 0 my_max_size: 21211136
00000078 10/1326/2020 16:1625:1506.77820723396295 [get_max_agreeable_size] [GENLVOLUME:1698] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): Skip the replication volume size comparison because it is a local node_ id: (0)
0000078000000079 10/1326/2020 16:1625:1506.77821093396358 [get_max_agreeable_size] [GENLVOLUME:1799] 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 명령 실행

Code Block
00000617
00000080 10/1326/2020 16:1625:1106.21368053396463 [NetlinkWorkThreadreceive_sizes] [NETLINKPROTOCOL:1839] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) begin ->
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 10/13r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): Proceed with device size setting
00000081 10/26/2020 16:1625:1106.25350243397114 [FsctlFlushDismountVolumeget_max_agreeable_size] [VOLUME:6298] bsr_info<6> [0xFFFFE000CCAC4880] try flush volume(\Device\HarddiskVolume2)
00000684 10/13/2020 16:16:11.2535729 [FsctlFlushDismountVolume] [VOLUME:63] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) flushed
00000685 10/13 bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): Skip the replication volume size comparison because it is a local node id(0)
00000082 10/26/2020 16:1625:1106.25357663397234 [FsctlFlushDismountVolumeget_max_agreeable_size] [VOLUME:6499] bsr_info<6> [0xFFFFE000CCAC4880] try dismount volume(\Device\HarddiskVolume2)
00000686 10/13 bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)

down

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

Info

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

Code Block
00000398 10/26/2020 16:1649:1110.25598222436929 [FsctlFlushDismountVolumeNetlinkWorkThread] [VOLUMENETLINK:1918] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) dismounted
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 10/13/2020 16:16:11.2569857 [FsctlUnlockVolume] [VOLUME:61BSR_ADM_DOWN:27 command has been received. Execute the command.

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

Code Block
00000399 10/26/2020 16:49:10.2437390 [FsctlLockVolume] [VOLUME:65] bsr_info<6> [0xFFFFE0012B2F9880] try lock volume(\Device\HarddiskVolume2)
00000472 10/26/2020 16:49:10.2864430 [FsctlLockVolume] [VOLUME:23] bsr_info<6> [0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) locked. handle(0xFFFFFFFF80000C20)

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

Code Block
00000473 10/26/2020 16:49:10.2864535 [FsctlFlushDismountVolume] [VOLUME:62] bsr_info<6> [0xFFFFE0012B2F9880] try flush volume(\Device\HarddiskVolume2)
00000474 10/26/2020 16:49:10.2864915 [FsctlFlushDismountVolume] [VOLUME:63] bsr_info<6> [0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) flushed

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

Code Block
00000475 10/26/2020 16:49:10.2864954 [FsctlFlushDismountVolume] [VOLUME:64] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] unlocktry dismount volume(\Device\HarddiskVolume2)
0000069100000479 10/1326/2020 16:1649:1110.25768992871632 [FsctlUnlockVolumeFsctlFlushDismountVolume] [VOLUME:2619] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) dismounted

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

Code Block
00000480 10/26/2020 16:49:10.2871910 [print_state_change] [STATE:18] bsr_info<6> bsr r0, r(Primary) unlocked
00000692, f(0x1), scf(0x83c): change_role, role( Primary -> Secondary )
00000481 10/1326/2020 16:1649:1110.25771792879558 [state__changereceive_lockuuids] [STATEUUID:4016] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDB38300
00000693 10/13warn<4> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): receive new current but not update UUID: CE5CC8B0672E645C
00000482 10/26/2020 16:1649:1110.25773282879607 [changebsr_clusteruuid_wide_statecompare] [TWOPCRESYNC/OV:34197] bsr_info<6> bsr r0, r(Secondary)/0 minor 2, fds(0x11UpToDate), scfdvflag(0x280x2): Preparing cluster-wide state change 1834520240 (0->1 496/16)
00000694 10/13 Local and peer current UUIDs are the same. rule(40), res(0)

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

Code Block
00000483 10/26/2020 16:1649:1110.25773552881069 [change_cluster_wide_stateFsctlUnlockVolume] [TWOPCVOLUME:3561] 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[0xFFFFE0012B2F9880] unlock volume(\Device\HarddiskVolume2)
00000484 10/26/2020 16:49:10.2889783 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) unlocked
00000485 10/26/2020 16:1649:1110.25802122890044 [state_change_cluster_wide_statelock] [TWOPCSTATE:3640] bsr_info<6> [0xFFFFE0012B2F9880] bsrWorker r0, r(Secondary), f(0x11), scf(0x28): [TWOPC:1834520240] target_node_id(1) get_cluster_wide_reply (3) 
00000696 10/13should not initiate state changes with CS_SERIALIZE current:FFFFF800A6319BD0 resource->worker.task:FFFFE0012C7D29A0

  • disconnect 를 수행합니다.

Code Block
00000486 10/26/2020 16:1649:1110.25802512890183 [change_cluster_wide_state] [TWOPC:3734] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x28): State Preparing cluster-wide state change 1834520240: primary_nodes=0, weak_nodes=0
000006971805107054 (0->1 496/16)
00000487 10/1326/2020 16:1649:1110.25802752890209 [change_cluster_wide_state] [TWOPC:3835] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), proler(Secondary), cflagf(0x210e0x1), scf(0x28): Cluster is now split
00000698 10/13 [TWOPC:1805107054] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000488 10/26/2020 16:1649:1110.25803002893052 [change_cluster_wide_state] [TWOPC:3936] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x28): Committing cluster-wide state change 1834520240 (0ms) (0->1)
00000699 10/13[TWOPC:1805107054] target_node_id(1) get_cluster_wide_reply (3) 
00000489 10/26/2020 16:1649:1110.25843882893089 [Receivechange_cluster_wide_state] [SOCKETTWOPC:6637] bsr_info<6> [0xFFFFE000CDB66880] receiver => Recv multiWait error. err(STATUS_CONNECTION_RESET) wsk(0xFFFFE000CE2A8198) size(16)
00000700 10/13bsr r0, r(Secondary), f(0x1), scf(0x28): State change 1805107054: primary_nodes=0, weak_nodes=0
00000490 10/26/2020 16:1649:1110.25845792893113 [bsr_recvchange_cluster_wide_state] [SOCKETTWOPC:1438] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(Secondary), cflag(0x210e0x10e), scf(0x28): socketCluster resetis duenow to peer.
00000701split
00000491 10/1326/2020 16:1649:1110.25847572893140 [printchange_cluster_wide_state_change] [STATETWOPC:1939] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(r(Secondary), cflagf(0x210e0x1), scf(0x210x28): bsr_recv, conn( Connected -> BrokenPipe ) peer( Secondary -> Unknown )
00000702 10/13Committing cluster-wide state change 1805107054 (1ms) (0->1)
00000492 10/26/2020 16:1649:1110.25848052895017 [print_state_change] [STATE:2119] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDatecs(Connected), prole(Secondary), prplcflag(Established0x10e), pdvflagscf(0x1006000x208): bsrconn_try_recvdisconnect, pdskconn( UpToDateConnected -> DUnknownDisconnecting ) replpeer( EstablishedSecondary -> OffUnknown )
0000070300000493 10/1326/2020 16:1649:1110.25850712895061 [bsrprint_recvstate_all_warnchange] [PROTOCOLSTATE:6421] bsr_warn<4>info<6> bsr r0/0 minor 2 pnode-id:1, cspdsk(BrokenPipeUpToDate), proleprpl(UnknownEstablished), cflagpdvflag(0x211e)0x100600): conn_try_disconnect, scf(0x0): short read (expected size 16)
00000704 10/13pdsk( UpToDate -> DUnknown ) repl( Established -> Off )
00000494 10/26/2020 16:1649:1110.25852472895371 [printbsr_state_changerecv] [STATESOCKET:1915] bsr_info<6> bsr r0 pnode-id:1, cs(BrokenPipeConnected), prole(UnknownSecondary), cflag(0x211e0x10e), scf(0x208): conn_try_disconnect, conn( BrokenPipe -> Disconnecting )
00000705 10/13 Data stream socket receive error(-15)
00000495 10/26/2020 16:1649:1110.25864952895990 [bsr_ack_receiver] [CONNECTION:16] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e0x10e), scf(0x0): ack_receiver terminated
0000070600000496 10/1326/2020 16:1649:1110.25865322896039 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e0x10e), scf(0x0): Terminating ack_recv thread
0000070700000497 10/1326/2020 16:1649:1110.25876922897546 [w_resync_timer] [RESYNC/OV:105] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x0): completed The resync is complete because it is not in the VerifyS or SyncTarget replication state.
0000070800000498 10/1326/2020 16:1649:1110.25911572900523 [conn_disconnect] [CONNECTION:9] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e0x10e), scf(0x0): Connection closed
0000070900000499 10/1326/2020 16:1649:1110.25916882900922 [print_state_change] [STATE:19] bsr_info<6> bsr r0 pnode-id:1, cs(Disconnecting), prole(Unknown), cflag(0x211e0x10e), scf(0x23): conn_disconnect, conn( Disconnecting -> StandAlone )
0000071000000500 10/1326/2020 16:1649:1110.25919812901181 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x211e0x10e), scf(0x0): Terminating receiver thread
0000071100000501 10/1326/2020 16:1649:1110.25924682901744 [bsr_thread_setup] [THREAD:9] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x211e0x10e), scf(0x0): Terminating sender thread
0000071200000502 10/1326/2020 16:1649:1110.25930362902522 [bsr_destroy_connection] [CONNECTION:1] bsr_info<6> bsr r0 pnode-id:1, cs(StandAlone), prole(Unknown), cflag(0x311e0x110e), scf(0x0): The bsr_destroy_connection 00000713object is removed.
00000503 10/1326/2020 16:1649:1110.25932412902683 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] workerWorker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0FFFFF800A6319BD0 resource->worker.task:FFFFE000CDB38300
00000714.task:FFFFE0012C7D29A0

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

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

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

Code Block
00000505 10/1326/2020 16:1649:1110.25933782902819 [finish_state_change] [UUID:19] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x10002): detaching to current UUID: 83F530CA41FA9868CE5CC8B0672E645C
0000071600000506 10/1326/2020 16:1649:1110.25938632903353 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Detaching), dvflag(0x1002): change_disk_state, disk( Detaching -> Diskless )
0000071700000507 10/1326/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.259915849:10.2909946 [bsr_bm_resize] [BITMAP:23] bsr_info<6> bsr r0/0 minor 2, ds(Diskless), dvflag(0x2): Start resizing the bitmap size resizeto calleddisk withcapacity. capacity sector(0)
0000071900000508 10/1326/2020 16:1649:1110.26011412912038 [bsr_thread_setup] [THREAD:10] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x0): Terminating worker thread
0000072000000509 10/1326/2020 16:1649:1110.26015622912489 [mvolWorkThread] [THREAD:20] bsr_info<6> [0xFFFFE000CDC928800xFFFFE0012CBCF880] Terminating mvolWorkThread
0000072100000510 10/1326/2020 16:1649:1110.26038182914483 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] bsr netlink cmd(BSR_ADM_DOWN:27) done command execution terminated. (cmd_pending command:0) <-

동기화

syncsource

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

Code Block

...

00000322 10/

...

26/2020 16:

...

48:

...

53.

...

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

...

A95D18E8D4AE8C78

...

00000323 10/

...

26/2020 16:

...

48:

...

53.

...

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

...

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

...

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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