Ceph » Linux kernel client

Zheng says:

inodes 0x100 to 0x1ff are mdsdir inode. this can happen when the inode
is stray dir. I think the fix is create dummy inode and snaprealm for
0x100 ~ 0x1ff. The dummy snaprealm has seq == 1, all of the rest fields
are set to 0.

He also mentioned creating just one entry for the entire range. I'll have to see if that is possible.

I'm still trying to wrap my brain around the locking in this code, but it's pretty clear that it's badly broken (or at least, not working as advertised). In particular, ceph_get_snap_realm is documented as requiring the caller hold the snap_rwsem for write, but it's not held for that in the ceph_add_cap codepath.

While adding the dummy realms that Zheng mentioned in the comment above might be part of the eventual fix, I think we're probably encountering some races in this code due to inconsistent locking that may be explain some of the refcounting issues.

The snaprealm locking is not as broken as I had originally feared. Some of the comments were definitely wrong, but they mostly just claimed you needed to hold the snap_rwsem for write when holding it for read is actually OK. I'm working some patches to fix those (and correct the comments).

I'll still need to spin up some code to handle creating this dummy snaprealm, but I'm not quite to where I understand this enough to do it yet.

The refcounting bug looks different however. I think that is actually indicative of a refcounting bug in the snap_context handling (not to be confused with a snap_realm). I suspect the BUG_ON in slub.c is showing the result of a double free, of one of those objects.

We have had two hangs today we think due to this bug, any thoughts on whether this will arrive in Octopus soon? thanks.

Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796634] ------------[ cut here ]------------
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796635] kernel BUG at mm/slub.c:306!
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796661] invalid opcode: 0000 [#1] SMP NOPTI
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796680] CPU: 58 PID: 6015 Comm: kworker/58:14 Tainted: G W 5.4.0-77-generic #86-Ubuntu
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796711] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-1 04/01/2014
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796748] Workqueue: ceph-msgr ceph_con_workfn [libceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796774] RIP: 0010:kfree+0x236/0x250
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796795] Code: e7 e8 ae 75 fd ff e9 ef fe ff ff 4d 89 f1 41 b8 01 00 00 00 48 89 d9 48 89 da 4c 89 e6 4c 89 ef e8 9f fa ff ff e9 d0 fe ff ff <0f> 0b 48 8b 05 31 c8 37 01 e9 ff fd ff ff 66 66 2e 0f 1f 84 00 00
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796862] RSP: 0018:ffffb8a0018e3c40 EFLAGS: 00010246
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796886] RAX: ffff8a66bfb81800 RBX: ffff8a66bfb81800 RCX: ffff8a66bfb81800
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796905] RDX: 000000000007f3eb RSI: ffff8a66bf9988f8 RDI: ffff8a66bfb81800
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796923] RBP: ffffb8a0018e3c60 R08: ffff8a615edb3e18 R09: ffff8a6686b70818
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796941] R10: 0000000000000000 R11: 0000000000000001 R12: ffffe4ef5dfee000
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796962] R13: ffff8a66d2806f40 R14: ffffffffc0b0a194 R15: ffff8a666b027c00
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.796985] FS: 0000000000000000(0000) GS:ffff8a66dfa80000(0000) knlGS:0000000000000000
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797009] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797033] CR2: 00007f8791321490 CR3: 0000002780024000 CR4: 00000000003406e0
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797055] Call Trace:
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797072] __destroy_snap_realm+0xa4/0x110 [ceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797104] ceph_put_snap_realm+0x6f/0xe0 [ceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797127] handle_reply+0x2e4/0x6a0 [ceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797146] dispatch+0xe9/0x610 [ceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797167] try_read+0x566/0x8c0 [libceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797185] ? __switch_to_asm+0x40/0x70
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797198] ? __switch_to_asm+0x34/0x70
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797210] ? __switch_to_asm+0x40/0x70
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797222] ? __switch_to+0x68/0x470
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797233] ? __switch_to_asm+0x34/0x70
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797251] ceph_con_workfn+0x130/0x620 [libceph]
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797270] process_one_work+0x1eb/0x3b0
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797286] worker_thread+0x4d/0x400
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797301] kthread+0x104/0x140
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797315] ? process_one_work+0x3b0/0x3b0
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797332] ? kthread_park+0x90/0x90
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797348] ret_from_fork+0x22/0x40
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797364] Modules linked in: xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 bpfilter br_netfilter bridge stp llc nfsv3 rpcsec_gss_krb5 nfsv4 nfs aufs ceph libceph fscache overlay dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg snd_hda_codec snd_hda_core snd_hwdep snd_pcm kvm_amd joydev ccp snd_timer snd soundcore input_leds kvm mac_hid serio_raw qemu_fw_cfg nfsd auth_rpcgss nfs_acl lockd sch_fq_codel grace sunrpc ip_tables x_tables autofs4 xfs btrfs zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic qxl ttm usbhid crct10dif_pclmul drm_kms_helper crc32_pclmul syscopyarea ghash_clmulni_intel sysfillrect aesni_intel virtio_net crypto_simd sysimgblt cryptd fb_sys_fops net_failover hid glue_helper psmouse
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.797379] virtio_blk drm failover i2c_piix4 floppy pata_acpi
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.798295] ---[ end trace a5b8b4af5b4054bb ]---
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.798952] RIP: 0010:kfree+0x236/0x250
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.799625] Code: e7 e8 ae 75 fd ff e9 ef fe ff ff 4d 89 f1 41 b8 01 00 00 00 48 89 d9 48 89 da 4c 89 e6 4c 89 ef e8 9f fa ff ff e9 d0 fe ff ff <0f> 0b 48 8b 05 31 c8 37 01 e9 ff fd ff ff 66 66 2e 0f 1f 84 00 00
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.800763] RSP: 0018:ffffb8a0018e3c40 EFLAGS: 00010246
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.801335] RAX: ffff8a66bfb81800 RBX: ffff8a66bfb81800 RCX: ffff8a66bfb81800
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.801914] RDX: 000000000007f3eb RSI: ffff8a66bf9988f8 RDI: ffff8a66bfb81800
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.802461] RBP: ffffb8a0018e3c60 R08: ffff8a615edb3e18 R09: ffff8a6686b70818
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.803000] R10: 0000000000000000 R11: 0000000000000001 R12: ffffe4ef5dfee000
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.803547] R13: ffff8a66d2806f40 R14: ffffffffc0b0a194 R15: ffff8a666b027c00
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.804086] FS: 0000000000000000(0000) GS:ffff8a66dfa80000(0000) knlGS:0000000000000000
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.804616] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul 6 00:50:19 rosalind-ceph-gw kernel: [ 5091.805146] CR2: 00007f8791321490 CR3: 0000002780024000 CR4: 00000000003406e0
Jul 6 00:50:45 rosalind-ceph-gw kernel: [ 5117.949546] libceph: mon1 (1)172.27.51.22:6789 session lost, hunting for new mon
Jul 6 00:50:45 rosalind-ceph-gw kernel: [ 5117.950444] libceph: mon1 (1)172.27.51.22:6789 session lost, hunting for new mon
Jul 6 00:50:45 rosalind-ceph-gw kernel: [ 5117.951025] libceph: mon1 (1)172.27.51.22:6789 session lost, hunting for new mon
Jul 6 00:50:45 rosalind-ceph-gw kernel: [ 5117.951608] libceph: mon0 (1)172.27.51.20:6789 session lost, hunting for new mon
Jul 6 00:50:45 rosalind-ceph-gw kernel: [ 5117.952148] libceph: mon2 (1)172.27.51.23:6789 session lost, hunting for new mon
Jul 6 00:51:12 rosalind-ceph-gw kernel: [ 5144.829632] ceph: mds0 caps stale
Jul 6 00:51:12 rosalind-ceph-gw kernel: [ 5144.830229] ceph: mds0 caps stale
Jul 6 00:51:12 rosalind-ceph-gw kernel: [ 5144.830727] ceph: mds0 caps stale
Jul 6 00:51:12 rosalind-ceph-gw kernel: [ 5144.831210] ceph: mds0 caps stale

This is a kernel bug, so it wouldn't land in a particular ceph release. That said, there are no patches for this yet, so the ETA is not yet clear.

I pulled down the kernel debuginfo for the kernel from Mark's original report. The stack trace that shows the refcount_t warning is putting the snaprealm at the end of the cap import process:

        case CEPH_CAP_OP_IMPORT:
                realm = NULL;
                if (snaptrace_len) {
                        down_write(&mdsc->snap_rwsem);
                        ceph_update_snap_trace(mdsc, snaptrace,
                                               snaptrace + snaptrace_len,
                                               false, &realm);
                        downgrade_write(&mdsc->snap_rwsem);
                } else {
                        down_read(&mdsc->snap_rwsem);
                }
                handle_cap_import(mdsc, inode, h, peer, session,
                                  &cap, &extra_info.issued);
                handle_cap_grant(inode, session, cap,
                                 h, msg->middle, &extra_info);
                if (realm)
                        ceph_put_snap_realm(mdsc, realm);                 <<<< refcount_t underput here
                goto done_unlocked;

Nigel Williams wrote:

We have had two hangs today we think due to this bug, any thoughts on whether this will arrive in Octopus soon? thanks.

Nigel, I'm not certain this is the same bug as the one Mark saw. It's possible that it's something different. You may want to try a newer kernel if you're having issues -- 5.4 is quite old at this point.

After going over this code in some pretty heavy detail, I think I've spotted a potential race in ceph_put_snap_realm:

void ceph_put_snap_realm(struct ceph_mds_client *mdsc,
                         struct ceph_snap_realm *realm)
{
        dout("put_snap_realm %llx %p %d -> %d\n", realm->ino, realm,
             atomic_read(&realm->nref), atomic_read(&realm->nref)-1);
        if (!atomic_dec_and_test(&realm->nref))
                return;

        if (down_write_trylock(&mdsc->snap_rwsem)) {
                __destroy_snap_realm(mdsc, realm);
                up_write(&mdsc->snap_rwsem);
        } else {
                spin_lock(&mdsc->snap_empty_lock);
                list_add(&realm->empty_item, &mdsc->snap_empty);
                spin_unlock(&mdsc->snap_empty_lock);
        }
}

The problem here is that a ceph_get_snap_realm could race with this, and we end up putting the thing on the snap_empty list when we shouldn't. What we probably need to do is atomic_dec_and_lock the snap_empty_lock here and then just drop it if we can get the mutex. There are a couple of other places that change the nref though that probably also need to hold the spinlock too.

Longer term, we probably need to re-think the lifecycle of the snaprealm objects altogether. The locking around them is really complicated, and the code currently makes heavy use of recursion (which is generally frowned-upon in the kernel). It could use a substantial rework.

Ok, patch posted here:

https://lore.kernel.org/ceph-devel/20210803175126.29165-1-jlayton@kernel.org/T/#u

I suspect this may be the cause of the panic that Nigel saw as well. I'll plan to put this into the testing kernel for now, but we'll probably want this in v5.14 and stable kernels.