Bug #57693
Messenger test failed against test_messenger_peer.cc
% Done:
0%
Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
[test_v2_peer_reuse_connector]
INFO 2022-09-28 15:31:54,106 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2] try_bind: done
INFO 2022-09-28 15:31:54,106 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2] try_bind: done
INFO 2022-09-28 15:31:54,112 [shard 0] ms - -- 0 --
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [Test] setup connection...
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [Test] connect_peer(v2:127.0.0.1:9014/4)
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -] new connection registered
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9014/4, peer_name=osd.?, cc=6443144342505288030 policy(lossy=false, server=false, standby=true, resetcheck=true)
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [Test] this is a new session
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [Test] send_peer()
INFO 2022-09-28 15:31:54,112 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] write_event: delay ...
INFO 2022-09-28 15:31:54,113 [shard 0] ms - [Test] connect_attempts=1
INFO 2022-09-28 15:31:54,113 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] intercepted SOCKET_CONNECTING(1)
INFO 2022-09-28 15:31:54,113 [shard 0] ms - [Test] peer_send_me()
INFO 2022-09-28 15:31:54,113 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted BANNER_WRITE(1)
INFO 2022-09-28 15:31:54,114 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted BANNER_READ(1)
INFO 2022-09-28 15:31:54,114 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted BANNER_PAYLOAD_READ(1)
INFO 2022-09-28 15:31:54,114 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted HELLO_WRITE(1)
INFO 2022-09-28 15:31:54,115 [shard 0] ms - [Test] wait_result(1) ...
INFO 2022-09-28 15:31:54,115 [shard 0] ms - [Test] wait_ready(): wait for connections, currently 1 out of 1, pending 1 ready ...
INFO 2022-09-28 15:31:54,115 [shard 0] ms - [Test] wait_ready(): wait for pending_send=0, pending_peer_receive=1, pending_receive=1, pending 1/0 ready/establish connections ...
INFO 2022-09-28 15:31:54,115 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted HELLO_READ(1)
INFO 2022-09-28 15:31:54,115 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted AUTH_REQUEST_WRITE(1)
INFO 2022-09-28 15:31:54,116 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted AUTH_DONE_READ(1)
INFO 2022-09-28 15:31:54,116 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted AUTH_SIGNATURE_WRITE(1)
INFO 2022-09-28 15:31:54,117 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted AUTH_SIGNATURE_READ(1)
INFO 2022-09-28 15:31:54,117 [shard 0] ms - [Test] client_connect_attempts=1
INFO 2022-09-28 15:31:54,117 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted CLIENT_IDENT_WRITE(1)
INFO 2022-09-28 15:31:54,117 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.? v2:127.0.0.1:9014/4] intercepted SERVER_IDENT_READ(1)
INFO 2022-09-28 15:31:54,118 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] connected: gs=1, pgs=1, cs=0, client_cookie=6443144342505288030, server_cookie=3783573194457186916, in_seq=0, out_seq=0, out_q=1
INFO 2022-09-28 15:31:54,118 [shard 0] ms - [Test] got connected (cnt_connect_dispatched=1) -- [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4]
INFO 2022-09-28 15:31:54,118 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] ready
INFO 2022-09-28 15:31:54,118 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] intercepted MESSAGE_WRITE(1)
INFO 2022-09-28 15:31:54,118 [shard 0] ms - [Test] wait_ready(): wait for pending_send=0, pending_peer_receive=1, pending_receive=1, pending 0/1 ready/establish connections ...
INFO 2022-09-28 15:31:54,119 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] intercepted MESSAGE_READ(1)
INFO 2022-09-28 15:31:54,119 [shard 0] ms - [Test] TestPeer said got op, left 0 ops
INFO 2022-09-28 15:31:54,119 [shard 0] ms - [Test] wait_ready(): wait for pending_send=0, pending_peer_receive=0, pending_receive=1, pending 0/1 ready/establish connections ...
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] intercepted ACK_WRITE(1)
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] got op, left 0 ops -- [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4]
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] wait_ready(): wait done!
INFO 2022-09-28 15:31:54,120 [shard 0] ms - -- 1 --
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] connector markdown...
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] markdown()
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] closing: reset no, replace no
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] connect_peer(v2:127.0.0.1:9014/4)
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [1] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -] new connection registered
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] ProtocolV2::start_connect(): peer_addr=v2:127.0.0.1:9014/4, peer_name=osd.?, cc=1173209242574536960 policy(lossy=false, server=false, standby=true, resetcheck=true)
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] this is a new session replacing an closed one
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [Test] connect_attempts=1
INFO 2022-09-28 15:31:54,120 [shard 0] ms - [1] [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] intercepted SOCKET_CONNECTING(2)
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [Test] send_peer()
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2 >> osd.? v2:127.0.0.1:9014/4] write_event: delay ...
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] write_event: nothing queued at drop, set exit_open
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [2] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -] new connection registered
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -@54022] ProtocolV2::start_accept(): target_addr=v2:127.0.0.1:54022/0
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [Test] accept_attempts=1
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [2] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -@54022] intercepted SOCKET_ACCEPTED(1)
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [2] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -@54022] intercepted BANNER_WRITE(2)
INFO 2022-09-28 15:31:54,121 [shard 0] ms - [Test] wait_result(2) ...
INFO 2022-09-28 15:31:54,122 [shard 0] ms - [2] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -@54022] intercepted BANNER_READ(2)
INFO 2022-09-28 15:31:54,122 [shard 0] ms - [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4] intercepted ACK_READ(1)
INFO 2022-09-28 15:31:54,122 [shard 0] ms - [1] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted BANNER_WRITE(3)
INFO 2022-09-28 15:31:54,123 [shard 0] ms - [1] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4] intercepted BANNER_READ(3)
INFO 2022-09-28 15:31:54,123 [shard 0] ms -
[FAIL: std::runtime_error (3 connections, more than expected: 2)]
INFO 2022-09-28 15:31:54,123 [shard 0] ms -
Result(0x611000547940):
conn: [0] [osd.2(Test) v2:127.0.0.1:9012/2@54824 >> osd.4 v2:127.0.0.1:9014/4]:
state: established
connect_attempts: 1
client_connect_attempts: 1
client_reconnect_attempts: 0
cnt_connect_dispatched: 1
accept_attempts: 0
server_connect_attempts: 0
server_reconnect_attempts: 0
cnt_accept_dispatched: 0
cnt_reset_dispatched: 0
cnt_remote_reset_dispatched: 0
INFO 2022-09-28 15:31:54,123 [shard 0] ms -
Result(0x611000547980):
conn: [1] [osd.2(Test) v2:127.0.0.1:9012/2@0 >> osd.? v2:127.0.0.1:9014/4]:
state: unknown
connect_attempts: 1
client_connect_attempts: 0
client_reconnect_attempts: 0
cnt_connect_dispatched: 0
accept_attempts: 0
server_connect_attempts: 0
server_reconnect_attempts: 0
cnt_accept_dispatched: 0
cnt_reset_dispatched: 0
cnt_remote_reset_dispatched: 0
INFO 2022-09-28 15:31:54,123 [shard 0] ms -
Result(0x6110005479c0):
conn: [2] [osd.2(Test) v2:127.0.0.1:9012/2 >> unknown.? -@54022]:
state: unknown
connect_attempts: 0
client_connect_attempts: 0
client_reconnect_attempts: 0
cnt_connect_dispatched: 0
accept_attempts: 1
server_connect_attempts: 0
server_reconnect_attempts: 0
cnt_accept_dispatched: 0
cnt_reset_dispatched: 0
cnt_remote_reset_dispatched: 0
History
#1 Updated by Yingxin Cheng over 1 year ago
- Status changed from New to Fix Under Review
Should be fixed by https://github.com/ceph/ceph/pull/48457
#2 Updated by Yingxin Cheng over 1 year ago
- Status changed from Fix Under Review to Resolved
- Assignee set to Yingxin Cheng
The fix was merged.