search

apache / incubator-pegasus

Apache Pegasus - A horizontally scalable, strongly consistent and high-performance key-value store
https://pegasus.apache.org/
Apache License 2.0
1.97k stars 313 forks source link

Unit test failed for tools_common.asio_network_provider_connection_threshold #1036

Open empiredan opened 2 years ago

empiredan commented 2 years ago

Unit test tools_common.asio_network_provider_connection_threshold sometimes failed for the following error:

[----------] 4 tests from tools_common
[ RUN      ] tools_common.asio_net_provider
[       OK ] tools_common.asio_net_provider (9 ms)
[ RUN      ] tools_common.asio_udp_provider
[       OK ] tools_common.asio_udp_provider (1007 ms)
[ RUN      ] tools_common.sim_net_provider
[       OK ] tools_common.sim_net_provider (6 ms)
[ RUN      ] tools_common.asio_network_provider_connection_threshold
/__w/incubator-pegasus/incubator-pegasus/rdsn/src/runtime/test/netprovider.cpp:95: Failure
Value of: ERR_TIMEOUT == ec
  Actual: false
Expected: true
[  FAILED  ] tools_common.asio_network_provider_connection_threshold (1078 ms)
[----------] 4 tests from tools_common (2100 ms total)

The messages from logging are as below: 

[  FAILED  ] 1 test, listed below:
[  FAILED  ] tools_common.asio_network_provider_connection_threshold
 1 FAILED TEST
dsn exit with code 1
run dsn_runtime_tests config-test.ini failed
---- ls ----
total 123528
drwxr-xr-x 3 root root      4096 Jul  6 07:34 CMakeFiles
-rw-r--r-- 1 root root     33775 Jul  6 07:34 Makefile
-rwxr-xr-x 1 root root      1238 Jul  6 07:34 clear.sh
-rw-r--r-- 1 root root      1320 Jul  6 07:34 cmake_install.cmake
-rw-r--r-- 1 root root       134 Jul  6 07:34 command.txt
-rw-r--r-- 1 root root      4068 Jul  6 07:34 config-test-corrupt-message.ini
-rw-r--r-- 1 root root      3416 Jul  6 07:34 config-test-sim.ini
-rw-r--r-- 1 root root      4210 Jul  6 07:34 config-test.ini
drwxr-xr-x 8 root root      4096 Jul  6 08:29 data
-rwxr-xr-x 1 root root 126408200 Jul  6 07:49 dsn_runtime_tests
-rw-r--r-- 1 root root       255 Jul  6 07:34 gtest.filter
-rwxr-xr-x 1 root root      2309 Jul  6 07:34 run.sh
./data/log/log.1.txt
---- tail -n 100 log.1.txt ----
W2022-07-06 08:29:50.739 (1657096190739289399 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: server_negotiation.cpp:137:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation failed, with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-07-06 08:29:50.739 (1657096190739366503 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-07-06 08:29:50.739 (1657096190739423206 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
W2022-07-06 08:29:50.739 (1657096190739454508 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: negotiation.cpp:65:check_status(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): get message(negotiation_select_mechanisms) while expect(negotiation_initiate)
D2022-07-06 08:29:50.739 (1657096190739507511 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-07-06 08:29:50.739 (1657096190739574915 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-07-06 08:29:50.739 (1657096190739613517 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-07-06 08:29:50.739 (1657096190739629218 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
W2022-07-06 08:29:50.739 (1657096190739644719 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: server_negotiation.cpp:151:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): retrive user name failed: with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-07-06 08:29:50.739 (1657096190739715122 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_SASL_INCOMPLETE), frequency: 100%, max_count: -1]
D2022-07-06 08:29:50.739 (1657096190739778426 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-07-06 08:29:50.739 (1657096190739833729 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
E2022-07-06 08:29:50.744 (1657096190744628594 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 14
E2022-07-06 08:29:50.744 (1657096190744640495 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 15
E2022-07-06 08:29:50.744 (1657096190744652295 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 16
E2022-07-06 08:29:50.744 (1657096190744664096 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 17
E2022-07-06 08:29:50.744 (1657096190744688497 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 18
E2022-07-06 08:29:50.744 (1657096190744709299 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 19
E2022-07-06 08:29:50.744 (1657096190744722599 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 20
E2022-07-06 08:29:50.744 (1657096190744734800 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 21
E2022-07-06 08:29:50.744 (1657096190744746701 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 22
E2022-07-06 08:29:50.744 (1657096190744765302 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 23
E2022-07-06 08:29:50.744 (1657096190744778302 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 24
E2022-07-06 08:29:50.744 (1657096190744793103 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 25
E2022-07-06 08:29:50.744 (1657096190744805704 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 26
E2022-07-06 08:29:50.744 (1657096190744[817](https://github.com/apache/incubator-pegasus/runs/7210178250?check_suite_focus=true#step:8:818)505 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 27
E2022-07-06 08:29:50.744 (1657096190744829305 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 28
E2022-07-06 08:29:50.744 (1657096190744841006 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 29
E2022-07-06 08:29:50.744 (1657096190744852807 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 30
E2022-07-06 08:29:50.744 (1657096190744870108 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 31
E2022-07-06 08:29:50.744 (16570961907448[828](https://github.com/apache/incubator-pegasus/runs/7210178250?check_suite_focus=true#step:8:829)08 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 32
E2022-07-06 08:29:50.744 (1657096190744894609 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 33
E2022-07-06 08:29:50.744 (1657096190744906310 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 34
E2022-07-06 08:29:50.744 (1657096190744992114 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 35
E2022-07-06 08:29:50.745 (1657096190745006915 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 36
E2022-07-06 08:29:50.745 (1657096190745024716 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 37
E2022-07-06 08:29:50.745 (1657096190745036717 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 38
E2022-07-06 08:29:50.745 (1657096190745059618 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 39
E2022-07-06 08:29:50.745 (1657096190745079419 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 40
E2022-07-06 08:29:50.745 (1657096190745091720 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 41
E2022-07-06 08:29:50.745 (1657096190745103420 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 42
E2022-07-06 08:29:50.745 (1657096190745115121 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 43
E2022-07-06 08:29:50.745 (1657096190745126922 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 44
E2022-07-06 08:29:50.745 (1657096190745138722 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 45
E2022-07-06 08:29:50.745 (1657096190745150523 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 46
E2022-07-06 08:29:50.745 (1657096190745166624 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 47
E2022-07-06 08:29:50.745 (1657096190745[833](https://github.com/apache/incubator-pegasus/runs/7210178250?check_suite_focus=true#step:8:834)261 4[841](https://github.com/apache/incubator-pegasus/runs/7210178250?check_suite_focus=true#step:8:842)) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 2
E2022-07-06 08:29:50.745 (16570961[907](https://github.com/apache/incubator-pegasus/runs/7210178250?check_suite_focus=true#step:8:908)45941667 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
E2022-07-06 08:29:50.746 (1657096190746741211 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
D2022-07-06 08:29:50.751 (1657096190751307364 4841) client.THREAD_POOL_DEFAULT0.000012d400010001: tracer.cpp:117:tracer_on_task_end(): LPC_CONTROL_SERVICE_APP EXEC END, task_id = 000012d400010001, err = ERR_OK
ERROR: run dsn_runtime_tests failed, return_code = 1
Error: Process completed with exit code 1.
empiredan commented 2 years ago

https://github.com/apache/incubator-pegasus/runs/7897027671?check_suite_focus=true

[----------] 4 tests from tools_common
[ RUN      ] tools_common.asio_net_provider
[       OK ] tools_common.asio_net_provider (11 ms)
[ RUN      ] tools_common.asio_udp_provider
[       OK ] tools_common.asio_udp_provider (1011 ms)
[ RUN      ] tools_common.sim_net_provider
[       OK ] tools_common.sim_net_provider (6 ms)
[ RUN      ] tools_common.asio_network_provider_connection_threshold
/__w/incubator-pegasus/incubator-pegasus/src/rdsn/src/runtime/test/netprovider.cpp:95: Failure
Value of: ERR_TIMEOUT == ec
  Actual: false
Expected: true
[  FAILED  ] tools_common.asio_network_provider_connection_threshold (1078 ms)
[----------] 4 tests from tools_common (2106 ms total)

......

[----------] Global test environment tear-down
[==========] 74 tests from 16 test cases ran. (6163 ms total)
[  PASSED  ] 73 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] tools_common.asio_network_provider_connection_threshold

 1 FAILED TEST
dsn exit with code 1
run dsn_runtime_tests config-test.ini failed
---- ls ----
total 124092
drwxr-xr-x 3 root root      4096 Aug 18 10:09 CMakeFiles
-rw-r--r-- 1 root root     36143 Aug 18 10:09 Makefile
-rwxr-xr-x 1 root root      1238 Aug 18 10:08 clear.sh
-rw-r--r-- 1 root root      1326 Aug 18 10:09 cmake_install.cmake
-rw-r--r-- 1 root root       134 Aug 18 10:08 command.txt
-rw-r--r-- 1 root root      4068 Aug 18 10:08 config-test-corrupt-message.ini
-rw-r--r-- 1 root root      3416 Aug 18 10:08 config-test-sim.ini
-rw-r--r-- 1 root root      4210 Aug 18 10:08 config-test.ini
drwxr-xr-x 8 root root      4096 Aug 18 11:16 data
-rwxr-xr-x 1 root root 126986272 Aug 18 10:12 dsn_runtime_tests
-rw-r--r-- 1 root root       255 Aug 18 10:08 gtest.filter
-rwxr-xr-x 1 root root      2309 Aug 18 10:08 run.sh
./data/log/log.1.txt
---- tail -n 100 log.1.txt ----
D2022-08-18 11:17:08.825 (1660821428825462404 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
W2022-08-18 11:17:08.825 (1660821428825506904 396) client.io-thrd.00396: server_negotiation.cpp:137:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation failed, with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.825 (1660821428825587105 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825640605 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
W2022-08-18 11:17:08.825 (1660821428825671006 396) client.io-thrd.00396: negotiation.cpp:65:check_status(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): get message(negotiation_select_mechanisms) while expect(negotiation_initiate)
D2022-08-18 11:17:08.825 (1660821428825724906 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825773907 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825810007 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.825 (1660821428825831707 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
W2022-08-18 11:17:08.825 (1660821428825847507 396) client.io-thrd.00396: server_negotiation.cpp:151:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): retrive user name failed: with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.825 (1660821428825922908 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_SASL_INCOMPLETE), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826001009 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826035109 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.826 (1660821428826107410 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826174110 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826206111 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.826 (1660821428826221211 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
D2022-08-18 11:17:08.826 (1660821428826233911 396) client.io-thrd.00396: server_negotiation.cpp:167:succ_negotiation(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation succeed
D2022-08-18 11:17:08.826 (1660821428826592714 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826661715 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826718416 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
W2022-08-18 11:17:08.826 (1660821428826754116 396) client.io-thrd.00396: server_negotiation.cpp:137:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation failed, with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.826 (1660821428826821917 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826865217 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
W2022-08-18 11:17:08.826 (1660821428826909517 396) client.io-thrd.00396: negotiation.cpp:65:check_status(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): get message(negotiation_select_mechanisms) while expect(negotiation_challenge_response)
D2022-08-18 11:17:08.826 (1660821428826967318 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827043419 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827075019 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827089919 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
W2022-08-18 11:17:08.827 (1660821428827104119 396) client.io-thrd.00396: server_negotiation.cpp:151:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): retrive user name failed: with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.827 (1660821428827153820 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_SASL_INCOMPLETE), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827227320 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827272021 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827347822 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827407822 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827438922 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827453023 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
D2022-08-18 11:17:08.827 (1660821428827465023 396) client.io-thrd.00396: server_negotiation.cpp:167:succ_negotiation(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation succeed
D2022-08-18 11:17:08.827 (1660821428827767325 396) client.io-thrd.00396: tracer.cpp:146:tracer_on_aio_enqueue(): LPC_TASK_TEST AIO.ENQUEUE, task_id = 0100018c00010038, queue size = 1
D2022-08-18 11:17:08.827 (1660821428827792326 396) client.io-thrd.00396.0100018c00010038: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c00010038
D2022-08-18 11:17:08.827 (1660821428827823326 396) client.io-thrd.00396.0100018c00010038: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c00010038, err = ERR_OK
D2022-08-18 11:17:08.827 (1660821428827965827 396) client.io-thrd.00396: tracer.cpp:69:tracer_on_task_create(): LPC_TASK_TEST CREATE, task_id = 0100018c00010039, type = TASK_TYPE_AIO
D2022-08-18 11:17:08.827 (1660821428827992628 396) client.io-thrd.00396: tracer.cpp:138:tracer_on_aio_call(): LPC_TASK_TEST AIO.CALL, task_id = 0100018c00010039, offset = 0, size = 128
D2022-08-18 11:17:08.828 (1660821428828007428 396) client.io-thrd.00396: tracer.cpp:69:tracer_on_task_create(): LPC_TASK_TEST CREATE, task_id = 0100018c0001003a, type = TASK_TYPE_AIO
D2022-08-18 11:17:08.828 (1660821428828034928 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c0001003a
D2022-08-18 11:17:08.828 (1660821428828057028 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:146:tracer_on_aio_enqueue(): LPC_TASK_TEST AIO.ENQUEUE, task_id = 0100018c00010039, queue size = 1
D2022-08-18 11:17:08.828 (1660821428828069528 279) client.THREAD_POOL_DEFAULT1.0100018c00010039: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c00010039
D2022-08-18 11:17:08.828 (1660821428828081128 279) client.THREAD_POOL_DEFAULT1.0100018c00010039: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c00010039, err = ERR_OK
D2022-08-18 11:17:08.828 (1660821428828091429 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c0001003a, err = ERR_OK
E2022-08-18 11:17:08.828 (1660821428828617434 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 0
E2022-08-18 11:17:08.828 (1660821428828647134 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 1
E2022-08-18 11:17:08.828 (1660821428828659934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 2
E2022-08-18 11:17:08.828 (1660821428828670934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 3
E2022-08-18 11:17:08.828 (1660821428828686034 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 4
E2022-08-18 11:17:08.828 (1660821428828698134 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 5
E2022-08-18 11:17:08.828 (1660821428828708934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 6
E2022-08-18 11:17:08.828 (1660821428828727935 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 7
E2022-08-18 11:17:08.828 (1660821428828739935 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 8
E2022-08-18 11:17:08.828 (1660821428828750735 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 9
E2022-08-18 11:17:08.828 (1660821428828761235 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 10
E2022-08-18 11:17:08.828 (1660821428828771835 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 11
E2022-08-18 11:17:08.828 (1660821428828782535 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 12
E2022-08-18 11:17:08.828 (1660821428828793035 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 13
E2022-08-18 11:17:08.828 (1660821428828803535 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 14
E2022-08-18 11:17:08.828 (1660821428828814035 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 15
E2022-08-18 11:17:08.828 (1660821428828828836 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 16
E2022-08-18 11:17:08.828 (1660821428828840736 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 17
E2022-08-18 11:17:08.828 (1660821428828851536 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 18
E2022-08-18 11:17:08.828 (1660821428828862336 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 19
E2022-08-18 11:17:08.828 (1660821428828872736 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 20
E2022-08-18 11:17:08.828 (1660821428828887836 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 21
E2022-08-18 11:17:08.828 (1660821428828909336 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 22
E2022-08-18 11:17:08.828 (1660821428828932737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 23
E2022-08-18 11:17:08.828 (1660821428828944737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 24
E2022-08-18 11:17:08.828 (1660821428828955237 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 25
E2022-08-18 11:17:08.828 (1660821428828965737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 26
E2022-08-18 11:17:08.828 (1660821428828976237 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 27
E2022-08-18 11:17:08.828 (1660821428828986637 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 28
E2022-08-18 11:17:08.828 (1660821428828997137 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 29
E2022-08-18 11:17:08.829 (1660821428829007637 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 30
E2022-08-18 11:17:08.829 (1660821428829043238 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 31
E2022-08-18 11:17:08.829 (1660821428829053938 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 32
E2022-08-18 11:17:08.829 (1660821428829074638 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 33
E2022-08-18 11:17:08.829 (1660821428829086238 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 34
E2022-08-18 11:17:08.829 (1660821428829151739 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 35
E2022-08-18 11:17:08.829 (1660821428829164639 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 36
E2022-08-18 11:17:08.829 (1660821428829179939 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 37
E2022-08-18 11:17:08.829 (1660821428829192539 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 38
E2022-08-18 11:17:08.829 (1660821428829203839 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 39
E2022-08-18 11:17:08.829 (1660821428829215239 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 40
E2022-08-18 11:17:08.829 (1660821428829226439 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 41
E2022-08-18 11:17:08.829 (1660821428829237939 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 42
E2022-08-18 11:17:08.829 (1660821428829259940 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 43
E2022-08-18 11:17:08.829 (1660821428829279240 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 44
E2022-08-18 11:17:08.829 (1660821428829291140 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 45
E2022-08-18 11:17:08.829 (1660821428829302440 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 46
E2022-08-18 11:17:08.829 (1660821428829313640 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 47
E2022-08-18 11:17:08.829 (1660821428829718544 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 2
E2022-08-18 11:17:08.829 (1660821428829813245 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
E2022-08-18 11:17:08.830 (1660821428830383750 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
Error: Process completed with exit code 1.
empiredan commented 2 years ago

https://github.com/apache/incubator-pegasus/runs/7897027671?check_suite_focus=true

[----------] 4 tests from tools_common
[ RUN      ] tools_common.asio_net_provider
[       OK ] tools_common.asio_net_provider (11 ms)
[ RUN      ] tools_common.asio_udp_provider
[       OK ] tools_common.asio_udp_provider (1011 ms)
[ RUN      ] tools_common.sim_net_provider
[       OK ] tools_common.sim_net_provider (6 ms)
[ RUN      ] tools_common.asio_network_provider_connection_threshold
/__w/incubator-pegasus/incubator-pegasus/src/rdsn/src/runtime/test/netprovider.cpp:95: Failure
Value of: ERR_TIMEOUT == ec
  Actual: false
Expected: true
[  FAILED  ] tools_common.asio_network_provider_connection_threshold (1078 ms)
[----------] 4 tests from tools_common (2106 ms total)

......

[----------] Global test environment tear-down
[==========] 74 tests from 16 test cases ran. (6163 ms total)
[  PASSED  ] 73 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] tools_common.asio_network_provider_connection_threshold

 1 FAILED TEST
dsn exit with code 1
run dsn_runtime_tests config-test.ini failed
---- ls ----
total 124092
drwxr-xr-x 3 root root      4096 Aug 18 10:09 CMakeFiles
-rw-r--r-- 1 root root     36143 Aug 18 10:09 Makefile
-rwxr-xr-x 1 root root      1238 Aug 18 10:08 clear.sh
-rw-r--r-- 1 root root      1326 Aug 18 10:09 cmake_install.cmake
-rw-r--r-- 1 root root       134 Aug 18 10:08 command.txt
-rw-r--r-- 1 root root      4068 Aug 18 10:08 config-test-corrupt-message.ini
-rw-r--r-- 1 root root      3416 Aug 18 10:08 config-test-sim.ini
-rw-r--r-- 1 root root      4210 Aug 18 10:08 config-test.ini
drwxr-xr-x 8 root root      4096 Aug 18 11:16 data
-rwxr-xr-x 1 root root 126986272 Aug 18 10:12 dsn_runtime_tests
-rw-r--r-- 1 root root       255 Aug 18 10:08 gtest.filter
-rwxr-xr-x 1 root root      2309 Aug 18 10:08 run.sh
./data/log/log.1.txt
---- tail -n 100 log.1.txt ----
D2022-08-18 11:17:08.825 (1660821428825462404 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
W2022-08-18 11:17:08.825 (1660821428825506904 396) client.io-thrd.00396: server_negotiation.cpp:137:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation failed, with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.825 (1660821428825587105 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825640605 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
W2022-08-18 11:17:08.825 (1660821428825671006 396) client.io-thrd.00396: negotiation.cpp:65:check_status(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): get message(negotiation_select_mechanisms) while expect(negotiation_initiate)
D2022-08-18 11:17:08.825 (1660821428825724906 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825773907 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.825 (1660821428825810007 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.825 (1660821428825831707 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
W2022-08-18 11:17:08.825 (1660821428825847507 396) client.io-thrd.00396: server_negotiation.cpp:151:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): retrive user name failed: with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.825 (1660821428825922908 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_SASL_INCOMPLETE), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826001009 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826035109 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.826 (1660821428826107410 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_start, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826174110 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826206111 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_start
D2022-08-18 11:17:08.826 (1660821428826221211 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
D2022-08-18 11:17:08.826 (1660821428826233911 396) client.io-thrd.00396: server_negotiation.cpp:167:succ_negotiation(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation succeed
D2022-08-18 11:17:08.826 (1660821428826592714 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826661715 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826718416 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
W2022-08-18 11:17:08.826 (1660821428826754116 396) client.io-thrd.00396: server_negotiation.cpp:137:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation failed, with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.826 (1660821428826821917 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.826 (1660821428826865217 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
W2022-08-18 11:17:08.826 (1660821428826909517 396) client.io-thrd.00396: negotiation.cpp:65:check_status(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): get message(negotiation_select_mechanisms) while expect(negotiation_challenge_response)
D2022-08-18 11:17:08.826 (1660821428826967318 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827043419 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_TIMEOUT), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827075019 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827089919 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
W2022-08-18 11:17:08.827 (1660821428827104119 396) client.io-thrd.00396: server_negotiation.cpp:151:do_challenge(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): retrive user name failed: with err = ERR_TIMEOUT, msg = ERR_TIMEOUT
D2022-08-18 11:17:08.827 (1660821428827153820 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_SASL_INCOMPLETE), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827227320 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827272021 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827347822 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_server_wrapper_step, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827407822 396) client.io-thrd.00396: fail_point.cpp:79:cfg(): add fail_point [name: sasl_wrapper_retrieve_username, task: Return(ERR_OK), frequency: 100%, max_count: -1]
D2022-08-18 11:17:08.827 (1660821428827438922 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_server_wrapper_step
D2022-08-18 11:17:08.827 (1660821428827453023 396) client.io-thrd.00396: fail_point.cpp:155:eval(): fail on sasl_wrapper_retrieve_username
D2022-08-18 11:17:08.827 (1660821428827465023 396) client.io-thrd.00396: server_negotiation.cpp:167:succ_negotiation(): SERVER_NEGOTIATION(CLIENT=127.0.0.1:10086): negotiation succeed
D2022-08-18 11:17:08.827 (1660821428827767325 396) client.io-thrd.00396: tracer.cpp:146:tracer_on_aio_enqueue(): LPC_TASK_TEST AIO.ENQUEUE, task_id = 0100018c00010038, queue size = 1
D2022-08-18 11:17:08.827 (1660821428827792326 396) client.io-thrd.00396.0100018c00010038: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c00010038
D2022-08-18 11:17:08.827 (1660821428827823326 396) client.io-thrd.00396.0100018c00010038: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c00010038, err = ERR_OK
D2022-08-18 11:17:08.827 (1660821428827965827 396) client.io-thrd.00396: tracer.cpp:69:tracer_on_task_create(): LPC_TASK_TEST CREATE, task_id = 0100018c00010039, type = TASK_TYPE_AIO
D2022-08-18 11:17:08.827 (1660821428827992628 396) client.io-thrd.00396: tracer.cpp:138:tracer_on_aio_call(): LPC_TASK_TEST AIO.CALL, task_id = 0100018c00010039, offset = 0, size = 128
D2022-08-18 11:17:08.828 (1660821428828007428 396) client.io-thrd.00396: tracer.cpp:69:tracer_on_task_create(): LPC_TASK_TEST CREATE, task_id = 0100018c0001003a, type = TASK_TYPE_AIO
D2022-08-18 11:17:08.828 (1660821428828034928 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c0001003a
D2022-08-18 11:17:08.828 (1660821428828057028 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:146:tracer_on_aio_enqueue(): LPC_TASK_TEST AIO.ENQUEUE, task_id = 0100018c00010039, queue size = 1
D2022-08-18 11:17:08.828 (1660821428828069528 279) client.THREAD_POOL_DEFAULT1.0100018c00010039: tracer.cpp:87:tracer_on_task_begin(): LPC_TASK_TEST EXEC BEGIN, task_id = 0100018c00010039
D2022-08-18 11:17:08.828 (1660821428828081128 279) client.THREAD_POOL_DEFAULT1.0100018c00010039: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c00010039, err = ERR_OK
D2022-08-18 11:17:08.828 (1660821428828091429 279) client.THREAD_POOL_DEFAULT1.0100018c0001003a: tracer.cpp:117:tracer_on_task_end(): LPC_TASK_TEST EXEC END, task_id = 0100018c0001003a, err = ERR_OK
E2022-08-18 11:17:08.828 (1660821428828617434 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 0
E2022-08-18 11:17:08.828 (1660821428828647134 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 1
E2022-08-18 11:17:08.828 (1660821428828659934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 2
E2022-08-18 11:17:08.828 (1660821428828670934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 3
E2022-08-18 11:17:08.828 (1660821428828686034 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 4
E2022-08-18 11:17:08.828 (1660821428828698134 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 5
E2022-08-18 11:17:08.828 (1660821428828708934 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 6
E2022-08-18 11:17:08.828 (1660821428828727935 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 7
E2022-08-18 11:17:08.828 (1660821428828739935 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 8
E2022-08-18 11:17:08.828 (1660821428828750735 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 9
E2022-08-18 11:17:08.828 (1660821428828761235 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 10
E2022-08-18 11:17:08.828 (1660821428828771835 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 11
E2022-08-18 11:17:08.828 (1660821428828782535 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 12
E2022-08-18 11:17:08.828 (1660821428828793035 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 13
E2022-08-18 11:17:08.828 (1660821428828803535 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 14
E2022-08-18 11:17:08.828 (1660821428828814035 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 15
E2022-08-18 11:17:08.828 (1660821428828828836 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 16
E2022-08-18 11:17:08.828 (1660821428828840736 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 17
E2022-08-18 11:17:08.828 (1660821428828851536 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 18
E2022-08-18 11:17:08.828 (1660821428828862336 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 19
E2022-08-18 11:17:08.828 (1660821428828872736 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 20
E2022-08-18 11:17:08.828 (1660821428828887836 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 21
E2022-08-18 11:17:08.828 (1660821428828909336 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 22
E2022-08-18 11:17:08.828 (1660821428828932737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 23
E2022-08-18 11:17:08.828 (1660821428828944737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 24
E2022-08-18 11:17:08.828 (1660821428828955237 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 25
E2022-08-18 11:17:08.828 (1660821428828965737 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 26
E2022-08-18 11:17:08.828 (1660821428828976237 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 27
E2022-08-18 11:17:08.828 (1660821428828986637 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 28
E2022-08-18 11:17:08.828 (1660821428828997137 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 29
E2022-08-18 11:17:08.829 (1660821428829007637 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 30
E2022-08-18 11:17:08.829 (1660821428829043238 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 31
E2022-08-18 11:17:08.829 (1660821428829053938 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 32
E2022-08-18 11:17:08.829 (1660821428829074638 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 33
E2022-08-18 11:17:08.829 (1660821428829086238 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 34
E2022-08-18 11:17:08.829 (1660821428829151739 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 35
E2022-08-18 11:17:08.829 (1660821428829164639 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 36
E2022-08-18 11:17:08.829 (1660821428829179939 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 37
E2022-08-18 11:17:08.829 (1660821428829192539 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 38
E2022-08-18 11:17:08.829 (1660821428829203839 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 39
E2022-08-18 11:17:08.829 (1660821428829215239 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 40
E2022-08-18 11:17:08.829 (1660821428829226439 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 41
E2022-08-18 11:17:08.829 (1660821428829237939 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 42
E2022-08-18 11:17:08.829 (1660821428829259940 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 43
E2022-08-18 11:17:08.829 (1660821428829279240 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 44
E2022-08-18 11:17:08.829 (1660821428829291140 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 45
E2022-08-18 11:17:08.829 (1660821428829302440 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 46
E2022-08-18 11:17:08.829 (1660821428829313640 396) client.io-thrd.00396: thrift_message_parser.cpp:166:parse_request_header(): hdr_length should be 48, but 47
E2022-08-18 11:17:08.829 (1660821428829718544 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 2
E2022-08-18 11:17:08.829 (1660821428829813245 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
E2022-08-18 11:17:08.830 (1660821428830383750 396) client.io-thrd.00396: thrift_message_parser.cpp:113:create_message_from_request_blob(): invalid message type: 65
Error: Process completed with exit code 1.