Actions
Bug #51705
closedqa: tasks.cephfs.fuse_mount:mount command failed
% Done:
0%
Source:
Q/A
Tags:
Backport:
pacific
Regression:
No
Severity:
3 - minor
Reviewed:
ceph-qa-suite:
fs
Component(FS):
Labels (FS):
qa
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
fuse_mount:mount command failed in:
http://qa-proxy.ceph.com/teuthology/yuriw-2021-07-08_23:33:26-fs-wip-yuri2-testing-2021-07-08-1142-pacific-distro-basic-smithi/6260276/teuthology.log
Description: fs/upgrade/volumes/import-legacy/{bluestore-bitmap clusters/1-mds-2-client-micro conf/{client mds mon osd} overrides/{frag_enable pg-warn whitelist_health whitelist_wrongly_marked_down} tasks/{0-nautilus 1-client 2-upgrade 3-verify} ubuntu_18.04}
2021-07-09T07:54:58.093 INFO:tasks.cephfs.fuse_mount:mount command failed.
2021-07-09T07:54:58.093 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/run_tasks.py", line 94, in run_tasks
manager.__enter__()
File "/usr/lib/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/ceph_fuse.py", line 159, in task
mount_x.mount(createfs=False)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/cephfs/fuse_mount.py", line 47, in mount
return self._mount(mntopts, check_status)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/cephfs/fuse_mount.py", line 167, in _mount
self.fuse_daemon.wait()
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/orchestra/run.py", line 161, in wait
self._raise_for_status()
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/orchestra/run.py", line 183, in _raise_for_status
node=self.hostname, label=self.label
teuthology.exceptions.CommandFailedError: Command failed on smithi196 with status 1: "sudo nsenter --net=/var/run/netns/ceph-ns-mnt.0 sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage daemon-helper kill ceph-fuse -f --admin-socket '/var/run/ceph/$cluster-$name.$pid.asok' --id vol_data_isolated --client_mountpoint=/volumes/_nogroup/vol_isolated mnt.0"
2021-07-09T07:54:58.195 ERROR:teuthology.run_tasks: Sentry event: https://sentry.ceph.com/organizations/ceph/?query=69ca6e53e5f548268f5af343f78d3fc2
Traceback (most recent call last):
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/run_tasks.py", line 94, in run_tasks
manager.__enter__()
File "/usr/lib/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/ceph_fuse.py", line 159, in task
mount_x.mount(createfs=False)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/cephfs/fuse_mount.py", line 47, in mount
return self._mount(mntopts, check_status)
File "/home/teuthworker/src/github.com_ceph_ceph-c_038f13de7ebd7e1a69e798ea35b0b27d4925132e/qa/tasks/cephfs/fuse_mount.py", line 167, in _mount
self.fuse_daemon.wait()
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/orchestra/run.py", line 161, in wait
self._raise_for_status()
File "/home/teuthworker/src/git.ceph.com_git_teuthology_24e3280d7d1fc156628af95b24b27a29e38b2766/teuthology/orchestra/run.py", line 183, in _raise_for_status
node=self.hostname, label=self.label
teuthology.exceptions.CommandFailedError: Command failed on smithi196 with status 1: "sudo nsenter --net=/var/run/netns/ceph-ns-mnt.0 sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage daemon-helper kill ceph-fuse -f --admin-socket '/var/run/ceph/$cluster-$name.$pid.asok' --id vol_data_isolated --client_mountpoint=/volumes/_nogroup/vol_isolated mnt.0"
2021-07-09T07:54:58.197 DEBUG:teuthology.run_tasks:Unwinding manager ceph-fuse
2021-07-09T07:54:58.207 DEBUG:teuthology.run_tasks:Unwinding manager ceph
2021-07-09T07:54:58.236 INFO:tasks.ceph.ceph_manager.ceph:Canceling any pending splits or merges...
2021-07-09T07:54:58.237 DEBUG:teuthology.orchestra.run.smithi190:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 120 ceph --cluster ceph osd dump --format=json
2021-07-09T07:54:58.346 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.347 7f5a0e96d700 1 Processor -- start
2021-07-09T07:54:58.346 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.347 7f5a0e96d700 1 -- start start
2021-07-09T07:54:58.349 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 --2- >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 0x7f5a081a7540 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 rx=0 tx=0).connect
2021-07-09T07:54:58.350 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 --2- >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 0x7f5a080e80a0 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 rx=0 tx=0).connect
2021-07-09T07:54:58.350 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- --> v1:172.21.15.190:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- 0x7f5a08101cd0 con 0x7f5a081a7b70
2021-07-09T07:54:58.350 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_getmap magic: 0 v1 -- 0x7f5a0810c450 con 0x7f5a081a7fc0
2021-07-09T07:54:58.351 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- --> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] -- mon_getmap magic: 0 v1 -- 0x7f5a080e6670 con 0x7f5a080ef970
2021-07-09T07:54:58.351 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f59fffff700 1 --1- >> v1:172.21.15.190:6789/0 conn(0x7f5a081a7b70 0x7f5a080e78a0 :-1 s=CONNECTING_WAIT_BANNER_AND_IDENTIFY pgs=0 cs=0 l=0).handle_server_banner_and_identify peer v1:172.21.15.190:6789/0 says I am v1:172.21.15.190:39856/0 (socket says 172.21.15.190:39856)
2021-07-09T07:54:58.351 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f59fffff700 1 -- 172.21.15.190:0/2665111017 learned_addr learned my addr 172.21.15.190:0/2665111017 (peer_addr_for_me v1:172.21.15.190:0/0)
2021-07-09T07:54:58.352 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 0x7f5a080e80a0 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2021-07-09T07:54:58.352 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a077fe700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 0x7f5a081a7540 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2021-07-09T07:54:58.352 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 <== mon.0 v1:172.21.15.190:6789/0 1 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (unknown 2795607676 0 0) 0x7f5a08101cd0 con 0x7f5a081a7b70
2021-07-09T07:54:58.353 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 --> v1:172.21.15.190:6789/0 -- auth(proto 2 36 bytes epoch 0) v1 -- 0x7f59e8003230 con 0x7f5a081a7b70
2021-07-09T07:54:58.353 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 -- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 msgr2=0x7f5a081a7540 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).mark_down
2021-07-09T07:54:58.353 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 <== mon.0 v1:172.21.15.190:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 214+0+0 (unknown 3221663228 0 0) 0x7f59f8001370 con 0x7f5a081a7b70
2021-07-09T07:54:58.354 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 0x7f5a081a7540 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rev1=1 rx=0 tx=0).stop
2021-07-09T07:54:58.354 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 -- 172.21.15.190:0/2665111017 >> v1:172.21.15.190:6789/0 conn(0x7f5a081a7b70 legacy=0x7f5a080e78a0 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=1).mark_down
2021-07-09T07:54:58.355 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 -- 172.21.15.190:0/2665111017 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x7f5a08101a40 con 0x7f5a081a7fc0
2021-07-09T07:54:58.355 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a077fe700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 0x7f5a081a7540 unknown :-1 s=CLOSED pgs=0 cs=0 l=0 rev1=1 rx=0 tx=0).handle_auth_done state changed!
2021-07-09T07:54:58.355 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a07fff700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 0x7f5a080e80a0 secure :-1 s=READY pgs=51 cs=0 l=1 rev1=1 rx=0x7f59f8001b10 tx=0x7f5a00009d30).ready entity=mon.1 client_cookie=c17c2a67f79a8f5f server_cookie=0 in_seq=0 out_seq=0
2021-07-09T07:54:58.355 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 <== mon.1 v2:172.21.15.190:3301/0 1 ==== mon_map magic: 0 v1 ==== 377+0+0 (secure 0 0 0) 0x7f5a08101a40 con 0x7f5a081a7fc0
2021-07-09T07:54:58.356 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 <== mon.1 v2:172.21.15.190:3301/0 2 ==== config(0 keys) v1 ==== 4+0+0 (secure 0 0 0) 0x7f5a0000b6c0 con 0x7f5a081a7fc0
2021-07-09T07:54:58.356 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 msgr2=0x7f5a080e80a0 secure :-1 s=STATE_CONNECTION_ESTABLISHED l=1).mark_down
2021-07-09T07:54:58.356 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a06ffd700 1 -- 172.21.15.190:0/2665111017 <== mon.1 v2:172.21.15.190:3301/0 3 ==== mon_map magic: 0 v1 ==== 377+0+0 (secure 0 0 0) 0x7f5a00002020 con 0x7f5a081a7fc0
2021-07-09T07:54:58.357 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 0x7f5a080e80a0 secure :-1 s=READY pgs=51 cs=0 l=1 rev1=1 rx=0x7f59f8001b10 tx=0x7f5a00009d30).stop
2021-07-09T07:54:58.357 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- 172.21.15.190:0/2665111017 shutdown_connections
2021-07-09T07:54:58.357 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a081a7fc0 0x7f5a080e80a0 unknown :-1 s=CLOSED pgs=51 cs=0 l=1 rev1=1 rx=0 tx=0).stop
2021-07-09T07:54:58.358 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 --2- 172.21.15.190:0/2665111017 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080ef970 0x7f5a081a7540 unknown :-1 s=CLOSED pgs=0 cs=0 l=0 rev1=1 rx=0 tx=0).stop
2021-07-09T07:54:58.358 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- 172.21.15.190:0/2665111017 >> 172.21.15.190:0/2665111017 conn(0x7f5a08119b50 msgr2=0x7f5a08119fa0 unknown :-1 s=STATE_NONE l=0).mark_down
2021-07-09T07:54:58.358 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- 172.21.15.190:0/2665111017 shutdown_connections
2021-07-09T07:54:58.359 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.351 7f5a0e96d700 1 -- 172.21.15.190:0/2665111017 wait complete.
2021-07-09T07:54:58.362 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 Processor -- start
2021-07-09T07:54:58.363 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 -- start start
2021-07-09T07:54:58.363 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 --2- >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 0x7f5a080b7730 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0).connect
2021-07-09T07:54:58.363 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 --2- >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a080b7d60 0x7f5a081a8720 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0).connect
2021-07-09T07:54:58.364 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 --2- >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080b81b0 0x7f5a081a8d50 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0).connect
2021-07-09T07:54:58.364 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 -- --> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] -- mon_getmap magic: 0 v1 -- 0x7f5a080e6260 con 0x7f5a080d8750
2021-07-09T07:54:58.364 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 -- --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_getmap magic: 0 v1 -- 0x7f5a080c9b10 con 0x7f5a080b7d60
2021-07-09T07:54:58.365 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a0e96d700 1 -- --> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] -- mon_getmap magic: 0 v1 -- 0x7f5a080ca3d0 con 0x7f5a080b81b0
2021-07-09T07:54:58.365 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a077fe700 1 --2- >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 0x7f5a080b7730 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2021-07-09T07:54:58.365 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a077fe700 1 --2- >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 0x7f5a080b7730 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_hello peer v2:172.21.15.190:3300/0 says I am v2:172.21.15.190:44270/0 (socket says 172.21.15.190:44270)
2021-07-09T07:54:58.366 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 --2- >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a080b7d60 0x7f5a081a8720 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2021-07-09T07:54:58.366 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a077fe700 1 -- 172.21.15.190:0/2474300057 learned_addr learned my addr 172.21.15.190:0/2474300057 (peer_addr_for_me v2:172.21.15.190:0/0)
2021-07-09T07:54:58.366 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a07fff700 1 --2- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080b81b0 0x7f5a081a8d50 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2021-07-09T07:54:58.367 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 -- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080b81b0 msgr2=0x7f5a081a8d50 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=1).mark_down
2021-07-09T07:54:58.367 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 --2- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3302/0,v1:172.21.15.190:6791/0] conn(0x7f5a080b81b0 0x7f5a081a8d50 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).stop
2021-07-09T07:54:58.367 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 -- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 msgr2=0x7f5a080b7730 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=1).mark_down
2021-07-09T07:54:58.368 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 --2- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 0x7f5a080b7730 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).stop
2021-07-09T07:54:58.368 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f59fffff700 1 -- 172.21.15.190:0/2474300057 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x7f5a080cb030 con 0x7f5a080b7d60
2021-07-09T07:54:58.368 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.355 7f5a077fe700 1 --2- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] conn(0x7f5a080d8750 0x7f5a080b7730 unknown :-1 s=CLOSED pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_auth_done state changed!
2021-07-09T07:54:58.369 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f59fffff700 1 --2- 172.21.15.190:0/2474300057 >> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] conn(0x7f5a080b7d60 0x7f5a081a8720 secure :-1 s=READY pgs=52 cs=0 l=1 rev1=1 rx=0x7f59f8001ad0 tx=0x7f59f800cbe0).ready entity=mon.1 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0
2021-07-09T07:54:58.369 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 1 ==== mon_map magic: 0 v1 ==== 377+0+0 (secure 0 0 0) 0x7f5a080cb030 con 0x7f5a080b7d60
2021-07-09T07:54:58.369 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 2 ==== config(0 keys) v1 ==== 4+0+0 (secure 0 0 0) 0x7f59f8007170 con 0x7f5a080b7d60
2021-07-09T07:54:58.370 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a0e96d700 1 -- 172.21.15.190:0/2474300057 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_subscribe({mgrmap=0+}) v3 -- 0x7f5a080c9460 con 0x7f5a080b7d60
2021-07-09T07:54:58.370 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 3 ==== mon_map magic: 0 v1 ==== 377+0+0 (secure 0 0 0) 0x7f59f80048f0 con 0x7f5a080b7d60
2021-07-09T07:54:58.370 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a0e96d700 1 -- 172.21.15.190:0/2474300057 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_subscribe({osdmap=0}) v3 -- 0x7f5a080d8d40 con 0x7f5a080b7d60
2021-07-09T07:54:58.371 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 4 ==== mgrmap(e 3) v1 ==== 33123+0+0 (secure 0 0 0) 0x7f59f8004af0 con 0x7f5a080b7d60
2021-07-09T07:54:58.371 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.359 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 5 ==== osd_map(17..17 src has 1..17) v4 ==== 3227+0+0 (secure 0 0 0) 0x7f59f8037d80 con 0x7f5a080b7d60
2021-07-09T07:54:58.371 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.363 7f5a0e96d700 1 -- 172.21.15.190:0/2474300057 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_command({"prefix": "get_command_descriptions"} v 0) v1 -- 0x7f5a080e5560 con 0x7f5a080b7d60
2021-07-09T07:54:58.373 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.367 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 6 ==== mon_command_ack([{"prefix": "get_command_descriptions"}]=0 v0) v1 ==== 72+0+111605 (secure 0 0 0) 0x7f5a080e3f00 con 0x7f5a080b7d60
2021-07-09T07:54:58.539 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.543 7f5a0e96d700 1 -- 172.21.15.190:0/2474300057 --> [v2:172.21.15.190:3301/0,v1:172.21.15.190:6790/0] -- mon_command({"prefix": "osd dump", "format": "json"} v 0) v1 -- 0x7f5a081b9ca0 con 0x7f5a080b7d60
2021-07-09T07:54:58.540 INFO:teuthology.orchestra.run.smithi190.stderr:2021-07-09 07:54:58.543 7f5a057fa700 1 -- 172.21.15.190:0/2474300057 <== mon.1 v2:172.21.15.190:3301/0 7 ==== mon_command_ack([{"prefix": "osd dump", "format": "json"}]=0 v17) v1 ==== 74+0+8785 (secure 0 0 0) 0x7f59f80044f0 con 0x7f5a080b7d60
Updated by Jos Collin almost 3 years ago
- Subject changed from qa: tasks.cephfs.fuse_mount:mount command failed to pacific: qa: tasks.cephfs.fuse_mount:mount command failed
Updated by Xiubo Li over 2 years ago
- Status changed from New to In Progress
- Assignee set to Xiubo Li
2021-11-12T03:34:05.231 DEBUG:teuthology.orchestra.run.smithi165:> sudo nsenter --net=/var/run/netns/ceph-ns-mnt.0 sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage daemon-helper kill ceph-fuse -f --admin-socket '/var/run/ceph/$cluster-$name.$pid.asok' --id vol_data_isolated --client_mountpoint=/volumes/_nogroup/vol_isolated mnt.0 2021-11-12T03:34:05.274 DEBUG:teuthology.orchestra.run.smithi165:> sudo modprobe fuse 2021-11-12T03:34:05.289 INFO:teuthology.orchestra.run:Running command with timeout 30 2021-11-12T03:34:05.289 DEBUG:teuthology.orchestra.run.smithi165:> sudo mount -t fusectl /sys/fs/fuse/connections /sys/fs/fuse/connections 2021-11-12T03:34:05.347 INFO:teuthology.orchestra.run.smithi165.stderr:mount: /sys/fs/fuse/connections: /sys/fs/fuse/connections already mounted or mount point busy. 2021-11-12T03:34:05.348 DEBUG:teuthology.orchestra.run:got remote process result: 32 2021-11-12T03:34:05.349 INFO:teuthology.orchestra.run:Running command with timeout 900 2021-11-12T03:34:05.349 DEBUG:teuthology.orchestra.run.smithi165:> ls /sys/fs/fuse/connections 2021-11-12T03:34:05.363 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:parse error setting 'rados_mon_op_timeout' to '15m' (strict_strtod: garbage at end of string. got: '15m') 2021-11-12T03:34:05.363 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:parse error setting 'rados_osd_op_timeout' to '15m' (strict_strtod: garbage at end of string. got: '15m') 2021-11-12T03:34:05.368 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:2021-11-12 03:34:05.376 7f80e4c6a700 -1 monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2] 2021-11-12T03:34:05.369 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:2021-11-12 03:34:05.376 7f80e546b700 -1 monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2] 2021-11-12T03:34:05.371 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:failed to fetch mon config (--no-mon-config to skip) 2021-11-12T03:34:05.539 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi165.stderr:daemon-helper: command failed with exit status 1 2021-11-12T03:34:06.473 DEBUG:teuthology.orchestra.run.smithi165:> sudo modprobe fuse 2021-11-12T03:34:06.490 INFO:teuthology.orchestra.run:Running command with timeout 30 2021-11-12T03:34:06.490 DEBUG:teuthology.orchestra.run.smithi165:> sudo mount -t fusectl /sys/fs/fuse/connections /sys/fs/fuse/connections 2021-11-12T03:34:06.547 INFO:teuthology.orchestra.run.smithi165.stderr:mount: /sys/fs/fuse/connections: /sys/fs/fuse/connections already mounted or mount point busy. 2021-11-12T03:34:06.548 DEBUG:teuthology.orchestra.run:got remote process result: 32 2021-11-12T03:34:06.549 INFO:teuthology.orchestra.run:Running command with timeout 900 2021-11-12T03:34:06.550 DEBUG:teuthology.orchestra.run.smithi165:> ls /sys/fs/fuse/connections 2021-11-12T03:34:06.599 DEBUG:teuthology.orchestra.run:got remote process result: 1 2021-11-12T03:34:06.599 INFO:tasks.cephfs.fuse_mount:mount command failed. 2021-11-12T03:34:06.600 ERROR:teuthology.run_tasks:Saw exception from tasks. Traceback (most recent call last):
The 'rados_osd_op_timeout' type should be TYPE_SECS, when parsing it from the config file it is using the 'strtod()' which is used for the TYPE_FLOAT type options.
Checked it from the Pacific source commit:
commit a8a23747aa081d938c9b277ab42507dd506bf6c2
Author: Patrick Donnelly <pdonnell@redhat.com>
Date: Fri Oct 2 17:11:54 2020 -0700
osdc: add timeout configs for mons/osds
Have the Objecter track the rados_(mon|osd)_op_timeout configs so that
it can be configured at runtime/startup. This is useful for the
MDS/ceph-fuse so that we can avoid waiting forever for a response from
the Monitors that will never come (statfs on a deleted file system's
pools).
Also: make these configs take a time value rather than double. This is
simpler to deal with in the code and allows time units to be used (e.g.
"5m" for 5 minutes).
Fixes: https://tracker.ceph.com/issues/47734
Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>
...
diff --git a/src/common/options.cc b/src/common/options.cc
index ee79029e973..1cc5a4fc74e 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -5249,13 +5249,17 @@ std::vector<Option> get_global_options() {
.set_default("/tmp/fio")
.set_description(""),
- Option("rados_mon_op_timeout", Option::TYPE_FLOAT, Option::LEVEL_ADVANCED)
+ Option("rados_mon_op_timeout", Option::TYPE_SECS, Option::LEVEL_ADVANCED)
.set_default(0)
- .set_description(""),
+ .set_description("timeout for operations handled by monitors such as statfs (0 is unlimited)")
+ .set_flag(Option::FLAG_RUNTIME)
+ .set_min(0),
...
There really change the options type.
Updated by Xiubo Li over 2 years ago
- Subject changed from pacific: qa: tasks.cephfs.fuse_mount:mount command failed to qa: tasks.cephfs.fuse_mount:mount command failed
- Target version set to v17.0.0
- Pull request ID set to 44422
Updated by Xiubo Li over 2 years ago
- Status changed from In Progress to Fix Under Review
Updated by Xiubo Li over 2 years ago
- Affected Versions v16.1.0, v16.1.1, v16.2.0, v16.2.1, v16.2.2, v16.2.3, v16.2.4, v16.2.5, v16.2.6, v16.2.7, v16.2.8, v17.0.0 added
- ceph-qa-suite fs added
Updated by Xiubo Li over 2 years ago
Not very sure will the above bug could lead to the auth fail issue:
2021-11-12 03:34:05.366 7ff230c39700 1 -- [v2:172.21.15.162:3300/0,v1:172.21.15.162:6789/0] <== client.? v1:172.21.15.165:0/3929876242 2 ==== auth(proto 2 2 bytes epoch 0) v1 ==== 32+0+0 (unknown 1586929805 0 0) 0x55c0b5bfd3c0 con 0x55c0b5b8f180 2021-11-12 03:34:05.366 7ff230c39700 20 mon.a@0(leader) e1 _ms_dispatch existing session 0x55c0b5bfa6c0 for client.? 2021-11-12 03:34:05.366 7ff230c39700 20 mon.a@0(leader) e1 entity_name client.vol_data_isolated global_id 4560 (new_pending) caps 2021-11-12 03:34:05.366 7ff230c39700 10 mon.a@0(leader).paxosservice(auth 1..4) dispatch 0x55c0b5bfd3c0 auth(proto 2 2 bytes epoch 0) v1 from client.? v1:172.21.15.165:0/3929876242 con 0x55c0b5b8f180 2021-11-12 03:34:05.366 7ff230c39700 5 mon.a@0(leader).paxos(paxos active c 1..106) is_readable = 1 - now=2021-11-12 03:34:05.372106 lease_expire=2021-11-12 03:34:09.396969 has v0 lc 106 2021-11-12 03:34:05.366 7ff230c39700 10 mon.a@0(leader).auth v4 preprocess_query auth(proto 2 2 bytes epoch 0) v1 from client.? v1:172.21.15.165:0/3929876242 2021-11-12 03:34:05.366 7ff230c39700 10 mon.a@0(leader).auth v4 prep_auth() blob_size=2 2021-11-12 03:34:05.366 7ff230c39700 10 cephx server client.vol_data_isolated: handle_request get_auth_session_key for client.vol_data_isolated 2021-11-12 03:34:05.366 7ff230c39700 0 cephx server client.vol_data_isolated: handle_request failed to decode CephXAuthenticate: buffer::end_of_buffer 2021-11-12 03:34:05.366 7ff230c39700 2 mon.a@0(leader) e1 send_reply 0x55c0b5bd6760 0x55c0b5aec640 auth_reply(proto 2 -1 (1) Operation not permitted) v1 2021-11-12 03:34:05.366 7ff230c39700 1 -- [v2:172.21.15.162:3300/0,v1:172.21.15.162:6789/0] --> v1:172.21.15.165:0/3929876242 -- auth_reply(proto 2 -1 (1) Operation not permitted) v1 -- 0x55c0b5aec640 con 0x55c0b5b8f180 2021-11-12 03:34:05.366 7ff22fc37700 1 -- [v2:172.21.15.162:3300/0,v1:172.21.15.162:6789/0] >> v1:172.21.15.165:0/3929876242 conn(0x55c0b5b8f180 legacy=0x55c0b5b93800 unknown :6789 s=STATE_CONNECTION_ESTABLISHED l=1).read_bulk peer close file descriptor 43
The monitor failed decoding the 'CephXAuthenticate' after that failure. I checked the source code didn't see any change could potentially cause the auth encoding/decoding related failure yet.
Updated by Venky Shankar over 2 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Backport Bot over 2 years ago
- Copied to Backport #53861: pacific: qa: tasks.cephfs.fuse_mount:mount command failed added
Updated by Loïc Dachary about 2 years ago
- Status changed from Pending Backport to Resolved
While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".
Actions