FYI, we noticed the following commit (built with gcc-7):
commit: b6da31b2c07c46f2dcad1d86caa835227a16d9ff ("tty: Fix data race in tty_insert_flip_string_fixed_flag")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -m 512M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+--------------------------------------------------------------------+------------+------------+
| | 638a6f4ebe | b6da31b2c0 |
+--------------------------------------------------------------------+------------+------------+
| boot_successes | 0 | 0 |
| boot_failures | 12 | 12 |
| WARNING:at_lib/debugobjects.c:#__debug_object_init | 12 | 12 |
| RIP:__debug_object_init | 12 | 12 |
| WARNING:suspicious_RCU_usage | 12 | 12 |
| lib/test_rhashtable.c:#suspicious_rcu_dereference_protected()usage | 12 | 12 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 8 |
+--------------------------------------------------------------------+------------+------------+
[ 242.923454] WARNING: possible circular locking dependency detected
[ 242.925453] 4.17.0-rc3-00051-gb6da31b #2 Tainted: G W
[ 242.927353] ------------------------------------------------------
[ 242.929490] S36udev-cache/214 is trying to acquire lock:
[ 242.932560] (ptrval) (&obj_hash[i].lock){..-.}, at: debug_object_activate+0x7d/0x18a
[ 242.936478]
[ 242.936478] but task is already holding lock:
[ 242.940058] (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write+0x39/0x83
[ 242.944880]
[ 242.944880] which lock already depends on the new lock.
[ 242.944880]
[ 242.949034]
[ 242.949034] the existing dependency chain (in reverse order) is:
[ 242.953209]
[ 242.953209] -> #3 (&(&port->lock)->rlock){-...}:
[ 242.956888] tty_port_tty_get+0x1b/0x46
[ 242.959260] tty_port_default_wakeup+0xb/0x26
[ 242.961381] serial8250_tx_chars+0x11c/0x198
[ 242.963306] serial8250_handle_irq+0x9e/0xba
[ 242.964824] serial8250_default_handle_irq+0x24/0x37
[ 242.966162] serial8250_interrupt+0x3c/0xb0
[ 242.967275] __handle_irq_event_percpu+0xf6/0x26b
[ 242.968301] handle_irq_event_percpu+0x1d/0x44
[ 242.969348] handle_irq_event+0x33/0x51
[ 242.970287] handle_edge_irq+0xd8/0xf4
[ 242.971074] handle_irq+0xe7/0xeb
[ 242.971771] do_IRQ+0x42/0xb1
[ 242.972525] ret_from_intr+0x0/0x2e
[ 242.973277] _raw_spin_unlock_irqrestore+0x49/0x57
[ 242.974292] uart_write+0xfe/0x13c
[ 242.975073] n_tty_write+0x21e/0x3ac
[ 242.975855] tty_write+0x1bd/0x256
[ 242.976668] __vfs_write+0x21/0x106
[ 242.977469] vfs_write+0xd9/0x17a
[ 242.978268] ksys_write+0x50/0x8c
[ 242.979113] do_syscall_64+0x91/0x1b8
[ 242.980012] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 242.981039]
[ 242.981039] -> #2 (&port_lock_key){-.-.}:
[ 242.984256] serial8250_console_write+0x8c/0x1f6
[ 242.986546] console_unlock+0x340/0x51f
[ 242.988486] vprintk_emit+0x37b/0x393
[ 242.990387] printk+0x43/0x4b
[ 242.991835] register_console+0x2f1/0x33d
[ 242.993999] univ8250_console_init+0x24/0x27
[ 242.996549] console_init+0x1a3/0x27b
[ 242.997866] start_kernel+0x358/0x470
[ 242.999281] secondary_startup_64+0xa5/0xb0
[ 243.001047]
[ 243.001047] -> #1 (console_owner){..-.}:
[ 243.002334] vprintk_emit+0x37b/0x393
[ 243.003140] printk+0x43/0x4b
[ 243.003915] __debug_object_init+0x419/0x439
[ 243.004856] rhashtable_init+0x1bc/0x201
[ 243.005896] rhltable_init+0xf/0x1b
[ 243.006747] test_insert_dup+0x45/0x62d
[ 243.007908] test_rht_init+0xd2e/0x1042
[ 243.008920] do_one_initcall+0xef/0x247
[ 243.010041] kernel_init_freeable+0x2a1/0x33d
[ 243.011122] kernel_init+0xa/0xe6
[ 243.011862] ret_from_fork+0x24/0x30
[ 243.012742]
[ 243.012742] -> #0 (&obj_hash[i].lock){..-.}:
[ 243.014124] _raw_spin_lock_irqsave+0x42/0x51
[ 243.015303] debug_object_activate+0x7d/0x18a
[ 243.016676] __queue_work+0x6b/0x3a8
[ 243.017780] queue_work_on+0x47/0x7e
[ 243.019006] pty_write+0x63/0x83
[ 243.020357] n_tty_write+0x21e/0x3ac
[ 243.021508] tty_write+0x1bd/0x256
[ 243.022847] __vfs_write+0x21/0x106
[ 243.024033] vfs_write+0xd9/0x17a
[ 243.025291] redirected_tty_write+0x86/0x9f
[ 243.026655] __vfs_write+0x21/0x106
[ 243.027775] vfs_write+0xd9/0x17a
[ 243.028723] ksys_write+0x50/0x8c
[ 243.030124] do_syscall_64+0x91/0x1b8
[ 243.031513] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 243.033444]
[ 243.033444] other info that might help us debug this:
[ 243.033444]
[ 243.035153] Chain exists of:
[ 243.035153] &obj_hash[i].lock --> &port_lock_key --> &(&port->lock)->rlock
[ 243.035153]
[ 243.037858] Possible unsafe locking scenario:
[ 243.037858]
[ 243.039342] CPU0 CPU1
[ 243.040510] ---- ----
[ 243.041687] lock(&(&port->lock)->rlock);
[ 243.042908] lock(&port_lock_key);
[ 243.044708] lock(&(&port->lock)->rlock);
[ 243.046106] lock(&obj_hash[i].lock);
[ 243.047113]
[ 243.047113] *** DEADLOCK ***
[ 243.047113]
[ 243.048155] 5 locks held by S36udev-cache/214:
[ 243.049104] #0: (ptrval) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x20/0x3a
[ 243.050596] #1: (ptrval) (&tty->atomic_write_lock){+.+.}, at: tty_write_lock+0x18/0x3f
[ 243.052290] #2: (ptrval) (&o_tty->termios_rwsem/1){++++}, at: n_tty_write+0x66/0x3ac
[ 243.054043] #3: (ptrval) (&ldata->output_lock){+.+.}, at: n_tty_write+0x118/0x3ac
[ 243.055835] #4: (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write+0x39/0x83
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Xiaolong