incubator-pegasus
incubator-pegasus copied to clipboard
apache
Unit test broken down with unhandled error for load_from_private_log_test.ignore_useless while failed to write mutation log file header
While unit test load_from_private_log_test.ignore_useless was being executed, it failed to write mutation log file header then broken down with an unhandled error as follows (https://github.com/apache/incubator-pegasus/runs/7387575656?check_suite_focus=true) :
[----------] 9 tests from load_from_private_log_test
[ RUN ] load_from_private_log_test.find_log_file_to_start
E2022-07-18 11:42:36.540 (1658144556540112657 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
E2022-07-18 11:42:36.540 (1658144556540365771 9611) replica.default0.0000257e00010001: [1.1@] unable to start duplication since no log file is available
[ OK ] load_from_private_log_test.find_log_file_to_start (7 ms)
[ RUN ] load_from_private_log_test.start_duplication_10000_4MB
E2022-07-18 11:42:36.547 (1658144556547914109 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
W2022-07-18 11:42:36.586 (1658144556586599550 9615) replica.replica0.010100000000004f: [1.1@] duplication status hasn't been sync completed, try next for delay 1s, last_commit_decree=10010, confirmed_decree=-1
[ OK ] load_from_private_log_test.start_duplication_10000_4MB (1059 ms)
[ RUN ] load_from_private_log_test.start_duplication_50000_4MB
E2022-07-18 11:42:37.607 (1658144557607002977 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
W2022-07-18 11:42:37.756 (1658144557756301528 9615) replica.replica0.0101000000000078: [1.1@] duplication status hasn't been sync completed, try next for delay 1s, last_commit_decree=50010, confirmed_decree=-1
E2022-07-18 11:42:38.831 (1658144558831113007 9615) replica.replica0.0104000000000015: [1.1@] ERR_FILE_OPERATION_FAILED: open_read
[ OK ] load_from_private_log_test.start_duplication_50000_4MB (1312 ms)
[ RUN ] load_from_private_log_test.start_duplication_10000_1MB
E2022-07-18 11:42:38.918 (1658144558918401664 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
W2022-07-18 11:42:38.951 (1658144558951939108 9615) replica.replica0.0101000000000099: [1.1@] duplication status hasn't been sync completed, try next for delay 1s, last_commit_decree=10010, confirmed_decree=-1
[ OK ] load_from_private_log_test.start_duplication_10000_1MB (1055 ms)
[ RUN ] load_from_private_log_test.start_duplication_50000_1MB
E2022-07-18 11:42:39.974 (1658144559974081135 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
W2022-07-18 11:42:40.119 (1658144560119475359 9615) replica.replica0.01010000000000ef: [1.1@] duplication status hasn't been sync completed, try next for delay 1s, last_commit_decree=50010, confirmed_decree=-1
E2022-07-18 11:42:41.121 (1658144561121544023 9615) replica.replica0.010400000000006a: [1.1@] ERR_FILE_OPERATION_FAILED: open_read
[ OK ] load_from_private_log_test.start_duplication_50000_1MB (2256 ms)
[ RUN ] load_from_private_log_test.start_duplication_100000_4MB
E2022-07-18 11:42:42.230 (1658144562230087457 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
W2022-07-18 11:42:42.505 (1658144562505037289 9615) replica.replica0.0101000000000143: [1.1@] duplication status hasn't been sync completed, try next for delay 1s, last_commit_decree=100010, confirmed_decree=-1
[ OK ] load_from_private_log_test.start_duplication_100000_4MB (1478 ms)
[ RUN ] load_from_private_log_test.handle_real_private_log
E2022-07-18 11:42:43.707 (1658144563707902946 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
E2022-07-18 11:42:43.711 (1658144563711313344 9611) replica.default0.0000257e00010001: [1.4@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
E2022-07-18 11:42:43.712 (1658144563712498012 9611) replica.default0.0000257e00010001: [1.4@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
E2022-07-18 11:42:43.713 (1658144563713367463 9611) replica.default0.0000257e00010001: [1.5@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
[ OK ] load_from_private_log_test.handle_real_private_log (6 ms)
[ RUN ] load_from_private_log_test.restart_duplication
E2022-07-18 11:42:43.714 (1658144563714207711 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
[ OK ] load_from_private_log_test.restart_duplication (2 ms)
[ RUN ] load_from_private_log_test.ignore_useless
E2022-07-18 11:42:43.715 (1658144563715980514 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
E2022-07-18 11:42:43.719 (1658144563719703030 9612) replica.default1.010100000000017f: write failed with errno=Bad file descriptor, return ERR_FILE_OPERATION_FAILED.
E2022-07-18 11:42:43.719 (1658144563719734132 9612) replica.default1.010100000000017e: write mutation log file header failed, file = ./test-log/log.1.0, err = ERR_FILE_OPERATION_FAILED
F2022-07-18 11:42:43.719 (1658144563719739932 9612) replica.default1.010100000000017e: assertion expression: false
F2022-07-18 11:42:43.719 (1658144563719745333 9612) replica.default1.010100000000017e: unhandled error
Aborted (core dumped)
I2022-07-18 11:42:43.711 (1658144563711978682 9612) replica.default1.010400010000000a: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0104000100000009
I2022-07-18 11:42:43.711 (1658144563711983482 9612) replica.default1.010100010000006a: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010400010000000b
I2022-07-18 11:42:43.712 (1658144563712013784 9612) replica.default1.010400010000000e: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010400010000000d
I2022-07-18 11:42:43.712 (1658144563712023085 9612) replica.default1.010100010000006b: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010400010000000f
D2022-07-18 11:42:43.712 (1658144563712032385 9616) replica.replica1.010400010000000c: no next log file (log.2) is found
D2022-07-18 11:42:43.712 (1658144563712465010 9611) replica.default0.0000257e00010001: [1.4@] closing duplication {"dupid":1,"status":"DS_PAUSE","remote":"remote_address","confirmed":0,"app":"temp"}
E2022-07-18 11:42:43.712 (1658144563712493112 9611) replica.default0.0000257e00010001: [1.4@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
I2022-07-18 11:42:43.712 (1658144563712540415 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.712 (1658144563712544915 9611) replica.default0.0000257e00010001: performance counter replica*eon.replica*private.log.size(MB)@1.4 is removed, remaining reference (1)
D2022-07-18 11:42:43.712 (1658144563712547915 9611) replica.default0.0000257e00010001: 1.4@: replica closed, time_used = 0ms
I2022-07-18 11:42:43.712 (1658144563712550215 9611) replica.default0.0000257e00010001: 1.4@: replica destroyed
I2022-07-18 11:42:43.712 (1658144563712642621 9612) replica.default1.010100010000006c: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000150
D2022-07-18 11:42:43.712 (1658144563712650821 9611) replica.default0.0000257e00010001: open private log ./test-log/log.1.0 succeed, start_offset = 0, end_offset = 426, size = 426, previous_max_decree = 0
D2022-07-18 11:42:43.712 (1658144563712657521 9611) replica.default0.0000257e00010001: start to replay mutation log ./test-log/log.1.0, offset = [0, 426), size = 426
I2022-07-18 11:42:43.712 (1658144563712685423 9612) replica.default1.0101000000000152: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000151
I2022-07-18 11:42:43.712 (1658144563712697624 9612) replica.default1.010100010000006d: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000153
I2022-07-18 11:42:43.712 (1658144563712716125 9612) replica.default1.0101000000000155: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000154
I2022-07-18 11:42:43.712 (1658144563712724925 9612) replica.default1.010100010000006e: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000156
D2022-07-18 11:42:43.712 (1658144563712731126 9611) replica.default0.0000257e00010001: finish to replay mutation log (./test-log/log.1.0) [err: ERR_HANDLE_EOF: failed to read log block]
D2022-07-18 11:42:43.712 (1658144563712741826 9611) replica.default0.0000257e00010001: [1.4@] initialize replica_duplicator[DS_PAUSE] [dupid:1, meta_confirmed_decree:0]
D2022-07-18 11:42:43.712 (1658144563712779029 9611) replica.default0.0000257e00010001: add fail_point [name: open_read, task: Return(), frequency: 25%, max_count: 1]
D2022-07-18 11:42:43.712 (1658144563712796630 9611) replica.default0.0000257e00010001: add fail_point [name: mutation_log_read_log_block, task: Return(), frequency: 25%, max_count: 1]
D2022-07-18 11:42:43.712 (1658144563712811030 9611) replica.default0.0000257e00010001: add fail_point [name: duplication_sync_complete, task: Void(), frequency: 100%, max_count: -1]
I2022-07-18 11:42:43.712 (1658144563712870434 9612) replica.default1.010100010000006f: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0104000100000012
D2022-07-18 11:42:43.712 (1658144563712875934 9616) replica.replica1.0101000000000157: [1.4@] start loading from log file ./test-log/log.1.0
I2022-07-18 11:42:43.712 (1658144563712952939 9612) replica.default1.0104000100000017: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0104000100000016
I2022-07-18 11:42:43.712 (1658144563712957739 9612) replica.default1.0101000100000070: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0104000100000018
I2022-07-18 11:42:43.712 (1658144563712979140 9612) replica.default1.010400010000001b: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010400010000001a
I2022-07-18 11:42:43.712 (1658144563712988241 9612) replica.default1.0101000100000071: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010400010000001c
D2022-07-18 11:42:43.712 (1658144563712994041 9616) replica.replica1.0104000100000019: no next log file (log.2) is found
D2022-07-18 11:42:43.713 (1658144563713336261 9611) replica.default0.0000257e00010001: [1.4@] closing duplication {"dupid":1,"status":"DS_PAUSE","remote":"remote_address","confirmed":0,"app":"temp"}
E2022-07-18 11:42:43.713 (1658144563713362462 9611) replica.default0.0000257e00010001: [1.5@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
I2022-07-18 11:42:43.713 (1658144563713413365 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.713 (1658144563713418166 9611) replica.default0.0000257e00010001: performance counter �چ}�U is removed, remaining reference (0)
D2022-07-18 11:42:43.713 (1658144563713420966 9611) replica.default0.0000257e00010001: 1.4@: replica closed, time_used = 0ms
I2022-07-18 11:42:43.713 (1658144563713423166 9611) replica.default0.0000257e00010001: 1.4@: replica destroyed
I2022-07-18 11:42:43.713 (1658144563713507771 9612) replica.default1.0101000100000072: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000015a
D2022-07-18 11:42:43.713 (1658144563713517071 9611) replica.default0.0000257e00010001: open private log ./test-log/log.1.0 succeed, start_offset = 0, end_offset = 405, size = 405, previous_max_decree = 0
D2022-07-18 11:42:43.713 (1658144563713523272 9611) replica.default0.0000257e00010001: start to replay mutation log ./test-log/log.1.0, offset = [0, 405), size = 405
I2022-07-18 11:42:43.713 (1658144563713554473 9612) replica.default1.010100000000015c: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000015b
I2022-07-18 11:42:43.713 (1658144563713565974 9612) replica.default1.0101000100000073: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000015d
I2022-07-18 11:42:43.713 (1658144563713581775 9612) replica.default1.010100000000015f: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000015e
I2022-07-18 11:42:43.713 (1658144563713590476 9612) replica.default1.0101000100000074: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000160
D2022-07-18 11:42:43.713 (1658144563713596476 9611) replica.default0.0000257e00010001: finish to replay mutation log (./test-log/log.1.0) [err: ERR_HANDLE_EOF: failed to read log block]
D2022-07-18 11:42:43.713 (1658144563713606877 9611) replica.default0.0000257e00010001: [1.5@] initialize replica_duplicator[DS_PAUSE] [dupid:1, meta_confirmed_decree:0]
D2022-07-18 11:42:43.713 (1658144563713648279 9611) replica.default0.0000257e00010001: add fail_point [name: open_read, task: Return(), frequency: 25%, max_count: 1]
D2022-07-18 11:42:43.713 (1658144563713665780 9611) replica.default0.0000257e00010001: add fail_point [name: mutation_log_read_log_block, task: Return(), frequency: 25%, max_count: 1]
D2022-07-18 11:42:43.713 (1658144563713679981 9611) replica.default0.0000257e00010001: add fail_point [name: duplication_sync_complete, task: Void(), frequency: 100%, max_count: -1]
I2022-07-18 11:42:43.713 (1658144563713740984 9612) replica.default1.0101000100000075: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 01040000000000f7
D2022-07-18 11:42:43.713 (1658144563713746285 9615) replica.replica0.0101000000000161: [1.5@] start loading from log file ./test-log/log.1.0
I2022-07-18 11:42:43.713 (1658144563713845090 9612) replica.default1.01040000000000fc: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 01040000000000fb
I2022-07-18 11:42:43.713 (1658144563713850891 9612) replica.default1.0101000100000076: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 01040000000000fd
I2022-07-18 11:42:43.713 (1658144563713873792 9612) replica.default1.0104000000000100: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 01040000000000ff
I2022-07-18 11:42:43.713 (1658144563713882793 9612) replica.default1.0101000100000077: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0104000000000101
D2022-07-18 11:42:43.713 (1658144563713889093 9615) replica.replica0.01040000000000fe: no next log file (log.2) is found
D2022-07-18 11:42:43.713 (1658144563713918795 9611) replica.default0.0000257e00010001: [1.5@] closing duplication {"dupid":1,"status":"DS_PAUSE","remote":"remote_address","confirmed":0,"app":"temp"}
I2022-07-18 11:42:43.713 (1658144563713936196 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.713 (1658144563713940896 9611) replica.default0.0000257e00010001: performance counter �چ}�U is removed, remaining reference (0)
D2022-07-18 11:42:43.713 (1658144563713943596 9611) replica.default0.0000257e00010001: 1.5@: replica closed, time_used = 0ms
I2022-07-18 11:42:43.713 (1658144563713945796 9611) replica.default0.0000257e00010001: 1.5@: replica destroyed
D2022-07-18 11:42:43.713 (1658144563713950996 9611) replica.default0.0000257e00010001: close block service manager.
E2022-07-18 11:42:43.714 (1658144563714189910 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
D2022-07-18 11:42:43.715 (1658144563715030559 9611) replica.default0.0000257e00010001: [1.1@] initialize replica_duplicator[DS_PAUSE] [dupid:1, meta_confirmed_decree:-1]
D2022-07-18 11:42:43.715 (1658144563715095163 9611) replica.default0.0000257e00010001: create new log file ./test-log/log.1.0 succeed, time_used = 20201 ns
I2022-07-18 11:42:43.715 (1658144563715236171 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.715 (1658144563715308975 9612) replica.default1.0101000100000078: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000168
D2022-07-18 11:42:43.715 (1658144563715330876 9611) replica.default0.0000257e00010001: open private log ./test-log/log.1.0 succeed, start_offset = 0, end_offset = 1192, size = 1192, previous_max_decree = 0
D2022-07-18 11:42:43.715 (1658144563715336677 9611) replica.default0.0000257e00010001: start to replay mutation log ./test-log/log.1.0, offset = [0, 1192), size = 1192
I2022-07-18 11:42:43.715 (1658144563715361578 9612) replica.default1.010100000000016a: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000169
I2022-07-18 11:42:43.715 (1658144563715372179 9612) replica.default1.0101000100000079: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000016b
I2022-07-18 11:42:43.715 (1658144563715398780 9612) replica.default1.010100000000016d: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000016c
I2022-07-18 11:42:43.715 (1658144563715407581 9612) replica.default1.010100010000007a: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000016e
D2022-07-18 11:42:43.715 (1658144563715415881 9611) replica.default0.0000257e00010001: finish to replay mutation log (./test-log/log.1.0) [err: ERR_HANDLE_EOF: failed to read log block]
D2022-07-18 11:42:43.715 (1658144563715446583 9611) replica.default0.0000257e00010001: create new log file ./test-log/log.2.1192 succeed, time_used = 22301 ns
I2022-07-18 11:42:43.715 (1658144563715548889 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.715 (1658144563715658095 9612) replica.default1.010100010000007b: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000177
D2022-07-18 11:42:43.715 (1658144563715670496 9611) replica.default0.0000257e00010001: open private log ./test-log/log.2.1192 succeed, start_offset = 1192, end_offset = 2400, size = 1208, previous_max_decree = 10
D2022-07-18 11:42:43.715 (1658144563715675596 9611) replica.default0.0000257e00010001: start to replay mutation log ./test-log/log.2.1192, offset = [1192, 2400), size = 1208
I2022-07-18 11:42:43.715 (1658144563715699098 9612) replica.default1.0101000000000179: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 0101000000000178
I2022-07-18 11:42:43.715 (1658144563715704698 9612) replica.default1.010100010000007c: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000017a
I2022-07-18 11:42:43.715 (1658144563715741300 9612) replica.default1.010100000000017c: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000017b
I2022-07-18 11:42:43.715 (1658144563715749901 9612) replica.default1.010100010000007d: disk operation failure with code LPC_AIO_IMMEDIATE_CALLBACK, err = ERR_HANDLE_EOF, aio_task_id = 010100000000017d
D2022-07-18 11:42:43.715 (1658144563715760101 9611) replica.default0.0000257e00010001: finish to replay mutation log (./test-log/log.2.1192) [err: ERR_HANDLE_EOF: failed to read log block]
D2022-07-18 11:42:43.715 (1658144563715768702 9611) replica.default0.0000257e00010001: [1.1@] start loading from log file ./test-log/log.2.1192
I2022-07-18 11:42:43.715 (1658144563715771402 9611) replica.default0.0000257e00010001: close mutation log ./test-log
D2022-07-18 11:42:43.715 (1658144563715793603 9611) replica.default0.0000257e00010001: [1.1@] closing duplication {"dupid":1,"status":"DS_PAUSE","remote":"remote_address","confirmed":-1,"app":"temp"}
I2022-07-18 11:42:43.715 (1658144563715797904 9611) replica.default0.0000257e00010001: close mutation log ./test-log
I2022-07-18 11:42:43.715 (1658144563715801904 9611) replica.default0.0000257e00010001: performance counter pe�}�U is removed, remaining reference (0)
D2022-07-18 11:42:43.715 (1658144563715804904 9611) replica.default0.0000257e00010001: 1.1@: replica closed, time_used = 0ms
I2022-07-18 11:42:43.715 (1658144563715807204 9611) replica.default0.0000257e00010001: 1.1@: replica destroyed
D2022-07-18 11:42:43.715 (1658144563715812704 9611) replica.default0.0000257e00010001: close block service manager.
E2022-07-18 11:42:43.715 (1658144563715973014 9611) replica.default0.0000257e00010001: [1.1@] get disk tag of ./test-log failed: ERR_OBJECT_NOT_FOUND, init it to empty
D2022-07-18 11:42:43.716 (1658144563716446741 9611) replica.default0.0000257e00010001: [1.1@] initialize replica_duplicator[DS_PAUSE] [dupid:1, meta_confirmed_decree:-1]
D2022-07-18 11:42:43.716 (1658144563716862265 9611) replica.default0.0000257e00010001: create new log file ./test-log/log.1.0 succeed, time_used = 25101 ns
I2022-07-18 11:42:43.718 (1658144563718476459 9611) replica.default0.0000257e00010001: close mutation log ./test-log
E2022-07-18 11:42:43.719 (1658144563719684229 9612) replica.default1.010100000000017f: write failed with errno=Bad file descriptor, return ERR_FILE_OPERATION_FAILED.
I2022-07-18 11:42:43.719 (1658144563719706130 9612) replica.default1.010100000000017f: disk operation failure with code LPC_WRITE_REPLICATION_LOG_COMMON, err = ERR_FILE_OPERATION_FAILED, aio_task_id = 010100000000017e
E2022-07-18 11:42:43.719 (1658144563719729232 9612) replica.default1.010100000000017e: write mutation log file header failed, file = ./test-log/log.1.0, err = ERR_FILE_OPERATION_FAILED
F2022-07-18 11:42:43.719 (1658144563719736132 9612) replica.default1.010100000000017e: assertion expression: false
F2022-07-18 11:42:43.719 (1658144563719741632 9612) replica.default1.010100000000017e: unhandled error
ERROR: run dsn_replica_dup_test failed, return_code = 1
Error: Process completed with exit code 1.
