Project

General

Profile

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]"

Added by Patrick Donnelly over 2 years ago. Updated over 1 year ago.

Status:
Duplicate
Priority:
High
Assignee:
Category:
-
Target version:
-
% Done:

0%

Source:
Q/A
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
fs
Component(FS):
ceph-fuse
Labels (FS):
task(medium)
Pull request ID:
Crash signature (v1):
Crash signature (v2):

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.

Also available in: Atom PDF