10 Feb
2023
10 Feb
'23
6:04 p.m.
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-…
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!
11 Feb
11 Feb
4:09 p.m.
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
7:47 p.m.
Hi,
do you have log output from the read-only MDS, probably in debug mode?
Zitat von kreept.sama(a)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-…
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(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io
12 Feb
12 Feb
2:16 p.m.
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...)
...
13 Feb
13 Feb
4:28 p.m.
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(a)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(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io
16 Feb
16 Feb
2:21 a.m.
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
2:56 p.m.
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(a)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(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io
5:01 p.m.
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]
5:02 p.m.
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>
...
5:31 p.m.
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.
2:53 a.m.
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"
443
days inactive
449
days old
10 comments
2 participants
participants (2)
-
Eugen Block -
kreept.sama＠gmail.com