Project

General

Profile

Actions
Copy link

Bug #48672

closed

unittest_seastar_messenger fails

Added by Xuehan Xu over 3 years ago. Updated almost 2 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Yingxin Cheng
Target version:
Ceph - v16.0.0
% Done:

0%

Source:
Community (dev)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

WARNING: debug mode. Not for benchmarking or production
WARN 2020-12-18 04:36:12,526 [shard 0] seastar - Unable to set SCHED_FIFO scheduling policy for timer thread; latency impact possible. Try adding CAP_SYS_NICE
INFO 2020-12-18 04:36:12,791 [shard 0] ms - test_echo(rounds=512, keepalive_ratio=0.1, v2=false):
INFO 2020-12-18 04:36:12,813 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2] bind: done
INFO 2020-12-18 04:36:12,828 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1] bind: done
INFO 2020-12-18 04:36:12,848 [shard 0] ms - [osd.3(client2) - >> osd.? v1:127.0.0.1:9031/1] write_event: delay ...
INFO 2020-12-18 04:36:12,855 [shard 0] ms - [osd.2(client1) - >> osd.? v1:127.0.0.1:9032/2] write_event: delay ...
INFO 2020-12-18 04:36:12,867 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1] learned myaddr=127.0.0.1:0/4 (unbound) from v1:127.0.0.1:55608/0
INFO 2020-12-18 04:36:12,868 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2] learned myaddr=127.0.0.1:0/3 (unbound) from v1:127.0.0.1:62588/0
INFO 2020-12-18 04:36:13,882 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2]: finished sending 512 pings with 48 keepalives
INFO 2020-12-18 04:36:13,886 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1]: finished sending 512 pings with 54 keepalives
INFO 2020-12-18 04:36:20,302 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1]: finished receiving 512 pongs
INFO 2020-12-18 04:36:20,304 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1]: handshake 0.074119021, pingpong 7.400657977
INFO 2020-12-18 04:36:20,313 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2]: finished receiving 512 pongs
INFO 2020-12-18 04:36:20,315 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2]: handshake 0.051159711, pingpong 7.407606128
INFO 2020-12-18 04:36:20,316 [shard 0] ms - client1 shutdown...
INFO 2020-12-18 04:36:20,317 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2] closing: reset no, replace no
WARN 2020-12-18 04:36:20,326 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2 >> osd.? v1:127.0.0.1:0/3@62588] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:20,327 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2 >> osd.? v1:127.0.0.1:0/3@62588] closing: reset yes, replace no
WARN 2020-12-18 04:36:20,327 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@62588 >> osd.? v1:127.0.0.1:9032/2] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:20,332 [shard 0] ms - client2 shutdown...
INFO 2020-12-18 04:36:20,334 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1] closing: reset no, replace no
WARN 2020-12-18 04:36:20,337 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1 >> osd.? v1:127.0.0.1:0/4@55608] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:20,338 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1 >> osd.? v1:127.0.0.1:0/4@55608] closing: reset yes, replace no
WARN 2020-12-18 04:36:20,340 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@55608 >> osd.? v1:127.0.0.1:9031/1] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:20,347 [shard 0] ms - server1 shutdown...
INFO 2020-12-18 04:36:20,353 [shard 0] ms - server2 shutdown...
INFO 2020-12-18 04:36:20,359 [shard 0] ms - test_echo() done!

INFO 2020-12-18 04:36:20,361 [shard 0] ms - test_echo(rounds=512, keepalive_ratio=0.1, v2=true):
INFO 2020-12-18 04:36:20,369 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1] bind: done
INFO 2020-12-18 04:36:20,370 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2] bind: done
INFO 2020-12-18 04:36:20,374 [shard 0] ms - [osd.3(client2) - >> osd.? v2:127.0.0.1:9033/1] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9033/1, peer_name=osd.?, cc=15823209544498107122 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO 2020-12-18 04:36:20,396 [shard 0] ms - [osd.3(client2) - >> osd.? v2:127.0.0.1:9033/1] write_event: delay ...
INFO 2020-12-18 04:36:20,397 [shard 0] ms - [osd.2(client1) - >> osd.? v2:127.0.0.1:9034/2] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9034/2, peer_name=osd.?, cc=16868673809930414960 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO 2020-12-18 04:36:20,397 [shard 0] ms - [osd.2(client1) - >> osd.? v2:127.0.0.1:9034/2] write_event: delay ...
INFO 2020-12-18 04:36:20,399 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> unknown.? @56542] ProtocolV2::start_accept(): target_addr=127.0.0.1:56542/0
INFO 2020-12-18 04:36:20,404 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> unknown.? -@50166] ProtocolV2::start_accept(): target_addr=127.0.0.1:50166/0
INFO 2020-12-18 04:36:20,452 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.? -@56542] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO 2020-12-18 04:36:20,458 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.? v2:127.0.0.1:9033/1] learned myaddr=127.0.0.1:0/4 (unbound) from v2:127.0.0.1:56542/0
INFO 2020-12-18 04:36:20,468 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.? v2:127.0.0.1:9034/2] learned myaddr=127.0.0.1:0/3 (unbound) from v2:127.0.0.1:50166/0
INFO 2020-12-18 04:36:20,475 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.? -@50166] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO 2020-12-18 04:36:20,566 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@56542] established: gs=0, pgs=1, cs=0, client_cookie=15823209544498107122, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO 2020-12-18 04:36:20,584 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1] connected: gs=1, pgs=1, cs=0, client_cookie=15823209544498107122, server_cookie=0, in_seq=0, out_seq=0, out_q=58
INFO 2020-12-18 04:36:20,628 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@50166] established: gs=0, pgs=1, cs=0, client_cookie=16868673809930414960, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO 2020-12-18 04:36:20,652 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2] connected: gs=1, pgs=1, cs=0, client_cookie=16868673809930414960, server_cookie=0, in_seq=0, out_seq=0, out_q=73
INFO 2020-12-18 04:36:24,374 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1]: finished sending 512 pings with 36 keepalives
INFO 2020-12-18 04:36:24,559 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2]: finished sending 512 pings with 55 keepalives
INFO 2020-12-18 04:36:43,543 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2]: finished receiving 512 pongs
INFO 2020-12-18 04:36:43,544 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2]: handshake 0.256535182, pingpong 22.890819045
INFO 2020-12-18 04:36:43,623 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1]: finished receiving 512 pongs
INFO 2020-12-18 04:36:43,624 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1]: handshake 0.212686808, pingpong 23.037972938
INFO 2020-12-18 04:36:43,624 [shard 0] ms - client1 shutdown...
INFO 2020-12-18 04:36:43,624 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2] closing: reset no, replace no
INFO 2020-12-18 04:36:43,626 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@50166 >> osd.1 v2:127.0.0.1:9034/2] execute_ready(): protocol aborted at CLOSING - std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,667 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@50166] execute_ready(): fault at READY on lossy channel, going to CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,667 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@50166] closing: reset yes, replace no
INFO 2020-12-18 04:36:43,669 [shard 0] ms - client2 shutdown...
INFO 2020-12-18 04:36:43,670 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1] closing: reset no, replace no
INFO 2020-12-18 04:36:43,671 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@56542] execute_ready(): fault at READY on lossy channel, going to CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,671 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@56542] closing: reset yes, replace no
INFO 2020-12-18 04:36:43,672 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@56542 >> osd.0 v2:127.0.0.1:9033/1] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,673 [shard 0] ms - server1 shutdown...
INFO 2020-12-18 04:36:43,709 [shard 0] ms - server2 shutdown...
INFO 2020-12-18 04:36:43,711 [shard 0] ms - test_echo() done!

INFO 2020-12-18 04:36:43,711 [shard 0] ms - test_concurrent_dispatch(v2=false):
INFO 2020-12-18 04:36:43,741 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5] bind: done
INFO 2020-12-18 04:36:43,753 [shard 0] ms - [osd.5(client3) - >> osd.? v1:127.0.0.1:9035/5] write_event: delay ...
INFO 2020-12-18 04:36:43,786 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59748 >> osd.? v1:127.0.0.1:9035/5] learned myaddr=127.0.0.1:0/6 (unbound) from v1:127.0.0.1:59748/0
INFO 2020-12-18 04:36:43,884 [shard 0] ms - client shutdown...
INFO 2020-12-18 04:36:43,887 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59748 >> osd.? v1:127.0.0.1:9035/5] closing: reset no, replace no
WARN 2020-12-18 04:36:43,899 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5 >> osd.? v1:127.0.0.1:0/6@59748] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,901 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5 >> osd.? v1:127.0.0.1:0/6@59748] closing: reset yes, replace no
WARN 2020-12-18 04:36:43,913 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59748 >> osd.? v1:127.0.0.1:9035/5] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:43,933 [shard 0] ms - server shutdown...
INFO 2020-12-18 04:36:43,949 [shard 0] ms - test_concurrent_dispatch() done!

INFO 2020-12-18 04:36:43,951 [shard 0] ms - test_concurrent_dispatch(v2=true):
INFO 2020-12-18 04:36:43,964 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5] bind: done
INFO 2020-12-18 04:36:43,970 [shard 0] ms - [osd.5(client3) - >> osd.? v2:127.0.0.1:9036/5] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9036/5, peer_name=osd.?, cc=901672323084127200 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO 2020-12-18 04:36:43,975 [shard 0] ms - [osd.5(client3) - >> osd.? v2:127.0.0.1:9036/5] write_event: delay ...
INFO 2020-12-18 04:36:43,989 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> unknown.? @59560] ProtocolV2::start_accept(): target_addr=127.0.0.1:59560/0
INFO 2020-12-18 04:36:44,057 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59560 >> osd.? v2:127.0.0.1:9036/5] learned myaddr=127.0.0.1:0/6 (unbound) from v2:127.0.0.1:59560/0
INFO 2020-12-18 04:36:44,064 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.? -@59560] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO 2020-12-18 04:36:44,148 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@59560] established: gs=0, pgs=1, cs=0, client_cookie=901672323084127200, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO 2020-12-18 04:36:44,164 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59560 >> osd.4 v2:127.0.0.1:9036/5] connected: gs=1, pgs=1, cs=0, client_cookie=901672323084127200, server_cookie=0, in_seq=0, out_seq=0, out_q=2
INFO 2020-12-18 04:36:44,203 [shard 0] ms - client shutdown...
INFO 2020-12-18 04:36:44,207 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59560 >> osd.4 v2:127.0.0.1:9036/5] closing: reset no, replace no
INFO 2020-12-18 04:36:44,219 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@59560] execute_ready(): fault at READY on lossy channel, going to CLOSING - std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:44,222 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@59560] closing: reset yes, replace no
INFO 2020-12-18 04:36:44,228 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@59560 >> osd.4 v2:127.0.0.1:9036/5] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:44,243 [shard 0] ms - server shutdown...
INFO 2020-12-18 04:36:44,261 [shard 0] ms - test_concurrent_dispatch() done!

INFO 2020-12-18 04:36:44,265 [shard 0] ms - test_preemptive_shutdown(v2=false):
INFO 2020-12-18 04:36:44,278 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7] bind: done
INFO 2020-12-18 04:36:44,288 [shard 0] ms - [osd.7(client4) - >> osd.? v1:127.0.0.1:9037/7] write_event: delay ...
INFO 2020-12-18 04:36:44,343 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64697 >> osd.? v1:127.0.0.1:9037/7] learned myaddr=127.0.0.1:0/8 (unbound) from v1:127.0.0.1:64697/0
INFO 2020-12-18 04:36:44,395 [shard 0] ms - client shutdown...
INFO 2020-12-18 04:36:44,398 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64697 >> osd.? v1:127.0.0.1:9037/7] closing: reset no, replace no
INFO 2020-12-18 04:36:44,411 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64697 >> osd.? v1:127.0.0.1:9037/7] write_event: dropped
WARN 2020-12-18 04:36:44,433 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64697 >> osd.? v1:127.0.0.1:9037/7] connecting fault: std::system_error (error crimson::net:4, read eof)
WARN 2020-12-18 04:36:44,455 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7 >> osd.? v1:127.0.0.1:0/8@64697] open fault: std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:44,457 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7 >> osd.? v1:127.0.0.1:0/8@64697] closing: reset yes, replace no
INFO 2020-12-18 04:36:44,480 [shard 0] ms - server shutdown...
INFO 2020-12-18 04:36:44,492 [shard 0] ms - test_preemptive_shutdown() done!

INFO 2020-12-18 04:36:44,493 [shard 0] ms - test_preemptive_shutdown(v2=true):
INFO 2020-12-18 04:36:44,502 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7] bind: done
INFO 2020-12-18 04:36:44,508 [shard 0] ms - [osd.7(client4) - >> osd.? v2:127.0.0.1:9038/7] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9038/7, peer_name=osd.?, cc=11383319140617739823 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO 2020-12-18 04:36:44,511 [shard 0] ms - [osd.7(client4) - >> osd.? v2:127.0.0.1:9038/7] write_event: delay ...
INFO 2020-12-18 04:36:44,520 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> unknown.? @62616] ProtocolV2::start_accept(): target_addr=127.0.0.1:62616/0
INFO 2020-12-18 04:36:44,615 [shard 0] ms - client shutdown...
INFO 2020-12-18 04:36:44,626 [shard 0] ms - [osd.7(client4) -@0 >> osd.? v2:127.0.0.1:9038/7] closing: reset no, replace no
INFO 2020-12-18 04:36:44,631 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.? -@62616] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO 2020-12-18 04:36:44,651 [shard 0] ms - [osd.7(client4) -@0 >> osd.? v2:127.0.0.1:9038/7] write_event: dropped
INFO 2020-12-18 04:36:44,664 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.? -@62616] execute_accepting(): fault at ACCEPTING, going to CLOSING - std::system_error (error crimson::net:4, read eof)
INFO 2020-12-18 04:36:44,666 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.? @62616] closing: reset no, replace no
INFO 2020-12-18 04:36:44,670 [shard 0] ms - [osd.7(client4) -@0 >> osd.? v2:127.0.0.1:9038/7] execute_connecting(): protocol aborted at CLOSING - std::system_error (error crimson::net:6, protocol aborted)
INFO 2020-12-18 04:36:44,710 [shard 0] ms - server shutdown...
INFO 2020-12-18 04:36:44,728 [shard 0] ms - test_preemptive_shutdown() done!

INFO 2020-12-18 04:36:44,731 [shard 0] ms - test_v2_protocol: start local TestPeer at v2:127.0.0.1:9013/0...
ERROR 2020-12-18 04:36:44,750 [shard 0] ms - FailoverTestPeer: there is another instance running at v2:127.0.0.1:9013/0
ERROR 2020-12-18 04:36:44,758 [shard 0] none - /home/jenkins-build/build/workspace/ceph-pull-requests/src/test/crimson/test_messenger.cc:1636 : In function '{anonymous}::FailoverTestPeer::init(entity_addr_t)::<lambda(const std::error_code&)>', abort(%s)
abort() called
Aborting on shard 0.
Backtrace:
/usr/lib/x86_64-linux-gnu/libasan.so.5+0x000000000006bb2f
0x000000000da2ffcc
0x000000000da0830f
0x000000000d8b89f6
0x000000000d8b8b69
0x000000000d91c909
0x000000000d9554d4
0x000000000d95556f
/lib/x86_64-linux-gnu/libpthread.so.0+0x000000000001289f
/lib/x86_64-linux-gnu/libc.so.6+0x000000000003ef46
/lib/x86_64-linux-gnu/libc.so.6+0x00000000000408b0
0x000000000d0f3212
0x000000000b0c1af7
0x000000000b237fc8
0x000000000b1b3b66
0x000000000b14c4b8
0x000000000b0c1bfa
0x000000000b29fe26
0x000000000b238044
0x000000000b1b3c19
0x000000000b14ca4f
0x000000000b29fec4
0x000000000b2380c0
0x000000000b1b3c95
0x000000000b14cf77
0x000000000b0c2746
0x000000000b0c2a97
0x000000000b23817e
0x000000000b1b3ec7
0x000000000b2a01d0
0x000000000b44b02f
0x000000000b425662
0x000000000b44b126
0x000000000b425117
0x000000000b52b4fa
0x000000000d900493
0x000000000d904ddd
0x000000000d90a673
0x000000000d77dcdc
0x000000000d77bba1
0x000000000d77c141
0x000000000b12788d
/lib/x86_64-linux-gnu/libc.so.6+0x0000000000021b96
0x000000000b0773d9

Files

consoleText.gz (135 KB) consoleText.gz Kefu Chai, 01/31/2021 04:09 AM
Actions
Copy link
 #1

Updated by Kefu Chai over 3 years ago 

184/213 Test #199: unittest-seastar-messenger ................***Exception: Child aborted 10.64 sec
WARNING: debug mode. Not for benchmarking or production
WARN  2020-12-20 17:38:16,500 [shard 0] seastar - Unable to set SCHED_FIFO scheduling policy for timer thread; latency impact possible. Try adding CAP_SYS_NICE
INFO  2020-12-20 17:38:16,696 [shard 0] ms - test_echo(rounds=512, keepalive_ratio=0.1, v2=false):
INFO  2020-12-20 17:38:16,704 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2] bind: done
INFO  2020-12-20 17:38:16,706 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1] bind: done
INFO  2020-12-20 17:38:16,711 [shard 0] ms - [osd.3(client2) - >> osd.? v1:127.0.0.1:9031/1] write_event: delay ...
INFO  2020-12-20 17:38:16,714 [shard 0] ms - [osd.2(client1) - >> osd.? v1:127.0.0.1:9032/2] write_event: delay ...
INFO  2020-12-20 17:38:16,738 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1] learned myaddr=127.0.0.1:0/4 (unbound) from v1:127.0.0.1:52599/0
INFO  2020-12-20 17:38:16,746 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2] learned myaddr=127.0.0.1:0/3 (unbound) from v1:127.0.0.1:55961/0
INFO  2020-12-20 17:38:17,980 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1]: finished sending 512 pings with 52 keepalives
INFO  2020-12-20 17:38:17,984 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2]: finished sending 512 pings with 63 keepalives
INFO  2020-12-20 17:38:21,693 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1]: finished receiving 512 pongs
INFO  2020-12-20 17:38:21,694 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1]: handshake 0.078464999, pingpong 4.906424702
INFO  2020-12-20 17:38:21,720 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2]: finished receiving 512 pongs
INFO  2020-12-20 17:38:21,720 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2]: handshake 0.082339291, pingpong 4.925561637
INFO  2020-12-20 17:38:21,721 [shard 0] ms - client1 shutdown...
INFO  2020-12-20 17:38:21,721 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2] closing: reset no, replace no
WARN  2020-12-20 17:38:21,722 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2 >> osd.? v1:127.0.0.1:0/3@55961] open fault: std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:21,722 [shard 0] ms - [osd.1(server2) v1:127.0.0.1:9032/2 >> osd.? v1:127.0.0.1:0/3@55961] closing: reset yes, replace no
WARN  2020-12-20 17:38:21,722 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@55961 >> osd.? v1:127.0.0.1:9032/2] open fault: std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:21,724 [shard 0] ms - client2 shutdown...
INFO  2020-12-20 17:38:21,724 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1] closing: reset no, replace no
WARN  2020-12-20 17:38:21,725 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@52599 >> osd.? v1:127.0.0.1:9031/1] open fault: std::system_error (error crimson::net:4, read eof)
WARN  2020-12-20 17:38:21,725 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1 >> osd.? v1:127.0.0.1:0/4@52599] open fault: std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:21,725 [shard 0] ms - [osd.0(server1) v1:127.0.0.1:9031/1 >> osd.? v1:127.0.0.1:0/4@52599] closing: reset yes, replace no
INFO  2020-12-20 17:38:21,726 [shard 0] ms - server1 shutdown...
INFO  2020-12-20 17:38:21,728 [shard 0] ms - server2 shutdown...
INFO  2020-12-20 17:38:21,729 [shard 0] ms - test_echo() done!

INFO  2020-12-20 17:38:21,729 [shard 0] ms - test_echo(rounds=512, keepalive_ratio=0.1, v2=true):
INFO  2020-12-20 17:38:21,731 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2] bind: done
INFO  2020-12-20 17:38:21,731 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1] bind: done
INFO  2020-12-20 17:38:21,732 [shard 0] ms - [osd.3(client2) - >> osd.? v2:127.0.0.1:9033/1] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9033/1, peer_name=osd.?, cc=13153731856599686624 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO  2020-12-20 17:38:21,732 [shard 0] ms - [osd.3(client2) - >> osd.? v2:127.0.0.1:9033/1] write_event: delay ...
INFO  2020-12-20 17:38:21,733 [shard 0] ms - [osd.2(client1) - >> osd.? v2:127.0.0.1:9034/2] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9034/2, peer_name=osd.?, cc=4554299212081085803 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO  2020-12-20 17:38:21,733 [shard 0] ms - [osd.2(client1) - >> osd.? v2:127.0.0.1:9034/2] write_event: delay ...
INFO  2020-12-20 17:38:21,735 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> unknown.? -@59702] ProtocolV2::start_accept(): target_addr=127.0.0.1:59702/0
INFO  2020-12-20 17:38:21,736 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> unknown.? -@57381] ProtocolV2::start_accept(): target_addr=127.0.0.1:57381/0
INFO  2020-12-20 17:38:21,747 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.? v2:127.0.0.1:9033/1] learned myaddr=127.0.0.1:0/4 (unbound) from v2:127.0.0.1:59702/0
INFO  2020-12-20 17:38:21,750 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.? -@59702] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO  2020-12-20 17:38:21,753 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.? v2:127.0.0.1:9034/2] learned myaddr=127.0.0.1:0/3 (unbound) from v2:127.0.0.1:57381/0
INFO  2020-12-20 17:38:21,754 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.? -@57381] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO  2020-12-20 17:38:21,768 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@57381] established: gs=0, pgs=1, cs=0, client_cookie=4554299212081085803, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO  2020-12-20 17:38:21,771 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2] connected: gs=1, pgs=1, cs=0, client_cookie=4554299212081085803, server_cookie=0, in_seq=0, out_seq=0, out_q=57
INFO  2020-12-20 17:38:21,862 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@59702] established: gs=0, pgs=1, cs=0, client_cookie=13153731856599686624, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO  2020-12-20 17:38:21,880 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1] connected: gs=1, pgs=1, cs=0, client_cookie=13153731856599686624, server_cookie=0, in_seq=0, out_seq=0, out_q=116
INFO  2020-12-20 17:38:22,479 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1]: finished sending 512 pings with 47 keepalives
INFO  2020-12-20 17:38:22,508 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2]: finished sending 512 pings with 58 keepalives
INFO  2020-12-20 17:38:25,494 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2]: finished receiving 512 pongs
INFO  2020-12-20 17:38:25,494 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2]: handshake 0.038903954, pingpong 3.722171466
INFO  2020-12-20 17:38:25,502 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1]: finished receiving 512 pongs
INFO  2020-12-20 17:38:25,503 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1]: handshake 0.148215056, pingpong 3.62261189
INFO  2020-12-20 17:38:25,503 [shard 0] ms - client1 shutdown...
INFO  2020-12-20 17:38:25,503 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2] closing: reset no, replace no
INFO  2020-12-20 17:38:25,504 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@57381] execute_ready(): fault at READY on lossy channel, going to CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,505 [shard 0] ms - [osd.1(server2) v2:127.0.0.1:9034/2 >> osd.2 127.0.0.1:0/3@57381] closing: reset yes, replace no
INFO  2020-12-20 17:38:25,505 [shard 0] ms - [osd.2(client1) 127.0.0.1:0/3@57381 >> osd.1 v2:127.0.0.1:9034/2] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,506 [shard 0] ms - client2 shutdown...
INFO  2020-12-20 17:38:25,507 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1] closing: reset no, replace no
INFO  2020-12-20 17:38:25,507 [shard 0] ms - [osd.3(client2) 127.0.0.1:0/4@59702 >> osd.0 v2:127.0.0.1:9033/1] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,508 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@59702] execute_ready(): fault at READY on lossy channel, going to CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,508 [shard 0] ms - [osd.0(server1) v2:127.0.0.1:9033/1 >> osd.3 127.0.0.1:0/4@59702] closing: reset yes, replace no
INFO  2020-12-20 17:38:25,509 [shard 0] ms - server1 shutdown...
INFO  2020-12-20 17:38:25,511 [shard 0] ms - server2 shutdown...
INFO  2020-12-20 17:38:25,512 [shard 0] ms - test_echo() done!

INFO  2020-12-20 17:38:25,512 [shard 0] ms - test_concurrent_dispatch(v2=false):
INFO  2020-12-20 17:38:25,513 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5] bind: done
INFO  2020-12-20 17:38:25,514 [shard 0] ms - [osd.5(client3) - >> osd.? v1:127.0.0.1:9035/5] write_event: delay ...
INFO  2020-12-20 17:38:25,520 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@57905 >> osd.? v1:127.0.0.1:9035/5] learned myaddr=127.0.0.1:0/6 (unbound) from v1:127.0.0.1:57905/0
INFO  2020-12-20 17:38:25,531 [shard 0] ms - client shutdown...
INFO  2020-12-20 17:38:25,531 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@57905 >> osd.? v1:127.0.0.1:9035/5] closing: reset no, replace no
WARN  2020-12-20 17:38:25,533 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@57905 >> osd.? v1:127.0.0.1:9035/5] open fault: std::system_error (error crimson::net:4, read eof)
WARN  2020-12-20 17:38:25,534 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5 >> osd.? v1:127.0.0.1:0/6@57905] open fault: std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,535 [shard 0] ms - [osd.4(server3) v1:127.0.0.1:9035/5 >> osd.? v1:127.0.0.1:0/6@57905] closing: reset yes, replace no
INFO  2020-12-20 17:38:25,538 [shard 0] ms - server shutdown...
INFO  2020-12-20 17:38:25,541 [shard 0] ms - test_concurrent_dispatch() done!

INFO  2020-12-20 17:38:25,542 [shard 0] ms - test_concurrent_dispatch(v2=true):
INFO  2020-12-20 17:38:25,544 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5] bind: done
INFO  2020-12-20 17:38:25,545 [shard 0] ms - [osd.5(client3) - >> osd.? v2:127.0.0.1:9036/5] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9036/5, peer_name=osd.?, cc=12840723286686088435 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO  2020-12-20 17:38:25,546 [shard 0] ms - [osd.5(client3) - >> osd.? v2:127.0.0.1:9036/5] write_event: delay ...
INFO  2020-12-20 17:38:25,548 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> unknown.? -@64063] ProtocolV2::start_accept(): target_addr=127.0.0.1:64063/0
INFO  2020-12-20 17:38:25,563 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.? -@64063] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO  2020-12-20 17:38:25,564 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@64063 >> osd.? v2:127.0.0.1:9036/5] learned myaddr=127.0.0.1:0/6 (unbound) from v2:127.0.0.1:64063/0
INFO  2020-12-20 17:38:25,614 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@64063] established: gs=0, pgs=1, cs=0, client_cookie=12840723286686088435, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO  2020-12-20 17:38:25,616 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@64063 >> osd.4 v2:127.0.0.1:9036/5] connected: gs=1, pgs=1, cs=0, client_cookie=12840723286686088435, server_cookie=0, in_seq=0, out_seq=0, out_q=2
INFO  2020-12-20 17:38:25,622 [shard 0] ms - client shutdown...
INFO  2020-12-20 17:38:25,623 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@64063 >> osd.4 v2:127.0.0.1:9036/5] closing: reset no, replace no
INFO  2020-12-20 17:38:25,625 [shard 0] ms - [osd.5(client3) 127.0.0.1:0/6@64063 >> osd.4 v2:127.0.0.1:9036/5] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,627 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@64063] execute_ready(): fault at READY on lossy channel, going to CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,628 [shard 0] ms - [osd.4(server3) v2:127.0.0.1:9036/5 >> osd.5 127.0.0.1:0/6@64063] closing: reset yes, replace no
INFO  2020-12-20 17:38:25,632 [shard 0] ms - server shutdown...
INFO  2020-12-20 17:38:25,636 [shard 0] ms - test_concurrent_dispatch() done!

INFO  2020-12-20 17:38:25,637 [shard 0] ms - test_preemptive_shutdown(v2=false):
INFO  2020-12-20 17:38:25,639 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7] bind: done
INFO  2020-12-20 17:38:25,641 [shard 0] ms - [osd.7(client4) - >> osd.? v1:127.0.0.1:9037/7] write_event: delay ...
INFO  2020-12-20 17:38:25,649 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64054 >> osd.? v1:127.0.0.1:9037/7] learned myaddr=127.0.0.1:0/8 (unbound) from v1:127.0.0.1:64054/0
INFO  2020-12-20 17:38:25,742 [shard 0] ms - client shutdown...
INFO  2020-12-20 17:38:25,743 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64054 >> osd.? v1:127.0.0.1:9037/7] closing: reset no, replace no
INFO  2020-12-20 17:38:25,744 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64054 >> osd.? v1:127.0.0.1:9037/7] write_event: dropped and set exit_open
WARN  2020-12-20 17:38:25,756 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@64054 >> osd.? v1:127.0.0.1:9037/7] open fault: std::system_error (error system:104, read: Connection reset by peer)
INFO  2020-12-20 17:38:25,766 [shard 0] ms - server shutdown...
INFO  2020-12-20 17:38:25,772 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7 >> osd.? v1:127.0.0.1:0/8@64054] closing: reset no, replace no
WARN  2020-12-20 17:38:25,888 [shard 0] ms - [osd.6(server4) v1:127.0.0.1:9037/7 >> osd.? v1:127.0.0.1:0/8@64054] open fault: std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:25,889 [shard 0] ms - test_preemptive_shutdown() done!

INFO  2020-12-20 17:38:25,889 [shard 0] ms - test_preemptive_shutdown(v2=true):
INFO  2020-12-20 17:38:25,891 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7] bind: done
INFO  2020-12-20 17:38:25,896 [shard 0] ms - [osd.7(client4) - >> osd.? v2:127.0.0.1:9038/7] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9038/7, peer_name=osd.?, cc=16032800350970142039 policy(lossy=true, server=false, standby=false, resetcheck=false)
INFO  2020-12-20 17:38:25,897 [shard 0] ms - [osd.7(client4) - >> osd.? v2:127.0.0.1:9038/7] write_event: delay ...
INFO  2020-12-20 17:38:25,898 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> unknown.? -@60812] ProtocolV2::start_accept(): target_addr=127.0.0.1:60812/0
INFO  2020-12-20 17:38:25,913 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@60812 >> osd.? v2:127.0.0.1:9038/7] learned myaddr=127.0.0.1:0/8 (unbound) from v2:127.0.0.1:60812/0
INFO  2020-12-20 17:38:25,914 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.? -@60812] UPDATE: peer_type=osd, policy(lossy=true server=true standby=false resetcheck=false)
INFO  2020-12-20 17:38:25,938 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.7 127.0.0.1:0/8@60812] established: gs=0, pgs=1, cs=0, client_cookie=16032800350970142039, server_cookie=0, in_seq=0, out_seq=0, out_q=0
INFO  2020-12-20 17:38:25,969 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@60812 >> osd.6 v2:127.0.0.1:9038/7] connected: gs=1, pgs=1, cs=0, client_cookie=16032800350970142039, server_cookie=0, in_seq=0, out_seq=0, out_q=67
INFO  2020-12-20 17:38:25,999 [shard 0] ms - client shutdown...
INFO  2020-12-20 17:38:25,999 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@60812 >> osd.6 v2:127.0.0.1:9038/7] closing: reset no, replace no
INFO  2020-12-20 17:38:26,004 [shard 0] ms - [osd.7(client4) 127.0.0.1:0/8@60812 >> osd.6 v2:127.0.0.1:9038/7] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:26,015 [shard 0] ms - server shutdown...
INFO  2020-12-20 17:38:26,022 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.7 127.0.0.1:0/8@60812] closing: reset no, replace no
INFO  2020-12-20 17:38:26,193 [shard 0] ms - [osd.6(server4) v2:127.0.0.1:9038/7 >> osd.7 127.0.0.1:0/8@60812] execute_ready(): protocol aborted at CLOSING -- std::system_error (error crimson::net:4, read eof)
INFO  2020-12-20 17:38:26,196 [shard 0] ms - test_preemptive_shutdown() done!

INFO  2020-12-20 17:38:26,197 [shard 0] ms - test_v2_protocol: start local TestPeer at v2:127.0.0.1:9013/0...
ERROR 2020-12-20 17:38:26,200 [shard 0] ms - FailoverTestPeer: there is another instance running at v2:127.0.0.1:9013/0
ERROR 2020-12-20 17:38:26,201 [shard 0] none - /home/jenkins-build/build/workspace/ceph-pull-requests/src/test/crimson/test_messenger.cc:1636 : In function '{anonymous}::FailoverTestPeer::init(entity_addr_t)::<lambda(const std::error_code&)>', abort(%s)
abort() called
Aborting on shard 0.
Backtrace:
  /usr/lib/x86_64-linux-gnu/libasan.so.5+0x000000000006bb2f
  0x000000000da3035c
  0x000000000da0869f
  0x000000000d8b8d86
  0x000000000d8b8ef9
  0x000000000d91cc99
  0x000000000d955864
  0x000000000d9558ff
  /lib/x86_64-linux-gnu/libpthread.so.0+0x000000000001289f
  /lib/x86_64-linux-gnu/libc.so.6+0x000000000003ef46
  /lib/x86_64-linux-gnu/libc.so.6+0x00000000000408b0
  0x000000000d0f35a4
  0x000000000b0c1d57
  0x000000000b238228
  0x000000000b1b3dc6
  0x000000000b14c718
  0x000000000b0c1e5a
  0x000000000b2a0086
  0x000000000b2382a4
  0x000000000b1b3e79
  0x000000000b14ccaf
  0x000000000b2a0124
  0x000000000b238320
  0x000000000b1b3ef5
  0x000000000b14d1d7
  0x000000000b0c29a6
  0x000000000b0c2cf7
  0x000000000b2383de
  0x000000000b1b4127
  0x000000000b2a0430
  0x000000000b44b28f
  0x000000000b4258c2
  0x000000000b44b386
  0x000000000b425377
  0x000000000b52b75a
  0x000000000d900823
  0x000000000d90516d
  0x000000000d90aa03
  0x000000000d77e06c
  0x000000000d77bf31
  0x000000000d77c4d1
  0x000000000b127aed
  /lib/x86_64-linux-gnu/libc.so.6+0x0000000000021b96
  0x000000000b077639
Actions
Copy link
 #2

Updated by Kefu Chai over 3 years ago

  • Assignee set to Yingxin Cheng

Yingxin, could you please take a look?

Actions
Copy link
 #3

Updated by Yingxin Cheng over 3 years ago

Maybe we can add a high-level seastar timer to abort the "another instance" after 300s timeout.

Actions
Copy link
 #5

Updated by Kefu Chai about 3 years ago

Yingxin, just attached a log where we have

INFO  2021-01-31 04:00:31,991 [shard 0] ms - [Test] client reconnect...
INFO  2021-01-31 04:00:31,994 [shard 0] ms - [Test] peer_connect_me(v2:127.0.0.1:9012/2)
ERROR 2021-01-31 04:00:32,026 [shard 0] ms - test_messenger timeout after 120s, abort! Consider to extend the period if the test is still running.
INFO  2021-01-31 04:00:32,065 [shard 0] ms - [osd.4(TestPeer) v2:127.0.0.1:9014/4@50564 >> osd.2 v2:127.0.0.1:9012/2] connected: gs=3, pgs=3, cs=0, client_cookie=1075705710413391785, server_cookie=6704935947889404640, in_seq=0, out_seq=0, out_q=0
INFO  2021-01-31 04:00:32,082 [shard 0] ms - [TestPeer] connect_peer(v2:127.0.0.1:9012/2)
INFO  2021-01-31 04:00:32,084 [shard 0] ms - [TestPeer] this is not a new session
Actions
Copy link
 #6

Updated by Yingxin Cheng about 3 years ago 

INFO  2021-01-31 03:58:32,182 [shard 0] ms - test_echo(rounds=512, keepalive_ratio=0.1, v2=false):
.... (~ 120 seconds) ...
INFO  2021-01-31 04:00:31,994 [shard 0] ms - [Test] peer_connect_me(v2:127.0.0.1:9012/2)
ERROR 2021-01-31 04:00:32,026 [shard 0] ms - test_messenger timeout after 120s, abort! Consider to extend the period if the test is still running.

The test looks normal, but it is running too slow and passing the 120s limit. Maybe other tests are competing the CPU cycles (see https://tracker.ceph.com/issues/49426), or consider to extend the 120s limit.

Actions
Copy link
 #7

Updated by Yingxin Cheng almost 2 years ago

  • Status changed from New to Resolved
Actions
Copy link

Also available in: Atom PDF