Project

General

Profile

Bug #57693

Messenger test failed against test_messenger_peer.cc

Added by Yingxin Cheng over 1 year ago. Updated over 1 year ago.

Status:
Resolved
Priority:
Normal
Assignee:
Target version:
-
% 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

#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.

Also available in: Atom PDF