Project

General

Profile

Actions
Copy link

Bug #41593

open

rbd with user key hangs

Added by Michal Nasiadka over 4 years ago. Updated over 4 years ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

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

Description

Ceph Nautilus deployed with ceph-ansible stable-4.0 on CentOS 7.6
using both upstream Nautilus 14.2.2 packages and CentOS Storage SIG 14.2.1 packages

ceph-ansible created OpenStack client users/keys and pools

It's possible to list/create/etc using rbd command line client using client.admin key, but not other keys

rbd -k /etc/ceph/ceph.client.openstack.key -p volumes ls hangs
(output with --debug-ms=99):

  1. rbd k /etc/ceph/ceph.client.openstack.keyring --debug-ms=99 -p volumes ls
    2019-09-02 06:34:38.197 7fbe041f7700 2 Event(0x55d35fee7e10 nevent=5000 time_id=1).set_owner idx=0 owner=140454089684736
    2019-09-02 06:34:38.197 7fbe041f7700 20 Event(0x55d35fee7e10 nevent=5000 time_id=1).create_file_event create event started fd=5 mask=1 original mask is 0
    2019-09-02 06:34:38.197 7fbe041f7700 20 EpollDriver.add_event add event fd=5 cur_mask=0 add_mask=1 to 4
    2019-09-02 06:34:38.197 7fbe041f7700 20 Event(0x55d35fee7e10 nevent=5000 time_id=1).create_file_event create event end fd=5 mask=1 original mask is 1
    2019-09-02 06:34:38.197 7fbe041f7700 10 stack operator() starting
    2019-09-02 06:34:38.197 7fbe041f7700 30 stack operator() calling event process
    2019-09-02 06:34:38.197 7fbe041f7700 30 Event(0x55d35fee7e10 nevent=5000 time_id=1).process_events wait second 30 usec 0
    2019-09-02 06:34:38.197 7fbe031f5700 2 Event(0x55d35fee78a0 nevent=5000 time_id=1).set_owner idx=2 owner=140454072899328
    2019-09-02 06:34:38.197 7fbe039f6700 2 Event(0x55d35fee6a60 nevent=5000 time_id=1).set_owner idx=1 owner=140454081292032
    2019-09-02 06:34:38.197 7fbe031f5700 20 Event(0x55d35fee78a0 nevent=5000 time_id=1).create_file_event create event started fd=11 mask=1 original mask is 0
    2019-09-02 06:34:38.197 7fbe031f5700 20 EpollDriver.add_event add event fd=11 cur_mask=0 add_mask=1 to 10
    2019-09-02 06:34:38.197 7fbe031f5700 20 Event(0x55d35fee78a0 nevent=5000 time_id=1).create_file_event create event end fd=11 mask=1 original mask is 1
    2019-09-02 06:34:38.197 7fbe031f5700 10 stack operator() starting
    2019-09-02 06:34:38.197 7fbe039f6700 20 Event(0x55d35fee6a60 nevent=5000 time_id=1).create_file_event create event started fd=8 mask=1 original mask is 0
    2019-09-02 06:34:38.197 7fbe039f6700 20 EpollDriver.add_event add event fd=8 cur_mask=0 add_mask=1 to 7
    2019-09-02 06:34:38.197 7fbe031f5700 30 stack operator() calling event process
    2019-09-02 06:34:38.197 7fbe031f5700 30 Event(0x55d35fee78a0 nevent=5000 time_id=1).process_events wait second 30 usec 0
    2019-09-02 06:34:38.197 7fbe039f6700 20 Event(0x55d35fee6a60 nevent=5000 time_id=1).create_file_event create event end fd=8 mask=1 original mask is 1
    2019-09-02 06:34:38.197 7fbe039f6700 10 stack operator() starting
    2019-09-02 06:34:38.197 7fbe039f6700 30 stack operator() calling event process
    2019-09-02 06:34:38.197 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events wait second 30 usec 0
    2019-09-02 06:34:38.197 7fbe1526cb00 30 stack get_worker
    2019-09-02 06:34:38.198 7fbe1526cb00 10 -     ready
    2019-09-02 06:34:38.198 7fbe1526cb00 1 Processor -- start
    2019-09-02 06:34:38.198 7fbe1526cb00 20 Event(0x55d35fee7e10 nevent=5000 time_id=1).wakeup
    2019-09-02 06:34:38.198 7fbe1526cb00 30 Event(0x55d35fee7e10 nevent=5000 time_id=1).dispatch_event_external 0x7ffc85993c70 pending 1
    2019-09-02 06:34:38.198 7fbe041f7700 30 Event(0x55d35fee7e10 nevent=5000 time_id=1).process_events event_wq process is 5 mask is 1
    2019-09-02 06:34:38.198 7fbe041f7700 30 Event(0x55d35fee7e10 nevent=5000 time_id=1).process_events do 0x7ffc85993c70
    2019-09-02 06:34:38.198 7fbe041f7700 30 stack operator() calling event process
    2019-09-02 06:34:38.198 7fbe041f7700 30 Event(0x55d35fee7e10 nevent=5000 time_id=1).process_events wait second 30 usec 0
    2019-09-02 06:34:38.198 7fbe1526cb00 1 -- start start
    2019-09-02 06:34:38.199 7fbe1526cb00 10 -- create_connect [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0], creating connection and registering
    2019-09-02 06:34:38.199 7fbe1526cb00 30 stack get_worker
    2019-09-02 06:34:38.199 7fbe1526cb00 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_NONE l=0)._connect
    2019-09-02 06:34:38.199 7fbe1526cb00 1 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=NONE pgs=0 cs=0 l=0 rx=0 tx=0).connect
    2019-09-02 06:34:38.199 7fbe1526cb00 20 Event(0x55d35fee6a60 nevent=5000 time_id=1).wakeup
    2019-09-02 06:34:38.199 7fbe1526cb00 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).dispatch_event_external 0x55d35ff72ba0 pending 1
    2019-09-02 06:34:38.199 7fbe1526cb00 10 -- create_connect 0x55d35ff745c0 [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0]
    2019-09-02 06:34:38.199 7fbe1526cb00 10 -- connect_to [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] new 0x55d35ff745c0
    2019-09-02 06:34:38.199 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events event_wq process is 8 mask is 1
    2019-09-02 06:34:38.199 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events do 0x55d35ff72ba0
    2019-09-02 06:34:38.199 7fbe1526cb00 1 -- --> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] -- mon_getmap magic: 0 v1 -- 0x55d35ff74380 con 0x55d35ff745c0
    2019-09-02 06:34:38.199 7fbe1526cb00 5 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=0 rx=0 tx=0).send_message enqueueing message m=0x55d35ff74380 type=5 mon_getmap magic: 0 v1
    2019-09-02 06:34:38.199 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTING l=0).process
    2019-09-02 06:34:38.199 7fbe1526cb00 15 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=0 rx=0 tx=0).send_message inline write is denied, reschedule m=0x55d35ff74380
    2019-09-02 06:34:38.200 7fbe039f6700 20 Event(0x55d35fee6a60 nevent=5000 time_id=1).create_file_event create event started fd=13 mask=1 original mask is 0
    2019-09-02 06:34:38.200 7fbe039f6700 20 EpollDriver.add_event add event fd=13 cur_mask=0 add_mask=1 to 7
    2019-09-02 06:34:38.200 7fbe039f6700 20 Event(0x55d35fee6a60 nevent=5000 time_id=1).create_file_event create event end fd=13 mask=1 original mask is 1
    2019-09-02 06:34:38.200 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).delete_file_event delete event started fd=13 mask=2 original mask is 1
    2019-09-02 06:34:38.200 7fbe039f6700 20 EpollDriver.del_event del event fd=13 cur_mask=1 delmask=2 to 7
    2019-09-02 06:34:38.200 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).delete_file_event delete event end fd=13 mask=2 original mask is 1
    2019-09-02 06:34:38.200 7fbe039f6700 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTING_RE l=0).process connect successfully, ready to send banner
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=0 rx=0 tx=0).read_event
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=0 rx=0 tx=0).start_client_banner_exchange
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0)._banner_exchange
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send cs.send 26 bytes
    2019-09-02 06:34:38.200 7fbe039f6700 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send sent bytes 26 remaining bytes 0
    2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=10
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 10 state_offset is 0
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 10 got 26
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0)._handle_peer_banner r=0
    2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=16
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 16 state_offset is 0
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until got 16 in buffer left is 0 buffer still has 0
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0)._handle_peer_banner_payload r=0
    2019-09-02 06:34:38.200 7fbe039f6700 1 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0)._handle_peer_banner_payload supported=0 required=0
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send cs.send 85 bytes
    2019-09-02 06:34:38.200 7fbe039f6700 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send sent bytes 85 remaining bytes 0
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).read_frame
    2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=32
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 32 state_offset is 0
    2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 32 got 85
    2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main r=0
    2019-09-02 06:34:38.200 7fbe039f6700 30 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main preamble
    00000000 01 01 24 00 00 00 08 00 00 00 00 00 00 00 00 00 |..$.............|
    00000010 00 00 00 00 00 00 00 00 00 00 00 00 3f bd 6b 06 |............?.k.|
    00000020

2019-09-02 06:34:38.200 7fbe039f6700 10 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main got new segment: len=36 align=8
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).read_frame_segment
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=36
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 36 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until got 36 in buffer left is 0 buffer still has 17
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_segment r=0
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=17
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 17 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until got 17 in buffer left is 0 buffer still has 0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_epilogue_main r=0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check success: expected_crc=1029930034 calculated_crc=1029930034
2019-09-02 06:34:38.200 7fbe039f6700 10 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_dispatch tag=1
2019-09-02 06:34:38.200 7fbe039f6700 30 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_frame_payload
00000000 01 01 01 01 1c 00 00 00 02 00 00 00 00 00 00 00 |................|
00000010 10 00 00 00 02 00 b4 78 0a 00 00 34 00 00 00 00 |.......x...4....|
00000020 00 00 00 00 |....|
00000024

2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_hello payload.length()=36
2019-09-02 06:34:38.200 7fbe039f6700 5 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_hello received hello: peer_type=1 peer_addr_for_me=v2:10.0.0.52:46200/0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).post_client_banner_exchange
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).send_auth_request peer_type 1 auth_client 0x7ffc85993f48
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send cs.send 87 bytes
2019-09-02 06:34:38.200 7fbe039f6700 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send sent bytes 87 remaining bytes 0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).read_frame
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=32
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 32 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 32 got 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until need len 32 remaining 32 bytes
2019-09-02 06:34:38.200 7fbe039f6700 30 stack operator() calling event process
2019-09-02 06:34:38.200 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events wait second 30 usec 0
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).process
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read continue len=32
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 32 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 32 got 62
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main r=0
2019-09-02 06:34:38.200 7fbe039f6700 30 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main preamble
00000000 04 01 0d 00 00 00 08 00 00 00 00 00 00 00 00 00 |................|
00000010 00 00 00 00 00 00 00 00 00 00 00 00 6a 09 4b c5 |............j.K.|
00000020

2019-09-02 06:34:38.200 7fbe039f6700 10 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main got new segment: len=13 align=8
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).read_frame_segment
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=13
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 13 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until got 13 in buffer left is 0 buffer still has 17
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_segment r=0
2019-09-02 06:34:38.200 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=17
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 17 state_offset is 0
2019-09-02 06:34:38.200 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until got 17 in buffer left is 0 buffer still has 0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_epilogue_main r=0
2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check success: expected_crc=4011858050 calculated_crc=4011858050
2019-09-02 06:34:38.200 7fbe039f6700 10 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_dispatch tag=4
2019-09-02 06:34:38.200 7fbe039f6700 30 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_frame_payload
00000000 09 00 00 00 01 88 7e 9d 5b 18 a1 26 ce |......~.[..&.|
0000000d

2019-09-02 06:34:38.200 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_auth_reply_more payload.length()=13
2019-09-02 06:34:38.201 7fbe039f6700 5 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_auth_reply_more auth reply more len=9
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send cs.send 55 bytes
2019-09-02 06:34:38.201 7fbe039f6700 10 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0)._try_send sent bytes 55 remaining bytes 0
2019-09-02 06:34:38.201 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).read_frame
2019-09-02 06:34:38.201 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=32
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 32 state_offset is 0
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 32 got 0
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until need len 32 remaining 32 bytes
2019-09-02 06:34:38.201 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events event_wq process is 13 mask is 1
2019-09-02 06:34:38.201 7fbe039f6700 30 stack operator() calling event process
2019-09-02 06:34:38.201 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).process_events wait second 30 usec 0
2019-09-02 06:34:38.201 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).process
2019-09-02 06:34:38.201 7fbe039f6700 20 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read continue len=32
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until len is 32 state_offset is 0
2019-09-02 06:34:38.201 7fbe039f6700 1 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_bulk peer close file descriptor 13
2019-09-02 06:34:38.201 7fbe039f6700 25 -- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read_bulk recv_end is 0 left is 32 got 1
2019-09-02 06:34:38.201 7fbe039f6700 1 - >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 msgr2=0x55d35ff712d0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read_until read failed
2019-09-02 06:34:38.201 7fbe039f6700 20 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main r=-1
2019-09-02 06:34:38.201 7fbe039f6700 1 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0).handle_read_frame_preamble_main read frame length and tag failed r=-1 ((1) Operation not permitted)
2019-09-02 06:34:38.201 7fbe039f6700 10 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rx=0 tx=0)._fault
2019-09-02 06:34:38.201 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).delete_file_event delete event started fd=13 mask=3 original mask is 1
2019-09-02 06:34:38.201 7fbe039f6700 20 EpollDriver.del_event del event fd=13 cur_mask=1 delmask=3 to 7
2019-09-02 06:34:38.201 7fbe039f6700 30 Event(0x55d35fee6a60 nevent=5000 time_id=1).delete_file_event delete event end fd=13 mask=3 original mask is 0
2019-09-02 06:34:38.201 7fbe039f6700 1 --2- >> [v2:10.0.0.52:3300/0,v1:10.0.0.52:6789/0] conn(0x55d35ff745c0 0x55d35ff712d0 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=0 rx=0 tx=0)._fault waiting 0.200000

Actions
Copy link
 #1

Updated by Jason Dillaman over 4 years ago

  • Project changed from rbd to Messengers
Actions
Copy link

Also available in: Atom PDF