Extremally need help. Openshift cluster is down :c
Hello everyone and sorry. Maybe someone has already faced this problem. A day ago, we restored our Openshift cluster, however, at the moment, the PVCs cannot connect to the pod. We looked at the status of the ceph and found that our MDS were in standby mode, then found that the metadata was corrupted. After some manipulations, we were able to turn on our MDS daemons, but there is still no record on the cluster, the ceph status command shows the following. sh-4.4$ ceph -s cluster: id: 9213604e-b0b6-49d5-bcb3-f55ab3d79119 health: HEALTH_ERR 1 MDSs report damaged metadata 1 MDSs are read only 6 daemons have recently crashed services: mon: 5 daemons, quorum bd,bj,bm,bn,bo (age 26h) mgr: a(active, since 25h) mds: 1/1 daemons up, 1 hot standby osd: 9 osds: 9 up (since 41h), 9 in (since 42h) rgw: 1 daemon active (1 hosts, 1 zones) data: volumes: 1/1 healthy pools: 10 pools, 225 pgs objects: 1.60M objects, 234 GiB usage: 606 GiB used, 594 GiB / 1.2 TiB avail pgs: 225 active+clean io: client: 852 B/s rd, 1 op/s rd, 0 op/s wr Now we trying to follow this instructions: https://docs.ceph.com/en/latest/cephfs/disaster-recovery-experts/#recovery-f... What else have we tried: cephfs-journal-tool --rank=1:0 event recover_dentries summary cephfs-journal-tool --rank=1:0 journal reset cephfs-table-tool all reset session ceph tell mds.gml--cephfs-a scrub start / recursive repair force ceph tell mds.gml--cephfs-b scrub start / recursive repair force ceph mds repaired 0 ceph tell mds.gml--cephfs-a damage ls [ { "damage_type": "dir_frag", "id": 26851730, "ino": 1100162409473, "frag": "*", "path": "/volumes/csi/csi-vol-5ad18c03-3205-11ed-9ba7-0a580a810206/e5664004-51e0-4bff-85c8-029944b431d8/store/096/096a1497-78ab-4802-a5a7-d09e011fd3a5/202301_1027796_1027796_0" }, ……… { "damage_type": "dir_frag", "id": 118336643, "ino": 1100162424469, "frag": "*", "path": "/volumes/csi/csi-vol-5ad18c03-3205-11ed-9ba7-0a580a810206/e5664004-51e0-4bff-85c8-029944b431d8/store/096/096a1497-78ab-4802-a5a7-d09e011fd3a5/202301_1027832_1027832_0" }, Now we trying: # Session table cephfs-table-tool 0 reset session # SnapServer cephfs-table-tool 0 reset snap # InoTable cephfs-table-tool 0 reset inode # Journal cephfs-journal-tool --rank=0 journal reset # Root inodes ("/" and MDS directory) cephfs-data-scan init cephfs-data-scan scan_extents <data pool> cephfs-data-scan scan_inodes <data pool> cephfs-data-scan scan_links Is it right way and cant it be our salvation? Thank you!
upd: we fix some issues, but mds still readonly. sh-4.4$ ceph -s cluster: id: 9213604e-b0b6-49d5-bcb3-f55ab3d79119 health: HEALTH_WARN 1 MDSs are read only 7 daemons have recently crashed services: mon: 5 daemons, quorum bd,bj,bm,bn,bo (age 18h) mgr: a(active, since 47h) mds: 1/1 daemons up, 1 hot standby osd: 9 osds: 9 up (since 2d), 9 in (since 2d) rgw: 1 daemon active (1 hosts, 1 zones) data: volumes: 1/1 healthy pools: 10 pools, 225 pgs objects: 1.60M objects, 234 GiB usage: 607 GiB used, 593 GiB / 1.2 TiB avail pgs: 225 active+clean io: client: 1.4 KiB/s rd, 2 op/s rd, 0 op/s wr
Hi, do you have log output from the read-only MDS, probably in debug mode? Zitat von kreept.sama@gmail.com:
Hello everyone and sorry. Maybe someone has already faced this problem. A day ago, we restored our Openshift cluster, however, at the moment, the PVCs cannot connect to the pod. We looked at the status of the ceph and found that our MDS were in standby mode, then found that the metadata was corrupted. After some manipulations, we were able to turn on our MDS daemons, but there is still no record on the cluster, the ceph status command shows the following.
sh-4.4$ ceph -s cluster: id: 9213604e-b0b6-49d5-bcb3-f55ab3d79119 health: HEALTH_ERR 1 MDSs report damaged metadata 1 MDSs are read only 6 daemons have recently crashed services: mon: 5 daemons, quorum bd,bj,bm,bn,bo (age 26h) mgr: a(active, since 25h) mds: 1/1 daemons up, 1 hot standby osd: 9 osds: 9 up (since 41h), 9 in (since 42h) rgw: 1 daemon active (1 hosts, 1 zones) data: volumes: 1/1 healthy pools: 10 pools, 225 pgs objects: 1.60M objects, 234 GiB usage: 606 GiB used, 594 GiB / 1.2 TiB avail pgs: 225 active+clean io: client: 852 B/s rd, 1 op/s rd, 0 op/s wr
Now we trying to follow this instructions: https://docs.ceph.com/en/latest/cephfs/disaster-recovery-experts/#recovery-f...
What else have we tried:
cephfs-journal-tool --rank=1:0 event recover_dentries summary cephfs-journal-tool --rank=1:0 journal reset cephfs-table-tool all reset session ceph tell mds.gml--cephfs-a scrub start / recursive repair force ceph tell mds.gml--cephfs-b scrub start / recursive repair force ceph mds repaired 0
ceph tell mds.gml--cephfs-a damage ls
[ { "damage_type": "dir_frag", "id": 26851730, "ino": 1100162409473, "frag": "*", "path": "/volumes/csi/csi-vol-5ad18c03-3205-11ed-9ba7-0a580a810206/e5664004-51e0-4bff-85c8-029944b431d8/store/096/096a1497-78ab-4802-a5a7-d09e011fd3a5/202301_1027796_1027796_0" }, ………
{ "damage_type": "dir_frag", "id": 118336643, "ino": 1100162424469, "frag": "*", "path": "/volumes/csi/csi-vol-5ad18c03-3205-11ed-9ba7-0a580a810206/e5664004-51e0-4bff-85c8-029944b431d8/store/096/096a1497-78ab-4802-a5a7-d09e011fd3a5/202301_1027832_1027832_0" },
Now we trying:
# Session table cephfs-table-tool 0 reset session # SnapServer cephfs-table-tool 0 reset snap # InoTable cephfs-table-tool 0 reset inode # Journal cephfs-journal-tool --rank=0 journal reset # Root inodes ("/" and MDS directory) cephfs-data-scan init
cephfs-data-scan scan_extents <data pool> cephfs-data-scan scan_inodes <data pool> cephfs-data-scan scan_links
Is it right way and cant it be our salvation? Thank you! _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hello Eugen, yes i have Its from object a ... debug 2023-02-12T07:12:55.469+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:05.453+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:15.478+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:25.477+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:35.445+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:45.487+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) ... and the same for object b ... debug 2023-02-12T07:15:41.496+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:15:51.479+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:16:01.477+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) ...
That doesn't really help, the startup log should contain information why the MDS is going into read-only mode, here's an example from the mailing list archive: 2020-07-30 18:14:44.835 7f646f33e700 -1 mds.0.159432 unhandled write error (90) Message too long, force readonly... 2020-07-30 18:14:44.835 7f646f33e700 1 mds.0.cache force file system read-only 2020-07-30 18:14:44.835 7f646f33e700 0 log_channel(cluster) log [WRN] : force file system read-only If necessary, turn on debug logs to provide more details. Zitat von kreept.sama@gmail.com:
Hello Eugen, yes i have Its from object a ... debug 2023-02-12T07:12:55.469+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:05.453+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:15.478+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:25.477+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:35.445+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:13:45.487+0000 7f66af51e700 1 mds.gml-okd-cephfs-a asok_command: status {prefix=status} (starting...) ... and the same for object b
... debug 2023-02-12T07:15:41.496+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:15:51.479+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) debug 2023-02-12T07:16:01.477+0000 7fdf6281e700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) ... _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Sorry, dont know where to find mds logs. I just found some logs in /var/log/ceph/ceph-volume.log from mds pod and here it is(just a piece): ... [2023-02-15 12:09:07,460][ceph_volume.main][INFO ] Running command: ceph-volume inventory --format json /dev/sda3 [2023-02-15 12:09:07,461][ceph_volume.process][INFO ] Running command: /usr/bin/lsblk -plno KNAME,NAME,TYPE [2023-02-15 12:09:07,471][ceph_volume.process][INFO ] stdout /dev/sda /dev/sda disk [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda1 /dev/sda1 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda2 /dev/sda2 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda3 /dev/sda3 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda4 /dev/sda4 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sdb /dev/sdb disk [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sr0 /dev/sr0 rom [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/dm-0 /dev/mapper/ceph--893e62b0--dc66--4db6--9487--404cad5907d6-osd--block--19ef4373--d828--4259--9159--86f2e89f4397 lvm [2023-02-15 12:09:07,479][ceph_volume.process][INFO ] Running command: /usr/sbin/lvs --noheadings --readonly --separator=";" -a --units=b --nosuffix -S lv_path=/dev/sda3 -o lv_tags,lv_path,lv_name,vg_name,lv_uuid,lv_size [2023-02-15 12:09:07,525][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will manage logical volume symlinks in device directory. [2023-02-15 12:09:07,526][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will obtain device list by scanning device directory. [2023-02-15 12:09:07,526][ceph_volume.process][INFO ] Running command: /usr/bin/lsblk --nodeps -P -o NAME,KNAME,MAJ:MIN,FSTYPE,MOUNTPOINT,LABEL,UUID,RO,RM,MODEL,SIZE,STATE,OWNER,GROUP,MODE,ALIGNMENT,PHY-SEC,LOG-SEC,ROTA,SCHED,TYPE,DISC-ALN,DISC-GRAN,DISC-MAX,DISC-ZERO,PKNAME,PARTLABEL /dev/sda3 [2023-02-15 12:09:07,544][ceph_volume.process][INFO ] stdout NAME="sda3" KNAME="sda3" MAJ:MIN="8:3" FSTYPE="" MOUNTPOINT="" LABEL="" UUID="" RO="0" RM="0" MODEL="" SIZE="1M" STATE="" OWNER="root" GROUP="disk" MODE="brw-rw----" ALIGNMENT="0" PHY-SEC="512" LOG-SEC="512" ROTA="1" SCHED="bfq" TYPE="part" DISC-ALN="0" DISC-GRAN="4K" DISC-MAX="1G" DISC-ZERO="0" PKNAME="sda" PARTLABEL="BIOS-BOOT" [2023-02-15 12:09:07,544][ceph_volume.process][INFO ] Running command: /usr/sbin/blkid -c /dev/null -p /dev/sda3 [2023-02-15 12:09:07,553][ceph_volume.process][INFO ] stdout /dev/sda3: PART_ENTRY_SCHEME="gpt" PART_ENTRY_NAME="BIOS-BOOT" PART_ENTRY_UUID="860433f4-8158-432c-88aa-e42901086299" PART_ENTRY_TYPE="21686148-6449-6e6f-744e-656564454649" PART_ENTRY_NUMBER="3" PART_ENTRY_OFFSET="1048576" PART_ENTRY_SIZE="2048" PART_ENTRY_DISK="8:0" [2023-02-15 12:09:07,554][ceph_volume.process][INFO ] Running command: /usr/sbin/pvs --noheadings --readonly --units=b --nosuffix --separator=";" -o vg_name,pv_count,lv_count,vg_attr,vg_extent_count,vg_free_count,vg_extent_size /dev/sda3 [2023-02-15 12:09:07,595][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will manage logical volume symlinks in device directory. [2023-02-15 12:09:07,595][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will obtain device list by scanning device directory. [2023-02-15 12:09:07,596][ceph_volume.process][INFO ] stderr Failed to find device for physical volume "/dev/sda3". [2023-02-15 12:09:07,596][ceph_volume.process][INFO ] Running command: /usr/bin/ceph-bluestore-tool show-label --dev /dev/sda3 [2023-02-15 12:09:07,630][ceph_volume.process][INFO ] stderr unable to read label for /dev/sda3: (2) No such file or directory [2023-02-15 12:09:07,630][ceph_volume.process][INFO ] Running command: /usr/bin/ceph-bluestore-tool show-label --dev /dev/sda3 [2023-02-15 12:09:07,672][ceph_volume.process][INFO ] stderr unable to read label for /dev/sda3: (2) No such file or directory [2023-02-15 12:09:07,673][ceph_volume.process][INFO ] Running command: /usr/sbin/udevadm info --query=property /dev/sda3 [2023-02-15 12:09:07,687][ceph_volume.process][INFO ] stdout DEVLINKS=/dev/disk/by-partuuid/860433f4-8158-432c-88aa-e42901086299 /dev/disk/by-id/scsi-SQEMU_QEMU_HARDDISK_6ef7d571-c0dc-4394-bcc0-4625a857778b-part3 /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_6ef7d571-c0dc-4394-bcc0-4625a857778b-part3 /dev/disk/by-path/pci-0000:00:06.0-scsi-0:0:0:0-part3 /dev/disk/by-partlabel/BIOS-BOOT [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVNAME=/dev/sda3 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVPATH=/devices/pci0000:00/0000:00:06.0/virtio2/host2/target2:0:0/2:0:0:0/block/sda/sda3 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVTYPE=partition [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_BUS=scsi [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_MODEL=QEMU_HARDDISK [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_PART_ENTRY_DISK=8:0 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_PART_ENTRY_NAME=BIOS-BOOT .... Also after some manipulation our filesystem now fine(few steps later we create new metadata pool and restore current from new). But mds still read only. Our ceph shows only this issue : cluster: id: 9213604e-b0b6-49d5-bcb3-f55ab3d79119 health: HEALTH_WARN 1 MDSs are read only 21 daemons have recently crashed services: mon: 5 daemons, quorum bd,bj,bm,bn,bo (age 8h) mgr: a(active, since 102m) mds: 1/1 daemons up, 1 hot standby osd: 9 osds: 9 up (since 8h), 9 in (since 7d) rgw: 1 daemon active (1 hosts, 1 zones) Thank you
On the MDS host you can see all cephadm daemon with 'cephadm ls', with 'cephadm logs --name mds.<DAEMON>' you get the logs. Zitat von kreept.sama@gmail.com:
Sorry, dont know where to find mds logs. I just found some logs in /var/log/ceph/ceph-volume.log from mds pod and here it is(just a piece): ... [2023-02-15 12:09:07,460][ceph_volume.main][INFO ] Running command: ceph-volume inventory --format json /dev/sda3 [2023-02-15 12:09:07,461][ceph_volume.process][INFO ] Running command: /usr/bin/lsblk -plno KNAME,NAME,TYPE [2023-02-15 12:09:07,471][ceph_volume.process][INFO ] stdout /dev/sda /dev/sda disk [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda1 /dev/sda1 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda2 /dev/sda2 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda3 /dev/sda3 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sda4 /dev/sda4 part [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sdb /dev/sdb disk [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/sr0 /dev/sr0 rom [2023-02-15 12:09:07,472][ceph_volume.process][INFO ] stdout /dev/dm-0 /dev/mapper/ceph--893e62b0--dc66--4db6--9487--404cad5907d6-osd--block--19ef4373--d828--4259--9159--86f2e89f4397 lvm [2023-02-15 12:09:07,479][ceph_volume.process][INFO ] Running command: /usr/sbin/lvs --noheadings --readonly --separator=";" -a --units=b --nosuffix -S lv_path=/dev/sda3 -o lv_tags,lv_path,lv_name,vg_name,lv_uuid,lv_size [2023-02-15 12:09:07,525][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will manage logical volume symlinks in device directory. [2023-02-15 12:09:07,526][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will obtain device list by scanning device directory. [2023-02-15 12:09:07,526][ceph_volume.process][INFO ] Running command: /usr/bin/lsblk --nodeps -P -o NAME,KNAME,MAJ:MIN,FSTYPE,MOUNTPOINT,LABEL,UUID,RO,RM,MODEL,SIZE,STATE,OWNER,GROUP,MODE,ALIGNMENT,PHY-SEC,LOG-SEC,ROTA,SCHED,TYPE,DISC-ALN,DISC-GRAN,DISC-MAX,DISC-ZERO,PKNAME,PARTLABEL /dev/sda3 [2023-02-15 12:09:07,544][ceph_volume.process][INFO ] stdout NAME="sda3" KNAME="sda3" MAJ:MIN="8:3" FSTYPE="" MOUNTPOINT="" LABEL="" UUID="" RO="0" RM="0" MODEL="" SIZE="1M" STATE="" OWNER="root" GROUP="disk" MODE="brw-rw----" ALIGNMENT="0" PHY-SEC="512" LOG-SEC="512" ROTA="1" SCHED="bfq" TYPE="part" DISC-ALN="0" DISC-GRAN="4K" DISC-MAX="1G" DISC-ZERO="0" PKNAME="sda" PARTLABEL="BIOS-BOOT" [2023-02-15 12:09:07,544][ceph_volume.process][INFO ] Running command: /usr/sbin/blkid -c /dev/null -p /dev/sda3 [2023-02-15 12:09:07,553][ceph_volume.process][INFO ] stdout /dev/sda3: PART_ENTRY_SCHEME="gpt" PART_ENTRY_NAME="BIOS-BOOT" PART_ENTRY_UUID="860433f4-8158-432c-88aa-e42901086299" PART_ENTRY_TYPE="21686148-6449-6e6f-744e-656564454649" PART_ENTRY_NUMBER="3" PART_ENTRY_OFFSET="1048576" PART_ENTRY_SIZE="2048" PART_ENTRY_DISK="8:0" [2023-02-15 12:09:07,554][ceph_volume.process][INFO ] Running command: /usr/sbin/pvs --noheadings --readonly --units=b --nosuffix --separator=";" -o vg_name,pv_count,lv_count,vg_attr,vg_extent_count,vg_free_count,vg_extent_size /dev/sda3 [2023-02-15 12:09:07,595][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will manage logical volume symlinks in device directory. [2023-02-15 12:09:07,595][ceph_volume.process][INFO ] stderr Udev is running and DM_DISABLE_UDEV environment variable is set. Bypassing udev, LVM will obtain device list by scanning device directory. [2023-02-15 12:09:07,596][ceph_volume.process][INFO ] stderr Failed to find device for physical volume "/dev/sda3". [2023-02-15 12:09:07,596][ceph_volume.process][INFO ] Running command: /usr/bin/ceph-bluestore-tool show-label --dev /dev/sda3 [2023-02-15 12:09:07,630][ceph_volume.process][INFO ] stderr unable to read label for /dev/sda3: (2) No such file or directory [2023-02-15 12:09:07,630][ceph_volume.process][INFO ] Running command: /usr/bin/ceph-bluestore-tool show-label --dev /dev/sda3 [2023-02-15 12:09:07,672][ceph_volume.process][INFO ] stderr unable to read label for /dev/sda3: (2) No such file or directory [2023-02-15 12:09:07,673][ceph_volume.process][INFO ] Running command: /usr/sbin/udevadm info --query=property /dev/sda3 [2023-02-15 12:09:07,687][ceph_volume.process][INFO ] stdout DEVLINKS=/dev/disk/by-partuuid/860433f4-8158-432c-88aa-e42901086299 /dev/disk/by-id/scsi-SQEMU_QEMU_HARDDISK_6ef7d571-c0dc-4394-bcc0-4625a857778b-part3 /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_6ef7d571-c0dc-4394-bcc0-4625a857778b-part3 /dev/disk/by-path/pci-0000:00:06.0-scsi-0:0:0:0-part3 /dev/disk/by-partlabel/BIOS-BOOT [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVNAME=/dev/sda3 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVPATH=/devices/pci0000:00/0000:00:06.0/virtio2/host2/target2:0:0/2:0:0:0/block/sda/sda3 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout DEVTYPE=partition [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_BUS=scsi [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_MODEL=QEMU_HARDDISK [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_PART_ENTRY_DISK=8:0 [2023-02-15 12:09:07,688][ceph_volume.process][INFO ] stdout ID_PART_ENTRY_NAME=BIOS-BOOT ....
Also after some manipulation our filesystem now fine(few steps later we create new metadata pool and restore current from new). But mds still read only. Our ceph shows only this issue : cluster: id: 9213604e-b0b6-49d5-bcb3-f55ab3d79119 health: HEALTH_WARN 1 MDSs are read only 21 daemons have recently crashed
services: mon: 5 daemons, quorum bd,bj,bm,bn,bo (age 8h) mgr: a(active, since 102m) mds: 1/1 daemons up, 1 hot standby osd: 9 osds: 9 up (since 8h), 9 in (since 7d) rgw: 1 daemon active (1 hosts, 1 zones)
Thank you _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Here, we enable mds debug logging into stdout ceph tell mds.gml-okd-cephfs-a config set debug_mds 20/0 ... debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server reply to stat on client_request(client.66426408:170 lookup #0x10000000001/csi-vol-91510028-3e45-11ec-9461-0a580a82014a 2023-02-16T09:49:56.266338+0000 caller_uid=0, caller_gid=0{}) v5 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server respond_to_request batch head request(client.66426408:170 nref=3 cr=0x558f9a150580) debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 respond: responding to batch ops with result=0: [batch front=request(client.66426408:170 nref=3 cr=0x558f9a150580)] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.server reply_client_request 0 ((0) Success) client_request(client.66426408:170 lookup #0x10000000001/csi-vol-91510028-3e45-11ec-9461-0a580a82014a 2023-02-16T09:49:56.266338+0000 caller_uid=0, caller_gid=0{}) v5 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server apply_allocated_inos 0x0 / [] / 0x0 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server lat 0.000551 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist snapid head debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server set_trace_dist snaprealm snaprealm(0x10001be180e seq 1 lc 0 cr 1 cps 2 snaps={} past_parent_snaps= 0x558f9982a200) len=96 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.cache.ino(0x10000000001) pfile 0 pauth 0 plink 0 pxattr 0 plocal 0 ctime 2022-12-26T14:29:05.859667+0000 valid=1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10000000001) encode_inodestat issuing pAsLsXsFs seq 56 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10000000001) encode_inodestat caps pAsLsXsFs seq 56 mseq 0 xattrv 0 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist added diri [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405 f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907) old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600] debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist added dir [dir 0x10000000001 /volumes/csi/ [2,head] auth v=400540078 cv=400540078/400540078 ap=0+2 state=1074003969|complete f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549125=1354219+194906) hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f9aa22d80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.locker issue_client_lease no/null lease on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dn sync r=1) (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e state=1073741824 | request=1 lock=1 inodepin=1 authpin=1 0x558f99828780] debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist added dn head [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dn sync r=1) (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e state=1073741824 | request=1 lock=1 inodepin=1 authpin=1 0x558f99828780] debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.cache.ino(0x10001be180e) pfile 0 pauth 0 plink 0 pxattr 0 plocal 0 ctime 2021-11-05T14:35:05.441183+0000 valid=1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10001be180e) add_client_cap first cap, joining realm snaprealm(0x10001be180e seq 1 lc 0 cr 1 cps 2 snaps={} past_parent_snaps= 0x558f9982a200) debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10001be180e) encode_inodestat issuing pAsLsXsFs seq 1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10001be180e) encode_inodestat caps pAsLsXsFs seq 1 mseq 0 xattrv 1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10001be180e) including xattrs version 1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist added in [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iauth sync r=1) (ilink sync r=1) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=5 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.350627 send_message_client client.66426408 10.25.1.17:0/1669277120 client_reply(???:170 = 0 (0) Success) v1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.cache request_finish request(client.66426408:170 nref=3 cr=0x558f9a150580) debug 2023-02-16T09:49:56.265+0000 7f0462329700 15 mds.0.cache request_cleanup request(client.66426408:170 nref=3 cr=0x558f9a150580) debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (isnap sync) on [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800 f(v1 m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000 b264347801454 1549251=1354337+194914)/n() (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1 caps=1 openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (isnap sync) on [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800 f(v1 m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000 b264347801454 1549251=1354337+194914)/n() (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1 caps=1 openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (isnap sync) on [inode 0x10000000000 [...c,head] /volumes/ auth v94872546 f(v0 m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911) old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (isnap sync) on [inode 0x10000000000 [...c,head] /volumes/ auth v94872546 f(v0 m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911) old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (isnap sync) on [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405 f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907) old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (isnap sync) on [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405 f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907) old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=0 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (iauth sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (ilink sync r=1) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=4 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (iauth sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (ilink sync r=1) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=4 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (ilink sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=3 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (ilink sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=3 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (ifile sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=2 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker file_eval wanted= loner_wanted= other_wanted= filelock=(ifile sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=2 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (ixattr sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=1 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (ixattr sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=1 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (isnap sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (isnap sync) on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80] debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish on (dn sync) on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e state=1073741824 | request=1 lock=0 inodepin=1 authpin=1 0x558f99828780] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (dn sync) on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e state=1073741824 | request=1 lock=0 inodepin=1 authpin=1 0x558f99828780] debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.ino(0x10001be180e) auth_unpin by 0x558f9aa3fc00 on [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1 openingsnapparents=0 authpin=0 0x558f99825b80] now 0 debug 2023-02-16T09:49:56.265+0000 7f0462329700 15 mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins -1 on [dir 0x10000000001 /volumes/csi/ [2,head] auth v=400540078 cv=400540078/400540078 ap=0+1 state=1074003969|complete f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549125=1354219+194906) hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f9aa22d80] by 0x558f9aa3fc00 count now 0/1 debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.cache.den(0x10000000001 csi-vol-91510028-3e45-11ec-9461-0a580a82014a) auth_unpin by 0x558f9aa3fc00 on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dversion lock) pv=0 v=400540078 ino=0x10001be180e state=1073741824 | request=1 lock=0 inodepin=1 authpin=0 0x558f99828780] now 0 debug 2023-02-16T09:49:56.265+0000 7f0462329700 15 mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins -1 on [dir 0x10000000001 /volumes/csi/ [2,head] auth v=400540078 cv=400540078/400540078 state=1074003969|complete f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549125=1354219+194906) hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f9aa22d80] by 0x558f9aa3fc00 count now 0/0 debug 2023-02-16T09:49:56.266+0000 7f0462329700 4 mds.0.server handle_client_request client_request(client.66426408:171 lookup #0x10001be180e/.meta 2023-02-16T09:49:56.268272+0000 caller_uid=0, caller_gid=0{}) v5 debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.350627 get_session have 0x558f98893900 client.66426408 10.25.1.17:0/1669277120 state open debug 2023-02-16T09:49:56.266+0000 7f0462329700 15 mds.0.server oldest_client_tid=170 debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache request_start request(client.66426408:171 nref=2 cr=0x558f9a150840) debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.server dispatch_client_request client_request(client.66426408:171 lookup #0x10001be180e/.meta 2023-02-16T09:49:56.268272+0000 caller_uid=0, caller_gid=0{}) v5 debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache traverse: opening base ino 0x10001be180e snap head debug 2023-02-16T09:49:56.266+0000 7f0462329700 12 mds.0.cache traverse: path seg depth 0 '.meta' snapid head debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.cache.dir(0x10001be180e) lookup (head, '.meta') debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.cache.dir(0x10001be180e) hit -> (.meta,head) debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache path_traverse finish on snapid head debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.server rdlock_path_pin_ref request(client.66426408:171 nref=3 cr=0x558f9a150840) #0x10001be180e/.meta debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache traverse: opening base ino 0x10001be180e snap head debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker try_rdlock_snap_layout request(client.66426408:171 nref=4 cr=0x558f9a150840) [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=0 lock=0 dirfrag=1 caps=1 openingsnapparents=0 authpin=0 0x558f99825b80] debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on (isnap sync r=1) [inode 0x10001be180e [...2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=0 lock=1 dirfrag=1 caps=1 openingsnapparents=0 authpin=0 0x558f99825b80] debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on (isnap sync r=1) [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405 f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907) old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on (isnap sync r=1) [inode 0x10000000000 [...c,head] /volumes/ auth v94872546 f(v0 m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956 rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911) old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080] debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on (isnap sync r=1) [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800 f(v1 m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000 b264347801454 1549251=1354337+194914)/n() (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=1 dirfrag=1 caps=1 openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 12 mds.0.cache traverse: path seg depth 0 '.meta' snapid head debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.cache.dir(0x10001be180e) lookup (head, '.meta') debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.cache.dir(0x10001be180e) hit -> (.meta,head) debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks request(client.66426408:171 nref=4 cr=0x558f9a150840) debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock (dn sync) [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824 | request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824 | request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker auth_pinning [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824 | request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache.den(0x10001be180e .meta) auth_pin by 0x558f9aa38000 on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810 state=1073741824 | request=1 lock=0 inodepin=0 authpin=1 0x558f988d2a00] now 1 debug 2023-02-16T09:49:56.266+0000 7f0462329700 15 mds.0.cache.dir(0x10001be180e) adjust_nested_auth_pins 1 on [dir 0x10001be180e /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ [2,head] auth v=192774 cv=192774/192774 ap=0+1 state=1073741825|complete f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 35=24+11) hs=2+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f98722480] by 0x558f9aa38000 count now 0/1 debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.locker rdlock_start on (dn sync) on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810 state=1073741824 | request=1 lock=0 inodepin=0 authpin=1 0x558f988d2a00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker got rdlock on (dn sync r=1) [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head] auth (dn sync r=1) (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810 state=1073741824 | request=1 lock=1 inodepin=0 authpin=1 0x558f988d2a00] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks request(client.66426408:171 nref=4 cr=0x558f9a150840) debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock (isnap sync) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker auth_pinning [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache.ino(0x10001be1810) auth_pin by 0x558f9aa38000 on [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=0 lock=0 caps=0 authpin=1 0x558f988cf600] now 1 debug 2023-02-16T09:49:56.266+0000 7f0462329700 15 mds.0.cache.dir(0x10001be180e) adjust_nested_auth_pins 1 on [dir 0x10001be180e /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ [2,head] auth v=192774 cv=192774/192774 ap=0+2 state=1073741825|complete f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796 rc2022-12-21T19:28:27.124662+0000 b57179 35=24+11) hs=2+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f98722480] by 0x558f988cf600 count now 0/2 debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.locker rdlock_start on (isnap sync) on [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=0 lock=0 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker got rdlock on (isnap sync r=1) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=0 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache path_traverse finish on snapid head debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.server ref is [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=0 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks request(client.66426408:171 nref=3 cr=0x558f9a150840) debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock (iauth sync) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=1 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock (ifile sync) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=1 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=1 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker already auth_pinned [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=1 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 7 mds.0.locker rdlock_start on (ifile sync) on [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) | request=1 lock=1 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker got rdlock on (ifile sync r=1) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (ifile sync r=1) (iversion lock) | request=1 lock=2 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 7 mds.0.locker rdlock_start on (iauth sync) on [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (ifile sync r=1) (iversion lock) | request=1 lock=2 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker got rdlock on (iauth sync r=1) [inode 0x10001be1810 [2,head] /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1 s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iauth sync r=1) (ifile sync r=1) (iversion lock) | request=1 lock=3 caps=0 authpin=1 0x558f988cf600] debug 2023-02-16T09:49:56.267+0000 7f0462329700 20 Session check_access path /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 MDSAuthCap is_capable inode(path /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta owner 0:0 mode 0100640) by caller 0:0 mask 1 new 0:0 cap: MDSAuthCaps[allow *] debug 2023-02-16T09:49:56.267+0000 7f0462329700 20 mds.0.bal hit_dir 0 pop is 1, frag * size 2 [pop IRD:[C 1.00e+00] IWR:[C 0.00e+00] RDR:[C 0.00e+00] FET:[C 0.00e+00] STR:[C 0.00e+00] *LOAD:1.0]
And one more for memory ceph tell mds.gml-okd-cephfs-a config set debug_mds 0/20 This logs from active mds ... debug 2023-02-16T09:54:39.906+0000 7f0460b26700 10 mds.0.cache |__ 0 auth [dir 0x100 ~mds0/ [2,head] auth v=1619006913 cv=1619006913/1619006913 dir_auth=0 state=1073741825|complete f(v0 10=0+10) n(v5122951 rc2023-01-03T22:31:26.260887+0000 b8320360 1131=1097+34)/n(v5122951 rc2023-01-03T22:31:26.236886+0000 b8122960 1092=1058+34) hs=10+0,ss=0+0 | child=1 subtree=1 subtreetemp=0 waiter=0 authpin=0 0x558f9aa22480] debug 2023-02-16T09:54:39.906+0000 7f0460b26700 10 mds.0.cache |__ 0 auth [dir 0x1 / [2,head] auth v=94872547 cv=0/0 dir_auth=0 state=1610874881|complete f(v1 m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000 b264347801454 1549250=1354337+194913) hs=3+0,ss=0+0 dirty=1 | child=1 subtree=1 subtreetemp=0 dirty=1 waiter=0 authpin=0 0x558f9aa22000] debug 2023-02-16T09:54:39.906+0000 7f0460b26700 10 mds.0.cache find_stale_fragment_freeze debug 2023-02-16T09:54:39.906+0000 7f0460b26700 10 mds.0.snap check_osd_map - version unchanged debug 2023-02-16T09:54:39.906+0000 7f0460b26700 20 mds.0.350627 updating export targets, currently 0 ranks are targets debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_client_metrics: mds.metrics: session=0x558f98893900 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=READ_LATENCY, session=0x558f98893900, latency=0.098249 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=WRITE_LATENCY, session=0x558f98893900, latency=0.000000 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=METADATA_LATENCY, session=0x558f98893900, latenc]y=0.399851 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=CAP_INFO, session=0x558f98893900, hits=9580, misses=36 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=DENTRY_LEASE, session=0x558f98893900, hits=0, misses=2063 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_FILES, session=0x558f98893900, opened_files=0, total_inodes=114 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=PINNED_ICAPS, session=0x558f98893900, pinned_icaps=114, total_inodes=114 debug 2023-02-16T09:54:40.130+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_INODES, session=0x558f98893900, opened_inodes=18446744073709551435, total_inodes=114 debug 2023-02-16T09:54:40.191+0000 7f0460b26700 20 mds.0.350627 get_task_status debug 2023-02-16T09:54:40.191+0000 7f0460b26700 20 mds.0.350627 schedule_update_timer_task debug 2023-02-16T09:54:40.619+0000 7f045e321700 20 mds.0.cache upkeep thread trimming cache; last trim 1.001014352s ago debug 2023-02-16T09:54:40.619+0000 7f045e321700 10 mds.0.cache trim_client_leases debug 2023-02-16T09:54:40.619+0000 7f045e321700 7 mds.0.cache trim bytes_used=4MB limit=4GB reservation=0.05% count=0 debug 2023-02-16T09:54:40.619+0000 7f045e321700 7 mds.0.cache trim_lru trimming 0 items from LRU size=1670 mid=1081 pintail=0 pinned=125 debug 2023-02-16T09:54:40.619+0000 7f045e321700 7 mds.0.cache trim_lru trimmed 0 items debug 2023-02-16T09:54:40.619+0000 7f045e321700 2 mds.0.cache Memory usage: total 510776, rss 79592, heap 356604, baseline 356604, 114 / 1673 inodes have caps, 114 caps, 0.0681411 caps per inode debug 2023-02-16T09:54:40.619+0000 7f045e321700 7 mds.0.server recall_client_state: min=100 max=1048576 total=114 flags=0xa debug 2023-02-16T09:54:40.619+0000 7f045e321700 7 mds.0.server recalled 0 client caps. debug 2023-02-16T09:54:40.619+0000 7f045e321700 20 mds.0.cache upkeep thread waiting interval 1.000000000s debug 2023-02-16T09:54:41.130+0000 7f0464b2e700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_client_metrics: mds.metrics: session=0x558f98893900 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=READ_LATENCY, session=0x558f98893900, latency=0.098249 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=WRITE_LATENCY, session=0x558f98893900, latency=0.000000 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=METADATA_LATENCY, session=0x558f98893900, latenc]y=0.399851 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=CAP_INFO, session=0x558f98893900, hits=9580, misses=36 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=DENTRY_LEASE, session=0x558f98893900, hits=0, misses=2063 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_FILES, session=0x558f98893900, opened_files=0, total_inodes=114 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=PINNED_ICAPS, session=0x558f98893900, pinned_icaps=114, total_inodes=114 debug 2023-02-16T09:54:41.131+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_INODES, session=0x558f98893900, opened_inodes=18446744073709551435, total_inodes=114 debug 2023-02-16T09:54:41.219+0000 7f0459b18700 10 mds.metric.aggregator ping_all_active_ranks: pinging 1 active mds(s) debug 2023-02-16T09:54:41.219+0000 7f0459b18700 20 mds.metric.aggregator ping_all_active_ranks: pinging rank=0 addr=[v2:10.25.0.246:6808/319674183,v1:10.25.0.246:6809/319674183] debug 2023-02-16T09:54:41.219+0000 7f0459b18700 10 mds.pinger send_ping: rank=0 debug 2023-02-16T09:54:41.219+0000 7f0459b18700 10 mds.pinger send_ping: sending ping with sequence=106 to rank=0 debug 2023-02-16T09:54:41.219+0000 7f0461b28700 20 set_next_seq: mds.metrics: current sequence number 105, setting next sequence number 106 debug 2023-02-16T09:54:41.268+0000 7f045a319700 20 update_rank0: mds.metrics debug 2023-02-16T09:54:41.268+0000 7f045a319700 20 update_rank0: mds.metrics: sending metric updates for 1 clients to rank 0 (address: [v2:10.25.0.246:6808/319674183,v1:10.25.0.246:6809/319674183]) with sequence number 106, last updated sequence number 263 debug 2023-02-16T09:54:41.268+0000 7f0461b28700 20 mds.metric.aggregator handle_mds_metrics: applying 1 updates for rank=0 with sequence number 106 debug 2023-02-16T09:54:41.268+0000 7f0461b28700 10 mds.pinger pong_received: rank=0, sequence=106 debug 2023-02-16T09:54:41.268+0000 7f0461b28700 20 mds.metric.aggregator refresh_metrics_for_rank: client=client.66407209 10.25.1.17:0/1432178834, rank=0, metrics=[update_type=0, metrics={cap_hit_metric={hits=9580, misses=36}, read_latency={latency=0.098249}, write_latency={latency=0.000000}, metadata_latency={latency=0.399851}, dentry_lease ={hits=0, misses=2063}, opened_files_metric ={opened_files=0, total_inodes=114}, pinned_icaps_metric ={pinned_icaps=114, total_inodes=114}, opened_inodes_metric ={opened_inodes=18446744073709551435, total_inodes=114}}] debug 2023-02-16T09:54:41.619+0000 7f045e321700 20 mds.0.cache upkeep thread trimming cache; last trim 1.000014305s ago debug 2023-02-16T09:54:41.619+0000 7f045e321700 10 mds.0.cache trim_client_leases debug 2023-02-16T09:54:41.619+0000 7f045e321700 7 mds.0.cache trim bytes_used=4MB limit=4GB reservation=0.05% count=0 debug 2023-02-16T09:54:41.619+0000 7f045e321700 7 mds.0.cache trim_lru trimming 0 items from LRU size=1670 mid=1081 pintail=0 pinned=125 debug 2023-02-16T09:54:41.619+0000 7f045e321700 7 mds.0.cache trim_lru trimmed 0 items debug 2023-02-16T09:54:41.620+0000 7f045e321700 2 mds.0.cache Memory usage: total 510776, rss 79592, heap 356604, baseline 356604, 114 / 1673 inodes have caps, 114 caps, 0.0681411 caps per inode debug 2023-02-16T09:54:41.620+0000 7f045e321700 7 mds.0.server recall_client_state: min=100 max=1048576 total=114 flags=0xa debug 2023-02-16T09:54:41.620+0000 7f045e321700 7 mds.0.server recalled 0 client caps. debug 2023-02-16T09:54:41.620+0000 7f045e321700 20 mds.0.cache upkeep thread waiting interval 1.000000000s debug 2023-02-16T09:54:42.053+0000 7f045fb24700 10 mds.pinger is_rank_lagging: rank=0 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_client_metrics: mds.metrics: session=0x558f98893900 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=READ_LATENCY, session=0x558f98893900, latency=0.098249 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=WRITE_LATENCY, session=0x558f98893900, latency=0.000000 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=METADATA_LATENCY, session=0x558f98893900, latenc]y=0.399851 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=CAP_INFO, session=0x558f98893900, hits=9580, misses=36 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=DENTRY_LEASE, session=0x558f98893900, hits=0, misses=2063 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_FILES, session=0x558f98893900, opened_files=0, total_inodes=114 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=PINNED_ICAPS, session=0x558f98893900, pinned_icaps=114, total_inodes=114 debug 2023-02-16T09:54:42.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_INODES, session=0x558f98893900, opened_inodes=18446744073709551435, total_inodes=114 debug 2023-02-16T09:54:42.192+0000 7f0460b26700 20 mds.0.350627 get_task_status debug 2023-02-16T09:54:42.192+0000 7f0460b26700 20 mds.0.350627 schedule_update_timer_task debug 2023-02-16T09:54:42.259+0000 7f0460325700 5 mds.beacon.gml-okd-cephfs-b Sending beacon up:active seq 169 debug 2023-02-16T09:54:42.259+0000 7f0460325700 20 mds.beacon.gml-okd-cephfs-b sender thread waiting interval 4s debug 2023-02-16T09:54:42.262+0000 7f046532f700 5 mds.beacon.gml-okd-cephfs-b received beacon reply up:active seq 169 rtt 0.00300004 debug 2023-02-16T09:54:42.597+0000 7f046432d700 1 mds.gml-okd-cephfs-b asok_command: status {prefix=status} (starting...) debug 2023-02-16T09:54:42.621+0000 7f045e321700 20 mds.0.cache upkeep thread trimming cache; last trim 1.000014305s ago debug 2023-02-16T09:54:42.621+0000 7f045e321700 10 mds.0.cache trim_client_leases debug 2023-02-16T09:54:42.621+0000 7f045e321700 7 mds.0.cache trim bytes_used=4MB limit=4GB reservation=0.05% count=0 debug 2023-02-16T09:54:42.621+0000 7f045e321700 7 mds.0.cache trim_lru trimming 0 items from LRU size=1670 mid=1081 pintail=0 pinned=125 debug 2023-02-16T09:54:42.621+0000 7f045e321700 7 mds.0.cache trim_lru trimmed 0 items debug 2023-02-16T09:54:42.621+0000 7f045e321700 2 mds.0.cache Memory usage: total 510776, rss 79592, heap 356604, baseline 356604, 114 / 1673 inodes have caps, 114 caps, 0.0681411 caps per inode debug 2023-02-16T09:54:42.621+0000 7f045e321700 7 mds.0.server recall_client_state: min=100 max=1048576 total=114 flags=0xa debug 2023-02-16T09:54:42.621+0000 7f045e321700 7 mds.0.server recalled 0 client caps. debug 2023-02-16T09:54:42.621+0000 7f045e321700 20 mds.0.cache upkeep thread waiting interval 1.000000000s debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_client_metrics: mds.metrics: session=0x558f98893900 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=READ_LATENCY, session=0x558f98893900, latency=0.098249 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=WRITE_LATENCY, session=0x558f98893900, latency=0.000000 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=METADATA_LATENCY, session=0x558f98893900, latenc]y=0.399851 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=CAP_INFO, session=0x558f98893900, hits=9580, misses=36 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=DENTRY_LEASE, session=0x558f98893900, hits=0, misses=2063 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_FILES, session=0x558f98893900, opened_files=0, total_inodes=114 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=PINNED_ICAPS, session=0x558f98893900, pinned_icaps=114, total_inodes=114 debug 2023-02-16T09:54:43.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_INODES, session=0x558f98893900, opened_inodes=18446744073709551435, total_inodes=114 debug 2023-02-16T09:54:43.269+0000 7f045a319700 20 update_rank0: mds.metrics debug 2023-02-16T09:54:43.269+0000 7f045a319700 20 update_rank0: mds.metrics: sending metric updates for 1 clients to rank 0 (address: [v2:10.25.0.246:6808/319674183,v1:10.25.0.246:6809/319674183]) with sequence number 106, last updated sequence number 264 debug 2023-02-16T09:54:43.269+0000 7f0461b28700 20 mds.metric.aggregator handle_mds_metrics: applying 1 updates for rank=0 with sequence number 106 debug 2023-02-16T09:54:43.269+0000 7f0461b28700 10 mds.pinger pong_received: rank=0, sequence=106 debug 2023-02-16T09:54:43.269+0000 7f0461b28700 20 mds.metric.aggregator refresh_metrics_for_rank: client=client.66407209 10.25.1.17:0/1432178834, rank=0, metrics=[update_type=0, metrics={cap_hit_metric={hits=9580, misses=36}, read_latency={latency=0.098249}, write_latency={latency=0.000000}, metadata_latency={latency=0.399851}, dentry_lease ={hits=0, misses=2063}, opened_files_metric ={opened_files=0, total_inodes=114}, pinned_icaps_metric ={pinned_icaps=114, total_inodes=114}, opened_inodes_metric ={opened_inodes=18446744073709551435, total_inodes=114}}] debug 2023-02-16T09:54:43.621+0000 7f045e321700 20 mds.0.cache upkeep thread trimming cache; last trim 1.000014305s ago debug 2023-02-16T09:54:43.621+0000 7f045e321700 10 mds.0.cache trim_client_leases debug 2023-02-16T09:54:43.621+0000 7f045e321700 7 mds.0.cache trim bytes_used=4MB limit=4GB reservation=0.05% count=0 debug 2023-02-16T09:54:43.621+0000 7f045e321700 7 mds.0.cache trim_lru trimming 0 items from LRU size=1670 mid=1081 pintail=0 pinned=125 debug 2023-02-16T09:54:43.621+0000 7f045e321700 7 mds.0.cache trim_lru trimmed 0 items debug 2023-02-16T09:54:43.622+0000 7f045e321700 2 mds.0.cache Memory usage: total 510776, rss 79592, heap 356604, baseline 356604, 114 / 1673 inodes have caps, 114 caps, 0.0681411 caps per inode debug 2023-02-16T09:54:43.622+0000 7f045e321700 7 mds.0.server recall_client_state: min=100 max=1048576 total=114 flags=0xa debug 2023-02-16T09:54:43.622+0000 7f045e321700 7 mds.0.server recalled 0 client caps. debug 2023-02-16T09:54:43.622+0000 7f045e321700 20 mds.0.cache upkeep thread waiting interval 1.000000000s debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_client_metrics: mds.metrics: session=0x558f98893900 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=READ_LATENCY, session=0x558f98893900, latency=0.098249 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=WRITE_LATENCY, session=0x558f98893900, latency=0.000000 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=METADATA_LATENCY, session=0x558f98893900, latenc]y=0.399851 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=CAP_INFO, session=0x558f98893900, hits=9580, misses=36 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=DENTRY_LEASE, session=0x558f98893900, hits=0, misses=2063 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_FILES, session=0x558f98893900, opened_files=0, total_inodes=114 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=PINNED_ICAPS, session=0x558f98893900, pinned_icaps=114, total_inodes=114 debug 2023-02-16T09:54:44.132+0000 7f0464b2e700 20 handle_payload: mds.metrics: type=OPENED_INODES, session=0x558f98893900, opened_inodes=18446744073709551435, total_inodes=114 debug 2023-02-16T09:54:44.132+0000 7f0462329700 20 mds.0.350627 get_session have 0x558f98893900 client.66407209 10.25.1.17:0/1432178834 state open debug 2023-02-16T09:54:44.132+0000 7f0462329700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 11) v1 from client.66407209 debug 2023-02-16T09:54:44.132+0000 7f0462329700 10 mds.0.sessionmap touch_session s=0x558f98893900 name=client.66407209 debug 2023-02-16T09:54:44.132+0000 7f0462329700 10 mds.0.350627 send_message_client client.66407209 10.25.1.17:0/1432178834 client_session(renewcaps seq 11) v4 debug 2023-02-16T09:54:44.192+0000 7f0460b26700 20 mds.0.350627 get_task_status debug 2023-02-16T09:54:44.192+0000 7f0460b26700 20 mds.0.350627 schedule_update_timer_task debug 2023-02-16T09:54:44.622+0000 7f045e321700 20 mds.0.cache upkeep thread trimming cache; last trim 1.000014305s ago debug 2023-02-16T09:54:44.622+0000 7f045e321700 10 mds.0.cache trim_client_leases debug 2023-02-16T09:54:44.622+0000 7f045e321700 7 mds.0.cache trim bytes_used=4MB limit=4GB reservation=0.05% count=0 debug 2023-02-16T09:54:44.622+0000 7f045e321700 7 mds.0.cache trim_lru trimming 0 items from LRU size=1670 mid=1081 pintail=0 pinned=125 debug 2023-02-16T09:54:44.622+0000 7f045e321700 7 mds.0.cache trim_lru trimmed 0 items debug 2023-02-16T09:54:44.623+0000 7f045e321700 2 mds.0.cache Memory usage: total 510776, rss 79592, heap 356604, baseline 356604, 114 / 1673 inodes have caps, 114 caps, 0.0681411 caps per inode debug 2023-02-16T09:54:44.623+0000 7f045e321700 7 mds.0.server recall_client_state: min=100 max=1048576 total=114 flags=0xa debug 2023-02-16T09:54:44.623+0000 7f045e321700 7 mds.0.server recalled 0 client caps. debug 2023-02-16T09:54:44.623+0000 7f045e321700 20 mds.0.cache upkeep thread waiting interval 1.000000000s debug 2023-02-16T09:54:44.907+0000 7f0460b26700 10 mds.0.log trim, ignoring read-only FS debug 2023-02-16T09:54:44.907+0000 7f0460b26700 10 mds.0.server find_idle_sessions. last cleared laggy state 666126s ago debug 2023-02-16T09:54:44.907+0000 7f0460b26700 20 mds.0.server laggiest active session is client.66407209 10.25.1.17:0/1432178834 and renewed caps recently (0.775011s ago) debug 2023-02-16T09:54:44.907+0000 7f0460b26700 10 mds.0.locker scatter_tick debug 2023-02-16T09:54:44.907+0000 7f0460b26700 20 mds.0.locker caps_tick 0 revoking caps debug 2023-02-16T09:54:44.907+0000 7f0460b26700 20 mds.0.bal handle_export_pins export_pin_queue size=0 debug 2023-02-16T09:54:44.907+0000 7f0460b26700 15 mds.0.bal tick tick last_sample now 666126.151461s debug 2023-02-16T09:54:44.907+0000 7f0460b26700 15 mds.0.bal get_load mdsload<[pop IRD:[C 1.05e-01] IWR:[C 0.00e+00] RDR:[C 0.00e+00] FET:[C 0.00e+00] STR:[C 0.00e+00] *LOAD:0.1] /[pop IRD:[C 1.05e-01] IWR:[C 0.00e+00] RDR:[C 0.00e+00] FET:[C 0.00e+00] STR:[C 0.00e+00] *LOAD:0.1] , req 0, hr 0, qlen 0, cpu 0.299996> ...
And we found this when active mds start booting. conf: [mds] debug_mds = 0/20 debug_mds_balancer = 1 debug 2023-02-16T10:25:15.393+0000 7fd58cbc6780 0 set uid:gid to 167:167 (ceph:ceph) debug 2023-02-16T10:25:15.393+0000 7fd58cbc6780 0 ceph version 16.2.4 (3cbe25cde3cfa028984618ad32de9edc4c1eaed0) pacific (stable), process ceph-mds, pid 1 debug 2023-02-16T10:25:15.395+0000 7fd58cbc6780 0 pidfile_write: ignore empty --pid-file starting mds.gml-okd-cephfs-a at debug 2023-02-16T10:28:02.642+0000 7fd575aef700 0 mds.0.journaler.pq(ro) _finish_read got error -2 debug 2023-02-16T10:28:02.642+0000 7fd575aef700 -1 mds.0.purge_queue _recover: Error -2 recovering write_pos debug 2023-02-16T10:28:02.671+0000 7fd575aef700 -1 mds.0.350650 unhandled write error (2) No such file or directory, force readonly... debug 2023-02-16T10:28:02.671+0000 7fd575aef700 0 log_channel(cluster) log [WRN] : force file system read-only debug 2023-02-16T10:28:02.671+0000 7fd575aef700 0 mds.0.journaler.pq(ro) _finish_read got error -2 debug 2023-02-16T10:28:02.671+0000 7fd5742ec700 0 mds.0.cache creating system inode with ino:0x100 debug 2023-02-16T10:28:02.672+0000 7fd5742ec700 0 mds.0.cache creating system inode with ino:0x1 debug 2023-02-16T10:28:02.780+0000 7fd5732ea700 0 mds.0.350650 boot error forcing transition to read-only; MDS will try to continue debug 2023-02-16T10:28:08.265+0000 7fd5782f4700 -1 mds.pinger is_rank_lagging: rank=0 was never sent ping request.
I forgot one more thing. Now when pod trying to mount pvc i have this issue: mssql-mssql-linux-698474b5d8-cpn6m MountVolume.MountDevice failed for volume "pvc-6b6ea6e8-ca60-4082-8f72-3a369aa99435" : rpc error: code = Internal desc = rados: ret=-30, Read-only file system: "error in setxattr"
participants (2)
-
Eugen Block
-
kreept.sama＠gmail.com