Table of Contents

목적

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

...

개요

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

동작

Info

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

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

커널 로드

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

드라이버 기동

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

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

Code Block

00000001 10/1326/2020 16:0924: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 [42.7079617 [initRegistry] [DRIVER:63] bsr_info<6> [0xFFFFE000CBABD8800xFFFFE0012A6BD880] 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: Wait 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/1326/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

상태 변경

...


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 상태 변경 시 로그 출력과 분석 시 주로 참고하는 로그의 설명입니다role의 상태가 변경될 때 발생하는 로그 입니다.

복수의 상태 변경이 하나의 로그에 출력 될 수 있습니다.예상하지 못한 상태 설정 시 로그를 통해 문제 등을 유추 할 수 있습니다.
예를 들어
연결 상태가 connected 에서 connecting 또는 standalone 으로
변경된다면
변경 될 경우, 연결 상태 변경
로그 중심으로 원인을 분석 할 수 있습니다
로그를 중심으로 분석합니다.
로그에는 해당 상태 변경을
진행한 함수 이름이 같이 출력되며 소스코드 확인이 가능하다면 더 상세한 분석을 할
수행한 호출자 함수의 이름이 같이 출력됩니다. 함수의 호출 흐름을 추적하여 디버깅 정보로 활용할 수 있습니다.
- 다음 로그에서 상태 변경을
  진행한 함수 이름은 “change
  수행한 호출자는 change_disk_state, recevie_state, change_role, connect_
  work” 입니다
  work 가 됩니다.

Code Block

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

Netlink 명령

...

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

명령 실행 시 “bsr netlink cmd(~) begin”, 명령 실행 후 “bsr netlink cmd(~) done” 로그를 출력하며 실행되는 명령은 cmd()안에 표시됩니다.
- 예를들어 명령 실행 시 “cmd(~) begin” 은 있으나 매칭되는 “cmd(~) done” 이 없다면 명령이 완료되지 않은 상황임을 알 수 있습니다.
명령에따라 실행 완료까지 대기 또는 대기하지 않을 수 있습니다.
명령 실행으로 출력되는 로그는 “..” 으로 작성했습니다.

...

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:18] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_RESOURCE:7 command has been received. Execute the command.
...//명령 수행
00000020 10/26/2020 16:25:03.2197637 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE0012B69D880] BSR_ADM_NEW_RESOURCE:7 command execution terminated. (pending command:0)

00000021 10/26/2020 16:25:03.2278267 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE0012A786040] BSR_ADM_NEW_MINOR:5 command has been received. Execute the command.
...//명령 수행
00000023 10/26/2020 16:25:03.2280254 [NetlinkWorkThread] [NETLINK:1820] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012A786040] 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> netlink[0xFFFFE0012B69D880] cmd(BSR_ADM_NEW_RESOURCE:7) begin ->
..
00000020 10/13PEER:44 command has been received. Execute the command.
...//명령 수행
00000027 10/26/2020 16:0925:2903.06122102354514 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012B69D880] bsr netlink cmd(BSR_ADM_NEW_RESOURCE:7) done (cmd_pendingPEER:44 command execution terminated. (pending command:0) <-
..
0000002100000028 10/1326/2020 16:0925:2903.09027722442056 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) begin ->
..
00000023 10/13PATH:45 command has been received. Execute the command.
...//명령 수행
00000029 10/26/2020 16:0925:2903.09063852444816 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012A786040] bsr netlink cmd(BSR_ADM_NEW_MINOR:5) done (cmd_pendingPATH:45 command execution terminated. (pending command:0)
<-
..00000030 00000024 10/1326/2020 16:0925:2903.10119072884146 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012B2FC880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) begin ->
..
00000027 10/13ATTACH:12 command has been received. Execute the command.
...//명령 수행
00000055 10/26/2020 16:0925:2903.10146843033626 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CCAA50400xFFFFE0012B2FC880] bsr netlink cmd(BSR_ADM_NEW_PEER:44) done (cmd_pendingATTACH:12 command execution terminated. (pending command:0)
<-
..00000056 00000028 10/1326/2020 16:0925:2903.11241803136502 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CC6EF8800xFFFFE0012B2F9880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) begin ->
..
00000029 10/13CONNECT:10 command has been received. Execute the command.
...//명령 수행
00000059 10/26/2020 16:0925:2903.11405153139110 [NetlinkWorkThread] [NETLINK:20] bsr_info<6> [0xFFFFE000CC6EF8800xFFFFE0012B2F9880] bsr netlink cmd(BSR_ADM_NEW_PATH:45) done (cmd_pendingCONNECT:10 command execution terminated. (pending command:0) <-

connect

...

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

...

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

Code Block

0000080900000056 10/1326/2020 16:1825:2203.94782533136502 [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/13 thread (from worker [2928])
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

0000081600000063 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

0000081800000065 10/1326/2020 16:1825:2506.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 00000074 .. [PROTOCOL:29] 로그는 피어 노드에게 수신 받은 peer device의 설정 정보가 출력됩니다.

Code Block

0000082700000074 10/1326/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
0000082800000075 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

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

Code Block

0000083000000077 10/1326/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):0 minor 2, 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

...

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

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

...

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

Code Block

00000093 10/26/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으로 상태 변경 시 출력됩니다연결을 직접 종료할 경우 연결 상태가 StandAlone으로 변경됩니다.

Code Block

0000079900000101 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): completedThe 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

...

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

...

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

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

Code Block

0000072200000018 10/1326/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)
<-
0000072500000021 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> [0xFFFFE000CCAAC040] bsr netlink cmd(0xFFFFE0012B69D880] BSR_ADM_NEW_PEER:44) done command execution terminated. (cmd_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)
<-00000030 00000734 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.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/132959854 [FsctlFlushDismountVolume] [VOLUME:17] bsr_info<6> [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:1625:1203.70478912959893 [get_max_agreeable_sizeFsctlFlushDismountVolume] [GENLVOLUME:1664] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000743 10/13[0xFFFFE0012B2FC880] try dismount volume(\Device\HarddiskVolume2)
00000039 10/26/2020 16:1625:1203.70479132965893 [get_max_agreeable_sizeFsctlFlushDismountVolume] [GENLVOLUME:1719] 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] volume(\Device\HarddiskVolume2) dismounted
00000040 10/26/2020 16:25:03.2965979 [FsctlUnlockVolume] [VOLUME:61] bsr_info<6> [0xFFFFE0012B2FC880] unlock volume(\Device\HarddiskVolume2)
00000041 10/26/2020 16:1625:1203.70481032969597 [get_max_agreeable_sizeFsctlUnlockVolume] [GENLVOLUME:1626] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): local node_id: 0
00000745 10/13[0xFFFFE0012B2FC880] volume(\Device\HarddiskVolume2) unlocked
00000042 10/26/2020 16:1625:1203.70481232969738 [getbsr_maxadm_agreeable_sizeattach] [GENL:1736] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdskds(DUnknownAttaching), prpl(Off), pdvflagdvflag(0x0): node id(1) bitmap index(0)The maximum number of bitmap uuid(0x0) flags(0x10) max size(0) disk state(DUnknown)
00000746peer devices is 1.
00000043 10/1326/2020 16:1625:1203.70481592979413 [bsr_bump_bmwrite_resizeordering] [BITMAPVOLUME:2366] bsr_info<6> bsr r0/0 minor 2, r(Secondary), dsf(Attaching0x0), dvflagscf(0x00x1): Method bitmapto resizeensure calledwrite with capacity(21211136)
00000747ordering: drain
00000044 10/1326/2020 16:1625:1203.70540152979447 [bsrget_max_bmagreeable_resizesize] [BITMAPVOLUME:2598] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): resize bitmap, bits(2651392) words(82856) pages(81)

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

Code Block

00000748 10/13 Skip the replication volume size comparison because it is a local node id(0)
00000045 10/26/2020 16:1625:1203.70540542979474 [bsrget_determinemax_devagreeable_size] [GENLVOLUME:1399] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), dsprpl(AttachingOff), dvflagpdvflag(0x0): Update disk size 10 GB (10605568 KB)
00000749 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.70929932979681 [bmget_max_rwagreeable_rangesize] [BITMAPVOLUME:2998] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): recounting of set bits took additional 1ms
00000750 10/13Skip the replication volume size comparison because it is a local node id(0)
00000047 10/26/2020 16:1625:1203.70930792979705 [stateget_max_changeagreeable_locksize] [STATEVOLUME:4099] 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 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)
00000048 10/26/2020 16:1625:1203.70932402979742 [printbsr_statebm_changeresize] [STATEBITMAP:2023] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): change_disk_state, disk( Attaching -> UpToDate )

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

Code Block

00000752 10/13): Start resizing the bitmap size to disk capacity. capacity sector(21211136)
00000049 10/26/2020 16:1625:1203.70932882985588 [finishbsr_statebm_changeresize] [UUIDBITMAP:1425] bsr_info<6> bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): attached The bitmap size has been resized to current UUID: 83F530CA41FA9868
00000753 10/13disk capacity. bits(2651392) words(82856) pages(81)

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

Code Block

00000050 10/26/2020 16:1625:1203.70976572985622 [NetlinkWorkThreadbsr_determine_dev_size] [NETLINKVOLUME:2096] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_ATTACH:12) done (cmd_pending:0) <-

connect 명령이 실행됩니다.

Code Block

00000754 10/13bsr r0/0 minor 2, ds(Attaching), dvflag(0x0): Update the disk size in the meta. 10 GB (10605568 KB)
00000051 10/26/2020 16:1625:1203.71867773028170 [NetlinkWorkThreadbm_rw_range] [NETLINKBITMAP:1829] bsr_info<6> [0xFFFFE000CCAAC040] bsr netlink cmd(BSR_ADM_CONNECT:10) begin ->
00000755 10/13bsr r0/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 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

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

Code Block

00000054 10/26/2020 16:1625:1203.71903223028511 [bsrfinish_threadstate_startchange] [THREADUUID:1114] bsr_info<6> bsr r0 pnode-id:1, cs(Unconnected), prole(Unknown/0 minor 2, ds(Attaching), cflagdvflag(0x0), scf(0x0): Starting receiver thread (from worker [2108])
00000759 10/13: attached to current UUID: A95D18E8D4AE8C78
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)

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 [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/13state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE0012C706040] Worker 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> [0xFFFFE0012CBD2040] bsrWorker r0, r(Secondary), f(0x0), scf(0x82a): [TWOPC:1853056548] target_node_id(1) get_cluster_wide_reply (3) 
00000769 10/13should 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): StatePreparing 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, csr(ConnectingSecondary), prole(Unknown), cflag(0xcf(0x0), scf(0xa0a0x82a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000772 10/13[TWOPC:177619259] target_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: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:33State 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 pnode-id:1, cs(Connecting), prole(Unknown), cflag(0xc), scf(0xa0a): connect_work, conn( Connecting -> Connected ) peer( Unknown -> Secondary )
00000074 10/26/2020 16:25:06.3391141 [receive_SyncParam] [PROTOCOL:29] 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_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:16resync_rate : 250k, c_plan_ahead : 20k, c_delay_target : 10k, c_fill_target : 100s, c_max_rate : 102400k, c_min_rate : 250k, ov_req_num : 10b, ov_req_interval : 100ms
00000075 10/26/2020 16:25:06.3396005 [receive_sizes] [PROTOCOL:32] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): 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(0x1000000x0): node id(1) bitmap index(0) bitmap uuid(0x0) flags(0x10) max size(21211136) disk state(DUnknown)
00000778 10/13peer_current_size: 10860101632 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): Proceed with device size setting
00000779 10/13md_effective_size: 21211136 my_user_size: 0 my_max_size: 21211136
00000078 10/26/2020 16:1625:1506.77820723396295 [get_max_agreeable_size] [GENLVOLUME:1698] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x0): 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 실행

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

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

Code Block

00000617 10/13
00000080 10/26/2020 16:25:06.3396463 [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
00000081 10/26/2020 16:1625:1106.21368053397114 [NetlinkWorkThreadget_max_agreeable_size] [NETLINKVOLUME:1898] bsr_info<6> [0xFFFFE000CCAC4880] bsr netlink cmd(BSR_ADM_DOWN:27) begin ->

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

Code Block

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

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

Code Block

00000683 10/13/2020 16:16:11.2535024 [FsctlFlushDismountVolume] [VOLUME:62 bsr 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:25:06.3397234 [get_max_agreeable_size] [VOLUME:99] 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 명령에서 순차적으로 수행하는 개별 동작 로그에 대해 설명합니다.

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

Code Block

00000398 10/26/2020 16:49:10.2436929 [NetlinkWorkThread] [NETLINK:18] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] try flush volume(\Device\HarddiskVolume2)
00000684 10/13/2020 16:16:11.2535729 [FsctlFlushDismountVolume] [VOLUME:63] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) flushed

...

BSR_ADM_DOWN:27 command has been received. Execute the command.

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

Code Block

0000068500000399 10/1326/2020 16:1649:1110.25357662437390 [FsctlFlushDismountVolumeFsctlLockVolume] [VOLUME:6465] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] try dismountlock volume(\Device\HarddiskVolume2)
0000068600000472 10/1326/2020 16:1649:1110.25598222864430 [FsctlFlushDismountVolumeFsctlLockVolume] [VOLUME:1923] bsr_info<6> [0xFFFFE000CCAC48800xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) dismounted

...

locked. handle(0xFFFFFFFF80000C20)

00000473 .. [VOLUME:62], 00000474 .. [STATEVOLUME:18] 로그는 down 시 role이 primary 일때 secondary 로 role을 변경 할때 출력됩니다63] 복제 볼륨에 대한 캐쉬 flush 를 수행합니다.

Code Block

0000068700000473 10/1326/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/1349:10.2864535 [FsctlFlushDismountVolume] [VOLUME:62] bsr_info<6> [0xFFFFE0012B2F9880] try flush volume(\Device\HarddiskVolume2)
00000474 10/26/2020 16:1649:1110.25682562864915 [__receive_uuidsFsctlFlushDismountVolume] [UUIDVOLUME:1663] bsr_warn<4>info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): receive new current but not update UUID: 83F530CA41FA9868
00000689 10/13[0xFFFFE0012B2F9880] volume(\Device\HarddiskVolume2) flushed

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

Code Block

00000475 10/26/2020 16:1649:1110.25683172864954 [bsr_uuid_compareFsctlFlushDismountVolume] [RESYNC/OVVOLUME:19764] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x2): Local and peer current UUIDs are the same. rule(40), res(0)

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

Code Block

00000690 10/13/2020 16:16:11.2569857 [FsctlUnlockVolume] [VOLUME:61] bsr_info<6> [0xFFFFE000CCAC4880] unlock volume(\Device\HarddiskVolume2)
00000691 10/13/2020 16:16:11.2576899 [FsctlUnlockVolume] [VOLUME:26] bsr_info<6> [0xFFFFE000CCAC4880] volume(\Device\HarddiskVolume2) unlocked
00000692 10/13/2020 16:16:11.2577179 [state_change_lock] [STATE:40] bsr_info<6> [0xFFFFE000CCAC4880] worker should not initiate state changes with CS_SERIALIZE current:FFFFF801707C9BD0 resource->worker.task:FFFFE000CDB38300

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

Code Block

00000693 10/13/2020 16:16:11.2577328 [change_cluster_wide_state] [TWOPC:34] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): Preparing cluster-wide state change 1834520240 (0->1 496/16)
00000694 10/13/2020 16:16:11.2577355 [change_cluster_wide_state] [TWOPC:35] bsr_info<6> bsr r0, r(Secondary), f(0x11), scf(0x28): [TWOPC:1834520240] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000695 10/13/2020 16:16:11.2580212[0xFFFFE0012B2F9880] try dismount volume(\Device\HarddiskVolume2)
00000479 10/26/2020 16:49:10.2871632 [FsctlFlushDismountVolume] [VOLUME:19] bsr_info<6> [0xFFFFE0012B2F9880] 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), f(0x1), scf(0x83c): change_role, role( Primary -> Secondary )
00000481 10/26/2020 16:49:10.2879558 [__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: CE5CC8B0672E645C
00000482 10/26/2020 16:49:10.2879607 [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)

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

Code Block

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

disconnect 를 수행합니다.

Code Block

00000486 10/26/2020 16:49:10.2890183 [change_cluster_wide_state] [TWOPC:3634] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x28): [TWOPC:1834520240] target_node_id(1) get_cluster_wide_reply (3) 
00000696 10/13Preparing cluster-wide state change 1805107054 (0->1 496/16)
00000487 10/26/2020 16:1649:1110.25802512890209 [change_cluster_wide_state] [TWOPC:3735] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x28): [TWOPC: State change 1834520240: primary_nodes=0, weak_nodes=0
00000697 10/131805107054] target_node_id(1) conn(Disconnecting) repl(-) disk(-) pdsk(-) role(-) peer(-) flags (8) 
00000488 10/26/2020 16:1649:1110.25802752893052 [change_cluster_wide_state] [TWOPC:3836] bsr_info<6> bsr r0 pnode-id:1, cs(Connected), prole(r(Secondary), cflagf(0x210e0x1), scf(0x28): Cluster is now split
00000698[TWOPC:1805107054] target_node_id(1) get_cluster_wide_reply (3) 
00000489 10/1326/2020 16:1649:1110.25803002893089 [change_cluster_wide_state] [TWOPC:3937] bsr_info<6> bsr r0, r(Secondary), f(0x110x1), scf(0x28): Committing cluster-wide stateState 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/131805107054: 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 [bsr_recvprint_allstate_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): completedThe 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
00000713connection object 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:FFFFE000CDB38300FFFFE0012C7D29A0

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

Code Block
0000071400000504 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 .. [UUID?:19] 로그는 detaching 시 대상 복제 볼륨에 설정되어있는 볼륨의 current UUID 가 출력됩니다.

Code Block

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

Code Block

0000059300000322 10/1326/2020 16:1448:0153.52737981027626 [__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: 7B326D963D9936CEA95D18E8D4AE8C78
0000059400000323 10/1326/2020 16:1448:0153.52738521027665 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20x0): Peer UUID and local bitmap UUID are the same. rule(70), res(2)

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

Code Block
0000059500000324 10/1326/2020 16:1448:0153.52754421029289 [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 00000325 .. [RESYNC/OV:65] 로그는 로컬 노드에 설정되어있는 UUID 정보가 로컬의 UUID가 출력됩니다.

Code Block

0000059600000325 10/1326/2020 16:1448:0153.52754811029330 [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 83F530CA41FA9869CE5CC8B0672E645D:7B326D963D9936CFA95D18E8D4AE8C78:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:87110 flags:12020

00000597 00000326 .. [RESYNC/OV:66] 로그는 피어 노드에 설정되어있는 UUID 정보가 피어의 UUID가 출력됩니다.

Code Block

0000059700000326 10/1326/2020 16:1448:0153.52755271029384 [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 7B326D963D9936CEA95D18E8D4AE8C78:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags:0100

00000598 00000327 .. [RESYNC/OV:202], 00000599 .. [RESYNC/OV:75] 로그는 로컬 노드와 피어 노드의 UUID 비교 후 ] 로컬과 피어의 uuid compare 결과가 출력됩니다.

Code Block

0000059800000327 10/1326/2020 16:1448:0153.52755681029433 [bsr_uuid_compare] [RESYNC/OV:202] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20x0): Peer UUID and local bitmap UUID are the same. rule(70), res(2)
0000059900000328 10/1326/2020 16:1448:0153.52755931029467 [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
0000060000000329 10/1326/2020 16:1448:0153.52756341029713 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(DUnknown), prpl(Off), pdvflag(0x100000): receiveReceive new repl state "WFBitMapS"
0000060100000330 10/1326/2020 16:1448:0153.52757811029830 [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 -> OutdatedConsistent ) repl( Off -> WFBitMapS )
0000060200000331 10/1326/2020 16:1448:0153.52774191030835 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20x0): send_bitmap (WFBitMapS), worker.task(FFFFE000CDB38300), current(FFFFE000CDB38300)
00000603 10/13.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:1448:0153.52979551048248 [receiveprint_state_change] [STATE:821] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(OutdatedConsistent), prpl(WFBitMapS), pdvflag(0x100600): receive new repl state "WFBitMapS"

...

_state, pdsk( Consistent -> Outdated )

00000334 .. [BITMAP:50] 로그는 로컬 노드의 비트맵을 로컬의 비트맵이 피어 노드에 전송 완료 시 출력됩니다되었습니다.

Code Block

0000060400000334 10/1326/2020 16:1448:0153.52993691049603 [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 5623(1), total 5623; compression: 100.0%

00000605 00000335 .. [BITMAP:50] 로그는 피어 노드의 비트맵을 로컬 노드가 비트맵이 로컬에서 수신 완료 시 출력됩니다되었습니다.

Code Block

0000060500000335 10/1326/2020 16:1448:0153.53218291065768 [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 5623(1), total 5623; compression: 100.0%

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

Code Block

0000060600000336 10/1326/2020 16:1448:0153.53218851065812 [receive_bitmap_finished] [BITMAP:52] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Outdated), prpl(WFBitMapS), pdvflag(0x100600): sendSend that bitmap exchange has been completed
0000060700000337 10/1326/2020 16:1448:0153.53235701066753 [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 00000338 .. [RESYNC/OV:144] 로그는 동기화가 시작되고 동기화 시작과 동기화 해야할 데이터 크기가 출력됩니다.

Code Block

0000060800000338 10/1326/2020 16:1448:0153.53240871067116 [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 348440 KB [87110 bits set]).
0000060900000339 10/1326/2020 16:1448:0153.53320031087501 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(Inconsistent), prpl(SyncSource), pdvflag(0x100600): receiveReceive new repl state "SyncSource"
0000061000000340 10/1326/2020 16:1448:1053.79328171170857 [__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: 83F530CA41FA9868CE5CC8B0672E645C
0000061100000341 10/1326/2020 16:1448:1053.79328811170913 [bsr_uuid_compare] [RESYNC/OV:197] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20x0): Local and peer current UUIDs are the same. rule(40), res(0)

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

00000612 .. 00000342 .. [UUID:1] 로그는 동기화 완료로 갱신되는 동기화 완료 후 새로 지정되는 UUID 정보가 출력됩니다.

Code Block

0000061200000342 10/1326/2020 16:1448:1053.79329221170949 [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 83F530CA41FA9869CE5CC8B0672E645D:0000000000000000:7B326D963D9936CEA95D18E8D4AE8C78:3DF87D1E1EFC3E92

00000613 .. [RESYNC/OV:116] 로그는 동기화 완료 후 동기화 진행 시간 및 초당 동기화 속도가 출력됩니다.

Code Block

0000061300000343 10/1326/2020 16:1448:1053.79391341180660 [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 91 sec; paused 0 sec; 38680 K/sec), hit bit (in sync 0; marked rl 0)
0000061400000344 10/1326/2020 16:1448:1053.79392951180792 [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 )
0000061500000345 10/1326/2020 16:1448:1053.79402751181716 [bsr_queue_bitmap_io] [RESYNC/OV:33] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(0x20x0): write from resync_finished, worker.task(FFFFE000CDB38300FFFFE0012C7D29A0), current(FFFFE000CDB38300FFFFE0012C7D29A0)
0000061600000346 10/1326/2020 16:1448:1053.79419941182718 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:1, pdsk(UpToDate), prpl(Established), pdvflag(0x100600): receiveReceive new repl state "Established"

synctarget

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

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

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

Code Block

0000008400000210 10/1326/2020 16:1448:01.3783975 [__receive_uuids] [UUID:16] bsr_warn<4>52.7780270 [bsr_uuid_compare] [RESYNC/OV:198] bsr_info<6> bsr r0/0 minor 2, ds(UpToDate), dvflag(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 pnode-id:0, pdskds(DUnknownUpToDate), prpldvflag(Off), pdvflag(0x100200)0x20000): __receive_uuids, newdisk( currentUpToDate but-> notOutdated update UUID: 83F530CA41FA9869
00000085 )
00000212 10/1326/2020 16:1448:0152.37844337789223 [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:
0000008600000213 10/1326/2020 16:1448:0152.37844847789252 [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 7B326D963D9936CEA95D18E8D4AE8C78:0000000000000000:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:0 flags:0100
0000008700000214 10/1326/2020 16:1448:0152.37845357789291 [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 83F530CA41FA9869CE5CC8B0672E645D:7B326D963D9936CFA95D18E8D4AE8C78:3DF87D1E1EFC3E92:3550951C1AA84A92 bits:87110 flags:12020
0000008800000215 10/1326/2020 16:1448:0152.37845897789328 [bsr_uuid_compare] [RESYNC/OV:198] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(0x00x20000): The local current UUID is the same as the peer bitmap UUID. rule(50), res(-2)
0000008900000216 10/1326/2020 16:1448:0152.37846267789352 [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
0000009000000217 10/1326/2020 16:1448:0152.37846827789384 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(DUnknown), prpl(Off), pdvflag(0x100200): receiveReceive new repl state "WFBitMapT"
0000009100000218 10/1326/2020 16:1448:0152.37848577789491 [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 )
0000009200000219 10/1326/2020 16:1448:0152.37854407790130 [w_after_state_change] [STATE:28] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): notNot sending state because of old replication repl_state(Off)
0000009300000220 10/1326/2020 16:1448:0152.37879837791844 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): receiveReceive new repl state "WFBitMapT"
0000009400000221 10/1326/2020 16:1448:0152.37884177797620 [w_after_state_change] [STATE:28] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): notNot sending state because of old repl_replication state(WFBitMapT)
0000009500000222 10/1326/2020 16:1448:0152.38071807798480 [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 5623(1), total 5623; compression: 100.0%
0000009600000223 10/1326/2020 16:1448:0152.38302867815593 [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 5623(1), total 5623; compression: 100.0%
0000009700000224 10/1326/2020 16:1448:0152.38310407815876 [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
0000009800000225 10/1326/2020 16:1448:0152.38336617817559 [receive_state] [STATE:8] bsr_info<6> bsr r0/0 minor 2 pnode-id:0, pdsk(UpToDate), prpl(WFBitMapT), pdvflag(0x100600): receiveReceive new repl state "WFBitMapT"
0000009900000226 10/1326/2020 16:1448:0152.38341757832750 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Outdated), dvflag(0x0): bsr_start_resync, disk( Outdated -> Inconsistent )
0000010000000227 10/1326/2020 16:1448:0152.38342127832782 [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 )
0000010100000228 10/1326/2020 16:1448:0152.38346827833043 [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 348440 KB [87110 bits set]).
0000010200000229 10/1326/2020 16:1448:0152.38411757838039 [__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: 83F530CA41FA9869CE5CC8B0672E645D

00000103 00000230 .. [RESYNC/OV:109107] 로그는 synctarget에서 동기화 데이터 요청을 syncsource에 모두 전송 했을때 출력됩니다.

Code Block

0000010300000230 10/1326/2020 16:1448:1052.63703167915051 [make_resync_request] [RESYNC/OV:109107] 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

...

Finished the resync. resync target area does not exist.

다음은 synctarget의 동기화 완료 로그입니다.

Code Block

0000010400000231 10/1326/2020 16:1448:1052.64365307918471 [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 91 sec; paused 0 sec; 38680 K/sec), hit bit (in sync 0; marked rl 0)
0000010500000232 10/1326/2020 16:1448:1052.64366137918549 [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 83F530CA41FA9868CE5CC8B0672E645C:0000000000000000:7B326D963D9936CEA95D18E8D4AE8C78:3DF87D1E1EFC3E92
0000010600000233 10/1326/2020 16:1448:1052.64367667918808 [print_state_change] [STATE:20] bsr_info<6> bsr r0/0 minor 2, ds(Inconsistent), dvflag(0x20004): bsr_resync_finished, disk( Inconsistent -> UpToDate )
0000010700000234 10/1326/2020 16:1448:1052.64367967918840 [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 )
0000010800000235 10/1326/2020 16:1448:1052.64417817927024 [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(FFFFE0016F4E7770FFFFE000E4CD8CF0), current(FFFFE0016F4E7770FFFFE000E4CD8CF0)

Versions Compared

Old Version 43

New Version Current

Key

목적

개요

동작

커널 로드

드라이버 기동

상태 변경

상태 변경

Netlink 명령

connect

disconnect

up

down 실행

down

동기화

syncsource

synctarget

Page Comparison

Versions Compared

Old Version 43

New Version Current

Key

목적

개요

동작

커널 로드

드라이버 기동

상태 변경

상태 변경

Netlink 명령

connect

disconnect

up

down 실행

down

동기화

syncsource

synctarget