Re: [BUG 6.3-rc1] Bad lock in ttm_bo_delayed_delete()

[Steven Rostedt]

On Wed, 8 Mar 2023 07:17:38 +0100
Christian König <christian.koenig@xxxxxxx> wrote:

> What test case/environment do you run to trigger this?

I'm running a 32bit x86 qemu instance. Attached is the config.

The libvirt xml file is here: https://rostedt.org/vm-images/tracetest-32.xml
and the VM image itself is here: https://rostedt.org/vm-images/tracetest-32.qcow2.bz2

It happened again in another test (it's not 100% reproducible).

[   23.234838] ------------[ cut here ]------------
[   23.236391] DEBUG_LOCKS_WARN_ON(lock->magic != lock)
[   23.236429] WARNING: CPU: 0 PID: 61 at kernel/locking/mutex.c:582 __ww_mutex_lock.constprop.0+0x566/0xfec
[   23.240990] Modules linked in:
[   23.242368] CPU: 0 PID: 61 Comm: kworker/0:1H Not tainted 6.3.0-rc1-test-00001-ga98bd42762ed-dirty #972
[   23.245106] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[   23.247900] Workqueue: ttm ttm_bo_delayed_delete
[   23.249642] EIP: __ww_mutex_lock.constprop.0+0x566/0xfec
[   23.251563] Code: e8 2b 5a 95 ff 85 c0 0f 84 25 fb ff ff 8b 0d 18 71 3b c8 85 c9 0f 85 17 fb ff ff 68 c0 58 07 c8 68 07 77 05 c8 e8 e6 0a 40 ff <0f> 0b 58 5a e9 ff fa ff ff e8 f8 59 95 ff 85 c0 74 0e 8b 0d 18 71
[   23.256901] EAX: 00000028 EBX: 00000000 ECX: c1847dd8 EDX: 00000002
[   23.258849] ESI: 00000000 EDI: c12958bc EBP: c1847f00 ESP: c1847eac
[   23.260786] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010286
[   23.262840] CR0: 80050033 CR2: ffbff000 CR3: 0850e000 CR4: 00150ef0
[   23.264781] Call Trace:
[   23.265899]  ? lock_is_held_type+0xbe/0x10c
[   23.267434]  ? ttm_bo_delayed_delete+0x30/0x94
[   23.268971]  ww_mutex_lock+0x32/0x94
[   23.270327]  ttm_bo_delayed_delete+0x30/0x94
[   23.271818]  process_one_work+0x21a/0x538
[   23.273242]  worker_thread+0x146/0x398
[   23.274616]  kthread+0xea/0x10c
[   23.275859]  ? process_one_work+0x538/0x538
[   23.277312]  ? kthread_complete_and_exit+0x1c/0x1c
[   23.278899]  ret_from_fork+0x1c/0x28
[   23.280223] irq event stamp: 33
[   23.281440] hardirqs last  enabled at (33): [<c7d28089>] _raw_spin_unlock_irqrestore+0x2d/0x58
[   23.283860] hardirqs last disabled at (32): [<c71d4ba5>] kvfree_call_rcu+0x155/0x2ec
[   23.286066] softirqs last  enabled at (0): [<c71217fd>] copy_process+0x989/0x2368
[   23.288220] softirqs last disabled at (0): [<00000000>] 0x0
[   23.289952] ---[ end trace 0000000000000000 ]---
[   23.291501] ------------[ cut here ]------------
[   23.293027] refcount_t: underflow; use-after-free.
[   23.294644] WARNING: CPU: 0 PID: 61 at lib/refcount.c:28 refcount_warn_saturate+0xb6/0xfc
[   23.296959] Modules linked in:
[   23.298168] CPU: 0 PID: 61 Comm: kworker/0:1H Tainted: G        W          6.3.0-rc1-test-00001-ga98bd42762ed-dirty #972
[   23.301073] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[   23.303642] Workqueue: ttm ttm_bo_delayed_delete
[   23.305190] EIP: refcount_warn_saturate+0xb6/0xfc
[   23.306767] Code: 68 70 e1 0c c8 e8 f6 d6 a9 ff 0f 0b 58 c9 c3 90 80 3d 8a 78 38 c8 00 75 8a c6 05 8a 78 38 c8 01 68 9c e1 0c c8 e8 d6 d6 a9 ff <0f> 0b 59 c9 c3 80 3d 88 78 38 c8 00 0f 85 67 ff ff ff c6 05 88 78
[   23.311935] EAX: 00000026 EBX: c1295950 ECX: c1847e40 EDX: 00000002
[   23.313884] ESI: c12958bc EDI: f7591100 EBP: c1847f18 ESP: c1847f14
[   23.315840] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010246
[   23.317887] CR0: 80050033 CR2: ffbff000 CR3: 0850e000 CR4: 00150ef0
[   23.319859] Call Trace:
[   23.320978]  ttm_bo_delayed_delete+0x8c/0x94
[   23.322492]  process_one_work+0x21a/0x538
[   23.323959]  worker_thread+0x146/0x398
[   23.325353]  kthread+0xea/0x10c
[   23.326609]  ? process_one_work+0x538/0x538
[   23.328081]  ? kthread_complete_and_exit+0x1c/0x1c
[   23.329683]  ret_from_fork+0x1c/0x28
[   23.331011] irq event stamp: 33
[   23.332251] hardirqs last  enabled at (33): [<c7d28089>] _raw_spin_unlock_irqrestore+0x2d/0x58
[   23.334334] hardirqs last disabled at (32): [<c71d4ba5>] kvfree_call_rcu+0x155/0x2ec
[   23.336176] softirqs last  enabled at (0): [<c71217fd>] copy_process+0x989/0x2368
[   23.337904] softirqs last disabled at (0): [<00000000>] 0x0
[   23.339313] ---[ end trace 0000000000000000 ]---

-- Steve

Attachment: config
Description: Binary data