Bug #53360
Bug #57083: ceph-fuse: monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2]
pacific: client: "handle_auth_bad_method server allowed_methods [2] but i only support [2]"
0%
Description
Nautilus ceph-fuse client fails to start for Pacific upgrade tests:
2021-11-20T08:10:35.568 DEBUG:teuthology.orchestra.run.smithi082:> 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-20T08:10:35.611 DEBUG:teuthology.orchestra.run.smithi082:> sudo modprobe fuse 2021-11-20T08:10:35.627 INFO:teuthology.orchestra.run:Running command with timeout 30 2021-11-20T08:10:35.628 DEBUG:teuthology.orchestra.run.smithi082:> sudo mount -t fusectl /sys/fs/fuse/connections /sys/fs/fuse/connections 2021-11-20T08:10:35.680 INFO:teuthology.orchestra.run.smithi082.stderr:mount: /sys/fs/fuse/connections: /sys/fs/fuse/connections already mounted or mount point busy. 2021-11-20T08:10:35.680 DEBUG:teuthology.orchestra.run:got remote process result: 32 2021-11-20T08:10:35.681 INFO:teuthology.orchestra.run:Running command with timeout 900 2021-11-20T08:10:35.682 DEBUG:teuthology.orchestra.run.smithi082:> ls /sys/fs/fuse/connections 2021-11-20T08:10:35.694 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:parse error setting 'rados_mon_op_timeout' to '15m' (strict_strtod: garbage at end of string. got: '15m') 2021-11-20T08:10:35.695 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:parse error setting 'rados_osd_op_timeout' to '15m' (strict_strtod: garbage at end of string. got: '15m') 2021-11-20T08:10:35.700 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:2021-11-20 08:10:35.700 7ff90b56a700 -1 monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2] 2021-11-20T08:10:35.700 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:2021-11-20 08:10:35.700 7ff90ad69700 -1 monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2] 2021-11-20T08:10:35.700 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:2021-11-20 08:10:35.700 7ff90bd6b700 -1 monclient(hunting): handle_auth_bad_method server allowed_methods [2] but i only support [2] 2021-11-20T08:10:35.701 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:failed to fetch mon config (--no-mon-config to skip) 2021-11-20T08:10:35.873 INFO:tasks.cephfs.fuse_mount.ceph-fuse.vol_data_isolated.smithi082.stderr:daemon-helper: command failed with exit status 1
From: /ceph/teuthology-archive/pdonnell-2021-11-20_07:49:53-fs:upgrade-wip-pdonnell-testing-20211120.024903-pacific-distro-basic-smithi/6515766/teuthology.log
History
#1 Updated by Patrick Donnelly over 2 years ago
- Project changed from Ceph to CephFS
#2 Updated by Venky Shankar over 2 years ago
- Status changed from New to Triaged
- Assignee set to Venky Shankar
- Component(FS) ceph-fuse added
- Labels (FS) task(medium) added
#3 Updated by Venky Shankar over 2 years ago
ceph-fuse fails way before `install.upgrade` in run. Looks like the failure is when everything is nautilus::
2021-11-20T08:08:48.968 INFO:teuthology.run_tasks:Running task print... 2021-11-20T08:08:48.980 INFO:teuthology.task.print:**** done installing nautilus 2021-11-20T08:08:48.981 INFO:teuthology.run_tasks:Running task ceph...
...
...
2021-11-20T08:10:34.319 INFO:teuthology.run_tasks:Running task print... 2021-11-20T08:10:34.329 INFO:teuthology.task.print:**** fs/volume_client create 2021-11-20T08:10:34.329 INFO:teuthology.run_tasks:Running task ceph-fuse... 2021-11-20T08:10:34.398 INFO:tasks.ceph_fuse:Running ceph_fuse task...
.. which fails. That is weird.
#4 Updated by Venky Shankar over 2 years ago
From monitor logs::
2021-11-20 08:10:35.698 7f524f622700 10 mon.a@0(leader) e1 handle_auth_request con 0x559175b03b00 (start) method 2 payload 34 2021-11-20 08:10:35.698 7f524f622700 10 mon.a@0(leader).auth v3 _assign_global_id 4560 (max 14096) 2021-11-20 08:10:35.698 7f524f622700 10 start_session entity_name=client.vol_data_isolated global_id=4560 is_new_global_id=1 2021-11-20 08:10:35.698 7f524f622700 10 cephx server client.vol_data_isolated: start_session server_challenge 75cb49f8939f4c67 2021-11-20 08:10:35.698 7f524f622700 10 mon.a@0(leader) e1 handle_auth_request con 0x559175b03b00 (more) method 2 payload 2 2021-11-20 08:10:35.698 7f524f622700 10 cephx server client.vol_data_isolated: handle_request get_auth_session_key for client.vol_data_isolated 2021-11-20 08:10:35.698 7f524f622700 0 cephx server client.vol_data_isolated: handle_request failed to decode CephXAuthenticate: buffer::end_of_buffer
Looks like the monitor failed to authenticate the client. Debugging more as to why...
#5 Updated by Venky Shankar over 2 years ago
`volume_client` script threw a traceback with "ModuleNotFoundError: No module named 'ceph_volume_client'"::
2021-11-20T08:10:33.844 INFO:tasks.workunit.client.0.smithi082.stderr:+ tee /tmp/tmp.pM6PpL4doG 2021-11-20T08:10:33.850 INFO:tasks.workunit.client.0.smithi082.stderr:Traceback (most recent call last): 2021-11-20T08:10:33.850 INFO:tasks.workunit.client.0.smithi082.stderr: File "<stdin>", line 2, in <module> 2021-11-20T08:10:33.851 INFO:tasks.workunit.client.0.smithi082.stderr:ModuleNotFoundError: No module named 'ceph_volume_client' 2021-11-20T08:10:33.852 INFO:tasks.workunit.client.0.smithi082.stderr:+ sudo touch -- /etc/ceph/ceph.client.vol_data_isolated.keyring 2021-11-20T08:10:33.858 INFO:tasks.workunit.client.0.smithi082.stderr:+ sudo ceph-authtool /etc/ceph/ceph.client.vol_data_isolated.keyring --import-keyring /tmp/tmp.pM6PpL4doG 2021-11-20T08:10:33.880 INFO:tasks.workunit.client.0.smithi082.stdout:importing contents of /tmp/tmp.pM6PpL4doG into /etc/ceph/ceph.client.vol_data_isolated.keyring 2021-11-20T08:10:33.882 INFO:tasks.workunit.client.0.smithi082.stderr:+ rm -f -- /tmp/tmp.pM6PpL4doG
Due to this, the "vol_data_isolated" user (and cephx auth keys) no not get created, which fails the subsequent cephfs-fuse mount with this user::
- ceph-fuse: client.0: auth_id: vol_data_isolated mount_path: /volumes/_nogroup/vol_isolated mountpoint: mnt.0
#6 Updated by Venky Shankar over 2 years ago
Ramana, any idea about the module traceback? I recall seeing it earlier...
#7 Updated by Xiubo Li over 1 year ago
- Status changed from Triaged to Duplicate
- Parent task set to #57083
Missed this existing tracker. Will track this in https://tracker.ceph.com/issues/57083 tracker. Have found root cause and will fix it.