From: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>
To: Petr Mladek <pmladek@suse.com>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
Jiri Slaby <jirislaby@kernel.org>,
Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
Steven Rostedt <rostedt@goodmis.org>,
John Ogness <john.ogness@linutronix.de>,
linux-kernel@vger.kernel.org
Subject: [PATCH v2] tty: use printk_deferred() at tty_msg()
Date: Wed, 7 Apr 2021 22:26:21 +0900 [thread overview]
Message-ID: <d78ae8da-16e9-38d9-e274-048c54e24360@i-love.sakura.ne.jp> (raw)
In-Reply-To: <3c15d32f-c568-7f6f-fa7e-af4deb9b49f9@i-love.sakura.ne.jp>
syzbot is reporting circular locking dependency due to calling printk()
with port lock held [1]. Update tty_msg() to use printk_deferred() in
order to break this dependency. Since tty_info_ratelimited() is used by
only tty_init_dev() which is called without holding port lock, just
redirect tty_info_ratelimited() to pr_info_ratelimited().
======================================================
WARNING: possible circular locking dependency detected
5.12.0-rc6-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.4/2155 is trying to acquire lock:
ffffffff8be805a0 (console_owner){....}-{0:0}, at: console_unlock+0x2f2/0xc80 kernel/printk/printk.c:2551
but task is already holding lock:
ffffffff90114698 (&port->lock){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #2 (&port->lock){-.-.}-{2:2}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159
tty_port_tty_get+0x1f/0x100 drivers/tty/tty_port.c:288
tty_port_default_wakeup+0x11/0x40 drivers/tty/tty_port.c:47
serial8250_tx_chars+0x487/0xa80 drivers/tty/serial/8250/8250_port.c:1832
serial8250_handle_irq.part.0+0x328/0x3d0 drivers/tty/serial/8250/8250_port.c:1919
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1892 [inline]
serial8250_default_handle_irq+0xb2/0x220 drivers/tty/serial/8250/8250_port.c:1935
serial8250_interrupt+0xfd/0x200 drivers/tty/serial/8250/8250_core.c:126
__handle_irq_event_percpu+0x303/0x8f0 kernel/irq/handle.c:156
handle_irq_event_percpu kernel/irq/handle.c:196 [inline]
handle_irq_event+0x102/0x290 kernel/irq/handle.c:213
handle_edge_irq+0x25f/0xd00 kernel/irq/chip.c:819
generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
handle_irq arch/x86/kernel/irq.c:231 [inline]
__common_interrupt+0x9e/0x200 arch/x86/kernel/irq.c:250
common_interrupt+0x9f/0xd0 arch/x86/kernel/irq.c:240
asm_common_interrupt+0x1e/0x40 arch/x86/include/asm/idtentry.h:623
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:161 [inline]
_raw_spin_unlock_irqrestore+0x38/0x70 kernel/locking/spinlock.c:191
spin_unlock_irqrestore include/linux/spinlock.h:409 [inline]
uart_write+0x30d/0x570 drivers/tty/serial/serial_core.c:615
do_output_char+0x5de/0x850 drivers/tty/n_tty.c:443
process_output drivers/tty/n_tty.c:510 [inline]
n_tty_write+0x4c3/0xfd0 drivers/tty/n_tty.c:2365
do_tty_write drivers/tty/tty_io.c:1043 [inline]
file_tty_write.constprop.0+0x526/0x910 drivers/tty/tty_io.c:1133
redirected_tty_write+0xa1/0xc0 drivers/tty/tty_io.c:1140
call_write_iter include/linux/fs.h:1977 [inline]
do_iter_readv_writev+0x46f/0x740 fs/read_write.c:740
do_iter_write+0x188/0x670 fs/read_write.c:866
vfs_writev+0x1aa/0x630 fs/read_write.c:939
do_writev+0x139/0x300 fs/read_write.c:982
do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
entry_SYSCALL_64_after_hwframe+0x44/0xae
-> #1 (&port_lock_key){-.-.}-{2:2}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159
serial8250_console_write+0x8b2/0xae0 drivers/tty/serial/8250/8250_port.c:3292
call_console_drivers kernel/printk/printk.c:1862 [inline]
console_unlock+0x895/0xc80 kernel/printk/printk.c:2576
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
register_console kernel/printk/printk.c:2927 [inline]
register_console+0x606/0x840 kernel/printk/printk.c:2807
univ8250_console_init+0x3a/0x46 drivers/tty/serial/8250/8250_core.c:690
console_init+0x3c7/0x596 kernel/printk/printk.c:3027
start_kernel+0x306/0x496 init/main.c:993
secondary_startup_64_no_verify+0xb0/0xbb
-> #0 (console_owner){....}-{0:0}:
check_prev_add kernel/locking/lockdep.c:2936 [inline]
check_prevs_add kernel/locking/lockdep.c:3059 [inline]
validate_chain kernel/locking/lockdep.c:3674 [inline]
__lock_acquire+0x2b14/0x54c0 kernel/locking/lockdep.c:4900
lock_acquire kernel/locking/lockdep.c:5510 [inline]
lock_acquire+0x1ab/0x740 kernel/locking/lockdep.c:5475
console_lock_spinning_enable kernel/printk/printk.c:1714 [inline]
console_unlock+0x371/0xc80 kernel/printk/printk.c:2573
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
tty_port_close_start.part.0+0x503/0x550 drivers/tty/tty_port.c:569
tty_port_close_start drivers/tty/tty_port.c:641 [inline]
tty_port_close+0x46/0x170 drivers/tty/tty_port.c:634
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1779
__fput+0x288/0x920 fs/file_table.c:280
task_work_run+0xdd/0x1a0 kernel/task_work.c:140
exit_task_work include/linux/task_work.h:30 [inline]
do_exit+0xbfc/0x2a60 kernel/exit.c:825
do_group_exit+0x125/0x310 kernel/exit.c:922
get_signal+0x47f/0x2150 kernel/signal.c:2781
arch_do_signal_or_restart+0x2a8/0x1eb0 arch/x86/kernel/signal.c:789
handle_signal_work kernel/entry/common.c:147 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x148/0x250 kernel/entry/common.c:208
__syscall_exit_to_user_mode_work kernel/entry/common.c:290 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:301
entry_SYSCALL_64_after_hwframe+0x44/0xae
other info that might help us debug this:
Chain exists of:
console_owner --> &port_lock_key --> &port->lock
Possible unsafe locking scenario:
CPU0 CPU1
---- ----
lock(&port->lock);
lock(&port_lock_key);
lock(&port->lock);
lock(console_owner);
*** DEADLOCK ***
3 locks held by syz-executor.4/2155:
#0: ffff88802ce391c0 (&tty->legacy_mutex){+.+.}-{3:3}, at: tty_lock+0xbd/0x120 drivers/tty/tty_mutex.c:19
#1: ffffffff90114698 (&port->lock){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567
#2: ffffffff8bf60920 (console_lock){+.+.}-{0:0}, at: vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
stack backtrace:
CPU: 0 PID: 2155 Comm: syz-executor.4 Not tainted 5.12.0-rc6-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
check_noncircular+0x25f/0x2e0 kernel/locking/lockdep.c:2127
check_prev_add kernel/locking/lockdep.c:2936 [inline]
check_prevs_add kernel/locking/lockdep.c:3059 [inline]
validate_chain kernel/locking/lockdep.c:3674 [inline]
__lock_acquire+0x2b14/0x54c0 kernel/locking/lockdep.c:4900
lock_acquire kernel/locking/lockdep.c:5510 [inline]
lock_acquire+0x1ab/0x740 kernel/locking/lockdep.c:5475
console_lock_spinning_enable kernel/printk/printk.c:1714 [inline]
console_unlock+0x371/0xc80 kernel/printk/printk.c:2573
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
tty_port_close_start.part.0+0x503/0x550 drivers/tty/tty_port.c:569
tty_port_close_start drivers/tty/tty_port.c:641 [inline]
tty_port_close+0x46/0x170 drivers/tty/tty_port.c:634
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1779
__fput+0x288/0x920 fs/file_table.c:280
task_work_run+0xdd/0x1a0 kernel/task_work.c:140
exit_task_work include/linux/task_work.h:30 [inline]
do_exit+0xbfc/0x2a60 kernel/exit.c:825
do_group_exit+0x125/0x310 kernel/exit.c:922
get_signal+0x47f/0x2150 kernel/signal.c:2781
arch_do_signal_or_restart+0x2a8/0x1eb0 arch/x86/kernel/signal.c:789
handle_signal_work kernel/entry/common.c:147 [inline]
exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
exit_to_user_mode_prepare+0x148/0x250 kernel/entry/common.c:208
__syscall_exit_to_user_mode_work kernel/entry/common.c:290 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:301
entry_SYSCALL_64_after_hwframe+0x44/0xae
Note that this patch has a small side effect that 5 tty_debug() messages
in __proc_set_tty()/tty_release_checks() are enabled, for pr_debug() is
conditional while KERN_DEBUG is unconditional. It seems that remaining
tty_debug() messages meant to be unconditional without knowing that
pr_debug() is conditional.
Note that this patch is not complete, for there is same dependency due to
memory allocation fault injection at tty_buffer_alloc().
By the way, as soon as applying this patch, I guess that syzkaller starts
generating hung task reports because /dev/ttyprintk can trivially trigger
flood of
tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
port->count);
message, and adding
if (strcmp(tty_driver_name(tty), "ttyprintk"))
immediately before this tty_warn() gave me Tested-by: response.
[1] https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com>
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Fixes: b6da31b2c07c46f2 ("tty: Fix data race in tty_insert_flip_string_fixed_flag")
Cc: <stable@vger.kernel.org> # 4.18+
---
include/linux/tty.h | 16 ++++++++--------
1 file changed, 8 insertions(+), 8 deletions(-)
diff --git a/include/linux/tty.h b/include/linux/tty.h
index 95fc2f100f12..042d968e5d50 100644
--- a/include/linux/tty.h
+++ b/include/linux/tty.h
@@ -772,16 +772,16 @@ static inline void proc_tty_register_driver(struct tty_driver *d) {}
static inline void proc_tty_unregister_driver(struct tty_driver *d) {}
#endif
-#define tty_msg(fn, tty, f, ...) \
- fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__)
+#define tty_msg(lv, tty, f, ...) \
+ printk_deferred(lv pr_fmt("%s %s: " f), tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__)
-#define tty_debug(tty, f, ...) tty_msg(pr_debug, tty, f, ##__VA_ARGS__)
-#define tty_info(tty, f, ...) tty_msg(pr_info, tty, f, ##__VA_ARGS__)
-#define tty_notice(tty, f, ...) tty_msg(pr_notice, tty, f, ##__VA_ARGS__)
-#define tty_warn(tty, f, ...) tty_msg(pr_warn, tty, f, ##__VA_ARGS__)
-#define tty_err(tty, f, ...) tty_msg(pr_err, tty, f, ##__VA_ARGS__)
+#define tty_debug(tty, f, ...) tty_msg(KERN_DEBUG, tty, f, ##__VA_ARGS__)
+#define tty_info(tty, f, ...) tty_msg(KERN_INFO, tty, f, ##__VA_ARGS__)
+#define tty_notice(tty, f, ...) tty_msg(KERN_NOTICE, tty, f, ##__VA_ARGS__)
+#define tty_warn(tty, f, ...) tty_msg(KERN_WARNING, tty, f, ##__VA_ARGS__)
+#define tty_err(tty, f, ...) tty_msg(KERN_ERR, tty, f, ##__VA_ARGS__)
#define tty_info_ratelimited(tty, f, ...) \
- tty_msg(pr_info_ratelimited, tty, f, ##__VA_ARGS__)
+ pr_info_ratelimited("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__)
#endif
--
2.18.4
next prev parent reply other threads:[~2021-04-07 13:27 UTC|newest]
Thread overview: 43+ messages / expand[flat|nested] mbox.gz Atom feed top
2021-04-03 4:14 [PATCH] tty: use printk_safe context at tty_msg() Tetsuo Handa
2021-04-03 6:52 ` kernel test robot
2021-04-03 10:11 ` [PATCH] printk: Make multiple inclusion of kernel/printk/internal.h safe Tetsuo Handa
2021-04-06 4:51 ` [PATCH] tty: use printk_safe context at tty_msg() Jiri Slaby
2021-04-06 5:31 ` Tetsuo Handa
2021-04-06 7:10 ` Greg Kroah-Hartman
2021-04-06 11:16 ` Tetsuo Handa
2021-04-06 13:42 ` Greg Kroah-Hartman
2021-04-06 15:10 ` Petr Mladek
2021-04-06 16:22 ` Tetsuo Handa
2021-04-06 19:10 ` Greg Kroah-Hartman
2021-04-07 9:20 ` Petr Mladek
2021-04-07 13:26 ` Tetsuo Handa [this message]
2021-04-07 13:48 ` [PATCH v2] tty: use printk_deferred() " Greg Kroah-Hartman
2021-04-07 14:24 ` Tetsuo Handa
2021-04-12 10:39 ` How to handle concurrent access to /dev/ttyprintk ? Tetsuo Handa
2021-04-12 10:44 ` Greg Kroah-Hartman
2021-04-12 11:25 ` Tetsuo Handa
2021-04-12 12:04 ` Greg Kroah-Hartman
2021-04-14 0:45 ` Tetsuo Handa
2021-04-14 11:11 ` Tetsuo Handa
2021-04-14 16:15 ` Samo Pogačnik
2021-04-15 0:22 ` [PATCH] ttyprintk: Add TTY hangup callback Tetsuo Handa
2021-04-18 11:16 ` Samo Pogačnik
2021-04-22 10:02 ` Greg Kroah-Hartman
2021-04-23 4:22 ` Jiri Slaby
2021-04-23 9:55 ` Samo Pogačnik
2021-04-23 10:12 ` Tetsuo Handa
2021-04-23 19:47 ` Samo Pogačnik
2021-04-24 1:16 ` Tetsuo Handa
2021-04-24 9:57 ` Samo Pogačnik
2021-04-26 10:00 ` Petr Mladek
2021-04-26 16:42 ` Samo Pogačnik
2021-04-27 10:08 ` Petr Mladek
2021-04-27 11:31 ` Samo Pogačnik
2021-04-23 10:28 ` Jiri Slaby
2021-04-23 12:23 ` [PATCH] ttyprintk: Add TTY port shutdown callback Samo Pogačnik
2021-04-12 12:41 ` How to handle concurrent access to /dev/ttyprintk ? Samo Pogačnik
2021-04-13 9:41 ` Petr Mladek
2021-04-13 11:10 ` Samo Pogačnik
2021-04-13 14:32 ` Petr Mladek
2021-04-13 15:22 ` Samo Pogačnik
2021-04-14 17:36 ` Petr Mladek
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=d78ae8da-16e9-38d9-e274-048c54e24360@i-love.sakura.ne.jp \
--to=penguin-kernel@i-love.sakura.ne.jp \
--cc=gregkh@linuxfoundation.org \
--cc=jirislaby@kernel.org \
--cc=john.ogness@linutronix.de \
--cc=linux-kernel@vger.kernel.org \
--cc=pmladek@suse.com \
--cc=rostedt@goodmis.org \
--cc=sergey.senozhatsky@gmail.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).