동작 로그

Owned by 한성원
Last updated: 2020/10/30 by SungEun Kim
17 min read

개요

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

동작

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

드라이버 기동

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

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

    • 윈도우즈 커널 드라이버는 시스템이 시작하는 시점에 기동합니다. 기동 시점의 로그 시간을 보면 시스템이 시작한 시간을 유추할 수 있습니다.

00000001 10/26/2020 16:24:42.7079617 [initRegistry] [DRIVER:63] bsr_info<6> [0xFFFFE0012A6BD880] registry_path[\Registry\Machine\System\CurrentControlSet\Services\bsr] 00000002 10/26/2020 16:24:42.7079678 [initRegistry] [DRIVER:64] bsr_info<6> [0xFFFFE0012A6BD880] bypass_level=0, read_filter=0, use_volume_lock=1, netlink_tcp_port=5678, daemon_tcp_port=5679, ver=1.5 00000003 10/26/2020 16:24:42.7080324 [wait_for_add_device] [LOG:10] bsr_info<6> [0xFFFFE0012A9DC300] 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/26/2020 16:24:42.7080380 [bsr_init] [DRIVER:78] bsr_info<6> [0xFFFFE0012A6BD880] 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/26/2020 16:24:42.7080400 [bsr_init] [DRIVER:79] bsr_info<6> [0xFFFFE0012A6BD880] 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의 상태가 변경될 때 발생하는 로그 입니다.

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

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

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

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

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

Netlink 명령

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

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

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

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

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

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

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: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> [0xFFFFE0012B2F9880] BSR_ADM_CONNECT:10 command has been received. Execute the command. ...//명령 수행 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)

connect

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

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

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

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

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

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

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

disconnect

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

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

up

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

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

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

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

  • connect 명령을 수행합니다.

down

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

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

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

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

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

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

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

  • disconnect 를 수행합니다.

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

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

동기화

syncsource

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

  • 00000324 .. [RESYNC/OV:73] 로컬 노드와 피어 노드의 동기화 핸드쉐이크를 시작합니다.

  • 00000325 .. [RESYNC/OV:65] 로컬의 UUID가 출력됩니다.

  • 00000326 .. [RESYNC/OV:66] 피어의 UUID가 출력됩니다.

  • 00000327 .. [RESYNC/OV:202], 00000599 .. [RESYNC/OV:75] 로컬과 피어의 uuid compare 결과가 출력됩니다.

  • 00000334 .. [BITMAP:50] 로컬의 비트맵이 피어 노드에 전송 완료 되었습니다.

  • 00000335 .. [BITMAP:50] 피어 노드의 비트맵이 로컬에서 수신 완료 되었습니다.

  • 00000336 .. [BITMAP:52] 비트맵 교환이 완료되었습니다.

  • 00000338 .. [RESYNC/OV:144] 동기화가 시작되고 동기화 해야할 데이터 크기가 출력됩니다.

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

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

synctarget

다음은 synctarget에서 동기화 시작 로그입니다.

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

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

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