Project

General

Profile

Bug #18996

api_misc: [ FAILED ] LibRadosMiscConnectFailure.ConnectFailure

Added by Kefu Chai about 7 years ago. Updated almost 7 years ago.

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

0%

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

Description

2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: [ RUN      ] LibRadosMiscConnectFailure.ConnectFailure
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.616382 7f7846e9c800 -1 WARNING: all dangerous and experimental features are enabled.
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.617083 7f7846e9c800 -1 asok(0x55859e06e840)  AdminSocketConfigObs::init: failed: AdminSocket::bind_and_listen: failed to bind the UNIX domain socket to '/var/run/ceph/ceph-client.admin.18540.asok': (17) File exists
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.617097 7f7846e9c800 10 monclient: build_initial_monmap
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.632744 7f7846e9c800  1 librados: starting msgr at -
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.632901 7f7846e9c800  1 librados: starting objecter
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.633560 7f7846e9c800  1  Processor -- start
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.633798 7f7846e9c800  1 -- - start start
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.633906 7f7846e9c800  1 librados: setting wanted keys
2017-02-19T15:59:24.646 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.634008 7f7846e9c800  1 librados: calling monclient init
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.634106 7f7846e9c800 10 monclient: init
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.634323 7f7846e9c800 10 monclient: auth_supported 2 method cephx
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.636604 7f7846e9c800 10 monclient: _reopen_session rank -1
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.637165 7f7846e9c800 10 monclient(hunting):picked mon.b con 0x55859e13d390 addr 172.21.4.128:6789/0
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.637612 7f7846e9c800 10 monclient(hunting):picked mon.c con 0x55859e140a00 addr 172.21.3.116:6790/0
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.637990 7f7832ffd700  1 -- 172.21.3.116:0/145937711 learned_addr learned my addr 172.21.3.116:0/145937711
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.638443 7f7846e9c800  1 -- 172.21.3.116:0/145937711 --> 172.21.4.128:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- 0x55859e114ba0 con 0
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.638589 7f7846e9c800  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- auth(proto 0 30 bytes epoch 0) v1 -- 0x55859e1151a0 con 0
2017-02-19T15:59:24.647 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.638859 7f7846e9c800 10 monclient(hunting): _renew_subs
2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.639011 7f7846e9c800 10 monclient(hunting): authenticate will time out at 2017-02-19 15:59:24.639011
2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.643307 7f7831ffb700 10 client.?.objecter ms_handle_connect 0x55859e13d390
2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.643335 7f7831ffb700 10 client.?.objecter resend_mon_ops
2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.643854 7f7831ffb700 10 client.?.objecter ms_handle_connect 0x55859e140a00
2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.643863 7f7831ffb700 10 client.?.objecter resend_mon_ops
2017-02-19T15:59:24.649 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.644605 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.2 172.21.3.116:6790/0 1 ==== mon_map magic: 0 v1 ==== 355+0+0 (691045880 0 0) 0x7f7820001060 con 0x55859e140a00
2017-02-19T15:59:24.649 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.644628 7f7831ffb700 10 monclient(hunting): handle_monmap mon_map magic: 0 v1
2017-02-19T15:59:24.649 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.644644 7f7831ffb700 10 monclient(hunting):  got monmap 2, mon.c is now rank 2
2017-02-19T15:59:24.649 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.644646 7f7831ffb700 10 monclient(hunting): dump:
2017-02-19T15:59:24.650 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: epoch 2
2017-02-19T15:59:24.650 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: fsid cfc25076-e2a6-4177-8c77-007ed278d2be
2017-02-19T15:59:24.650 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: last_changed 2017-02-19 15:58:49.923743
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: created 2017-02-19 15:58:01.626783
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 0: 172.21.3.116:6789/0 mon.a
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 1: 172.21.4.128:6789/0 mon.b
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2: 172.21.3.116:6790/0 mon.c
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc:
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645052 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.2 172.21.3.116:6790/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (2942301640 0 0) 0x7f7820001380 con 0x55859e140a00
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645078 7f7831ffb700 10 monclient(hunting): my global_id is 4241
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645167 7f7831ffb700  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f7818001ab0 con 0
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645503 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.1 172.21.4.128:6789/0 1 ==== mon_map magic: 0 v1 ==== 355+0+0 (691045880 0 0) 0x7f78280010e0 con 0x55859e13d390
2017-02-19T15:59:24.651 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645516 7f7831ffb700 10 monclient(hunting): handle_monmap mon_map magic: 0 v1
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645525 7f7831ffb700 10 monclient(hunting):  got monmap 2, mon.b is now rank 1
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.645527 7f7831ffb700 10 monclient(hunting): dump:
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: epoch 2
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: fsid cfc25076-e2a6-4177-8c77-007ed278d2be
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: last_changed 2017-02-19 15:58:49.923743
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: created 2017-02-19 15:58:01.626783
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 0: 172.21.3.116:6789/0 mon.a
2017-02-19T15:59:24.652 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 1: 172.21.4.128:6789/0 mon.b
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2: 172.21.3.116:6790/0 mon.c
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc:
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.646346 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.1 172.21.4.128:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (3666301376 0 0) 0x7f7828001390 con 0x55859e13d390
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.646367 7f7831ffb700 10 monclient(hunting): my global_id is 4234
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.646425 7f7831ffb700  1 -- 172.21.3.116:0/145937711 --> 172.21.4.128:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f7818003ac0 con 0
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.646856 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.2 172.21.3.116:6790/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (3290750594 0 0) 0x7f7820000d00 con 0x55859e140a00
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.646928 7f7831ffb700  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- auth(proto 2 165 bytes epoch 0) v1 -- 0x7f7818001f10 con 0
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.647810 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.1 172.21.4.128:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (2224928937 0 0) 0x7f7828001010 con 0x55859e13d390
2017-02-19T15:59:24.653 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.647883 7f7831ffb700  1 -- 172.21.3.116:0/145937711 --> 172.21.4.128:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- 0x7f7818002630 con 0
2017-02-19T15:59:24.657 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648274 7f7831ffb700  1 -- 172.21.3.116:0/145937711 <== mon.2 172.21.3.116:6790/0 4 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 564+0+0 (3969616104 0 0) 0x7f78200012b0 con 0x55859e140a00
2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648379 7f7831ffb700  1 -- 172.21.3.116:0/145937711 >> 172.21.4.128:6789/0 conn(0x55859e13d390 :-1 s=STATE_OPEN pgs=59 cs=1 l=1).mark_down
2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648414 7f7831ffb700  1 monclient: found mon.c
2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648417 7f7831ffb700 10 monclient: _send_mon_message to mon.c at 172.21.3.116:6790/0
2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648420 7f7831ffb700  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- mon_subscribe({monmap=0+}) v2 -- 0x55859e114ea0 con 0
2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648434 7f7831ffb700 20 monclient: _check_auth_rotating not needed by client.admin
2017-02-19T15:59:24.659 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.652818 7f7846e9c800  5 monclient: authenticate success, global_id 4241
2017-02-19T15:59:24.659 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.653744 7f7846e9c800 10 monclient: _renew_subs
2017-02-19T15:59:24.659 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.653899 7f7846e9c800 10 monclient: _send_mon_message to mon.c at 172.21.3.116:6790/0
2017-02-19T15:59:24.659 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654003 7f7846e9c800  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- mon_subscribe({mgrmap=0+}) v2 -- 0x55859e1151a0 con 0
2017-02-19T15:59:24.659 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654232 7f7846e9c800 10 client.4241.objecter _maybe_request_map subscribing (onetime) to next osd map
2017-02-19T15:59:24.660 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654389 7f7846e9c800 10 monclient: _renew_subs
2017-02-19T15:59:24.660 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654496 7f7846e9c800 10 monclient: _send_mon_message to mon.c at 172.21.3.116:6790/0
2017-02-19T15:59:24.660 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654614 7f7846e9c800  1 -- 172.21.3.116:0/145937711 --> 172.21.3.116:6790/0 -- mon_subscribe({osdmap=0}) v2 -- 0x55859e112200 con 0
2017-02-19T15:59:24.660 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.654836 7f7846e9c800  1 librados: init done
2017-02-19T15:59:24.660 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: /build/ceph-12.0.0-538-g8ac3230/src/test/librados/misc.cc:69: Failure
2017-02-19T15:59:24.661 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: Expected: (0) != (rados_connect(cluster)), actual: 0 vs 0
2017-02-19T15:59:24.661 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: [  FAILED  ] LibRadosMiscConnectFailure.ConnectFailure (68 ms)

the connect succeeded.

see http://pulpito.ceph.com/kchai-2017-02-18_17:57:32-rados-wip-kefu-testing---basic-mira/831453/

History

#1 Updated by Kefu Chai about 7 years ago

  • Description updated (diff)

#2 Updated by Kefu Chai about 7 years ago

  • Description updated (diff)

#3 Updated by Kefu Chai about 7 years ago

the authenticate would time out at "15:59:24.639011".

2017-02-19T15:59:24.648 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.639011 7f7846e9c800 10 monclient(hunting): authenticate will time out at 2017-02-19 15:59:24.639011

and authentication succeeded at "15:59:24.648434".

2017-02-19T15:59:24.658 INFO:tasks.workunit.client.0.mira012.stdout:                 api_misc: 2017-02-19 15:59:24.648434 7f7831ffb700 20 monclient: _check_auth_rotating not needed by client.admin

strange enough...

#4 Updated by Greg Farnum almost 7 years ago

  • Project changed from Ceph to RADOS
  • Category set to Tests
  • Component(RADOS) librados added

Also available in: Atom PDF