https://tracker.ceph.com/
https://tracker.ceph.com/favicon.ico
2021-04-16T02:52:27Z
Ceph
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=191931
2021-04-16T02:52:27Z
Patrick Donnelly
pdonnell@redhat.com
<ul></ul><p>/ceph/teuthology-archive/pdonnell-2021-04-15_01:35:57-fs-wip-pdonnell-testing-20210414.230315-distro-basic-smithi/6047654/teuthology.log</p>
<p>testing kernel again</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192046
2021-04-19T13:47:12Z
Patrick Donnelly
pdonnell@redhat.com
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Triaged</i></li><li><strong>Assignee</strong> set to <i>Jeff Layton</i></li></ul>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192070
2021-04-19T16:38:25Z
Jeff Layton
jlayton@redhat.com
<ul></ul><p>Looks like the client kernel hit a GPF. The address appears to be a poisoned list value, so this may be a use-after-free:</p>
<pre>
smithi035 login: [ 2896.447494] general protection fault, probably for non-canonical address 0xdead000000000100: 0000 [#1] SMP PTI
[ 2896.457547] CPU: 0 PID: 27465 Comm: kworker/0:3 Tainted: G W 5.12.0-rc4-ceph-ga390f0b08638 #1
[ 2896.467435] Hardware name: Supermicro SYS-5018R-WR/X10SRW-F, BIOS 1.0c 09/07/2015
[ 2896.474970] Workqueue: events delayed_work [ceph]
[ 2896.479757] RIP: 0010:rb_erase+0x1a/0x310
[ 2896.483828] Code: fe ff ff 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8b 4f 10 4c 8b 47 08 48 85 c9 0f 84 f1 01 00 00 4d 85 c0 0f 84 57 02 00 00 <49> 8b 40 10 4c 89 c2 48 85 c0 75 0b e9 af 01 00 0
0 48 89 c2 48 89
[ 2896.502661] RSP: 0000:ffffa94e8868fda8 EFLAGS: 00010286
[ 2896.507941] RAX: ffff97a18585ae58 RBX: ffff97a18585ae58 RCX: dead000000000122
[ 2896.515130] RDX: 0000000000000001 RSI: ffff97a1c5cd9ae8 RDI: ffff97a18585ae40
[ 2896.522323] RBP: ffff97a1c5cd9000 R08: dead000000000100 R09: 0000000000000002
[ 2896.529507] R10: 0000000000000000 R11: ffff97a3c202b230 R12: ffffa94e8868fdb8
[ 2896.536693] R13: 000000010008c149 R14: ffff97a1c5cd9af0 R15: ffff97a1c48b4000
[ 2896.543877] FS: 0000000000000000(0000) GS:ffff97a8dfc00000(0000) knlGS:0000000000000000
[ 2896.552017] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2896.557810] CR2: 000055dfa60ea260 CR3: 000000014414e002 CR4: 00000000001706f0
[ 2896.564997] Call Trace:
[ 2896.567516] ceph_trim_snapid_map+0x86/0x1a0 [ceph]
[ 2896.572486] delayed_work+0x1db/0x220 [ceph]
[ 2896.576843] process_one_work+0x238/0x550
[ 2896.580924] ? process_one_work+0x550/0x550
[ 2896.585178] worker_thread+0x50/0x3b0
[ 2896.588914] ? process_one_work+0x550/0x550
[ 2896.593171] kthread+0x117/0x150
[ 2896.596469] ? kthread_insert_work_sanity_check+0x60/0x60
[ 2896.601943] ret_from_fork+0x1f/0x30
[ 2896.605592] Modules linked in: ceph libceph fscache netfs veth 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 br_netfilter bridge stp llc xfs libcrc32c rdma_ucm ib_uverbs rdma_cm iw_cm ib_cm configfs ib_core overlay intel_rapl_msr intel_rapl_common ipmi_ssif sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul ghash_clmulni_intel aesni_intel crypto_simd cryptd joydev mei_me mei ioatdma wmi 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 nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 hid_generic usbhid hid igb ixgbe i2c_algo_bit crc32_pclmul i2c_i801 dca i2c_smbus nvme ahci ptp libahci lpc_ich nvme_core pps_core mdio
[ 2896.682869] ---[ end trace 4e28fbd490b7bb11 ]---
[ 2898.342946] RIP: 0010:rb_erase+0x1a/0x310
[ 2898.347043] Code: fe ff ff 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8b 4f 10 4c 8b 47 08 48 85 c9 0f 84 f1 01 00 00 4d 85 c0 0f 84 57 02 00 00 <49> 8b 40 10 4c 89 c2 48 85 c0 75 0b e9 af 01 00 00 48 89 c2 48 89
[ 2898.365941] RSP: 0000:ffffa94e8868fda8 EFLAGS: 00010286
[ 2898.371249] RAX: ffff97a18585ae58 RBX: ffff97a18585ae58 RCX: dead000000000122
[ 2898.378470] RDX: 0000000000000001 RSI: ffff97a1c5cd9ae8 RDI: ffff97a18585ae40
[ 2898.385691] RBP: ffff97a1c5cd9000 R08: dead000000000100 R09: 0000000000000002
[ 2898.392910] R10: 0000000000000000 R11: ffff97a3c202b230 R12: ffffa94e8868fdb8
[ 2898.400132] R13: 000000010008c149 R14: ffff97a1c5cd9af0 R15: ffff97a1c48b4000
[ 2898.407346] FS: 0000000000000000(0000) GS:ffff97a8dfc00000(0000) knlGS:0000000000000000
[ 2898.415543] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2898.421368] CR2: 000055dfa60ea260 CR3: 000000014414e002 CR4: 00000000001706f0
[ 2898.428598] note: kworker/0:3[27465] exited with preempt_count 1
</pre>
<p>Patrick, are there other instances of this failure? It might be good to check the client kernel logs on those and see if they have similar oopses in them.</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192071
2021-04-19T17:20:20Z
Patrick Donnelly
pdonnell@redhat.com
<ul></ul><p>/ceph/teuthology-archive/pdonnell-2021-04-15_01:35:57-fs-wip-pdonnell-testing-20210414.230315-distro-basic-smithi/6047654</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192072
2021-04-19T17:25:54Z
Jeff Layton
jlayton@redhat.com
<ul></ul><p>Same problem there:</p>
<pre>
smithi029 login: [ 2106.147389] general protection fault, probably for non-canonical address 0xdead000000000100: 0000 [#1] SMP PTI
[ 2106.157445] CPU: 2 PID: 26286 Comm: kworker/2:0 Tainted: G W 5.12.0-rc4-ceph-g0bcfc80ef004 #1
[ 2106.167332] Hardware name: Supermicro SYS-5018R-WR/X10SRW-F, BIOS 1.0c 09/07/2015
[ 2106.174868] Workqueue: events delayed_work [ceph]
[ 2106.179644] RIP: 0010:rb_erase+0x1a/0x310
[ 2106.183716] Code: fe ff ff 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8b 4f 10 4c 8b 47 08 48 85 c9 0f 84 f1 01 00 00 4d 85 c0 0f 84 57 02 00 00 <49> 8b 40 10 4c 89 c2 48 85 c0 75 0b e9 af 01 00 0
0 48 89 c2 48 89
[ 2106.202549] RSP: 0000:ffffbc4505983da8 EFLAGS: 00010286
[ 2106.207830] RAX: ffffa0b2cd4782b8 RBX: ffffa0b2cd4782b8 RCX: dead000000000122
[ 2106.215019] RDX: 0000000000000001 RSI: ffffa0b2c1b2eae8 RDI: ffffa0b2cd4782a0
[ 2106.222214] RBP: ffffa0b2c1b2e000 R08: dead000000000100 R09: 0000000000000002
[ 2106.229406] R10: 0000000000000000 R11: ffffa0b307440970 R12: ffffbc4505983db8
[ 2106.236600] R13: 000000010005bd8a R14: ffffa0b2c1b2eaf0 R15: ffffa0b2deda8000
[ 2106.243794] FS: 0000000000000000(0000) GS:ffffa0ba1fc80000(0000) knlGS:0000000000000000
[ 2106.251942] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2106.257742] CR2: 000056522205d030 CR3: 000000014551e005 CR4: 00000000001706e0
[ 2106.264933] Call Trace:
[ 2106.267454] ceph_trim_snapid_map+0x86/0x1a0 [ceph]
[ 2106.272428] delayed_work+0x1db/0x220 [ceph]
[ 2106.276794] process_one_work+0x238/0x550
[ 2106.280885] ? process_one_work+0x550/0x550
[ 2106.285147] worker_thread+0x50/0x3b0
[ 2106.288882] ? process_one_work+0x550/0x550
[ 2106.293137] kthread+0x117/0x150
[ 2106.296436] ? kthread_insert_work_sanity_check+0x60/0x60
[ 2106.301912] ret_from_fork+0x1f/0x30
[ 2106.305566] Modules linked in: ceph libceph fscache netfs veth 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 br_netfilter bridge stp llc xfs libcrc32c rdma_ucm ib_uverbs rdma_cm iw_cm ib_cm configfs ib_core overlay intel_rapl_msr intel_rapl_common sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp ipmi_ssif crct10dif_pclmul ghash_clmulni_intel aesni_intel crypto_simd joydev cryptd mei_me ioatdma mei wmi 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 nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables x_tables autofs4 hid_generic usbhid hid igb i2c_algo_bit ixgbe crc32_pclmul i2c_i801 nvme dca ahci i2c_smbus ptp libahci lpc_ich nvme_core pps_core mdio
[ 2106.382825] ---[ end trace 1774ba2170907b2f ]---
</pre>
<p>One issue I see: ceph_put_snapid_map looks for RB_EMPTY_NODE to indicate its status during cleanup, but ceph_trim_snapid_map doesn't call RB_CLEAR_NODE after an rb_erase(). I think this means we can end up putting the thing back onto the LRU after it has been moved to the (on-stack) to_free list if we do the last put at an inopportune time. I'm still going over the code to verify that theory though.</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192076
2021-04-19T19:44:03Z
Jeff Layton
jlayton@redhat.com
<ul></ul><p>Ok, I think I see the issue. We had a patch that had done a conversion from atomic_t to refcount_t for some objects, including the snapid_maps. That patch is broken though, as it tried to convert an atomic_inc_return into a refcount_inc/refcount_read and that's not atomic enough for this codepath:</p>
<pre><code><a class="external" href="https://lore.kernel.org/ceph-devel/20210324102625.112640-1-yejune.deng@gmail.com/">https://lore.kernel.org/ceph-devel/20210324102625.112640-1-yejune.deng@gmail.com/</a></code></pre>
<p>I've reverted the patch for now, but I'll leave this open for a bit until we can verify that this is really fixed.</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192077
2021-04-19T20:55:04Z
Patrick Donnelly
pdonnell@redhat.com
<ul></ul><p>test run: <a class="external" href="https://pulpito.ceph.com/pdonnell-2021-04-19_20:54:09-fs:snaps-master-distro-basic-smithi/">https://pulpito.ceph.com/pdonnell-2021-04-19_20:54:09-fs:snaps-master-distro-basic-smithi/</a></p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=192081
2021-04-19T22:44:13Z
Patrick Donnelly
pdonnell@redhat.com
<ul><li><strong>Status</strong> changed from <i>Triaged</i> to <i>Resolved</i></li></ul><p>Considering this resolved -- thanks Jeff.</p>
CephFS - Bug #50281: qa: untar_snap_rm timeout
https://tracker.ceph.com/issues/50281?journal_id=195258
2021-05-15T03:44:36Z
Patrick Donnelly
pdonnell@redhat.com
<ul><li><strong>Related to</strong> <i><a class="issue tracker-1 status-5 priority-4 priority-default closed" href="/issues/50826">Bug #50826</a>: kceph: stock RHEL kernel hangs on snaptests with mon|osd thrashers</i> added</li></ul>