Ceph : Issues
https://tracker.ceph.com/
https://tracker.ceph.com/favicon.ico
2024-03-18T07:58:55Z
Ceph
Redmine
CephFS - Bug #64961 (Fix Under Review): ceph-fuse: crash when try to open & trunc a encrypted file
https://tracker.ceph.com/issues/64961
2024-03-18T07:58:55Z
Xiubo Li
xiubli@redhat.com
<p>Mount a kclient and encrypt it and then use a ceph-fuse client tries to open & trunc it, though it returned failure with <strong>read-only</strong> filesystem, but the size will be truncated successfully and at the same time the <strong>ceph-fuse</strong> daemon will crash:</p>
<pre>
1503 -9> 2024-03-18T14:53:28.233+0800 7fbade000640 10 client.4286 _release_fh 0x7fba800032e0 on inode 0x1000000000d.head(faked_ino=0 nref=14 ll_ref=1 cap_refs={} open={2=0} mode=100644 size=0/0 nlink=1 btime=2024-03-18T14:15:08 .337113+0800 mtime=2024-03-18T14:53:27.906965+0800 ctime=2024-03-18T14:53:27.906965+0800 change_attr=14 caps=pAsxLsXsxFscb(0=pAsxLsXsxFscb) objectset[0x1000000000d ts 6/0 objects 0 dirty_or_tx 0] parents=0x1000000000c.head["+R 3FPdfhbcIGXae7a2+ZSg"] 0x7fbaa8009220) no async_err state
1504 -8> 2024-03-18T14:53:28.233+0800 7fbade000640 20 client.4286 put_inode on 0x1000000000d.head(faked_ino=0 nref=14 ll_ref=1 cap_refs={} open={2=0} mode=100644 size=0/0 nlink=1 btime=2024-03-18T14:15:08.337113+0800 mtime=2024 -03-18T14:53:27.906965+0800 ctime=2024-03-18T14:53:27.906965+0800 change_attr=14 caps=pAsxLsXsxFscb(0=pAsxLsXsxFscb) objectset[0x1000000000d ts 6/0 objects 0 dirty_or_tx 0] parents=0x1000000000c.head["+R3FPdfhbcIGXae7a2+ZSg"] 0x7fbaa8009220) n = 1
1505 -7> 2024-03-18T14:53:28.233+0800 7fbaea000640 1 -- 192.168.0.100:0/1186915634 <== mds.0 v2:192.168.0.100:6813/4235335776 12 ==== client_caps(trunc ino 0x1000000000d 62 seq 5 caps=pAsxLsXsxFscb dirty=- wanted=pAsxXsxFxwb f ollows 0 size 0/4194304 ts 6/0 mtime 2024-03-18T14:53:27.906965+0800 ctime 2024-03-18T14:53:27.906965+0800 change_attr 14 tws 4) v12 ==== 316+0+0 (crc 0 0 0) 0x7fbae400e7b0 con 0x5627ae355150
1506 -6> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 mds.0 seq now 4
1507 -5> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 handle_cap_trunc : 5540 lxb ---------------------------
1508 -4> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 handle_cap_trunc : 5542 lxb ---------------------------
1509 -3> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 handle_cap_trunc : 5544 lxb ---------------------------
1510 -2> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 handle_cap_trunc : 5547 lxb ---------------------------
1511 -1> 2024-03-18T14:53:28.233+0800 7fbaea000640 10 client.4286 handle_cap_trunc : 5549 lxb ---------------------------
1512 0> 2024-03-18T14:53:28.239+0800 7fbaea000640 -1 *** Caught signal (Aborted) **
1513 in thread 7fbaea000640 thread_name:ms_dispatch
1514
1515 ceph version 19.0.0-2007-g49f7bc2afcf (49f7bc2afcf1d8c2a0c49dc924490ec7189afe5e) squid (dev)
1516 1: /lib64/libc.so.6(+0x54df0) [0x7fbb0b254df0]
1517 2: /lib64/libc.so.6(+0xa157c) [0x7fbb0b2a157c]
1518 3: raise()
1519 4: abort()
1520 5: /lib64/libstdc++.so.6(+0xa1a01) [0x7fbb0b6a1a01]
1521 6: /lib64/libstdc++.so.6(+0xad37c) [0x7fbb0b6ad37c]
1522 7: /lib64/libstdc++.so.6(+0xad3e7) [0x7fbb0b6ad3e7]
1523 8: /lib64/libstdc++.so.6(+0xad649) [0x7fbb0b6ad649]
1524 9: (std::__throw_invalid_argument(char const*)+0x41) [0x7fbb0b6a4363]
1525 10: (long long __gnu_cxx::__stoa<long long, long long, char, int>(long long (*)(char const*, char**, int), char const*, char const*, unsigned long*, int)+0xa7) [0x5627acf40629]
1526 11: (Client::handle_cap_trunc(MetaSession*, Inode*, boost::intrusive_ptr<MClientCaps const> const&)+0x17d) [0x5627aceb18e3]
1527 12: (Client::handle_caps(boost::intrusive_ptr<MClientCaps const> const&)+0x284) [0x5627acf1ef14]
1528 13: (Client::ms_dispatch2(boost::intrusive_ptr<Message> const&)+0x251) [0x5627acf32119]
1529 14: (Messenger::ms_deliver_dispatch(boost::intrusive_ptr<Message> const&)+0xb6) [0x7fbb0c6389a4]
1530 15: (DispatchQueue::entry()+0xb0b) [0x7fbb0c6360bb]
1531 16: (DispatchQueue::DispatchThread::entry()+0xd) [0x7fbb0c7169a9]
1532 17: (Thread::entry_wrapper()+0x3f) [0x7fbb0c4861a7]
1533 18: (Thread::_entry_func(void*)+0x9) [0x7fbb0c4861bf]
1534 19: /lib64/libc.so.6(+0x9f832) [0x7fbb0b29f832]
1535 20: /lib64/libc.so.6(+0x3f450) [0x7fbb0b23f450]
1536 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
1537
</pre>
CephFS - Bug #64679 (Fix Under Review): cephfs: removexattr should always return -ENODATA when xa...
https://tracker.ceph.com/issues/64679
2024-03-04T07:05:10Z
Xiubo Li
xiubli@redhat.com
<p>This issue is from <a class="external" href="https://github.com/ceph/ceph/pull/55087">https://github.com/ceph/ceph/pull/55087</a>.</p>
<p>The POSIX says we should return -ENODATA when the corresponding<br />attribute doesn't exist when removing it. While there is one<br />exception for the acl ones in the local filesystems, for exmaple<br />for xfs, which will treat it as success.</p>
<p>While in the MDS side there have two ways to remove the xattr:<br />sending a CEPH_MDS_OP_SETXATTR request by setting the 'flags' with<br />CEPH_XATTR_REMOVE and just issued a CEPH_MDS_OP_RMXATTR request<br />directly.</p>
<p>For the first one it will always return 0 when the corresponding<br />xattr doesn't exist, while for the later one it will return<br />-ENODATA instead, this should be fixed in MDS to make them to be<br />consistent.</p>
CephFS - Bug #64654 (Duplicate): fscrypt: add mount-syntax/v2 test for fscrypt
https://tracker.ceph.com/issues/64654
2024-03-01T03:07:12Z
Xiubo Li
xiubli@redhat.com
<p>We missed the v2 test for fscrypt.</p>
Linux kernel client - Bug #64607 (Fix Under Review): ceph: fstest generic/580 test failure with i...
https://tracker.ceph.com/issues/64607
2024-02-28T04:41:33Z
Xiubo Li
xiubli@redhat.com
<p>This is reported by Luis, please see <a class="external" href="https://patchwork.kernel.org/project/ceph-devel/patch/20240125023920.1287555-4-xiubli@redhat.com/">https://patchwork.kernel.org/project/ceph-devel/patch/20240125023920.1287555-4-xiubli@redhat.com/</a>.</p>
<pre>
I'm seeing an issue with fstest generic/580, which seems to enter an
infinite loop effectively rendering the testing VM unusable. It's pretty
easy to reproduce, just run the test ensuring to be using msgv2 (I'm
mounting the filesystem with 'ms_mode=crc'), and you should see the
following on the logs:
[...]
libceph: prepare_sparse_read_cont: ret 0x1000 total_resid 0x0 resid 0x0
libceph: osd1 (2)192.168.155.1:6810 read processing error
libceph: mon0 (2)192.168.155.1:40608 session established
libceph: bad late_status 0x1
libceph: osd1 (2)192.168.155.1:6810 protocol error, bad epilogue
libceph: mon0 (2)192.168.155.1:40608 session established
libceph: prepare_sparse_read_cont: ret 0x1000 total_resid 0x0 resid 0x0
libceph: osd1 (2)192.168.155.1:6810 read processing error
libceph: mon0 (2)192.168.155.1:40608 session established
libceph: bad late_status 0x1
[...]
Reverting this patch (commit 8e46a2d068c9 ("libceph: just wait for more
data to be available on the socket")) seems to fix. I haven't
investigated it further, but since it'll take me some time to refresh my
memory, I thought I should report it immediately. Maybe someone has any
idea.
Cheers,
--
Luís
</pre>
Linux kernel client - Bug #64035 (Fix Under Review): fscrypt test trigger "kernel BUG at fs/ceph/...
https://tracker.ceph.com/issues/64035
2024-01-16T07:49:16Z
Xiubo Li
xiubli@redhat.com
<pre>
<6>[ 773.668394] libceph: mon0 (1)192.168.0.108:40357 session established
<6>[ 773.670260] libceph: client34235 fsid 85accf61-baa5-4166-8ad4-a22b1b6a04f1
<4>[ 773.670739] ceph: test_dummy_encryption mode enabled
<12>[ 774.251933] run fstests ceph/002 at 2024-01-16 12:27:17
<6>[ 775.508975] fscrypt: AES-256-XTS using implementation "xts-aes-aesni"
<12>[ 776.567073] run fstests ceph/003 at 2024-01-16 12:27:19
<12>[ 778.967859] run fstests ceph/004 at 2024-01-16 12:27:22
<4>[ 780.664091] ------------[ cut here ]------------
<4>[ 780.664099] WARNING: CPU: 2 PID: 78 at fs/crypto/crypto.c:123 fscrypt_crypt_data_unit+0x3a9/0x3d0
<4>[ 780.664110] Modules linked in: ceph(E) libceph(E) dns_resolver fscache netfs xsk_diag snd_seq_dummy snd_hrtimer qrtr rfkill intel_rapl_msr intel_rapl_common snd_intel8x0 intel_pmc_core snd_ac97_codec ac97_bus rapl snd_seq snd_seq_device snd_pcm pktcdvd snd_timer snd pcspkr soundcore i2c_piix4 xfs libcrc32c sr_mod sd_mod cdrom t10_pi sg ata_generic vmwgfx drm_ttm_helper ttm ahci crct10dif_pclmul crc32_pclmul virtio_net video drm_kms_helper net_failover crc32c_intel libahci ata_piix wmi failover ghash_clmulni_intel drm e1000 libata serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse
<4>[ 780.664213] CPU: 2 PID: 78 Comm: kworker/u23:0 Kdump: loaded Tainted: G E 6.7.0+ #38
<4>[ 780.664219] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
<4>[ 780.664222] Workqueue: writeback wb_workfn (flush-ceph-2)
<4>[ 780.664231] RIP: 0010:fscrypt_crypt_data_unit+0x3a9/0x3d0
<4>[ 780.664237] Code: e8 3c 45 d6 00 44 8b a4 24 68 01 00 00 c7 84 24 08 01 00 00 00 00 00 00 e9 e0 fe ff ff 0f 0b 41 bc ea ff ff ff e9 e7 fe ff ff <0f> 0b 41 bc ea ff ff ff e9 da fe ff ff 41 bc f4 ff ff ff e9 cf fe
<4>[ 780.664242] RSP: 0018:ffff888101057150 EFLAGS: 00010202
<4>[ 780.664248] RAX: 0000000000000000 RBX: 1ffff1102020ae2d RCX: ffffffff8c3d641e
<4>[ 780.664252] RDX: dffffc0000000000 RSI: 0000000000000000 RDI: ffff8882d94613c0
<4>[ 780.664256] RBP: 0000000000000000 R08: ffffffff8be6662f R09: 0000000000000000
<4>[ 780.664259] R10: ffffffff8ef6b467 R11: ffffffff8bc5dff0 R12: 0000000000000001
<4>[ 780.664263] R13: ffff8882d94613c0 R14: ffff888124fc3700 R15: 0000000000000000
<4>[ 780.664269] FS: 0000000000000000(0000) GS:ffff888469400000(0000) knlGS:0000000000000000
<4>[ 780.664274] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 780.664277] CR2: 000055f9b72ba000 CR3: 000000013952a004 CR4: 00000000000706f0
<4>[ 780.664281] Call Trace:
<4>[ 780.664285] <TASK>
<4>[ 780.664288] ? __warn+0xa1/0x200
<4>[ 780.664296] ? fscrypt_crypt_data_unit+0x3a9/0x3d0
<4>[ 780.664309] ? report_bug+0x1c7/0x1d0
<4>[ 780.664317] ? handle_bug+0x3c/0x70
<4>[ 780.664322] ? exc_invalid_op+0x14/0x50
<4>[ 780.664328] ? asm_exc_invalid_op+0x16/0x20
<4>[ 780.664336] ? ret_from_fork+0x30/0x50
<4>[ 780.664348] ? lockdep_init_map_type+0xdf/0x370
<4>[ 780.664354] ? fscrypt_crypt_data_unit+0xee/0x3d0
<4>[ 780.664360] ? fscrypt_crypt_data_unit+0x3a9/0x3d0
<4>[ 780.664368] ? __pfx_fscrypt_crypt_data_unit+0x10/0x10
<4>[ 780.664373] ? alloc_pages_mpol+0x113/0x300
<4>[ 780.664379] ? kthread+0x1a7/0x1f0
<4>[ 780.664385] ? __pfx_alloc_pages_mpol+0x10/0x10
<4>[ 780.664391] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664396] ? __writeback_single_inode+0x95/0x450
<4>[ 780.664402] ? writeback_sb_inodes+0x395/0x7e0
<4>[ 780.664407] ? wb_writeback+0x2ab/0x530
<4>[ 780.664412] ? fs_reclaim_acquire+0x63/0xf0
<4>[ 780.664419] ? __pfx_mempool_alloc_pages+0x10/0x10
<4>[ 780.664428] ? mempool_alloc+0xe9/0x270
<4>[ 780.664438] ? __kmem_cache_alloc_node+0x235/0x3d0
<4>[ 780.664444] ? trace_hardirqs_on+0x12/0xe0
<4>[ 780.664451] fscrypt_encrypt_pagecache_blocks+0x1c3/0x260
<4>[ 780.664460] ceph_writepages_start+0x891/0x2aa0 [ceph]
<4>[ 780.664548] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.664554] ? __list_add_valid_or_report+0x35/0xc0
<4>[ 780.664568] ? blk_insert_flush+0x1b5/0x2f0
<4>[ 780.664579] ? __pfx_ceph_writepages_start+0x10/0x10 [ceph]
<4>[ 780.664662] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664669] ? lock_acquire+0xc7/0x3e0
<4>[ 780.664674] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664680] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664687] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664692] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664698] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664704] ? lock_acquire+0xc7/0x3e0
<4>[ 780.664710] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664730] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.664737] ? __pfx_do_raw_spin_trylock+0x10/0x10
<4>[ 780.664747] do_writepages+0x106/0x320
<4>[ 780.664753] ? __pfx_do_writepages+0x10/0x10
<4>[ 780.664758] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664764] ? __pfx_wb_calc_thresh+0x10/0x10
<4>[ 780.664771] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.664777] ? __pfx_do_raw_spin_trylock+0x10/0x10
<4>[ 780.664784] __writeback_single_inode+0x95/0x450
<4>[ 780.664793] writeback_sb_inodes+0x395/0x7e0
<4>[ 780.664801] ? lock_acquire+0xc7/0x3e0
<4>[ 780.664807] ? __pfx_writeback_sb_inodes+0x10/0x10
<4>[ 780.664817] ? down_read_trylock+0x47/0x60
<4>[ 780.664824] __writeback_inodes_wb+0x6a/0x130
<4>[ 780.664831] wb_writeback+0x2ab/0x530
<4>[ 780.664837] ? __pfx_wb_writeback+0x10/0x10
<4>[ 780.664844] ? _find_next_bit+0x37/0xc0
<4>[ 780.664854] wb_do_writeback+0x434/0x4f0
<4>[ 780.664860] ? __pfx_wb_do_writeback+0x10/0x10
<4>[ 780.664865] ? __update_load_avg_cfs_rq+0x5f/0x480
<4>[ 780.664883] wb_workfn+0xe0/0x400
<4>[ 780.664889] ? __pfx_wb_workfn+0x10/0x10
<4>[ 780.664894] ? set_next_entity+0xff/0x320
<4>[ 780.664900] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664905] ? lock_acquire+0xc7/0x3e0
<4>[ 780.664911] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664916] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.664921] ? lock_unpin_lock+0x77/0x240
<4>[ 780.664928] ? rcu_is_watching+0x1f/0x50
<4>[ 780.664933] ? lockdep_hardirqs_on_prepare+0xc/0x60
<4>[ 780.664938] ? trace_hardirqs_on+0x12/0xe0
<4>[ 780.664944] ? finish_task_switch.isra.0+0x1ae/0x560
<4>[ 780.664952] process_one_work+0x46a/0x910
<4>[ 780.664962] ? __pfx_process_one_work+0x10/0x10
<4>[ 780.664968] ? __list_add_valid_or_report+0x35/0xc0
<4>[ 780.664979] worker_thread+0x385/0x670
<4>[ 780.664988] ? __pfx_worker_thread+0x10/0x10
<4>[ 780.664993] kthread+0x1a7/0x1f0
<4>[ 780.664999] ? kthread+0xf9/0x1f0
<4>[ 780.665004] ? __pfx_kthread+0x10/0x10
<4>[ 780.665045] ret_from_fork+0x30/0x50
<4>[ 780.665054] ? __pfx_kthread+0x10/0x10
<4>[ 780.665061] ret_from_fork_asm+0x1b/0x30
<4>[ 780.665072] </TASK>
<4>[ 780.665075] irq event stamp: 1818
<4>[ 780.665078] hardirqs last enabled at (1817): [<ffffffff8d1490d4>] _raw_spin_unlock_irq+0x24/0x40
<4>[ 780.665085] hardirqs last disabled at (1818): [<ffffffff8d138f0f>] __schedule+0x6ef/0xde0
<4>[ 780.665091] softirqs last enabled at (1270): [<ffffffff8d14b3f9>] __do_softirq+0x3d9/0x4d5
<4>[ 780.665096] softirqs last disabled at (1261): [<ffffffff8bd7bd82>] __irq_exit_rcu+0xf2/0x110
<4>[ 780.665102] ---[ end trace 0000000000000000 ]---
<3>[ 780.665108] ceph: [85accf61-baa5-4166-8ad4-a22b1b6a04f1 34229]: inode->i_blkbits=12
<4>[ 780.665154] ------------[ cut here ]------------
<2>[ 780.665158] kernel BUG at fs/ceph/addr.c:1183!
<4>[ 780.665169] invalid opcode: 0000 [#1] PREEMPT SMP KASAN PTI
<4>[ 780.665178] CPU: 2 PID: 78 Comm: kworker/u23:0 Kdump: loaded Tainted: G W E 6.7.0+ #38
<4>[ 780.665187] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
<4>[ 780.665193] Workqueue: writeback wb_workfn (flush-ceph-2)
<4>[ 780.665203] RIP: 0010:ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665334] Code: 20 47 95 c1 4c 89 fa 48 c7 c6 20 2f 95 c1 48 c7 c7 10 8e 91 c1 e8 e8 9a e5 ca 48 c7 85 48 fd ff ff ff ff ff ff e9 da de ff ff <0f> 0b 0f 0b 48 8b bd e0 fd ff ff e8 c8 71 9e ca 4c 8b bd f8 fd ff
<4>[ 780.665339] RSP: 0018:ffff8881010573a0 EFLAGS: 00010246
<4>[ 780.665344] RAX: 0000000000000047 RBX: ffff888123e3a200 RCX: 0000000000000027
<4>[ 780.665348] RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffff8884695ffbc8
<4>[ 780.665352] RBP: ffff8881010576f0 R08: ffffffff8c0506ce R09: ffffed108d2bff79
<4>[ 780.665356] R10: ffff8884695ffbcb R11: 0000000000000001 R12: ffff88812d791910
<4>[ 780.665360] R13: ffffea000ba2c7c0 R14: 0000000000000000 R15: ffff8881da544000
<4>[ 780.665366] FS: 0000000000000000(0000) GS:ffff888469400000(0000) knlGS:0000000000000000
<4>[ 780.665370] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[ 780.665374] CR2: 000055f9b72ba000 CR3: 000000013952a004 CR4: 00000000000706f0
<4>[ 780.665378] Call Trace:
<4>[ 780.665382] <TASK>
<4>[ 780.665385] ? die+0x33/0x90
<4>[ 780.665392] ? do_trap+0x133/0x170
<4>[ 780.665398] ? ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665486] ? do_error_trap+0xab/0x130
<4>[ 780.665492] ? ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665579] ? ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665689] ? handle_invalid_op+0x2c/0x40
<4>[ 780.665698] ? ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665811] ? exc_invalid_op+0x2b/0x50
<4>[ 780.665818] ? asm_exc_invalid_op+0x16/0x20
<4>[ 780.665830] ? irq_work_claim+0x1e/0x40
<4>[ 780.665840] ? ceph_writepages_start+0x2598/0x2aa0 [ceph]
<4>[ 780.665958] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.665969] ? __list_add_valid_or_report+0x35/0xc0
<4>[ 780.665983] ? blk_insert_flush+0x1b5/0x2f0
<4>[ 780.666001] ? __pfx_ceph_writepages_start+0x10/0x10 [ceph]
<4>[ 780.666107] ? rcu_is_watching+0x1f/0x50
<4>[ 780.666117] ? lock_acquire+0xc7/0x3e0
<4>[ 780.666126] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.666136] ? rcu_is_watching+0x1f/0x50
<4>[ 780.666149] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.666157] ? rcu_is_watching+0x1f/0x50
<4>[ 780.666163] ? rcu_is_watching+0x1f/0x50
<4>[ 780.666169] ? lock_acquire+0xc7/0x3e0
<4>[ 780.666175] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.666181] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.666187] ? __pfx_do_raw_spin_trylock+0x10/0x10
<4>[ 780.666197] do_writepages+0x106/0x320
<4>[ 780.666203] ? __pfx_do_writepages+0x10/0x10
<4>[ 780.666208] ? __pfx_lock_acquire+0x10/0x10
<4>[ 780.666216] ? __pfx_wb_calc_thresh+0x10/0x10
<4>[ 780.666227] ? do_raw_spin_trylock+0xd0/0x120
<4>[ 780.666236] ? __pfx_do_raw_spin_trylock+0x10/0x10
<4>[ 780.666247] __writeback_single_inode+0x95/0x450
<4>[ 780.666270] writeback_sb_inodes+0x395/0x7e0
<4>[ 780.666285] ? lock_acquire+0xc7/0x3e0
<4>[ 780.666292] ? __pfx_writeback_sb_inodes+0x10/0x10
<4>[ 780.666302] ? down_read_trylock+0x47/0x60
<4>[ 780.666309] __writeback_inodes_wb+0x6a/0x130
client_loop: send disconnect: Broken pipe
</pre>
<p>It was introduce by the following commit:</p>
<pre>
commit 5b11888471806edf699316d4dcb9b426caebbef2
Author: Eric Biggers <ebiggers@google.com>
Date: Sun Sep 24 22:54:51 2023 -0700
fscrypt: support crypto data unit size less than filesystem block size
Until now, fscrypt has always used the filesystem block size as the
granularity of file contents encryption. Two scenarios have come up
where a sub-block granularity of contents encryption would be useful:
1. Inline crypto hardware that only supports a crypto data unit size
that is less than the filesystem block size.
2. Support for direct I/O at a granularity less than the filesystem
block size, for example at the block device's logical block size in
order to match the traditional direct I/O alignment requirement.
(1) first came up with older eMMC inline crypto hardware that only
supports a crypto data unit size of 512 bytes. That specific case
ultimately went away because all systems with that hardware continued
using out of tree code and never actually upgraded to the upstream
inline crypto framework. But, now it's coming back in a new way: some
current UFS controllers only support a data unit size of 4096 bytes, and
there is a proposal to increase the filesystem block size to 16K.
(2) was discussed as a "nice to have" feature, though not essential,
when support for direct I/O on encrypted files was being upstreamed.
Still, the fact that this feature has come up several times does suggest
it would be wise to have available. Therefore, this patch implements it
by using one of the reserved bytes in fscrypt_policy_v2 to allow users
to select a sub-block data unit size. Supported data unit sizes are
powers of 2 between 512 and the filesystem block size, inclusively.
Support is implemented for both the FS-layer and inline crypto cases.
This patch focuses on the basic support for sub-block data units. Some
things are out of scope for this patch but may be addressed later:
- Supporting sub-block data units in combination with
FSCRYPT_POLICY_FLAG_IV_INO_LBLK_64, in most cases. Unfortunately this
combination usually causes data unit indices to exceed 32 bits, and
thus fscrypt_supported_policy() correctly disallows it. The users who
potentially need this combination are using f2fs. To support it, f2fs
would need to provide an option to slightly reduce its max file size.
- Supporting sub-block data units in combination with
FSCRYPT_POLICY_FLAG_IV_INO_LBLK_32. This has the same problem
described above, but also it will need special code to make DUN
wraparound still happen on a FS block boundary.
- Supporting use case (2) mentioned above. The encrypted direct I/O
code will need to stop requiring and assuming FS block alignment.
This won't be hard, but it belongs in a separate patch.
- Supporting this feature on filesystems other than ext4 and f2fs.
(Filesystems declare support for it via their fscrypt_operations.)
On UBIFS, sub-block data units don't make sense because UBIFS encrypts
variable-length blocks as a result of compression. CephFS could
support it, but a bit more work would be needed to make the
fscrypt_*_block_inplace functions play nicely with sub-block data
units. I don't think there's a use case for this on CephFS anyway.
Link: https://lore.kernel.org/r/20230925055451.59499-6-ebiggers@kernel.org
Signed-off-by: Eric Biggers <ebiggers@google.com>
</pre>
CephFS - Backport #63833 (Resolved): pacific: mds: incorrectly issued the Fc caps in LOCK_EXCL_XS...
https://tracker.ceph.com/issues/63833
2023-12-15T04:02:40Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://github.com/ceph/ceph/pull/54912">https://github.com/ceph/ceph/pull/54912</a></p>
CephFS - Backport #63832 (Rejected): pacific: kernel/fuse client using ceph ID with uid restricte...
https://tracker.ceph.com/issues/63832
2023-12-15T03:07:37Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://github.com/ceph/ceph/pull/54909">https://github.com/ceph/ceph/pull/54909</a></p>
CephFS - Bug #63710 (Duplicate): client.5394 isn't responding to mclientcaps(revoke), ino 0x10000...
https://tracker.ceph.com/issues/63710
2023-12-01T02:22:34Z
Xiubo Li
xiubli@redhat.com
<p>This time it says the <strong>Fs</strong> caps is not released by the client, while from the client side when I stat the corresponding file by enabling the kernel debug logs:</p>
<pre>
[xiubli@ceph kcephfs.B]$ stat .
File: .
Size: 20 Blocks: 0 IO Block: 65536 directory
Device: 2dh/45d Inode: 1099511627777 Links: 22
Access: (0755/drwxr-xr-x) Uid: ( 1000/ xiubli) Gid: ( 1000/ xiubli)
Access: 2023-11-30 17:23:51.320089270 +0800
Modify: 2023-11-30 21:24:04.227273296 +0800
Change: 2023-11-30 21:24:04.227273296 +0800
Birth: 2023-11-30 17:23:51.320089270 +0800
</pre>
<pre>
<7>[84024.461142] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] delayed_work: mdsc delayed_work
<7>[84024.461166] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_check_delayed_caps: begin
<7>[84024.461173] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_check_delayed_caps: done
<7>[84024.461183] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_queue_cap_reclaim_work: caps reclaim work queued
<7>[84025.491515] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 4256] delayed_work: mdsc delayed_work
<7>[84025.491552] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 4256] ceph_check_delayed_caps: begin
<7>[84025.491560] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 4256] ceph_check_delayed_caps: done
<7>[84025.491572] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 4256] ceph_queue_cap_reclaim_work: caps reclaim work queued
<7>[84025.719421] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_do_getattr: inode 00000000745cb99f 10000000001.fffffffffffffffe mask As mode 040755
<7>[84025.719448] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_caps_issued_mask: mask 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a issued pAsLsXs (mask As)
<7>[84025.719461] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __touch_cap: 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a mds0
<7>[84025.719476] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_do_getattr: inode 00000000745cb99f 10000000001.fffffffffffffffe mask AsXsFs mode 040755
<7>[84025.719487] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_caps_issued: 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a issued pAsLsXs
<7>[84025.719535] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_mdsc_do_request: do_request on 00000000018dbb8a
<7>[84025.719545] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_mdsc_submit_request: submit_request on 00000000018dbb8a for inode 0000000000000000
<7>[84025.719556] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_reserve_caps: ctx=00000000c3e0afdc need=1
<7>[84025.719598] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_reserve_caps: ctx=00000000c3e0afdc 86 = 3 used + 83 resv + 0 avail
<7>[84025.719607] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __register_request: 00000000018dbb8a tid 28
<7>[84025.719619] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __choose_mds: 00000000745cb99f 10000000001.fffffffffffffffe is_hash=0 (0x0) mode 2
<7>[84025.719630] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __choose_mds: 00000000745cb99f 10000000001.fffffffffffffffe mds0 (auth cap 00000000ff1f815a)
<7>[84025.719642] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __do_request: mds0 session 000000006dcba806 state open
<7>[84025.719653] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __prepare_send_request: 00000000018dbb8a tid 28 getattr (attempt 1)
<7>[84025.719663] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] set_request_path_attr: inode 00000000745cb99f 10000000001.fffffffffffffffe
<7>[84025.719786] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __prepare_send_request: r_parent = 0000000000000000
<7>[84025.719821] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_mdsc_wait_request: do_request waiting
<7>[84025.721451] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] handle_reply: handle_reply 00000000018dbb8a
<7>[84025.721483] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __unregister_request: 00000000018dbb8a tid 28
<7>[84025.721497] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] handle_reply: tid 28 result 0
<7>[84025.721519] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_get_inode: on 10000000001=10000000001.fffffffffffffffe got 00000000745cb99f new 0
<7>[84025.721539] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_update_snap_trace: deletion=0
<7>[84025.721554] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __lookup_snap_realm: 1 00000000183cd74c
<7>[84025.721568] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_update_snap_trace: 1 00000000183cd74c seq 1 unchanged
<7>[84025.721583] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_update_snap_trace: done with 1 00000000183cd74c, rebuild_snapcs=0, 00000000cdae45ec 00000000cdae45ec
<7>[84025.721601] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_fill_trace: 00000000018dbb8a is_dentry 0 is_target 1
<7>[84025.721617] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_fill_inode: 00000000745cb99f ino 10000000001.fffffffffffffffe v 157290 had 157290
<7>[84025.721636] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_get_cap: ctx=00000000c3e0afdc (1) 86 = 3 used + 83 resv + 0 avail
<7>[84025.721782] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_caps_issued: 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a issued pAsLsXs
<7>[84025.721804] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_add_cap: 00000000745cb99f 10000000001.fffffffffffffffe mds0 cap 4f30 pAsLsXs seq 22
<7>[84025.721823] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_caps_issued: 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a issued pAsLsXs
<7>[84025.721841] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_add_cap: inode 00000000745cb99f 10000000001.fffffffffffffffe cap 00000000ff1f815a pAsLsXs now pAsLsXs seq 22 mds0
<7>[84025.721863] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_put_cap: 00000000a3c5a7b4 86 = 4 used + 82 resv + 0 avail
<7>[84025.721951] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_fill_trace: done err=0
<7>[84025.722046] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_mdsc_wait_request: do_request waited, got 0
<7>[84025.722062] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] ceph_mdsc_do_request: do_request 00000000018dbb8a done, result 0
<7>[84025.722177] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_put_cap_refs: 00000000745cb99f 10000000001.fffffffffffffffe had p
<7>[84025.722210] ceph: [6e016130-5830-4f25-b08d-dd1693d1b894 5424] __ceph_do_getattr: result=0
</pre>
<p>I can see that the inode <strong>10000000001</strong> has already released it:</p>
<pre>
10000000001.fffffffffffffffe cap 00000000ff1f815a issued pAsLsXs
</pre>
<p>It should be the MDS missed it in some corner cases.</p>
CephFS - Bug #63685 (Rejected): mds: FAILED ceph_assert(_head.empty())
https://tracker.ceph.com/issues/63685
2023-11-30T02:26:04Z
Xiubo Li
xiubli@redhat.com
<p>When I was running some xfstests locally I hit the mds crash:</p>
<pre>
-129> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7dac00]
-128> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7dac00]
-127> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d3b) try_remove_dentries_for_stray
-126> 2023-11-30T10:21:45.810+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d3b) close_dirfrag *
-125> 2023-11-30T10:21:45.810+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d3b) remove_null_dentries [dir 0x10000009d3b ~mds0/stray5/10000009d3b/ [2,head] auth v=1 cv=0/0 state=1073741825|complete f() n() hs=0+0,ss=0+0 0x562859e6b600]
-124> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3b) clear_dirty_parent
-123> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e73d400]
-122> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x605) auth_pin by 0x562858d735b8 on [dir 0x605 ~mds0/stray5/ [2,head] auth v=79536 cv=79482/79482 ap=3+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.439498+0800 11=8+3) n(v0 rc2023-11-30T10:21:44.439498+0800 b2138112 11=8+3) hs=11+7,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda880] count now 3
-121> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e73d400] [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7dac00]
-120> 2023-11-30T10:21:45.810+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d3b
-119> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-118> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-117> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e73d400]
-116> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f101680]
-115> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x100000092b8 [2,head] ~mds0/stray6/100000092b8 auth v78342 DIRTYPARENT s=413696 nl=0 n(v0 rc2023-11-30T10:21:39.678247+0800 b413696 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b2ab700]
-114> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092b8) clear_dirty_parent
-113> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f101680]
-112> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x606) auth_pin by 0x562858d735b8 on [dir 0x606 ~mds0/stray6/ [2,head] auth v=78353 cv=78329/78329 ap=1+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.247942+0800 3=3+0) n(v1 rc2023-11-30T10:21:43.247942+0800 b1286144 3=3+0) hs=3+9,ss=0+0 dirty=3 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddad00] count now 1
-111> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f101680] [inode 0x100000092b8 [2,head] ~mds0/stray6/100000092b8 auth v78342 s=413696 nl=0 n(v0 rc2023-11-30T10:21:39.678247+0800 b413696 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b2ab700]
-110> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-109> 2023-11-30T10:21:45.810+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x100000092b8
-108> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-107> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-106> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f101680]
-105> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285baaa780]
-104> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d40 [2,head] ~mds0/stray4/10000009d40 auth v79472 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.697145+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64db80]
-103> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d40) clear_dirty_parent
-102> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285baaa780]
-101> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x604) auth_pin by 0x562858d735b8 on [dir 0x604 ~mds0/stray4/ [2,head] auth pv=79763 v=79483 cv=79445/79445 ap=3+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.337458+0800 5=4+1) n(v0 rc2023-11-30T10:21:43.337458+0800 5=4+1) hs=5+11,ss=0+0 dirty=5 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda400] count now 3
-100> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285baaa780] [inode 0x10000009d40 [2,head] ~mds0/stray4/10000009d40 auth v79472 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.697145+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64db80]
-99> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-98> 2023-11-30T10:21:45.810+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d40
-97> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-96> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-95> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285baaa780]
-94> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74f00]
-93> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d3f [2,head] ~mds0/stray9/10000009d3f auth v78344 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.703112+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64e100]
-92> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3f) clear_dirty_parent
-91> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74f00]
-90> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x609) auth_pin by 0x562858d735b8 on [dir 0x609 ~mds0/stray9/ [2,head] auth pv=79578 v=79574 cv=78337/78337 ap=3+2 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:44.108289+0800 10=7+3) n(v1 rc2023-11-30T10:21:44.108289+0800 b4669440 10=7+3) hs=10+13,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddba80] count now 3
-89> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74f00] [inode 0x10000009d3f [2,head] ~mds0/stray9/10000009d3f auth v78344 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.703112+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64e100]
-88> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-87> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d3f
-86> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-85> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-84> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74f00]
-83> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x5628594ee000]
-82> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x100000092bb [2,head] ~mds0/stray2/100000092bb auth v79715 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.709080+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64c000]
-81> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092bb) clear_dirty_parent
-80> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x5628594ee000]
-79> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x602) auth_pin by 0x562858d735b8 on [dir 0x602 ~mds0/stray2/ [2,head] auth v=79789 cv=79712/79712 ap=1+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.404686+0800 7=7+0) n(v0 rc2023-11-30T10:21:44.404686+0800 b1183744 7=7+0) hs=7+11,ss=0+0 dirty=8 | child=1 sticky=1 dirty=1 authpin=1 0x562858dd9b00] count now 1
-78> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x5628594ee000] [inode 0x100000092bb [2,head] ~mds0/stray2/100000092bb auth v79715 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.709080+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64c000]
-77> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-76> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x100000092bb
-75> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-74> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-73> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x5628594ee000]
-72> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f420f00]
-71> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 DIRTYPARENT f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5628593d8580]
-70> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 DIRTYPARENT f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5628593d8580]
-69> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d36) try_remove_dentries_for_stray
-68> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d36) close_dirfrag *
-67> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d36) remove_null_dentries [dir 0x10000009d36 ~mds0/stray8/10000009d36/ [2,head] auth v=28 cv=0/0 state=1073741825|complete f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.423624+0800) hs=0+0,ss=0+0 0x56285db55680]
-66> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d36) clear_dirty_parent
-65> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f420f00]
-64> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x608) auth_pin by 0x562858d735b8 on [dir 0x608 ~mds0/stray8/ [2,head] auth pv=79801 v=79797 cv=78414/78414 ap=4+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.421594+0800 10=6+4) n(v0 rc2023-11-30T10:21:44.457401+0800 b2011136 10=6+4) hs=10+12,ss=0+0 dirty=12 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddb600] count now 4
-63> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f420f00] [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x5628593d8580]
-62> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d36
-61> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-60> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-59> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f420f00]
-58> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x562859640500]
-57> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x100000092b6 [2,head] ~mds0/stray8/100000092b6 auth v78429 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.979617+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x5628593db180]
-56> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092b6) clear_dirty_parent
-55> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x562859640500]
-54> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x608) auth_pin by 0x562858d735b8 on [dir 0x608 ~mds0/stray8/ [2,head] auth pv=79801 v=79797 cv=78414/78414 ap=5+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.421594+0800 10=6+4) n(v0 rc2023-11-30T10:21:44.457401+0800 b2011136 10=6+4) hs=10+12,ss=0+0 dirty=12 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddb600] count now 5
-53> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x562859640500] [inode 0x100000092b6 [2,head] ~mds0/stray8/100000092b6 auth v78429 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.979617+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x5628593db180]
-52> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-51> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x100000092b6
-50> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-49> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-48> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x562859640500]
-47> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e978500]
-46> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9080]
-45> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9080]
-44> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d3c) try_remove_dentries_for_stray
-43> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d3c) close_dirfrag *
-42> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d3c) remove_null_dentries [dir 0x10000009d3c ~mds0/stray9/10000009d3c/ [2,head] auth v=1 cv=0/0 state=1073741825|complete f() n() hs=0+0,ss=0+0 0x56286505f180]
-41> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3c) clear_dirty_parent
-40> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e978500]
-39> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x609) auth_pin by 0x562858d735b8 on [dir 0x609 ~mds0/stray9/ [2,head] auth pv=79578 v=79574 cv=78337/78337 ap=4+2 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:44.108289+0800 10=7+3) n(v1 rc2023-11-30T10:21:44.108289+0800 b4669440 10=7+3) hs=10+13,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddba80] count now 4
-38> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e978500] [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7d9080]
-37> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d3c
-36> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-35> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-34> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e978500]
-33> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74000]
-32> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d3e [2,head] ~mds0/stray0/10000009d3e auth v78279 DIRTYPARENT s=729088 nl=0 n(v0 rc2023-11-30T10:21:39.715048+0800 b729088 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9b80]
-31> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3e) clear_dirty_parent
-30> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74000]
-29> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x600) auth_pin by 0x562858d735b8 on [dir 0x600 ~mds0/stray0/ [2,head] auth pv=79554 v=79552 cv=78272/78272 ap=2+1 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:43.351382+0800 7=6+1) n(v0 rc2023-11-30T10:21:43.351382+0800 b3432448 7=6+1) hs=7+7,ss=0+0 dirty=8 | child=1 sticky=1 dirty=1 authpin=1 0x562858dd9200] count now 2
-28> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74000] [inode 0x10000009d3e [2,head] ~mds0/stray0/10000009d3e auth v78279 s=729088 nl=0 n(v0 rc2023-11-30T10:21:39.715048+0800 b729088 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7d9b80]
-27> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-26> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x10000009d3e
-25> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-24> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-23> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74000]
-22> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ee76f00]
-21> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x100000092be [2,head] ~mds0/stray4/100000092be auth v79474 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:40.002493+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285bad4100]
-20> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092be) clear_dirty_parent
-19> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ee76f00]
-18> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x604) auth_pin by 0x562858d735b8 on [dir 0x604 ~mds0/stray4/ [2,head] auth pv=79763 v=79483 cv=79445/79445 ap=4+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.337458+0800 5=4+1) n(v0 rc2023-11-30T10:21:43.337458+0800 5=4+1) hs=5+11,ss=0+0 dirty=5 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda400] count now 4
-17> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ee76f00] [inode 0x100000092be [2,head] ~mds0/stray4/100000092be auth v79474 s=0 nl=0 n(v0 rc2023-11-30T10:21:40.002493+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x56285bad4100]
-16> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
-15> 2023-11-30T10:21:45.811+0800 7fe51f97b640 4 mds.0.purge_queue push: pushing inode 0x100000092be
-14> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
-13> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume: not readable right now
-12> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ee76f00]
-11> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray7/10000009d25 [2,head] auth (dversion lock) v=78672 ino=0x10000009d25 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f870780]
-10> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays inode is [inode 0x10000009d25 [...2,head] ~mds0/stray7/10000009d25/ auth v78672 DIRTYPARENT f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:40.008461+0800 1=0+1) (inest lock) (iversion lock) | dirtyscattered=0 request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285b2e6b00]
-9> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d25 [...2,head] ~mds0/stray7/10000009d25/ auth v78672 DIRTYPARENT f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:40.008461+0800 1=0+1) (inest lock) (iversion lock) | dirtyscattered=0 request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285b2e6b00]
-8> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d25) try_remove_dentries_for_stray
-7> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d25) close_dirfrag *
-6> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d25) remove_null_dentries [dir 0x10000009d25 ~mds0/stray7/10000009d25/ [2,head] auth v=30 cv=0/0 state=1073741825|complete f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:38.672685+0800) hs=0+0,ss=0+0 0x562859576400]
-5> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: tick
-4> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: _check_auth_tickets
-3> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2023-11-30T10:21:15.860971+0800)
-2> 2023-11-30T10:21:45.913+0800 7fe523983640 1 -- v1:192.168.0.103:6813/3126691049 <== client.4254 v1:192.168.0.103:0/3585876660 99518 ==== client_caps(update ino 0x10000009a3c 1 seq 5 caps=pAsLsXsFsc dirty=- wanted=- follows 0 size 2105344/0 mtime 2023-11-30T10:21:35.767397+0800 ctime 2023-11-30T10:21:35.767397+0800 change_attr 22 tws 1 xattrs(v=18446744071793450223 l=0)) v12 ==== 316+0+0 (unknown 1434914571 0 0) 0x56285c24a000 con 0x562858f82400
-1> 2023-11-30T10:21:46.015+0800 7fe51f97b640 -1 /home/xiubli/cephdev/ceph/src/include/elist.h: In function 'elist<T>::~elist() [with T = MDLockCache::DirItem*]' thread 7fe51f97b640 time 2023-11-30T10:21:45.812068+0800
/home/xiubli/cephdev/ceph/src/include/elist.h: 91: FAILED ceph_assert(_head.empty())
ceph version 18.0.0-6843-g092ae0c319c (092ae0c319ca3f6846be394747507421c8f9c257) reef (dev)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x11c) [0x7fe529898769]
2: (ceph::register_assert_context(ceph::common::CephContext*)+0) [0x7fe529898970]
3: (CDir::~CDir()+0x3c5) [0x562852d48345]
4: (CDir::~CDir()+0x9) [0x562852d483df]
5: (CInode::close_dirfrag(frag_t)+0x6de) [0x562852d83086]
6: (CInode::close_dirfrags()+0x44) [0x562852d8314e]
7: (StrayManager::_eval_stray(CDentry*)+0x1233) [0x562852c60509]
8: (StrayManager::eval_stray(CDentry*)+0x1c) [0x562852c6062e]
9: (StrayManager::advance_delayed()+0x69) [0x562852c6069d]
10: (MDCache::trim(unsigned long)+0x8e) [0x562852bac908]
11: (MDCache::upkeep_main()+0x67f) [0x562852bc2d3b]
12: (std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (MDCache::*)(), MDCache*> > >::_M_run()+0x2a) [0x562852c0bfc0]
13: /lib64/libstdc++.so.6(+0xdb9d4) [0x7fe528adb9d4]
14: /lib64/libc.so.6(+0x9f832) [0x7fe52869f832]
15: /lib64/libc.so.6(+0x3f450) [0x7fe52863f450]
0> 2023-11-30T10:21:46.065+0800 7fe51f97b640 -1 *** Caught signal (Aborted) **
in thread 7fe51f97b640 thread_name:ms_dispatch
ceph version 18.0.0-6843-g092ae0c319c (092ae0c319ca3f6846be394747507421c8f9c257) reef (dev)
1: /lib64/libc.so.6(+0x54df0) [0x7fe528654df0]
2: /lib64/libc.so.6(+0xa157c) [0x7fe5286a157c]
3: raise()
4: abort()
5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x263) [0x7fe5298988b0]
6: (ceph::register_assert_context(ceph::common::CephContext*)+0) [0x7fe529898970]
7: (CDir::~CDir()+0x3c5) [0x562852d48345]
8: (CDir::~CDir()+0x9) [0x562852d483df]
9: (CInode::close_dirfrag(frag_t)+0x6de) [0x562852d83086]
10: (CInode::close_dirfrags()+0x44) [0x562852d8314e]
11: (StrayManager::_eval_stray(CDentry*)+0x1233) [0x562852c60509]
12: (StrayManager::eval_stray(CDentry*)+0x1c) [0x562852c6062e]
13: (StrayManager::advance_delayed()+0x69) [0x562852c6069d]
14: (MDCache::trim(unsigned long)+0x8e) [0x562852bac908]
15: (MDCache::upkeep_main()+0x67f) [0x562852bc2d3b]
16: (std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (MDCache::*)(), MDCache*> > >::_M_run()+0x2a) [0x562852c0bfc0]
17: /lib64/libstdc++.so.6(+0xdb9d4) [0x7fe528adb9d4]
18: /lib64/libc.so.6(+0x9f832) [0x7fe52869f832]
19: /lib64/libc.so.6(+0x3f450) [0x7fe52863f450]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
</pre>
CephFS - Bug #63646 (Pending Backport): mds: incorrectly issued the Fc caps in LOCK_EXCL_XSYN sta...
https://tracker.ceph.com/issues/63646
2023-11-27T07:59:01Z
Xiubo Li
xiubli@redhat.com
<pre>
# sudo ceph tell mds.a dump inode 1099928481958
{
"path": "/volumes/csi/csi-vol-8/c1/user/08905",
"ino": 1099928481958,
"rdev": 0,
"ctime": "2023-11-22T17:43:18.475402+0000",
"btime": "2023-11-22T17:43:18.471402+0000",
"mode": 33188,
"uid": 1000,
"gid": 1000,
"nlink": 1,
"dir_layout": {
"dir_hash": 0,
"unused1": 0,
"unused2": 0,
"unused3": 0
},
"layout": {
"stripe_unit": 4194304,
"stripe_count": 1,
"object_size": 4194304,
"pool_id": 3,
"pool_ns": ""
},
"old_pools": [],
"size": 57944,
"truncate_seq": 1,
"truncate_size": 18446744073709551615,
"truncate_from": 0,
"truncate_pending": 0,
"mtime": "2023-11-22T17:43:18.474402+0000",
"atime": "2023-11-22T17:43:18.471402+0000",
"time_warp_seq": 1,
"change_attr": 8,
"export_pin": -1,
"export_ephemeral_random_pin": 0,
"export_ephemeral_distributed_pin": false,
"client_ranges": [
{
"client": 292645041,
"byte range": {
"first": 0,
"last": 4194304
},
"follows": 27828
}
],
"dirstat": {
"version": 0,
"mtime": "0.000000",
"num_files": 0,
"num_subdirs": 0,
"change_attr": 0
},
"rstat": {
"version": 0,
"rbytes": 57944,
"rfiles": 1,
"rsubdirs": 0,
"rsnaps": 0,
"rctime": "2023-11-22T17:43:18.475402+0000"
},
"accounted_rstat": {
"version": 0,
"rbytes": 57944,
"rfiles": 1,
"rsubdirs": 0,
"rsnaps": 0,
"rctime": "2023-11-22T17:43:18.475402+0000"
},
"version": 42583120,
"file_data_version": 0,
"xattr_version": 1,
"backtrace_version": 42574155,
"stray_prior_path": "",
"max_size_ever": 0,
"quota": {
"max_bytes": 0,
"max_files": 0
},
"last_scrub_stamp": "0.000000",
"last_scrub_version": 0,
"symlink": "",
"xattrs": [
{
"key": "security.selinux",
"val": "system_u:object_r:container_file_t:s0:c14,c27\u0000"
}
],
"dirfragtree": {
"splits": []
},
"old_inodes": [],
"oldest_snap": 18446744073709551614,
"damage_flags": 0,
"is_auth": true,
"auth_state": {
"replicas": {}
},
"replica_state": {
"authority": [
0,
-2
],
"replica_nonce": 0
},
"auth_pins": 3,
"is_frozen": false,
"is_freezing": false,
"pins": {
"ptrwaiter": 13,
"request": 240,
"lock": 1,
"caps": 1,
"dirtyrstat": 0,
"dirty": 0,
"waiter": 1,
"authpin": 1
},
"nref": 257,
"versionlock": {
"gather_set": [],
"state": "lock",
"is_leased": false,
"num_rdlocks": 0,
"num_wrlocks": 0,
"num_xlocks": 0,
"xlock_by": {}
},
"authlock": {},
"linklock": {},
"dirfragtreelock": {},
"filelock": {
"gather_set": [],
"state": "excl->xsyn",
"is_leased": false,
"num_rdlocks": 0,
"num_wrlocks": 0,
"num_xlocks": 0,
"xlock_by": {}
},
"xattrlock": {},
"snaplock": {
"gather_set": [],
"state": "sync",
"is_leased": false,
"num_rdlocks": 2,
"num_wrlocks": 0,
"num_xlocks": 0,
"xlock_by": {}
},
"nestlock": {
"gather_set": [],
"state": "lock",
"is_leased": false,
"num_rdlocks": 0,
"num_wrlocks": 0,
"num_xlocks": 0,
"xlock_by": {}
},
"flocklock": {},
"policylock": {},
"states": [
"auth"
],
"client_caps": [
{
"client_id": 292644945,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 26
},
{
"client_id": 292645008,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 3
},
{
"client_id": 292645041,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFcr",
"wanted": "-",
"last_sent": 25
},
{
"client_id": 294423859,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 184
},
{
"client_id": 294423874,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 10
},
{
"client_id": 294423919,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 9
},
{
"client_id": 294423985,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 12
},
{
"client_id": 294424000,
"pending": "pAsLsXsFc",
"issued": "pAsLsXsFc",
"wanted": "-",
"last_sent": 3
}
],
"loner": 292645041,
"want_loner": -1,
"mds_caps_wanted": []
}
</pre>
CephFS - Bug #63587 (Pending Backport): Test failure: test_filesystem_sync_stuck_for_around_5s (t...
https://tracker.ceph.com/issues/63587
2023-11-20T02:16:25Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://pulpito.ceph.com/yuriw-2023-11-15_23:07:34-fs-wip-yuri-testing-2023-11-14-0743-reef-distro-default-smithi/7460053/">https://pulpito.ceph.com/yuriw-2023-11-15_23:07:34-fs-wip-yuri-testing-2023-11-14-0743-reef-distro-default-smithi/7460053/</a></p>
<pre>
2023-11-16T04:49:25.624 INFO:teuthology.orchestra.run.smithi005.stderr:2023-11-16T04:49:25.619+0000 7f9ce68f1640 1 -- 172.21.15.5:0/2045590866 shutdown_connections
2023-11-16T04:49:25.624 INFO:teuthology.orchestra.run.smithi005.stderr:2023-11-16T04:49:25.619+0000 7f9ce68f1640 1 -- 172.21.15.5:0/2045590866 wait complete.
2023-11-16T04:49:25.646 INFO:tasks.cephfs_test_runner:To check whether the fsync will be stuck to wait for the mdlog to be ... FAIL
2023-11-16T04:49:25.646 INFO:tasks.cephfs_test_runner:
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:======================================================================
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:FAIL: test_filesystem_sync_stuck_for_around_5s (tasks.cephfs.test_misc.TestMisc)
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:To check whether the fsync will be stuck to wait for the mdlog to be
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner: File "/home/teuthworker/src/github.com_ceph_ceph-c_cb2179fff8710af9ff3936b02b8bc8cd99900af3/qa/tasks/cephfs/test_misc.py", line 288, in test_filesystem_sync_stuck_for_around_5s
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner: self._test_sync_stuck_for_around_5s(dir_path)
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner: File "/home/teuthworker/src/github.com_ceph_ceph-c_cb2179fff8710af9ff3936b02b8bc8cd99900af3/qa/tasks/cephfs/test_misc.py", line 277, in _test_sync_stuck_for_around_5s
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner: self.assertLess(duration, 4)
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:AssertionError: 6.773383140563965 not less than 4
2023-11-16T04:49:25.647 INFO:tasks.cephfs_test_runner:
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:Ran 14 tests in 2185.087s
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:FAILED (failures=1)
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:======================================================================
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:FAIL: test_filesystem_sync_stuck_for_around_5s (tasks.cephfs.test_misc.TestMisc)
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:To check whether the fsync will be stuck to wait for the mdlog to be
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner: File "/home/teuthworker/src/github.com_ceph_ceph-c_cb2179fff8710af9ff3936b02b8bc8cd99900af3/qa/tasks/cephfs/test_misc.py", line 288, in test_filesystem_sync_stuck_for_around_5s
2023-11-16T04:49:25.648 INFO:tasks.cephfs_test_runner: self._test_sync_stuck_for_around_5s(dir_path)
2023-11-16T04:49:25.649 INFO:tasks.cephfs_test_runner: File "/home/teuthworker/src/github.com_ceph_ceph-c_cb2179fff8710af9ff3936b02b8bc8cd99900af3/qa/tasks/cephfs/test_misc.py", line 277, in _test_sync_stuck_for_around_5s
2023-11-16T04:49:25.649 INFO:tasks.cephfs_test_runner: self.assertLess(duration, 4)
2023-11-16T04:49:25.649 INFO:tasks.cephfs_test_runner:AssertionError: 6.773383140563965 not less than 4
2023-11-16T04:49:25.649 INFO:tasks.cephfs_test_runner:
2023-11-16T04:49:25.649 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
File "/home/teuthworker/src/git.ceph.com_teuthology_6899cd26fceddb2fec83dc1a1349394b28c8998e/teuthology/run_tasks.py", line 109, in run_tasks
manager.__enter__()
File "/usr/lib/python3.8/contextlib.py", line 113, in __enter__
return next(self.gen)
File "/home/teuthworker/src/github.com_ceph_ceph-c_cb2179fff8710af9ff3936b02b8bc8cd99900af3/qa/tasks/cephfs_test_runner.py", line 211, in task
raise RuntimeError("Test failure: {0}".format(", ".join(bad_tests)))
RuntimeError: Test failure: test_filesystem_sync_stuck_for_around_5s (tasks.cephfs.test_misc.TestMisc)
2023-11-16T04:49:25.714 ERROR:teuthology.util.sentry: Sentry event: https://sentry.ceph.com/organizations/ceph/?query=22b205cc57aa4163842515db3f0b6b5f
Traceback (most recent call last):
</pre>
Linux kernel client - Bug #63586 (Fix Under Review): libceph: osd_sparse_read: failed to allocate...
https://tracker.ceph.com/issues/63586
2023-11-20T01:43:37Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://pulpito.ceph.com/yuriw-2023-11-15_23:07:34-fs-wip-yuri-testing-2023-11-14-0743-reef-distro-default-smithi/7459949/">https://pulpito.ceph.com/yuriw-2023-11-15_23:07:34-fs-wip-yuri-testing-2023-11-14-0743-reef-distro-default-smithi/7459949/</a></p>
<p>From remote/smithi204/syslog/kern.log.gz:</p>
<pre>
2023-11-16T02:47:20.751447+00:00 smithi204 kernel: [ 1895.456434] libceph: client5322 fsid 1325a234-ab9e-4632-9a6e-98afbef8ae76
2023-11-16T02:47:20.751448+00:00 smithi204 kernel: [ 1895.456483] ceph: test_dummy_encryption mode enabled
2023-11-16T02:50:12.194680+00:00 smithi204 kernel: [ 2066.894411] ------------[ cut here ]------------
2023-11-16T02:50:12.194695+00:00 smithi204 kernel: [ 2066.894484] WARNING: CPU: 7 PID: 112988 at mm/page_alloc.c:4402 __alloc_pages+0x1e7/0x270
2023-11-16T02:50:12.194696+00:00 smithi204 kernel: [ 2066.894518] Modules linked in: ceph libceph fscache netfs veth xfs xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo xt_addrtype nft_compat nf_tables libcrc32c nfnetlink br_netfilter bridge stp llc rdma_ucm ib_uverbs rdma_cm iw_cm ib_cm ib_core overlay ipmi_ssif intel_rapl_msr intel_rapl_common sb_edac x86_pkg_temp_thermal intel_powerclamp mei_me coretemp crct10dif_pclmul ghash_clmulni_intel sha512_ssse3 aesni_intel mei crypto_simd cryptd joydev wmi ioatdma acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad kvm_intel kvm irqbypass sch_fq_codel scsi_transport_iscsi lp parport ramoops reed_solomon nfsd efi_pstore configfs auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 hid_generic usbhid hid igb ixgbe i2c_algo_bit dca crc32_pclmul nvme i2c_i801 ahci ptp i2c_smbus lpc_ich libahci pps_core nvme_core mdio
2023-11-16T02:50:12.194699+00:00 smithi204 kernel: [ 2066.894671] CPU: 7 PID: 112988 Comm: kworker/7:0 Not tainted 6.6.0-rc5-g3b796cfe2969 #1
2023-11-16T02:50:12.194699+00:00 smithi204 kernel: [ 2066.894674] Hardware name: Supermicro SYS-5018R-WR/X10SRW-F, BIOS 2.0a 08/02/2016
2023-11-16T02:50:12.194730+00:00 smithi204 kernel: [ 2066.894676] Workqueue: ceph-msgr ceph_con_workfn [libceph]
2023-11-16T02:50:12.194732+00:00 smithi204 kernel: [ 2066.894701] RIP: 0010:__alloc_pages+0x1e7/0x270
2023-11-16T02:50:12.194732+00:00 smithi204 kernel: [ 2066.894704] Code: ff ff 00 0f 84 19 ff ff ff 80 ce 01 e9 11 ff ff ff 83 fe 0a 0f 86 9d fe ff ff 80 3d 80 f4 53 01 00 75 09 c6 05 77 f4 53 01 01 <0f> 0b 45 31 ed e9 57 ff ff ff e8 9a f3 e0 ff 84 c0 0f 85 4a ff ff
2023-11-16T02:50:12.194733+00:00 smithi204 kernel: [ 2066.894706] RSP: 0018:ffffbcae88d5bc58 EFLAGS: 00010246
2023-11-16T02:50:12.194734+00:00 smithi204 kernel: [ 2066.894709] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
2023-11-16T02:50:12.194734+00:00 smithi204 kernel: [ 2066.894711] RDX: 0000000000000000 RSI: 0000000000000018 RDI: 0000000000000000
2023-11-16T02:50:12.194742+00:00 smithi204 kernel: [ 2066.894713] RBP: 0000000000040c00 R08: ffff9ab023c70f00 R09: 0000000000000000
2023-11-16T02:50:12.194742+00:00 smithi204 kernel: [ 2066.894715] R10: ffff9aaf00ebf030 R11: ffff9ab023c6ee00 R12: 0000000000000018
2023-11-16T02:50:12.194743+00:00 smithi204 kernel: [ 2066.894717] R13: 0000000000000018 R14: ffffffffc1235c85 R15: ffff9aaf00ebf030
2023-11-16T02:50:12.194744+00:00 smithi204 kernel: [ 2066.894718] FS: 0000000000000000(0000) GS:ffff9ab65fdc0000(0000) knlGS:0000000000000000
2023-11-16T02:50:12.194744+00:00 smithi204 kernel: [ 2066.894720] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2023-11-16T02:50:12.194745+00:00 smithi204 kernel: [ 2066.894722] CR2: 00007f8a8a03c180 CR3: 000000005a63e002 CR4: 00000000003706e0
2023-11-16T02:50:12.194750+00:00 smithi204 kernel: [ 2066.894724] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
2023-11-16T02:50:12.194750+00:00 smithi204 kernel: [ 2066.894726] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
2023-11-16T02:50:12.194751+00:00 smithi204 kernel: [ 2066.894728] Call Trace:
2023-11-16T02:50:12.194751+00:00 smithi204 kernel: [ 2066.894730] <TASK>
2023-11-16T02:50:12.194751+00:00 smithi204 kernel: [ 2066.894732] ? __warn+0x84/0x170
2023-11-16T02:50:12.194752+00:00 smithi204 kernel: [ 2066.894736] ? __alloc_pages+0x1e7/0x270
2023-11-16T02:50:12.194752+00:00 smithi204 kernel: [ 2066.894740] ? report_bug+0x191/0x1a0
2023-11-16T02:50:12.194756+00:00 smithi204 kernel: [ 2066.894747] ? handle_bug+0x42/0x70
2023-11-16T02:50:12.194756+00:00 smithi204 kernel: [ 2066.894751] ? exc_invalid_op+0x18/0x70
2023-11-16T02:50:12.194757+00:00 smithi204 kernel: [ 2066.894754] ? asm_exc_invalid_op+0x1a/0x20
2023-11-16T02:50:12.194757+00:00 smithi204 kernel: [ 2066.894760] ? osd_sparse_read+0x115/0x670 [libceph]
2023-11-16T02:50:12.194757+00:00 smithi204 kernel: [ 2066.894791] ? __alloc_pages+0x1e7/0x270
2023-11-16T02:50:12.194758+00:00 smithi204 kernel: [ 2066.894798] __kmalloc_large_node+0x88/0x140
2023-11-16T02:50:12.194762+00:00 smithi204 kernel: [ 2066.894804] __kmalloc+0xdf/0x150
2023-11-16T02:50:12.194762+00:00 smithi204 kernel: [ 2066.894819] osd_sparse_read+0x115/0x670 [libceph]
2023-11-16T02:50:12.194762+00:00 smithi204 kernel: [ 2066.894834] ? read_partial_message_chunk+0x8b/0x90 [libceph]
2023-11-16T02:50:12.194763+00:00 smithi204 kernel: [ 2066.894850] ceph_con_v1_try_read+0x17cc/0x1e00 [libceph]
2023-11-16T02:50:12.194763+00:00 smithi204 kernel: [ 2066.894881] ? ceph_con_workfn+0x2e/0x730 [libceph]
2023-11-16T02:50:12.194763+00:00 smithi204 kernel: [ 2066.894894] ? lock_acquire+0xcc/0x2a0
2023-11-16T02:50:12.194764+00:00 smithi204 kernel: [ 2066.894911] ? process_one_work+0x176/0x4c0
2023-11-16T02:50:12.194768+00:00 smithi204 kernel: [ 2066.894915] ceph_con_workfn+0x383/0x730 [libceph]
2023-11-16T02:50:12.194768+00:00 smithi204 kernel: [ 2066.894929] ? process_one_work+0x176/0x4c0
2023-11-16T02:50:12.194768+00:00 smithi204 kernel: [ 2066.894932] process_one_work+0x1dd/0x4c0
2023-11-16T02:50:12.194769+00:00 smithi204 kernel: [ 2066.894939] worker_thread+0x1df/0x3e0
2023-11-16T02:50:12.194769+00:00 smithi204 kernel: [ 2066.894943] ? drain_workqueue+0x120/0x120
2023-11-16T02:50:12.194769+00:00 smithi204 kernel: [ 2066.894947] kthread+0xf4/0x130
2023-11-16T02:50:12.194774+00:00 smithi204 kernel: [ 2066.894959] ? kthread_complete_and_exit+0x20/0x20
2023-11-16T02:50:12.194774+00:00 smithi204 kernel: [ 2066.894964] ret_from_fork+0x31/0x50
2023-11-16T02:50:12.194774+00:00 smithi204 kernel: [ 2066.894967] ? kthread_complete_and_exit+0x20/0x20
2023-11-16T02:50:12.194775+00:00 smithi204 kernel: [ 2066.894970] ret_from_fork_asm+0x11/0x20
2023-11-16T02:50:12.194775+00:00 smithi204 kernel: [ 2066.894980] </TASK>
2023-11-16T02:50:12.194775+00:00 smithi204 kernel: [ 2066.894982] irq event stamp: 4219761
2023-11-16T02:50:12.194779+00:00 smithi204 kernel: [ 2066.894984] hardirqs last enabled at (4219767): [<ffffffffa213778d>] console_unlock+0x11d/0x150
2023-11-16T02:50:12.194780+00:00 smithi204 kernel: [ 2066.894988] hardirqs last disabled at (4219772): [<ffffffffa2137772>] console_unlock+0x102/0x150
2023-11-16T02:50:12.194780+00:00 smithi204 kernel: [ 2066.894991] softirqs last enabled at (4219726): [<ffffffffa20a5777>] __irq_exit_rcu+0x77/0xa0
2023-11-16T02:50:12.194780+00:00 smithi204 kernel: [ 2066.894996] softirqs last disabled at (4219709): [<ffffffffa20a5777>] __irq_exit_rcu+0x77/0xa0
2023-11-16T02:50:12.194781+00:00 smithi204 kernel: [ 2066.894998] ---[ end trace 0000000000000000 ]---
2023-11-16T02:50:12.194781+00:00 smithi204 kernel: [ 2066.895001] libceph: osd_sparse_read: failed to allocate 2208169984 sparse read extents
2023-11-16T02:50:12.194788+00:00 smithi204 kernel: [ 2066.903155] libceph: osd6 (1)172.21.15.70:6812 socket error on read
2023-11-16T02:50:12.218371+00:00 smithi204 kernel: [ 2066.908743] libceph: osd_sparse_read: failed to allocate 2208169984 sparse read extents
2023-11-16T02:50:12.218406+00:00 smithi204 kernel: [ 2066.917112] libceph: osd6 (1)172.21.15.70:6812 socket error on read
2023-11-16T02:50:12.218407+00:00 smithi204 kernel: [ 2066.918810] libceph: osd_sparse_read: failed to allocate 2208169984 sparse read extents
2023-11-16T02:50:12.219434+00:00 smithi204 kernel: [ 2066.926987] libceph: osd6 (1)172.21.15.70:6812 socket error on read
...
2023-11-16T14:13:46.983459+00:00 smithi204 kernel: [43082.250808] libceph: osd6 (1)172.21.15.70:6812 socket error on read
2023-11-16T14:13:47.002106+00:00 smithi204 kernel: [43082.252340] libceph: osd_sparse_read: failed to allocate 2208169984 sparse read extents
2023-11-16T14:13:47.002112+00:00 smithi204 kernel: [43082.260503] libceph: osd6 (1)172.21.15.70:6812 socket error on read
</pre>
<p>The Rados just returned a very large extents <strong>2208169984</strong> and <strong>kernel libceph</strong> couldn't allocate enough memory for it and reset the connection and keep retrying the osd requests.</p>
<p>While in the Rados side, the <strong>osd.6</strong>, the read was succeeful:</p>
<pre>
2023-11-16T02:50:12.200+0000 7fec2cc41640 15 osd.6 pg_epoch: 33 pg[5.11( v 33'9174 (0'0,33'9174] local-lis/les=31/32 n=4 ec=31/31 lis/c=31/31 les/c/f=32/32/0 sis=31) [6,4] r=0 lpr=31 crt=33'9174 lcod 33'9173 mlcod 33'9173 active+clean] log_op_stats osd_op(client.5322.0:160938 5.11 5:8b7d215f:::1000000985f.00000000:head [sparse-read 3756032~65536 out=65560b] snapc 0=[] RETRY=1 ondisk+retry+read+known_if_redirected e33) v8 inb 0 outb 65560 lat 0.000235
2023-11-16T02:50:12.200+0000 7fec28438640 10 osd.6 pg_epoch: 33 pg[5.2( v 33'5683 (0'0,33'5683] local-lis/les=31/32 n=1 ec=31/31 lis/c=31/31 les/c/f=32/32/0 sis=31) [6,0] r=0 lpr=31 crt=33'5683 lcod 33'5682 mlcod 33'5682 active+clean] do_op osd_op(client.5322.0:160962 5.2 5:411858ae:::10000009858.00000001:head [sparse-read 1630208~65536 [1@-1]] snapc 0=[] RETRY=1 ondisk+retry+read+known_if_redirected e33) v8 may_read -> read-ordered flags ondisk+retry+read+known_if_redirected
2023-11-16T02:50:12.200+0000 7fec2cc41640 20 osd.6 pg_epoch: 33 pg[5.11( v 33'9174 (0'0,33'9174] local-lis/les=31/32 n=4 ec=31/31 lis/c=31/31 les/c/f=32/32/0 sis=31) [6,4] r=0 lpr=31 crt=33'9174 lcod 33'9173 mlcod 33'9173 active+clean] prepare_stats_for_publish reporting purged_snaps []
2023-11-16T02:50:12.200+0000 7fec2cc41640 15 osd.6 pg_epoch: 33 pg[5.11( v 33'9174 (0'0,33'9174] local-lis/les=31/32 n=4 ec=31/31 lis/c=31/31 les/c/f=32/32/0 sis=31) [6,4] r=0 lpr=31 crt=33'9174 lcod 33'9173 mlcod 33'9173 active+clean] publish_stats_to_osd 33:9995
2023-11-16T02:50:12.200+0000 7fec28438640 10 osd.6 pg_epoch: 33 pg[5.2( v 33'5683 (0'0,33'5683] local-lis/les=31/32 n=1 ec=31/31 lis/c=31/31 les/c/f=32/32/0 sis=31) [6,0] r=0 lpr=31 crt=33'5683 lcod 33'5682 mlcod 33'5682 active+clean] get_object_context: found obc in cache: obc(5:411858ae:::10000009858.00000001:head rwstate(none n=0 w=0))
2023-11-16T02:50:12.200+0000 7fec2cc41640 1 -- [v2:172.21.15.70:6809/38829,v1:172.21.15.70:6812/38829] --> v1:172.21.15.204:0/484060394 -- osd_op_reply(160938 1000000985f.00000000 [sparse-read 3756032~65536 out=65560b] v0'0 uv9173 ondisk = 0) v8 -- 0x55b9f7dd4b40 con 0x55ba006e0400
</pre>
CephFS - Bug #63552 (Pending Backport): mds: use explicitly sized types for network and disk enco...
https://tracker.ceph.com/issues/63552
2023-11-16T07:36:24Z
Xiubo Li
xiubli@redhat.com
<p>Some members are use <strong>unsigned</strong> for network and disk encoding, which will be in different size in different OSs.</p>
CephFS - Backport #63513 (Resolved): pacific: MDS slow requests for the internal 'rename' requests
https://tracker.ceph.com/issues/63513
2023-11-13T08:12:55Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://github.com/ceph/ceph/pull/54517">https://github.com/ceph/ceph/pull/54517</a></p>
CephFS - Backport #63512 (Resolved): pacific: client: queue a delay cap flushing if there are dit...
https://tracker.ceph.com/issues/63512
2023-11-13T08:05:20Z
Xiubo Li
xiubli@redhat.com
<p><a class="external" href="https://github.com/ceph/ceph/pull/54472">https://github.com/ceph/ceph/pull/54472</a></p>