Bug 1654538
| Summary: | panic and/or list_del corruption in cifs_reconnect while iterating retry_list due to use-after-free of a struct mid_q_entry | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 8 | Reporter: | xiaoli feng <xifeng> |
| Component: | kernel | Assignee: | Dave Wysochanski <dwysocha> |
| kernel sub component: | CIFS | QA Contact: | xiaoli feng <xifeng> |
| Status: | CLOSED DUPLICATE | Docs Contact: | |
| Severity: | unspecified | ||
| Priority: | unspecified | CC: | cifs-maint, dwysocha, fsorenso, lsahlber, rhandlin, stalexan, xzhou |
| Version: | 8.0 | Keywords: | Reproducer |
| Target Milestone: | rc | Flags: | pm-rhel:
mirror+
|
| Target Release: | 8.0 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | 1596570 | Environment: | |
| Last Closed: | 2019-10-28 08:24:12 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
| Bug Depends On: | 1596570, 1614201 | ||
| Bug Blocks: | 1607178 | ||
| Attachments: | |||
|
Comment 13
Dave Wysochanski
2019-10-16 18:55:08 UTC
Yesterday I instrumented the 5.4-rc3 kernel with the a debug patch after looking at the code and concluding the list is protected everywhere it is run by GlobalMid_Lock and there is no possibility of an interrupt. I instrumented 5.4-rc3 with a small patch (attached) which added cifs_dbg statements to print out the address of the mid in: 1) cifs_delete_mid, and including the function name of the caller 2) cifs_reconnect before the list_move to retry_list 3) cifs_reconnect before the list_del_init while iterating retry_list The significant findings after crashing with the above were: 1. Most of the time I would see a sequence of mid addresses printed from #2, followed by the same sequence of addresses in reverse order printed from #3 2. Just before the crash, a sequence of addresses printed from #2 did not match at all sequences from #3. That is, the very first address printed from #3 looked corrupted and every address after that was corrupted. 3. Just before the crash, the same addresses are printed in "compound_send_recv calling cifs_delete_mid" as are printed in "list_move" Example of tracing output: [ 182.243712] CIFS VFS: cifs_reconnect: list_move(mid = ffff9ba76b7b4780) <-----+ [ 182.246402] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba76b7b4780) <--+ Same mid as last list_move (expected) ... [ 203.293987] CIFS VFS: cifs_reconnect: list_move(mid = ffff9ba76b7b4d80) <------+ [ 203.296640] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba76b7b4d80) <--+ Same mid as last list_move (expected) ... [ 297.923123] CIFS VFS: cifs_reconnect: list_move(mid = ffff9ba76e2cbd80) <------+ [ 297.925843] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba772d94000) <--+ Should be same address as last list_move (unexpected) [ 297.928735] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba7723a8f00) [ 297.931632] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba766800240) [ 297.934577] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9ba766800a80) [ 297.937447] list_del corruption. prev->next should be ffff9ba766800a80, but was dd4a63b0bee92640 [ 297.941146] ------------[ cut here ]------------ [ 297.943040] kernel BUG at lib/list_debug.c:51! [ 297.944973] invalid opcode: 0000 [#1] SMP PTI [ 297.946930] CPU: 5 PID: 13315 Comm: cifsd Kdump: loaded Not tainted 5.4.0-rc3-dbg1+ #20 [ 297.949378] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011 [ 297.951585] RIP: 0010:__list_del_entry_valid.cold+0x31/0x55 [ 297.953809] Code: 5e 15 9f e8 54 a3 c5 ff 0f 0b 48 c7 c7 70 5f 15 9f e8 46 a3 c5 ff 0f 0b 48 89 f2 48 89 fe 48 c7 c7 30 5f 15 9f e8 32 a3 c5 ff <0f> 0b 48 89 fe 4c 89 c2 48 c7 c7 f8 5e 15 9f e8 1e a3 c5 ff 0f 0b [ 297.961508] RSP: 0018:ffffb1c44040bd38 EFLAGS: 00010246 [ 297.963583] RAX: 0000000000000054 RBX: ffff9ba76dc1a800 RCX: 0000000000000000 [ 297.966414] RDX: 0000000000000000 RSI: ffff9ba777b57908 RDI: ffff9ba777b57908 [ 297.969191] RBP: ffff9ba766800a80 R08: ffff9ba777b57908 R09: 0000000000000440 [ 297.972025] R10: ffffb1c44040bbf0 R11: ffffb1c44040bbf5 R12: ffff9ba76dc1a9c0 [ 297.974799] R13: ffffb1c44040bd48 R14: ffff9ba7668003c0 R15: ffff9ba7723a8f00 [ 297.977584] FS: 0000000000000000(0000) GS:ffff9ba777b40000(0000) knlGS:0000000000000000 [ 297.980731] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 297.982993] CR2: 00007f399ce888a0 CR3: 0000000233604000 CR4: 00000000000406e0 [ 297.985782] Call Trace: [ 297.987181] cifs_reconnect+0x294/0x650 [cifs] [ 297.989099] cifs_readv_from_socket+0x220/0x250 [cifs] [ 297.991246] cifs_read_from_socket+0x4a/0x70 [cifs] [ 297.993274] ? try_to_wake_up+0x212/0x650 [ 297.994936] ? cifs_buf_get+0x16/0x60 [cifs] [ 297.996722] ? allocate_buffers+0x3e/0x120 [cifs] [ 297.998673] cifs_demultiplex_thread+0xdc/0xc30 [cifs] [ 298.000805] kthread+0xfb/0x130 [ 298.002128] ? cifs_handle_standard+0x190/0x190 [cifs] [ 298.004217] ? kthread_park+0x90/0x90 [ 298.005721] ret_from_fork+0x35/0x40 [ 298.007201] Modules linked in: cifs libdes libarc4 ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat iptable_mangle iptable_raw iptable_security nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables joydev crct10dif_pclmul crc32_pclmul virtio_balloon ghash_clmulni_intel i2c_piix4 nfsd nfs_acl lockd auth_rpcgss grace sunrpc xfs libcrc32c virtio_net virtio_console net_failover failover virtio_blk ata_generic crc32c_intel serio_raw pata_acpi qemu_fw_cfg Here is the latest trace, adding a bit more debug information. [ 44.680272] Mounted xfs file system at /mnt/build supports timestamps until 2038 (0x7fffffff) [ 84.294992] Key type cifs.idmap registered [ 84.310281] CIFS: Attempting to mount //192.168.122.44/example [ 84.329833] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.335914] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.358111] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.367292] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.374213] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.383804] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.388958] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.394066] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.413435] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 84.420233] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3849c0, flags = 0x0) [ 88.667912] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa32962480, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.679962] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa32962840, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.685558] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa323af840, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.691128] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa317d76c0, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.696671] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa337d1840, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.702230] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa31dece40, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.707702] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa32962780, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.713185] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa317d7d80, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.718684] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa337d1d80, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.724240] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa2c3846c0, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 88.729761] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa2c3846c0) [ 88.732733] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa337d1d80) [ 88.735721] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa317d7d80) [ 88.738709] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa32962780) [ 88.741646] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa31dece40) [ 88.744614] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa337d1840) [ 88.747552] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa317d76c0) [ 88.750488] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa323af840) [ 88.753433] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa32962840) [ 88.756377] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa32962480) [ 91.830138] compound_send_recv: 7606 callbacks suppressed [ 91.830143] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa3128bf00, flags = 0x0) [ 91.863892] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa3128bf00, flags = 0x0) [ 91.878870] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa3128bf00, flags = 0x0) [ 91.886828] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa3128bf00, flags = 0x0) [ 91.896884] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa3128bf00, flags = 0x0) [ 96.952525] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa323af780, flags = 0x0) [ 97.009439] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa323af780, flags = 0x0) [ 97.023629] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa323af780, flags = 0x0) [ 97.031488] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa323af780, flags = 0x0) [ 97.040064] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa323af780, flags = 0x0) [ 99.117328] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa31dece40, flags = 0x0) [ 99.125521] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa32962480, flags = 0x0) [ 99.125527] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa317d76c0, flags = 0x0) [ 99.132685] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa337d1840, flags = 0x0) [ 99.132689] CIFS VFS: CIFS VFS: compound_send_recv calling cifs_delete_mid (mid = ffff9aaa2c3846c0, flags = 0x0) [ 99.184847] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa317d76c0, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fcc0) [ 99.199475] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa317d7300, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fcc0) [ 99.205076] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa317d7780, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.210299] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa323af780, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.215515] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa2c3846c0, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.221890] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa2c3849c0, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.277952] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa31dece40, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.283372] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa31decf00, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.288609] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa337d1780, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.293854] CIFS VFS: cifs_reconnect: list_move(mid = ffff9aaa337d1600, mid_state = 0x2, mid_flags = 0x0, refcount = 1, callback = ffffffffc057fd50) [ 99.299074] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa317d7540) [ 99.301885] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa337d1600) [ 99.304684] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa337d1780) [ 99.307484] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa31decf00) [ 99.310280] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa31dece40) [ 99.313059] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa2c3849c0) [ 99.315846] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa2c3846c0) [ 99.318638] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa323af780) [ 99.321421] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa317d7780) [ 99.324259] CIFS VFS: cifs_reconnect: list_del_init(mid = ffff9aaa317d7300) [ 99.333756] list_del corruption. prev->next should be ffff9aaa317d7300, but was 3652e909f35448b1 [ 99.337414] ------------[ cut here ]------------ [ 99.339261] kernel BUG at lib/list_debug.c:51! [ 99.341144] invalid opcode: 0000 [#1] SMP PTI [ 99.342989] CPU: 3 PID: 13200 Comm: cifsd Kdump: loaded Not tainted 5.4.0-rc3-dbg2+ #22 [ 99.346230] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011 [ 99.348619] RIP: 0010:__list_del_entry_valid.cold+0x31/0x55 [ 99.350905] Code: 5e 15 b8 e8 54 a3 c5 ff 0f 0b 48 c7 c7 78 5f 15 b8 e8 46 a3 c5 ff 0f 0b 48 89 f2 48 89 fe 48 c7 c7 38 5f 15 b8 e8 32 a3 c5 ff <0f> 0b 48 89 fe 4c 89 c2 48 c7 c7 00 5f 15 b8 e8 1e a3 c5 ff 0f 0b [ 99.358417] RSP: 0018:ffffa99d0045bd38 EFLAGS: 00010246 [ 99.360550] RAX: 0000000000000054 RBX: ffff9aaa31581800 RCX: 0000000000000000 [ 99.363451] RDX: 0000000000000000 RSI: ffff9aaa37ad7908 RDI: ffff9aaa37ad7908 [ 99.366346] RBP: ffff9aaa317d7300 R08: ffff9aaa37ad7908 R09: 00000000000002c4 [ 99.369240] R10: ffffa99d0045bbf0 R11: ffffa99d0045bbf5 R12: ffff9aaa315819c0 [ 99.372123] R13: ffffa99d0045bd48 R14: ffff9aaa317d76c0 R15: ffff9aaa337d1600 [ 99.375016] FS: 0000000000000000(0000) GS:ffff9aaa37ac0000(0000) knlGS:0000000000000000 [ 99.378328] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 99.380680] CR2: 00007f0e9ddf2cd0 CR3: 000000004040a000 CR4: 00000000000406e0 [ 99.383590] Call Trace: [ 99.384689] cifs_reconnect+0x294/0x650 [cifs] [ 99.386541] cifs_readv_from_socket+0x220/0x250 [cifs] [ 99.388681] cifs_read_from_socket+0x4a/0x70 [cifs] [ 99.390704] ? try_to_wake_up+0x212/0x650 [ 99.392392] ? cifs_small_buf_get+0x16/0x30 [cifs] [ 99.394386] ? allocate_buffers+0x66/0x120 [cifs] [ 99.396335] cifs_demultiplex_thread+0xdc/0xc30 [cifs] [ 99.398481] kthread+0xfb/0x130 [ 99.399819] ? cifs_handle_standard+0x190/0x190 [cifs] [ 99.401948] ? kthread_park+0x90/0x90 [ 99.403455] ret_from_fork+0x35/0x40 [ 99.404941] Modules linked in: cifs libdes libarc4 ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat iptable_mangle iptable_raw iptable_security nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables joydev crct10dif_pclmul crc32_pclmul ghash_clmulni_intel virtio_balloon i2c_piix4 nfsd nfs_acl lockd auth_rpcgss grace sunrpc xfs libcrc32c virtio_net net_failover ata_generic crc32c_intel virtio_blk virtio_console failover serio_raw pata_acpi qemu_fw_cfg [ 99.426521] ---[ end trace 6fc84efb010e0c43 ]--- [ 99.428468] RIP: 0010:__list_del_entry_valid.cold+0x31/0x55 [ 99.430827] Code: 5e 15 b8 e8 54 a3 c5 ff 0f 0b 48 c7 c7 78 5f 15 b8 e8 46 a3 c5 ff 0f 0b 48 89 f2 48 89 fe 48 c7 c7 38 5f 15 b8 e8 32 a3 c5 ff <0f> 0b 48 89 fe 4c 89 c2 48 c7 c7 00 5f 15 b8 e8 1e a3 c5 ff 0f 0b [ 99.438531] RSP: 0018:ffffa99d0045bd38 EFLAGS: 00010246 [ 99.440734] RAX: 0000000000000054 RBX: ffff9aaa31581800 RCX: 0000000000000000 [ 99.443708] RDX: 0000000000000000 RSI: ffff9aaa37ad7908 RDI: ffff9aaa37ad7908 [ 99.446647] RBP: ffff9aaa317d7300 R08: ffff9aaa37ad7908 R09: 00000000000002c4 [ 99.449587] R10: ffffa99d0045bbf0 R11: ffffa99d0045bbf5 R12: ffff9aaa315819c0 [ 99.452529] R13: ffffa99d0045bd48 R14: ffff9aaa317d76c0 R15: ffff9aaa337d1600 [ 99.455510] FS: 0000000000000000(0000) GS:ffff9aaa37ac0000(0000) knlGS:0000000000000000 [ 99.458848] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 99.461235] CR2: 00007f0e9ddf2cd0 CR3: 000000004040a000 CR4: 00000000000406e0 Created attachment 1626773 [details]
first debug patch on 5.4-rc3
That is a very good find!!! It matches what I speculated on earlier today, The loop over the retry_list (3 in your example) is not protected by the mutex so it could race with with a different thread that is already holding the same mid and then calling list_del and colliding with the retry_list loop also calling list_del. Or the race could also be that we get the mid in the retry_list loop, then before we get much further, a different thread calling cifs_delete_mid()/DeleteMidQEntry() which will free the mid structure. (causing the retry_list loop and possibly the call to mid->callback referencing free memory.) I have started sketching on a wip patch for this but it is there are dragons. (In reply to Ronnie Sahlberg from comment #17) > That is a very good find!!! > > It matches what I speculated on earlier today, > > The loop over the retry_list (3 in your example) is not protected by the > mutex > so it could race with with a different thread that is already holding the > same mid and then calling > list_del and colliding with the retry_list loop also calling list_del. > > Or the race could also be that we get the mid in the retry_list loop, then > before we get much further, > a different thread calling cifs_delete_mid()/DeleteMidQEntry() which will > free the mid structure. > (causing the retry_list loop and possibly the call to mid->callback > referencing free memory.) > > > I have started sketching on a wip patch for this but it is there are dragons. Ok. I confess I'm not 100% sure I have the other thread that touches the mid, and I'm tracing all callers of cifs_del_mid though I guess I should shift to in memory tracing or fix the suppressions: [ 91.830138] compound_send_recv: 7606 callbacks suppressed If you have ideas on where to trace I can try to add it. I'm adding the 'next' and 'prev' pointers to see if it is easier to identify that first list_del_init address which seems not to map to anything readily obvious. I was thinking about skipping a mid inside cifs_reconnect loops based on the mid state or flags but it looks like the 'good' case is the same as the 'bad' case but then again probably we are getting the important messages suppressed so I need to fix that first. Created attachment 1626822 [details]
debug output from 3rd debug iteration
I posted a wip idea on how we can fix the two bugs I suspect we have in this loop to the list. (bug 1: need to protect the list mutate functions with the mutex bug 2: need to protect the mid frombeing freed before we call the callback) the wip patch looks like this if you want to try it : diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c index bdea4b3e8005..3a1a9b63bd9b 100644 --- a/fs/cifs/connect.c +++ b/fs/cifs/connect.c @@ -572,11 +572,19 @@ cifs_reconnect(struct TCP_Server_Info *server) mutex_unlock(&server->srv_mutex); cifs_dbg(FYI, "%s: issuing mid callbacks\n", __func__); + spin_lock(&GlobalMid_Lock); list_for_each_safe(tmp, tmp2, &retry_list) { mid_entry = list_entry(tmp, struct mid_q_entry, qhead); list_del_init(&mid_entry->qhead); + kref_get(&mid_entry->refcount); + spin_unlock(&GlobalMid_Lock); + mid_entry->callback(mid_entry); + cifs_mid_q_entry_release(mid_entry); + + spin_lock(&GlobalMid_Lock); } + spin_unlock(&GlobalMid_Lock); if (cifs_rdma_enabled(server)) { mutex_lock(&server->srv_mutex); Created attachment 1626836 [details]
debug output from 4th debug iteration with ratelimit disabled - still not clear where root of problem is but looks like it is a use after free
Created attachment 1627175 [details]
patch under test to fix this bug
Pavel has posted a new version of the bug upstream which will be tested. It is a simpler version of a fix to make backporting easier and then we can do more elaborate fixes in master going forward. (In reply to Dave Wysochanski from comment #21) > Created attachment 1626836 [details] > debug output from 4th debug iteration with ratelimit disabled - still not > clear where root of problem is but looks like it is a use after free The root of this problem was that the code _looked_ like it was safe to call list_del_init in that second loop when were were iterating through retry_list, however it was not. The reason is that the loop was unprotected by anything, and another thread also could be operating on the same mid, changing the mid_entry->qhead pointer values, hence corrupting them. The end result could be that the second loop would loop on a singleton list and never finish, and eventually use the mid_entry after the memory was freed. This happened even though the refcount was added in the first loop - it didn't prevent a crash because we could loop over the same item again and again dropping the reference. The fix is to make some way to avoid calling list_del_init twice on the same mid_entry->qhead. (In reply to Ronnie Sahlberg from comment #23) > Pavel has posted a new version of the bug upstream which will be tested. > It is a simpler version of a fix to make backporting easier and then we can > do more elaborate fixes in master going forward. Yes I am going to build his patch on top of 5.4-rc4 and run a test shortly and report back. I would not say "its simpler" as it looks more complicated to me but it may be better and obviously you and Pavel know these areas better than me - I've not looked in depth at his patch yet but will read it today. I ran the reproducer on a test kernel that was 5.4-rc4 plus Pavel's patch (see below) and it did not crash or throw list_del corruption to the console, so I think it is fine to fix this issue. https://git.samba.org/?p=sfrench/cifs-2.6.git;a=commit;h=85b711d8867a4c1c9e5a9b654857be4e04218c20 Now pavel's patch to fix this has been pulled in for testing. However, I just got notice that buildbot failed one test so not sure of status now. (In reply to Dave Wysochanski from comment #25) > I ran the reproducer on a test kernel that was 5.4-rc4 plus Pavel's patch > (see below) and it did not crash or throw list_del corruption to the > console, so I think it is fine to fix this issue. > https://git.samba.org/?p=sfrench/cifs-2.6.git;a=commit; > h=85b711d8867a4c1c9e5a9b654857be4e04218c20 > > Now pavel's patch to fix this has been pulled in for testing. However, I > just got notice that buildbot failed one test so not sure of status now. It looks like the buildbot failure may have been due to a separate issue that it's unclear how it's related. Pavel submitted another patch for that and it's under testing and may even fix another bug which we have open, Bug 1685457 - RHEL 7.6 : frequent panics in cifsFileInfo_put due to a freed cifsFileInfo struct *** This bug has been marked as a duplicate of bug 1765979 *** |