[PATCH] tty: use printk_safe context at tty_msg()

[PATCH] tty: use printk_safe context at tty_msg()

[Tetsuo Handa]

syzbot is reporting circular locking dependency due to calling printk()
with port lock held [1]. When this problem was reported, we worried
whether printk_safe context will remain available in future kernels [2],
and then this problem was forgotten. But in order to utilize syzbot's
resource for finding other bugs/reproducers by closing this one of top
crashers, let's apply a patch which counts on availability of printk_safe
context.

syzbot is also reporting same dependency due to memory allocation fault
injection at tty_buffer_alloc(). Although __GFP_NOWARN cannot prevent
memory allocation fault injection from calling printk(), let's use
__GFP_NOWARN at tty_buffer_alloc() in addition to using printk_safe
context, for generating many lines of messages due to warn_alloc() is
annoying. If we want to report it, we can use pr_warn() instead.

[1] https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
[2] https://lkml.kernel.org/r/20190218054649.GA26686@jagdpanzerIV

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+
---
 drivers/tty/tty_buffer.c | 5 ++++-
 include/linux/tty.h      | 9 ++++++++-
 2 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
index 6d4995a5f318..d59f7873bc49 100644
--- a/drivers/tty/tty_buffer.c
+++ b/drivers/tty/tty_buffer.c
@@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
 {
 	struct llist_node *free;
 	struct tty_buffer *p;
+	unsigned long flags;
 
 	/* Round the buffer size out */
 	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
@@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
 	   have queued and recycle that ? */
 	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
 		return NULL;
-	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
+	printk_safe_enter_irqsave(flags);
+	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
+	printk_safe_exit_irqrestore(flags);
 	if (p == NULL)
 		return NULL;
 
diff --git a/include/linux/tty.h b/include/linux/tty.h
index 95fc2f100f12..7ae8eb46fec3 100644
--- a/include/linux/tty.h
+++ b/include/linux/tty.h
@@ -14,6 +14,7 @@
 #include <uapi/linux/tty.h>
 #include <linux/rwsem.h>
 #include <linux/llist.h>
+#include <../../kernel/printk/internal.h>
 
 
 /*
@@ -773,7 +774,13 @@ 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__)
+	do {						\
+		unsigned long flags;			\
+							\
+		printk_safe_enter_irqsave(flags);	\
+		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
+		printk_safe_exit_irqrestore(flags);	\
+	} while (0)
 
 #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__)
-- 
2.18.4

Re: [PATCH] tty: use printk_safe context at tty_msg()

[kernel test robot]

[-- Attachment #1: Type: text/plain, Size: 11862 bytes --]

Hi Tetsuo,

I love your patch! Yet something to improve:

[auto build test ERROR on tty/tty-testing]
[also build test ERROR on v5.12-rc5 next-20210401]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]

url:    https://github.com/0day-ci/linux/commits/Tetsuo-Handa/tty-use-printk_safe-context-at-tty_msg/20210403-121636
base:   https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/tty.git tty-testing
config: microblaze-randconfig-r001-20210403 (attached as .config)
compiler: microblaze-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/0day-ci/linux/commit/88235b87a105a519a205a28753857b7db5e6b3d1
        git remote add linux-review https://github.com/0day-ci/linux
        git fetch --no-tags linux-review Tetsuo-Handa/tty-use-printk_safe-context-at-tty_msg/20210403-121636
        git checkout 88235b87a105a519a205a28753857b7db5e6b3d1
        # save the attached .config to linux build tree
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=microblaze 

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@intel.com>

All error/warnings (new ones prefixed by >>):

   In file included from include/linux/tty.h:17,
                    from kernel/signal.c:26:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
--
   In file included from include/linux/tty.h:17,
                    from kernel/audit.h:13,
                    from kernel/audit.c:63:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   kernel/audit.c:1778:14: warning: no previous prototype for 'audit_serial' [-Wmissing-prototypes]
    1778 | unsigned int audit_serial(void)
         |              ^~~~~~~~~~~~
   kernel/audit.c: In function 'audit_log_vformat':
   kernel/audit.c:1926:2: warning: function 'audit_log_vformat' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
    1926 |  len = vsnprintf(skb_tail_pointer(skb), avail, fmt, args);
         |  ^~~
   kernel/audit.c:1935:3: warning: function 'audit_log_vformat' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
    1935 |   len = vsnprintf(skb_tail_pointer(skb), avail, fmt, args2);
         |   ^~~
--
   In file included from include/linux/tty.h:17,
                    from kernel/audit.h:13,
                    from kernel/auditfilter.c:23:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   kernel/auditfilter.c: In function 'audit_data_to_entry':
   kernel/auditfilter.c:609:37: warning: suggest braces around empty body in an 'if' statement [-Wempty-body]
     609 |   audit_remove_mark(entry->rule.exe); /* that's the template one */
         |                                     ^
   kernel/auditfilter.c: In function 'audit_dupe_rule':
   kernel/auditfilter.c:875:32: warning: suggest braces around empty body in an 'if' statement [-Wempty-body]
     875 |     audit_remove_mark(new->exe);
         |                                ^
   kernel/auditfilter.c: In function 'audit_del_rule':
   kernel/auditfilter.c:1045:35: warning: suggest braces around empty body in an 'if' statement [-Wempty-body]
    1045 |   audit_remove_mark_rule(&e->rule);
         |                                   ^
   kernel/auditfilter.c: In function 'audit_rule_change':
   kernel/auditfilter.c:1150:38: warning: suggest braces around empty body in an 'if' statement [-Wempty-body]
    1150 |    audit_remove_mark(entry->rule.exe);
         |                                      ^
   kernel/auditfilter.c: In function 'update_lsm_rule':
   kernel/auditfilter.c:1402:37: warning: suggest braces around empty body in an 'if' statement [-Wempty-body]
    1402 |   audit_remove_mark(entry->rule.exe);
         |                                     ^
--
   In file included from include/linux/tty.h:17,
                    from kernel/fork.c:78:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   kernel/fork.c:161:13: warning: no previous prototype for 'arch_release_task_struct' [-Wmissing-prototypes]
     161 | void __weak arch_release_task_struct(struct task_struct *tsk)
         |             ^~~~~~~~~~~~~~~~~~~~~~~~
   kernel/fork.c:746:20: warning: no previous prototype for 'arch_task_cache_init' [-Wmissing-prototypes]
     746 | void __init __weak arch_task_cache_init(void) { }
         |                    ^~~~~~~~~~~~~~~~~~~~
   kernel/fork.c:836:12: warning: no previous prototype for 'arch_dup_task_struct' [-Wmissing-prototypes]
     836 | int __weak arch_dup_task_struct(struct task_struct *dst,
         |            ^~~~~~~~~~~~~~~~~~~~
--
   In file included from include/linux/tty.h:17,
                    from include/linux/vt_kern.h:12,
                    from kernel/panic.c:19:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   kernel/panic.c:85:13: warning: no previous prototype for 'panic_smp_self_stop' [-Wmissing-prototypes]
      85 | void __weak panic_smp_self_stop(void)
         |             ^~~~~~~~~~~~~~~~~~~
   kernel/panic.c:95:13: warning: no previous prototype for 'nmi_panic_self_stop' [-Wmissing-prototypes]
      95 | void __weak nmi_panic_self_stop(struct pt_regs *regs)
         |             ^~~~~~~~~~~~~~~~~~~
   kernel/panic.c:106:13: warning: no previous prototype for 'crash_smp_send_stop' [-Wmissing-prototypes]
     106 | void __weak crash_smp_send_stop(void)
         |             ^~~~~~~~~~~~~~~~~~~
   kernel/panic.c:576:6: warning: no previous prototype for '__warn' [-Wmissing-prototypes]
     576 | void __warn(const char *file, int line, void *caller, unsigned taint,
         |      ^~~~~~
   kernel/panic.c: In function '__warn':
   kernel/panic.c:590:3: warning: function '__warn' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
     590 |   vprintk(args->fmt, args->args);
         |   ^~~~~~~
   kernel/panic.c: At top level:
   kernel/panic.c:620:6: warning: no previous prototype for 'warn_slowpath_fmt' [-Wmissing-prototypes]
     620 | void warn_slowpath_fmt(const char *file, int line, unsigned taint,
         |      ^~~~~~~~~~~~~~~~~
--
   In file included from include/linux/tty.h:17,
                    from kernel/exit.c:21:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   kernel/exit.c:1763:13: warning: no previous prototype for 'abort' [-Wmissing-prototypes]
    1763 | __weak void abort(void)
         |             ^~~~~
--
   In file included from include/linux/tty.h:17,
                    from kernel/printk/printk.c:24:
>> include/uapi/../../kernel/printk/internal.h:59:20: warning: no previous prototype for 'vprintk_func' [-Wmissing-prototypes]
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   In file included from kernel/printk/printk.c:61:
>> kernel/printk/internal.h:59:20: error: redefinition of 'vprintk_func'
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   In file included from include/linux/tty.h:17,
                    from kernel/printk/printk.c:24:
   include/uapi/../../kernel/printk/internal.h:59:20: note: previous definition of 'vprintk_func' was here
      59 | __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
         |                    ^~~~~~~~~~~~
   In file included from kernel/printk/printk.c:61:
>> kernel/printk/internal.h:72:20: error: redefinition of 'printk_safe_init'
      72 | static inline void printk_safe_init(void) { }
         |                    ^~~~~~~~~~~~~~~~
   In file included from include/linux/tty.h:17,
                    from kernel/printk/printk.c:24:
   include/uapi/../../kernel/printk/internal.h:72:20: note: previous definition of 'printk_safe_init' was here
      72 | static inline void printk_safe_init(void) { }
         |                    ^~~~~~~~~~~~~~~~
   In file included from kernel/printk/printk.c:61:
>> kernel/printk/internal.h:73:20: error: redefinition of 'printk_percpu_data_ready'
      73 | static inline bool printk_percpu_data_ready(void) { return false; }
         |                    ^~~~~~~~~~~~~~~~~~~~~~~~
   In file included from include/linux/tty.h:17,
                    from kernel/printk/printk.c:24:
   include/uapi/../../kernel/printk/internal.h:73:20: note: previous definition of 'printk_percpu_data_ready' was here
      73 | static inline bool printk_percpu_data_ready(void) { return false; }
         |                    ^~~~~~~~~~~~~~~~~~~~~~~~
   kernel/printk/printk.c:175:5: warning: no previous prototype for 'devkmsg_sysctl_set_loglvl' [-Wmissing-prototypes]
     175 | int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
         |     ^~~~~~~~~~~~~~~~~~~~~~~~~


vim +/vprintk_func +59 kernel/printk/internal.h

099f1c84c0052e Sergey Senozhatsky 2016-12-27  58  
099f1c84c0052e Sergey Senozhatsky 2016-12-27 @59  __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
099f1c84c0052e Sergey Senozhatsky 2016-12-27  60  
099f1c84c0052e Sergey Senozhatsky 2016-12-27  61  /*
099f1c84c0052e Sergey Senozhatsky 2016-12-27  62   * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
099f1c84c0052e Sergey Senozhatsky 2016-12-27  63   * semaphore and some of console functions (console_unlock()/etc.), so
099f1c84c0052e Sergey Senozhatsky 2016-12-27  64   * printk-safe must preserve the existing local IRQ guarantees.
099f1c84c0052e Sergey Senozhatsky 2016-12-27  65   */
099f1c84c0052e Sergey Senozhatsky 2016-12-27  66  #define printk_safe_enter_irqsave(flags) local_irq_save(flags)
099f1c84c0052e Sergey Senozhatsky 2016-12-27  67  #define printk_safe_exit_irqrestore(flags) local_irq_restore(flags)
099f1c84c0052e Sergey Senozhatsky 2016-12-27  68  
099f1c84c0052e Sergey Senozhatsky 2016-12-27  69  #define printk_safe_enter_irq() local_irq_disable()
099f1c84c0052e Sergey Senozhatsky 2016-12-27  70  #define printk_safe_exit_irq() local_irq_enable()
099f1c84c0052e Sergey Senozhatsky 2016-12-27  71  
ab6f762f0f5316 Sergey Senozhatsky 2020-03-03 @72  static inline void printk_safe_init(void) { }
ab6f762f0f5316 Sergey Senozhatsky 2020-03-03 @73  static inline bool printk_percpu_data_ready(void) { return false; }

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@lists.01.org

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 32620 bytes --]

[PATCH] printk: Make multiple inclusion of kernel/printk/internal.h safe

[Tetsuo Handa]

kernel test robot reported that kernel/printk/internal.h is not ready
to be #include'd for multiple times, and that vprintk_func() for
CONFIG_PRINTK=n should be marked as "static inline".

Since "tty: use printk_safe context at tty_msg()" will make
kernel/printk/internal.h be #include'd for multiple times, let's fix
this problem first.

Reported-by: kernel test robot <lkp@intel.com>
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Fixes: 099f1c84c0052ec1 ("printk: introduce per-cpu safe_print seq buffer")
Cc: <stable@vger.kernel.org> # 4.11+
---
 kernel/printk/internal.h | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 3a8fd491758c..2119c546cba2 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -2,6 +2,10 @@
 /*
  * internal.h - printk internal definitions
  */
+
+#ifndef _KERNEL_PRINTK_INTERNAL_H
+#define _KERNEL_PRINTK_INTERNAL_H
+
 #include <linux/percpu.h>
 
 #ifdef CONFIG_PRINTK
@@ -56,7 +60,7 @@ void defer_console_output(void);
 
 #else
 
-__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
+static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
 
 /*
  * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
@@ -72,3 +76,5 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
 static inline void printk_safe_init(void) { }
 static inline bool printk_percpu_data_ready(void) { return false; }
 #endif /* CONFIG_PRINTK */
+
+#endif
-- 
2.18.4

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Jiri Slaby]

On 03. 04. 21, 6:14, Tetsuo Handa wrote:
> syzbot is reporting circular locking dependency due to calling printk()
> with port lock held [1]. When this problem was reported, we worried
> whether printk_safe context will remain available in future kernels [2],
> and then this problem was forgotten. But in order to utilize syzbot's
> resource for finding other bugs/reproducers by closing this one of top
> crashers, let's apply a patch which counts on availability of printk_safe
> context.
> 
> syzbot is also reporting same dependency due to memory allocation fault
> injection at tty_buffer_alloc(). Although __GFP_NOWARN cannot prevent
> memory allocation fault injection from calling printk(), let's use
> __GFP_NOWARN at tty_buffer_alloc() in addition to using printk_safe
> context, for generating many lines of messages due to warn_alloc() is
> annoying. If we want to report it, we can use pr_warn() instead.
> 
> [1] https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> [2] https://lkml.kernel.org/r/20190218054649.GA26686@jagdpanzerIV
> 
> 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+
> ---
>   drivers/tty/tty_buffer.c | 5 ++++-
>   include/linux/tty.h      | 9 ++++++++-
>   2 files changed, 12 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
> index 6d4995a5f318..d59f7873bc49 100644
> --- a/drivers/tty/tty_buffer.c
> +++ b/drivers/tty/tty_buffer.c
> @@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>   {
>   	struct llist_node *free;
>   	struct tty_buffer *p;
> +	unsigned long flags;
>   
>   	/* Round the buffer size out */
>   	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
> @@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>   	   have queued and recycle that ? */
>   	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
>   		return NULL;
> -	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
> +	printk_safe_enter_irqsave(flags);
> +	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
> +	printk_safe_exit_irqrestore(flags);
>   	if (p == NULL)
>   		return NULL;
>   
> diff --git a/include/linux/tty.h b/include/linux/tty.h
> index 95fc2f100f12..7ae8eb46fec3 100644
> --- a/include/linux/tty.h
> +++ b/include/linux/tty.h
> @@ -14,6 +14,7 @@
>   #include <uapi/linux/tty.h>
>   #include <linux/rwsem.h>
>   #include <linux/llist.h>
> +#include <../../kernel/printk/internal.h>

Including printk's internal header in linux/tty.h doesn't look correct 
to me.

> @@ -773,7 +774,13 @@ 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__)
> +	do {						\
> +		unsigned long flags;			\
> +							\
> +		printk_safe_enter_irqsave(flags);	\
> +		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
> +		printk_safe_exit_irqrestore(flags);	\
> +	} while (0)
>   
>   #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__)
> 


-- 
js

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Tetsuo Handa]

On 2021/04/06 13:51, Jiri Slaby wrote:
> On 03. 04. 21, 6:14, Tetsuo Handa wrote:
>> --- a/include/linux/tty.h
>> +++ b/include/linux/tty.h
>> @@ -14,6 +14,7 @@
>>   #include <uapi/linux/tty.h>
>>   #include <linux/rwsem.h>
>>   #include <linux/llist.h>
>> +#include <../../kernel/printk/internal.h>
> 
> Including printk's internal header in linux/tty.h doesn't look correct to me.
> 

This is because this patch wants __printk_safe_enter()/__printk_safe_exit()
without #ifdef'ing CONFIG_PRINTK.

Peter and Sergey, what should we do?
Can we move printk_safe_enter_irqsave()/printk_safe_exit_irqrestore() to include/linux/printk.h ?

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Greg Kroah-Hartman]

On Tue, Apr 06, 2021 at 02:31:43PM +0900, Tetsuo Handa wrote:
> On 2021/04/06 13:51, Jiri Slaby wrote:
> > On 03. 04. 21, 6:14, Tetsuo Handa wrote:
> >> --- a/include/linux/tty.h
> >> +++ b/include/linux/tty.h
> >> @@ -14,6 +14,7 @@
> >>   #include <uapi/linux/tty.h>
> >>   #include <linux/rwsem.h>
> >>   #include <linux/llist.h>
> >> +#include <../../kernel/printk/internal.h>
> > 
> > Including printk's internal header in linux/tty.h doesn't look correct to me.
> > 
> 
> This is because this patch wants __printk_safe_enter()/__printk_safe_exit()
> without #ifdef'ing CONFIG_PRINTK.

Then those functions need to be "properly" exported, not placed only in
an "internal.h" file that obviously should not be included from anywhere
like this.

> Peter and Sergey, what should we do?
> Can we move printk_safe_enter_irqsave()/printk_safe_exit_irqrestore() to include/linux/printk.h ?

Are you sure that is the only way to resolve this?

thanks,

greg k-h

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Tetsuo Handa]

On 2021/04/06 16:10, Greg Kroah-Hartman wrote:
> On Tue, Apr 06, 2021 at 02:31:43PM +0900, Tetsuo Handa wrote:
>> On 2021/04/06 13:51, Jiri Slaby wrote:
>>> On 03. 04. 21, 6:14, Tetsuo Handa wrote:
>>>> --- a/include/linux/tty.h
>>>> +++ b/include/linux/tty.h
>>>> @@ -14,6 +14,7 @@
>>>>   #include <uapi/linux/tty.h>
>>>>   #include <linux/rwsem.h>
>>>>   #include <linux/llist.h>
>>>> +#include <../../kernel/printk/internal.h>
>>>
>>> Including printk's internal header in linux/tty.h doesn't look correct to me.
>>>
>>
>> This is because this patch wants __printk_safe_enter()/__printk_safe_exit()
>> without #ifdef'ing CONFIG_PRINTK.
> 
> Then those functions need to be "properly" exported, not placed only in
> an "internal.h" file that obviously should not be included from anywhere
> like this.
> 
>> Peter and Sergey, what should we do?
>> Can we move printk_safe_enter_irqsave()/printk_safe_exit_irqrestore() to include/linux/printk.h ?
> 
> Are you sure that is the only way to resolve this?

Publishing printk_safe_enter_irqsave() etc. was once proposed at
https://lkml.kernel.org/r/20181016050428.17966-3-sergey.senozhatsky@gmail.com and
Peter Zijlstra did not like such change. But we reconfirmed that "tty_port lock must
switch to printk_safe" at https://lkml.kernel.org/r/20190219013254.GA20023@jagdpanzerIV .

Two years has elapsed since a completely new printk implementation which would not
use printk_safe context was proposed, but printk_safe context is still remaining.
Therefore, we might need to tolerate, with a warning that printk_safe_enter_irqsave()
etc. are not intended for general use, use of printk_safe context for tty_msg() and
tty_buffer_alloc().

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Greg Kroah-Hartman]

On Tue, Apr 06, 2021 at 08:16:43PM +0900, Tetsuo Handa wrote:
> On 2021/04/06 16:10, Greg Kroah-Hartman wrote:
> > On Tue, Apr 06, 2021 at 02:31:43PM +0900, Tetsuo Handa wrote:
> >> On 2021/04/06 13:51, Jiri Slaby wrote:
> >>> On 03. 04. 21, 6:14, Tetsuo Handa wrote:
> >>>> --- a/include/linux/tty.h
> >>>> +++ b/include/linux/tty.h
> >>>> @@ -14,6 +14,7 @@
> >>>>   #include <uapi/linux/tty.h>
> >>>>   #include <linux/rwsem.h>
> >>>>   #include <linux/llist.h>
> >>>> +#include <../../kernel/printk/internal.h>
> >>>
> >>> Including printk's internal header in linux/tty.h doesn't look correct to me.
> >>>
> >>
> >> This is because this patch wants __printk_safe_enter()/__printk_safe_exit()
> >> without #ifdef'ing CONFIG_PRINTK.
> > 
> > Then those functions need to be "properly" exported, not placed only in
> > an "internal.h" file that obviously should not be included from anywhere
> > like this.
> > 
> >> Peter and Sergey, what should we do?
> >> Can we move printk_safe_enter_irqsave()/printk_safe_exit_irqrestore() to include/linux/printk.h ?
> > 
> > Are you sure that is the only way to resolve this?
> 
> Publishing printk_safe_enter_irqsave() etc. was once proposed at
> https://lkml.kernel.org/r/20181016050428.17966-3-sergey.senozhatsky@gmail.com and
> Peter Zijlstra did not like such change. But we reconfirmed that "tty_port lock must
> switch to printk_safe" at https://lkml.kernel.org/r/20190219013254.GA20023@jagdpanzerIV .
> 
> Two years has elapsed since a completely new printk implementation which would not
> use printk_safe context was proposed, but printk_safe context is still remaining.
> Therefore, we might need to tolerate, with a warning that printk_safe_enter_irqsave()
> etc. are not intended for general use, use of printk_safe context for tty_msg() and
> tty_buffer_alloc().

The printk work is still ongoing, perhaps work with those developers on
this?

thanks,

greg k-h

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Petr Mladek]

On Sat 2021-04-03 13:14:44, Tetsuo Handa wrote:
> syzbot is reporting circular locking dependency due to calling printk()
> with port lock held [1]. When this problem was reported, we worried

Could you please include the lockdep report into the commit message?
External links are not guaranteed to stay.


> whether printk_safe context will remain available in future kernels [2],
> and then this problem was forgotten. But in order to utilize syzbot's
> resource for finding other bugs/reproducers by closing this one of
> top

Is it possible to quantify how many resources are wasted by this
bug, please? Is this visible in one run from 10 or from 1000
or from 100000 runs?

I ask because this is just a workaround. It takes our time instead
of working on the proper solution. It will also add extra work when
the right solution is in please. See below for more details.

> crashers, let's apply a patch which counts on availability of printk_safe
> context.
> 
> syzbot is also reporting same dependency due to memory allocation fault
> injection at tty_buffer_alloc(). Although __GFP_NOWARN cannot prevent
> memory allocation fault injection from calling printk(), let's use
> __GFP_NOWARN at tty_buffer_alloc() in addition to using printk_safe
> context, for generating many lines of messages due to warn_alloc() is
> annoying. If we want to report it, we can use pr_warn() instead.
> 
> [1] https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> [2] https://lkml.kernel.org/r/20190218054649.GA26686@jagdpanzerIV
> 
> 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+
> ---
>  drivers/tty/tty_buffer.c | 5 ++++-
>  include/linux/tty.h      | 9 ++++++++-
>  2 files changed, 12 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
> index 6d4995a5f318..d59f7873bc49 100644
> --- a/drivers/tty/tty_buffer.c
> +++ b/drivers/tty/tty_buffer.c
> @@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>  {
>  	struct llist_node *free;
>  	struct tty_buffer *p;
> +	unsigned long flags;
>  
>  	/* Round the buffer size out */
>  	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
> @@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>  	   have queued and recycle that ? */
>  	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
>  		return NULL;
> -	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
> +	printk_safe_enter_irqsave(flags);
> +	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
> +	printk_safe_exit_irqrestore(flags);

I do not see tty_buffer_alloc() anywhere at
https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a

Could you please provide more details why this is needed?


>  	if (p == NULL)
>  		return NULL;
>  
> diff --git a/include/linux/tty.h b/include/linux/tty.h
> index 95fc2f100f12..7ae8eb46fec3 100644
> --- a/include/linux/tty.h
> +++ b/include/linux/tty.h
> @@ -14,6 +14,7 @@
>  #include <uapi/linux/tty.h>
>  #include <linux/rwsem.h>
>  #include <linux/llist.h>
> +#include <../../kernel/printk/internal.h>

Do not do this, please! We would need to make the printk_safe() API
public if we want to use it outside kernel/printk/

>  /*
> @@ -773,7 +774,13 @@ 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__)
> +	do {						\
> +		unsigned long flags;			\
> +							\
> +		printk_safe_enter_irqsave(flags);	\
> +		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
> +		printk_safe_exit_irqrestore(flags);	\
> +	} while (0)

There is no need to call single printk() in printk_safe() context.
printk_deferred() is enough.

Anyway, I am not sure if it is really a deadlock. One part of the
cycle is:

PU: 1 PID: 9840 Comm: syz-executor339 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
 tracehook_notify_resume include/linux/tracehook.h:189 [inline]
 exit_to_user_mode_loop kernel/entry/common.c:174 [inline]
 exit_to_user_mode_prepare+0x249/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

It guess that the tty using this port_lock is not longer
registered console when tty_port_close() is called. If this
is true than the problematic port_lock will not longer
be taken from console_unlock().


Sure, this report breaks the test and might prevent finding
real problems.

Just note that printk_deferred()/printk_safe() is only temporary
solution. It will get obsoleted by offloading the console handling
to kthreads. It goes slowly because it is not trivial. We want
to do it a clean way and carefully. Any historic or new
workarounds/hacks would only slow it down.

My estimation is that we could have the offloaded consoles
within the next 3-4 development cycles.

Please, consider whether it is really worth adding these workarounds.

Best Regards,
Petr

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Tetsuo Handa]

On 2021/04/07 0:10, Petr Mladek wrote:
>> diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
>> index 6d4995a5f318..d59f7873bc49 100644
>> --- a/drivers/tty/tty_buffer.c
>> +++ b/drivers/tty/tty_buffer.c
>> @@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>>  {
>>  	struct llist_node *free;
>>  	struct tty_buffer *p;
>> +	unsigned long flags;
>>  
>>  	/* Round the buffer size out */
>>  	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
>> @@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
>>  	   have queued and recycle that ? */
>>  	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
>>  		return NULL;
>> -	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
>> +	printk_safe_enter_irqsave(flags);
>> +	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
>> +	printk_safe_exit_irqrestore(flags);
> 
> I do not see tty_buffer_alloc() anywhere at
> https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> 
> Could you please provide more details why this is needed?

Quoting from https://syzkaller.appspot.com/text?tag=CrashLog&x=131d4ddf800000 at https://syzkaller.appspot.com/bug?id=bda1a87bea05a9072003e6447c44b03ca1492b1c :

[  274.992629] FAULT_INJECTION: forcing a failure.
[  274.992629] name failslab, interval 1, probability 0, space 0, times 0
[  274.994085] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
[  274.994094] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[  274.994099] Call Trace:
[  274.994120]  dump_stack+0x1b9/0x294
[  274.994145]  ? dump_stack_print_info.cold.2+0x52/0x52
[  275.270563]  should_fail.cold.4+0xa/0x1a
[  275.274639]  ? fault_create_debugfs_attr+0x1f0/0x1f0
[  275.279747]  ? graph_lock+0x170/0x170
[  275.283541]  ? check_noncircular+0x20/0x20
[  275.287788]  ? debug_check_no_locks_freed+0x310/0x310
[  275.292983]  ? lock_acquire+0x1dc/0x520
[  275.296961]  ? process_echoes+0xb6/0x170
[  275.301021]  ? check_same_owner+0x320/0x320
[  275.305347]  ? print_usage_bug+0xc0/0xc0
[  275.309404]  ? __might_sleep+0x95/0x190
[  275.313394]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.318934]  __should_failslab+0x124/0x180
[  275.323168]  should_failslab+0x9/0x14
[  275.326974]  __kmalloc+0x63/0x760
[  275.330423]  ? mutex_trylock+0x2a0/0x2a0
[  275.334479]  ? print_usage_bug+0xc0/0xc0
[  275.338539]  ? __tty_buffer_request_room+0x2d2/0x7f0
[  275.343648]  __tty_buffer_request_room+0x2d2/0x7f0
[  275.348576]  ? flush_to_ldisc+0x560/0x560
[  275.352717]  ? lock_acquire+0x1dc/0x520
[  275.356698]  ? pty_write+0xf9/0x1f0
[  275.360325]  ? lock_release+0xa10/0xa10
[  275.364293]  ? kasan_check_read+0x11/0x20
[  275.368434]  ? do_raw_spin_unlock+0x9e/0x2e0
[  275.372831]  ? do_raw_spin_trylock+0x1b0/0x1b0
[  275.377411]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
[  275.382942]  ? do_raw_spin_lock+0xc1/0x200
[  275.387174]  pty_write+0x12c/0x1f0
[  275.390720]  tty_put_char+0x129/0x150
[  275.394525]  ? dev_match_devt+0x90/0x90
[  275.398498]  ? pty_write_room+0xc9/0xf0
[  275.402485]  ? __sanitizer_cov_trace_switch+0x53/0x90
[  275.407684]  __process_echoes+0x4d9/0x8d0
[  275.411829]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
[  275.416936]  process_echoes+0xfc/0x170
[  275.420816]  n_tty_set_termios+0xb56/0xe80
[  275.425047]  ? n_tty_receive_signal_char+0x120/0x120
[  275.430148]  tty_set_termios+0x7a0/0xac0
[  275.434201]  ? tty_wait_until_sent+0x5b0/0x5b0
[  275.438782]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.444318]  set_termios+0x41e/0x7d0
[  275.448026]  ? tty_perform_flush+0x80/0x80
[  275.452256]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.457845]  tty_mode_ioctl+0x535/0xb50
[  275.461821]  ? set_termios+0x7d0/0x7d0
[  275.465740]  ? check_same_owner+0x320/0x320
[  275.470059]  ? graph_lock+0x170/0x170
[  275.473857]  n_tty_ioctl_helper+0x54/0x3b0
[  275.478085]  n_tty_ioctl+0x54/0x320
[  275.481711]  ? ldsem_down_read+0x37/0x40
[  275.485760]  ? ldsem_down_read+0x37/0x40
[  275.489836]  tty_ioctl+0x5e1/0x1870
[  275.493454]  ? commit_echoes+0x1d0/0x1d0
[  275.497506]  ? tty_vhangup+0x30/0x30
[  275.501212]  ? rcu_is_watching+0x85/0x140
[  275.505353]  ? rcu_report_qs_rnp+0x790/0x790
[  275.509757]  ? __fget+0x40c/0x650
[  275.513243]  ? find_held_lock+0x31/0x1c0
[  275.517439]  ? expand_files.part.8+0x9a0/0x9a0
[  275.522033]  ? kasan_check_write+0x14/0x20
[  275.526389]  ? __mutex_unlock_slowpath+0x180/0x8a0
[  275.531314]  ? wait_for_completion+0x870/0x870
[  275.535907]  ? tty_vhangup+0x30/0x30
[  275.539616]  do_vfs_ioctl+0x1cf/0x16f0
[  275.543522]  ? ioctl_preallocate+0x2e0/0x2e0
[  275.547934]  ? fget_raw+0x20/0x20
[  275.551554]  ? __sb_end_write+0xac/0xe0
[  275.555525]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  275.561064]  ? fput+0x130/0x1a0
[  275.564345]  ? ksys_write+0x1a6/0x250
[  275.568144]  ? security_file_ioctl+0x94/0xc0
[  275.572576]  ksys_ioctl+0xa9/0xd0
[  275.576028]  __x64_sys_ioctl+0x73/0xb0
[  275.579911]  do_syscall_64+0x1b1/0x800
[  275.583789]  ? finish_task_switch+0x1ca/0x840
[  275.588301]  ? syscall_return_slowpath+0x5c0/0x5c0
[  275.593310]  ? syscall_return_slowpath+0x30f/0x5c0
[  275.598239]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
[  275.603605]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  275.608463]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  275.613649] RIP: 0033:0x4559f9
[  275.616823] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 eb b9 fb ff c3 66 2e 0f 1f 84 00 00 00 00 
[  275.636056] RSP: 002b:00007f7ad0e91c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  275.643775] RAX: ffffffffffffffda RBX: 00007f7ad0e926d4 RCX: 00000000004559f9
[  275.651034] RDX: 0000000020002000 RSI: 0000000000005403 RDI: 0000000000000015
[  275.658293] RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
[  275.665554] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000016
[  275.672819] R13: 00000000004be500 R14: 00000000004ccad8 R15: 0000000000000000
[  275.680137] CPU: 0 PID: 19202 Comm: syz-executor2 Not tainted 4.17.0+ #89
[  275.680139] 
[  275.680149] ======================================================
[  275.680154] WARNING: possible circular locking dependency detected
[  275.680156] 4.17.0+ #89 Not tainted
[  275.680160] ------------------------------------------------------
[  275.680163] syz-executor6/19187 is trying to acquire lock:
[  275.680165] 000000006e810651 (console_owner){-.-.}, at: vprintk_emit+0x826/0xde0
[  275.680175] 
[  275.680178] but task is already holding lock:
[  275.680181] 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
[  275.680192] 
[  275.680196] which lock already depends on the new lock.
[  275.680197] 
[  275.680199] 
[  275.680203] the existing dependency chain (in reverse order) is:
[  275.680205] 
[  275.680207] -> #2 (&(&port->lock)->rlock){-.-.}:
[  275.680219]        _raw_spin_lock_irqsave+0x96/0xc0
[  275.680222]        tty_port_tty_get+0x20/0x80
[  275.680226]        tty_port_default_wakeup+0x15/0x40
[  275.680230]        tty_port_tty_wakeup+0x5d/0x70
[  275.680233]        uart_write_wakeup+0x44/0x60
[  275.680237]        serial8250_tx_chars+0x4be/0xb60
[  275.680241]        serial8250_handle_irq.part.25+0x1ee/0x280
[  275.680245]        serial8250_default_handle_irq+0xc8/0x150
[  275.680248]        serial8250_interrupt+0xfa/0x1d0
[  275.680252]        __handle_irq_event_percpu+0x1c0/0xad0
[  275.680256]        handle_irq_event_percpu+0x98/0x1c0
[  275.680259]        handle_irq_event+0xa7/0x135
[  275.680262]        handle_edge_irq+0x20f/0x870
[  275.680265]        handle_irq+0x18c/0x2e7
[  275.680268]        do_IRQ+0x78/0x190
[  275.680271]        ret_from_intr+0x0/0x1e
[  275.680274]        native_safe_halt+0x6/0x10
[  275.680277]        default_idle+0xc2/0x440
[  275.680280]        arch_cpu_idle+0x10/0x20
[  275.680283]        default_idle_call+0x6d/0x90
[  275.680286]        do_idle+0x395/0x560
[  275.680289]        cpu_startup_entry+0x104/0x120
[  275.680293]        start_secondary+0x42b/0x5c0
[  275.680296]        secondary_startup_64+0xa5/0xb0
[  275.680298] 
[  275.680300] -> #1 (&port_lock_key){-.-.}:
[  275.680312]        _raw_spin_lock_irqsave+0x96/0xc0
[  275.680315]        serial8250_console_write+0x8d5/0xb00
[  275.680319]        univ8250_console_write+0x5f/0x70
[  275.680322]        console_unlock+0xa9d/0x10a0
[  275.680325]        vprintk_emit+0x6b2/0xde0
[  275.680329]        vprintk_default+0x28/0x30
[  275.680332]        vprintk_func+0x7a/0xe7
[  275.680335]        printk+0x9e/0xba
[  275.680338]        register_console+0x7e7/0xc00
[  275.680341]        univ8250_console_init+0x3f/0x4b
[  275.680344]        console_init+0x6d9/0xa38
[  275.680348]        start_kernel+0x608/0x92d
[  275.680351]        x86_64_start_reservations+0x29/0x2b
[  275.680354]        x86_64_start_kernel+0x76/0x79
[  275.680358]        secondary_startup_64+0xa5/0xb0
[  275.680359] 
[  275.680361] -> #0 (console_owner){-.-.}:
[  275.680372]        lock_acquire+0x1dc/0x520
[  275.680375]        vprintk_emit+0x884/0xde0
[  275.680379]        vprintk_default+0x28/0x30
[  275.680382]        vprintk_func+0x7a/0xe7
[  275.680384]        printk+0x9e/0xba
[  275.680388]        should_fail+0x97a/0xbcd
[  275.680391]        __should_failslab+0x124/0x180
[  275.680394]        should_failslab+0x9/0x14
[  275.680397]        __kmalloc+0x63/0x760
[  275.680401]        __tty_buffer_request_room+0x2d2/0x7f0
[  275.680405]        tty_insert_flip_string_fixed_flag+0x8d/0x1f0
[  275.680408]        pty_write+0x12c/0x1f0
[  275.680411]        tty_put_char+0x129/0x150
[  275.680414]        __process_echoes+0x4d9/0x8d0
[  275.680418]        process_echoes+0xfc/0x170
[  275.680421]        n_tty_set_termios+0xb56/0xe80
[  275.680424]        tty_set_termios+0x7a0/0xac0
[  275.680427]        set_termios+0x41e/0x7d0
[  275.680430]        tty_mode_ioctl+0x535/0xb50
[  275.680434]        n_tty_ioctl_helper+0x54/0x3b0
[  275.680437]        n_tty_ioctl+0x54/0x320
[  275.680440]        tty_ioctl+0x5e1/0x1870
[  275.680443]        do_vfs_ioctl+0x1cf/0x16f0
[  275.680446]        ksys_ioctl+0xa9/0xd0
[  275.680449]        __x64_sys_ioctl+0x73/0xb0
[  275.680452]        do_syscall_64+0x1b1/0x800
[  275.680456]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  275.680458] 
[  275.680461] other info that might help us debug this:
[  275.680463] 
[  275.680466] Chain exists of:
[  275.680467]   console_owner --> &port_lock_key --> &(&port->lock)->rlock
[  275.680482] 
[  275.680485]  Possible unsafe locking scenario:
[  275.680487] 
[  275.680490]        CPU0                    CPU1
[  275.680493]        ----                    ----
[  275.680495]   lock(&(&port->lock)->rlock);
[  275.680503]                                lock(&port_lock_key);
[  275.680511]                                lock(&(&port->lock)->rlock);
[  275.680517]   lock(console_owner);
[  275.680524] 
[  275.680526]  *** DEADLOCK ***
[  275.680528] 
[  275.680531] 5 locks held by syz-executor6/19187:
[  275.680533]  #0: 000000007080a3ba (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40
[  275.680547]  #1: 000000006fe00659 (&o_tty->termios_rwsem/1){++++}, at: tty_set_termios+0xfd/0xac0
[  275.680563]  #2: 000000007080a3ba (&tty->ldisc_sem){++++}, at: tty_ldisc_ref+0x22/0x90
[  275.680576]  #3: 00000000f8d1ab16 (&ldata->output_lock){+.+.}, at: process_echoes+0xb6/0x170
[  275.680589]  #4: 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
[  275.680603] 
[  275.680605] stack backtrace:
[  275.680610] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
[  275.680616] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[  275.680618] Call Trace:
[  275.680621]  dump_stack+0x1b9/0x294
[  275.680625]  ? dump_stack_print_info.cold.2+0x52/0x52
[  275.680628]  ? vprintk_func+0xd0/0xe7
[  275.680632]  print_circular_bug.isra.36.cold.56+0x1bd/0x27d
[  275.680636]  ? save_trace+0xe0/0x290
[  275.680639]  __lock_acquire+0x343e/0x5140
[  275.680643]  ? debug_check_no_locks_freed+0x310/0x310
[  275.680646]  ? check_noncircular+0x20/0x20
[  275.680649]  ? dentry_name+0x687/0x930
[  275.680653]  ? restricted_pointer+0x400/0x400
[  275.680656]  ? __lock_acquire+0x7f5/0x5140
[  275.680659]  ? print_usage_bug+0xc0/0xc0
[  275.680662]  ? graph_lock+0x170/0x170
[  275.680665]  ? graph_lock+0x170/0x170
[  275.680668]  ? graph_lock+0x170/0x170
[  275.680672]  ? find_held_lock+0x36/0x1c0
[  275.680675]  lock_acquire+0x1dc/0x520
[  275.680678]  ? vprintk_emit+0x826/0xde0
[  275.680681]  ? lock_release+0xa10/0xa10
[  275.680684]  ? kasan_check_read+0x11/0x20
[  275.680687]  ? do_raw_spin_unlock+0x9e/0x2e0
[  275.680691]  ? do_raw_spin_trylock+0x1b0/0x1b0
[  275.680694]  ? kasan_check_write+0x14/0x20
[  275.680698]  ? do_raw_spin_lock+0xc1/0x200
[  275.680701]  vprintk_emit+0x884/0xde0
[  275.680704]  ? vprintk_emit+0x826/0xde0
[  275.680707]  ? wake_up_klogd+0x100/0x100
[  275.680711]  ? debug_check_no_locks_freed+0x310/0x310
[  275.680714]  ? print_usage_bug+0xc0/0xc0
[  275.680717]  ? print_usage_bug+0xc0/0xc0
[  275.680720]  vprintk_default+0x28/0x30
[  275.680723]  vprintk_func+0x7a/0xe7
[  275.680726]  printk+0x9e/0xba
[  275.680730]  ? kmsg_dump_rewind_nolock+0xe4/0xe4
[  275.680733]  should_fail+0x97a/0xbcd
[  275.680737]  ? fault_create_debugfs_attr+0x1f0/0x1f0
[  275.680740]  ? graph_lock+0x170/0x170
[  275.680743]  ? check_noncircular+0x20/0x20
[  275.680747]  ? debug_check_no_locks_freed+0x310/0x310
[  275.680750]  ? lock_acquire+0x1dc/0x520
[  275.680753]  ? process_echoes+0xb6/0x170
[  275.680757]  ? check_same_owner+0x320/0x320
[  275.680760]  ? print_usage_bug+0xc0/0xc0
[  275.680763]  ? __might_sleep+0x95/0x190
[  275.680767]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.680770]  __should_failslab+0x124/0x180
[  275.680774]  should_failslab+0x9/0x14
[  275.680776]  __kmalloc+0x63/0x760
[  275.680780]  ? mutex_trylock+0x2a0/0x2a0
[  275.680783]  ? print_usage_bug+0xc0/0xc0
[  275.680787]  ? __tty_buffer_request_room+0x2d2/0x7f0
[  275.680790]  __tty_buffer_request_room+0x2d2/0x7f0
[  275.680794]  ? flush_to_ldisc+0x560/0x560
[  275.680797]  ? lock_acquire+0x1dc/0x520
[  275.680800]  ? pty_write+0xf9/0x1f0
[  275.680803]  ? lock_release+0xa10/0xa10
[  275.680806]  ? kasan_check_read+0x11/0x20
[  275.680810]  ? do_raw_spin_unlock+0x9e/0x2e0
[  275.680813]  ? do_raw_spin_trylock+0x1b0/0x1b0
[  275.680817]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
[  275.680821]  ? do_raw_spin_lock+0xc1/0x200
[  275.680823]  pty_write+0x12c/0x1f0
[  275.680827]  tty_put_char+0x129/0x150
[  275.680830]  ? dev_match_devt+0x90/0x90
[  275.680833]  ? pty_write_room+0xc9/0xf0
[  275.680837]  ? __sanitizer_cov_trace_switch+0x53/0x90
[  275.680840]  __process_echoes+0x4d9/0x8d0
[  275.680844]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
[  275.680847]  process_echoes+0xfc/0x170
[  275.680850]  n_tty_set_termios+0xb56/0xe80
[  275.680854]  ? n_tty_receive_signal_char+0x120/0x120
[  275.680857]  tty_set_termios+0x7a0/0xac0
[  275.680861]  ? tty_wait_until_sent+0x5b0/0x5b0
[  275.680865]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.680868]  set_termios+0x41e/0x7d0
[  275.680871]  ? tty_perform_flush+0x80/0x80
[  275.680875]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  275.680878]  tty_mode_ioctl+0x535/0xb50
[  275.680881]  ? set_termios+0x7d0/0x7d0
[  275.680885]  ? check_same_owner+0x320/0x320
[  275.680887]  ? graph_lock+0x170/0x170
[  275.680891]  n_tty_ioctl_helper+0x54/0x3b0
[  275.680894]  n_tty_ioctl+0x54/0x320
[  275.680897]  ? ldsem_down_read+0x37/0x40
[  275.680900]  ? ldsem_down_read+0x37/0x40
[  275.680903]  tty_ioctl+0x5e1/0x1870
[  275.680906]  ? commit_echoes+0x1d0/0x1d0
[  275.680909]  ? tty_vhangup+0x30/0x30
[  275.680913]  ? rcu_is_watching+0x85/0x140
[  275.680916]  ? rcu_report_qs_rnp+0x790/0x790
[  275.680919]  ? __fget+0x40c/0x650
[  275.680922]  ? find_held_lock+0x31/0x1c0
[  275.680926]  ? expand_files.part.8+0x9a0/0x9a0
[  275.680929]  ? kasan_check_write+0x14/0x20
[  275.680933]  ? __mutex_unlock_slowpath+0x180/0x8a0
[  275.680936]  ? wait_for_completion+0x870/0x870
[  275.680939]  ? tty_vhangup+0x30/0x30
[  275.680942]  do_vfs_ioctl+0x1cf/0x16f0
[  275.680945]  ? ioctl_preallocate+0x2e0/0x2e0
[  275.680948]  ? fget_raw+0x20/0x20
[  275.680951]  ? __sb_end_write+0xac/0xe0
[  275.680955]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  275.680958]  ? fput+0x130/0x1a0
[  275.680961]  ? ksys_write+0x1a6/0x250
[  275.680965]  ? security_file_ioctl+0x94/0xc0
[  275.680968]  ksys_ioctl+0xa9/0xd0
[  275.680970]  __x64_sys_ioctl+0x73/0xb0
[  275.680974]  do_syscall_64+0x1b1/0x800
[  275.680977]  ? finish_task_switch+0x1ca/0x840
[  275.680981]  ? syscall_return_slowpath+0x5c0/0x5c0
[  275.680984]  ? syscall_return_slowpath+0x30f/0x5c0
[  275.680988]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
[  275.680992]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  275.680996]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  275.680999] RIP: 0033:0x4559f9
[  275.681001] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff

>>  /*
>> @@ -773,7 +774,13 @@ 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__)
>> +	do {						\
>> +		unsigned long flags;			\
>> +							\
>> +		printk_safe_enter_irqsave(flags);	\
>> +		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
>> +		printk_safe_exit_irqrestore(flags);	\
>> +	} while (0)
> 
> There is no need to call single printk() in printk_safe() context.
> printk_deferred() is enough.

Then, regarding tty_msg() we can update

  #define tty_msg(fn, tty, f, ...) \
          fn("%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_info_ratelimited(tty, f, ...) \
                  tty_msg(pr_info_ratelimited, tty, f, ##__VA_ARGS__)

to use printk_deferred().

> Just note that printk_deferred()/printk_safe() is only temporary
> solution. It will get obsoleted by offloading the console handling
> to kthreads. It goes slowly because it is not trivial. We want
> to do it a clean way and carefully. Any historic or new
> workarounds/hacks would only slow it down.
> 
> My estimation is that we could have the offloaded consoles
> within the next 3-4 development cycles.
> 
> Please, consider whether it is really worth adding these workarounds.

1000+ days have elapsed since this problem was reported. Given that
offloading the console handling to kthreads needs big changes which
are not suitable for backporting, what can we offer for current and
stable kernels?

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Greg Kroah-Hartman]

On Wed, Apr 07, 2021 at 01:22:34AM +0900, Tetsuo Handa wrote:
> On 2021/04/07 0:10, Petr Mladek wrote:
> >> diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
> >> index 6d4995a5f318..d59f7873bc49 100644
> >> --- a/drivers/tty/tty_buffer.c
> >> +++ b/drivers/tty/tty_buffer.c
> >> @@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
> >>  {
> >>  	struct llist_node *free;
> >>  	struct tty_buffer *p;
> >> +	unsigned long flags;
> >>  
> >>  	/* Round the buffer size out */
> >>  	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
> >> @@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
> >>  	   have queued and recycle that ? */
> >>  	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
> >>  		return NULL;
> >> -	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
> >> +	printk_safe_enter_irqsave(flags);
> >> +	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
> >> +	printk_safe_exit_irqrestore(flags);
> > 
> > I do not see tty_buffer_alloc() anywhere at
> > https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> > 
> > Could you please provide more details why this is needed?
> 
> Quoting from https://syzkaller.appspot.com/text?tag=CrashLog&x=131d4ddf800000 at https://syzkaller.appspot.com/bug?id=bda1a87bea05a9072003e6447c44b03ca1492b1c :
> 
> [  274.992629] FAULT_INJECTION: forcing a failure.
> [  274.992629] name failslab, interval 1, probability 0, space 0, times 0
> [  274.994085] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
> [  274.994094] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> [  274.994099] Call Trace:
> [  274.994120]  dump_stack+0x1b9/0x294
> [  274.994145]  ? dump_stack_print_info.cold.2+0x52/0x52
> [  275.270563]  should_fail.cold.4+0xa/0x1a
> [  275.274639]  ? fault_create_debugfs_attr+0x1f0/0x1f0
> [  275.279747]  ? graph_lock+0x170/0x170
> [  275.283541]  ? check_noncircular+0x20/0x20
> [  275.287788]  ? debug_check_no_locks_freed+0x310/0x310
> [  275.292983]  ? lock_acquire+0x1dc/0x520
> [  275.296961]  ? process_echoes+0xb6/0x170
> [  275.301021]  ? check_same_owner+0x320/0x320
> [  275.305347]  ? print_usage_bug+0xc0/0xc0
> [  275.309404]  ? __might_sleep+0x95/0x190
> [  275.313394]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.318934]  __should_failslab+0x124/0x180
> [  275.323168]  should_failslab+0x9/0x14
> [  275.326974]  __kmalloc+0x63/0x760
> [  275.330423]  ? mutex_trylock+0x2a0/0x2a0
> [  275.334479]  ? print_usage_bug+0xc0/0xc0
> [  275.338539]  ? __tty_buffer_request_room+0x2d2/0x7f0
> [  275.343648]  __tty_buffer_request_room+0x2d2/0x7f0
> [  275.348576]  ? flush_to_ldisc+0x560/0x560
> [  275.352717]  ? lock_acquire+0x1dc/0x520
> [  275.356698]  ? pty_write+0xf9/0x1f0
> [  275.360325]  ? lock_release+0xa10/0xa10
> [  275.364293]  ? kasan_check_read+0x11/0x20
> [  275.368434]  ? do_raw_spin_unlock+0x9e/0x2e0
> [  275.372831]  ? do_raw_spin_trylock+0x1b0/0x1b0
> [  275.377411]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> [  275.382942]  ? do_raw_spin_lock+0xc1/0x200
> [  275.387174]  pty_write+0x12c/0x1f0
> [  275.390720]  tty_put_char+0x129/0x150
> [  275.394525]  ? dev_match_devt+0x90/0x90
> [  275.398498]  ? pty_write_room+0xc9/0xf0
> [  275.402485]  ? __sanitizer_cov_trace_switch+0x53/0x90
> [  275.407684]  __process_echoes+0x4d9/0x8d0
> [  275.411829]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
> [  275.416936]  process_echoes+0xfc/0x170
> [  275.420816]  n_tty_set_termios+0xb56/0xe80
> [  275.425047]  ? n_tty_receive_signal_char+0x120/0x120
> [  275.430148]  tty_set_termios+0x7a0/0xac0
> [  275.434201]  ? tty_wait_until_sent+0x5b0/0x5b0
> [  275.438782]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.444318]  set_termios+0x41e/0x7d0
> [  275.448026]  ? tty_perform_flush+0x80/0x80
> [  275.452256]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.457845]  tty_mode_ioctl+0x535/0xb50
> [  275.461821]  ? set_termios+0x7d0/0x7d0
> [  275.465740]  ? check_same_owner+0x320/0x320
> [  275.470059]  ? graph_lock+0x170/0x170
> [  275.473857]  n_tty_ioctl_helper+0x54/0x3b0
> [  275.478085]  n_tty_ioctl+0x54/0x320
> [  275.481711]  ? ldsem_down_read+0x37/0x40
> [  275.485760]  ? ldsem_down_read+0x37/0x40
> [  275.489836]  tty_ioctl+0x5e1/0x1870
> [  275.493454]  ? commit_echoes+0x1d0/0x1d0
> [  275.497506]  ? tty_vhangup+0x30/0x30
> [  275.501212]  ? rcu_is_watching+0x85/0x140
> [  275.505353]  ? rcu_report_qs_rnp+0x790/0x790
> [  275.509757]  ? __fget+0x40c/0x650
> [  275.513243]  ? find_held_lock+0x31/0x1c0
> [  275.517439]  ? expand_files.part.8+0x9a0/0x9a0
> [  275.522033]  ? kasan_check_write+0x14/0x20
> [  275.526389]  ? __mutex_unlock_slowpath+0x180/0x8a0
> [  275.531314]  ? wait_for_completion+0x870/0x870
> [  275.535907]  ? tty_vhangup+0x30/0x30
> [  275.539616]  do_vfs_ioctl+0x1cf/0x16f0
> [  275.543522]  ? ioctl_preallocate+0x2e0/0x2e0
> [  275.547934]  ? fget_raw+0x20/0x20
> [  275.551554]  ? __sb_end_write+0xac/0xe0
> [  275.555525]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
> [  275.561064]  ? fput+0x130/0x1a0
> [  275.564345]  ? ksys_write+0x1a6/0x250
> [  275.568144]  ? security_file_ioctl+0x94/0xc0
> [  275.572576]  ksys_ioctl+0xa9/0xd0
> [  275.576028]  __x64_sys_ioctl+0x73/0xb0
> [  275.579911]  do_syscall_64+0x1b1/0x800
> [  275.583789]  ? finish_task_switch+0x1ca/0x840
> [  275.588301]  ? syscall_return_slowpath+0x5c0/0x5c0
> [  275.593310]  ? syscall_return_slowpath+0x30f/0x5c0
> [  275.598239]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
> [  275.603605]  ? trace_hardirqs_off_thunk+0x1a/0x1c
> [  275.608463]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [  275.613649] RIP: 0033:0x4559f9
> [  275.616823] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 eb b9 fb ff c3 66 2e 0f 1f 84 00 00 00 00 
> [  275.636056] RSP: 002b:00007f7ad0e91c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [  275.643775] RAX: ffffffffffffffda RBX: 00007f7ad0e926d4 RCX: 00000000004559f9
> [  275.651034] RDX: 0000000020002000 RSI: 0000000000005403 RDI: 0000000000000015
> [  275.658293] RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
> [  275.665554] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000016
> [  275.672819] R13: 00000000004be500 R14: 00000000004ccad8 R15: 0000000000000000
> [  275.680137] CPU: 0 PID: 19202 Comm: syz-executor2 Not tainted 4.17.0+ #89
> [  275.680139] 
> [  275.680149] ======================================================
> [  275.680154] WARNING: possible circular locking dependency detected
> [  275.680156] 4.17.0+ #89 Not tainted
> [  275.680160] ------------------------------------------------------
> [  275.680163] syz-executor6/19187 is trying to acquire lock:
> [  275.680165] 000000006e810651 (console_owner){-.-.}, at: vprintk_emit+0x826/0xde0
> [  275.680175] 
> [  275.680178] but task is already holding lock:
> [  275.680181] 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
> [  275.680192] 
> [  275.680196] which lock already depends on the new lock.
> [  275.680197] 
> [  275.680199] 
> [  275.680203] the existing dependency chain (in reverse order) is:
> [  275.680205] 
> [  275.680207] -> #2 (&(&port->lock)->rlock){-.-.}:
> [  275.680219]        _raw_spin_lock_irqsave+0x96/0xc0
> [  275.680222]        tty_port_tty_get+0x20/0x80
> [  275.680226]        tty_port_default_wakeup+0x15/0x40
> [  275.680230]        tty_port_tty_wakeup+0x5d/0x70
> [  275.680233]        uart_write_wakeup+0x44/0x60
> [  275.680237]        serial8250_tx_chars+0x4be/0xb60
> [  275.680241]        serial8250_handle_irq.part.25+0x1ee/0x280
> [  275.680245]        serial8250_default_handle_irq+0xc8/0x150
> [  275.680248]        serial8250_interrupt+0xfa/0x1d0
> [  275.680252]        __handle_irq_event_percpu+0x1c0/0xad0
> [  275.680256]        handle_irq_event_percpu+0x98/0x1c0
> [  275.680259]        handle_irq_event+0xa7/0x135
> [  275.680262]        handle_edge_irq+0x20f/0x870
> [  275.680265]        handle_irq+0x18c/0x2e7
> [  275.680268]        do_IRQ+0x78/0x190
> [  275.680271]        ret_from_intr+0x0/0x1e
> [  275.680274]        native_safe_halt+0x6/0x10
> [  275.680277]        default_idle+0xc2/0x440
> [  275.680280]        arch_cpu_idle+0x10/0x20
> [  275.680283]        default_idle_call+0x6d/0x90
> [  275.680286]        do_idle+0x395/0x560
> [  275.680289]        cpu_startup_entry+0x104/0x120
> [  275.680293]        start_secondary+0x42b/0x5c0
> [  275.680296]        secondary_startup_64+0xa5/0xb0
> [  275.680298] 
> [  275.680300] -> #1 (&port_lock_key){-.-.}:
> [  275.680312]        _raw_spin_lock_irqsave+0x96/0xc0
> [  275.680315]        serial8250_console_write+0x8d5/0xb00
> [  275.680319]        univ8250_console_write+0x5f/0x70
> [  275.680322]        console_unlock+0xa9d/0x10a0
> [  275.680325]        vprintk_emit+0x6b2/0xde0
> [  275.680329]        vprintk_default+0x28/0x30
> [  275.680332]        vprintk_func+0x7a/0xe7
> [  275.680335]        printk+0x9e/0xba
> [  275.680338]        register_console+0x7e7/0xc00
> [  275.680341]        univ8250_console_init+0x3f/0x4b
> [  275.680344]        console_init+0x6d9/0xa38
> [  275.680348]        start_kernel+0x608/0x92d
> [  275.680351]        x86_64_start_reservations+0x29/0x2b
> [  275.680354]        x86_64_start_kernel+0x76/0x79
> [  275.680358]        secondary_startup_64+0xa5/0xb0
> [  275.680359] 
> [  275.680361] -> #0 (console_owner){-.-.}:
> [  275.680372]        lock_acquire+0x1dc/0x520
> [  275.680375]        vprintk_emit+0x884/0xde0
> [  275.680379]        vprintk_default+0x28/0x30
> [  275.680382]        vprintk_func+0x7a/0xe7
> [  275.680384]        printk+0x9e/0xba
> [  275.680388]        should_fail+0x97a/0xbcd
> [  275.680391]        __should_failslab+0x124/0x180
> [  275.680394]        should_failslab+0x9/0x14
> [  275.680397]        __kmalloc+0x63/0x760
> [  275.680401]        __tty_buffer_request_room+0x2d2/0x7f0
> [  275.680405]        tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> [  275.680408]        pty_write+0x12c/0x1f0
> [  275.680411]        tty_put_char+0x129/0x150
> [  275.680414]        __process_echoes+0x4d9/0x8d0
> [  275.680418]        process_echoes+0xfc/0x170
> [  275.680421]        n_tty_set_termios+0xb56/0xe80
> [  275.680424]        tty_set_termios+0x7a0/0xac0
> [  275.680427]        set_termios+0x41e/0x7d0
> [  275.680430]        tty_mode_ioctl+0x535/0xb50
> [  275.680434]        n_tty_ioctl_helper+0x54/0x3b0
> [  275.680437]        n_tty_ioctl+0x54/0x320
> [  275.680440]        tty_ioctl+0x5e1/0x1870
> [  275.680443]        do_vfs_ioctl+0x1cf/0x16f0
> [  275.680446]        ksys_ioctl+0xa9/0xd0
> [  275.680449]        __x64_sys_ioctl+0x73/0xb0
> [  275.680452]        do_syscall_64+0x1b1/0x800
> [  275.680456]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [  275.680458] 
> [  275.680461] other info that might help us debug this:
> [  275.680463] 
> [  275.680466] Chain exists of:
> [  275.680467]   console_owner --> &port_lock_key --> &(&port->lock)->rlock
> [  275.680482] 
> [  275.680485]  Possible unsafe locking scenario:
> [  275.680487] 
> [  275.680490]        CPU0                    CPU1
> [  275.680493]        ----                    ----
> [  275.680495]   lock(&(&port->lock)->rlock);
> [  275.680503]                                lock(&port_lock_key);
> [  275.680511]                                lock(&(&port->lock)->rlock);
> [  275.680517]   lock(console_owner);
> [  275.680524] 
> [  275.680526]  *** DEADLOCK ***
> [  275.680528] 
> [  275.680531] 5 locks held by syz-executor6/19187:
> [  275.680533]  #0: 000000007080a3ba (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40
> [  275.680547]  #1: 000000006fe00659 (&o_tty->termios_rwsem/1){++++}, at: tty_set_termios+0xfd/0xac0
> [  275.680563]  #2: 000000007080a3ba (&tty->ldisc_sem){++++}, at: tty_ldisc_ref+0x22/0x90
> [  275.680576]  #3: 00000000f8d1ab16 (&ldata->output_lock){+.+.}, at: process_echoes+0xb6/0x170
> [  275.680589]  #4: 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
> [  275.680603] 
> [  275.680605] stack backtrace:
> [  275.680610] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
> [  275.680616] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> [  275.680618] Call Trace:
> [  275.680621]  dump_stack+0x1b9/0x294
> [  275.680625]  ? dump_stack_print_info.cold.2+0x52/0x52
> [  275.680628]  ? vprintk_func+0xd0/0xe7
> [  275.680632]  print_circular_bug.isra.36.cold.56+0x1bd/0x27d
> [  275.680636]  ? save_trace+0xe0/0x290
> [  275.680639]  __lock_acquire+0x343e/0x5140
> [  275.680643]  ? debug_check_no_locks_freed+0x310/0x310
> [  275.680646]  ? check_noncircular+0x20/0x20
> [  275.680649]  ? dentry_name+0x687/0x930
> [  275.680653]  ? restricted_pointer+0x400/0x400
> [  275.680656]  ? __lock_acquire+0x7f5/0x5140
> [  275.680659]  ? print_usage_bug+0xc0/0xc0
> [  275.680662]  ? graph_lock+0x170/0x170
> [  275.680665]  ? graph_lock+0x170/0x170
> [  275.680668]  ? graph_lock+0x170/0x170
> [  275.680672]  ? find_held_lock+0x36/0x1c0
> [  275.680675]  lock_acquire+0x1dc/0x520
> [  275.680678]  ? vprintk_emit+0x826/0xde0
> [  275.680681]  ? lock_release+0xa10/0xa10
> [  275.680684]  ? kasan_check_read+0x11/0x20
> [  275.680687]  ? do_raw_spin_unlock+0x9e/0x2e0
> [  275.680691]  ? do_raw_spin_trylock+0x1b0/0x1b0
> [  275.680694]  ? kasan_check_write+0x14/0x20
> [  275.680698]  ? do_raw_spin_lock+0xc1/0x200
> [  275.680701]  vprintk_emit+0x884/0xde0
> [  275.680704]  ? vprintk_emit+0x826/0xde0
> [  275.680707]  ? wake_up_klogd+0x100/0x100
> [  275.680711]  ? debug_check_no_locks_freed+0x310/0x310
> [  275.680714]  ? print_usage_bug+0xc0/0xc0
> [  275.680717]  ? print_usage_bug+0xc0/0xc0
> [  275.680720]  vprintk_default+0x28/0x30
> [  275.680723]  vprintk_func+0x7a/0xe7
> [  275.680726]  printk+0x9e/0xba
> [  275.680730]  ? kmsg_dump_rewind_nolock+0xe4/0xe4
> [  275.680733]  should_fail+0x97a/0xbcd
> [  275.680737]  ? fault_create_debugfs_attr+0x1f0/0x1f0
> [  275.680740]  ? graph_lock+0x170/0x170
> [  275.680743]  ? check_noncircular+0x20/0x20
> [  275.680747]  ? debug_check_no_locks_freed+0x310/0x310
> [  275.680750]  ? lock_acquire+0x1dc/0x520
> [  275.680753]  ? process_echoes+0xb6/0x170
> [  275.680757]  ? check_same_owner+0x320/0x320
> [  275.680760]  ? print_usage_bug+0xc0/0xc0
> [  275.680763]  ? __might_sleep+0x95/0x190
> [  275.680767]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.680770]  __should_failslab+0x124/0x180
> [  275.680774]  should_failslab+0x9/0x14
> [  275.680776]  __kmalloc+0x63/0x760
> [  275.680780]  ? mutex_trylock+0x2a0/0x2a0
> [  275.680783]  ? print_usage_bug+0xc0/0xc0
> [  275.680787]  ? __tty_buffer_request_room+0x2d2/0x7f0
> [  275.680790]  __tty_buffer_request_room+0x2d2/0x7f0
> [  275.680794]  ? flush_to_ldisc+0x560/0x560
> [  275.680797]  ? lock_acquire+0x1dc/0x520
> [  275.680800]  ? pty_write+0xf9/0x1f0
> [  275.680803]  ? lock_release+0xa10/0xa10
> [  275.680806]  ? kasan_check_read+0x11/0x20
> [  275.680810]  ? do_raw_spin_unlock+0x9e/0x2e0
> [  275.680813]  ? do_raw_spin_trylock+0x1b0/0x1b0
> [  275.680817]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> [  275.680821]  ? do_raw_spin_lock+0xc1/0x200
> [  275.680823]  pty_write+0x12c/0x1f0
> [  275.680827]  tty_put_char+0x129/0x150
> [  275.680830]  ? dev_match_devt+0x90/0x90
> [  275.680833]  ? pty_write_room+0xc9/0xf0
> [  275.680837]  ? __sanitizer_cov_trace_switch+0x53/0x90
> [  275.680840]  __process_echoes+0x4d9/0x8d0
> [  275.680844]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
> [  275.680847]  process_echoes+0xfc/0x170
> [  275.680850]  n_tty_set_termios+0xb56/0xe80
> [  275.680854]  ? n_tty_receive_signal_char+0x120/0x120
> [  275.680857]  tty_set_termios+0x7a0/0xac0
> [  275.680861]  ? tty_wait_until_sent+0x5b0/0x5b0
> [  275.680865]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.680868]  set_termios+0x41e/0x7d0
> [  275.680871]  ? tty_perform_flush+0x80/0x80
> [  275.680875]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> [  275.680878]  tty_mode_ioctl+0x535/0xb50
> [  275.680881]  ? set_termios+0x7d0/0x7d0
> [  275.680885]  ? check_same_owner+0x320/0x320
> [  275.680887]  ? graph_lock+0x170/0x170
> [  275.680891]  n_tty_ioctl_helper+0x54/0x3b0
> [  275.680894]  n_tty_ioctl+0x54/0x320
> [  275.680897]  ? ldsem_down_read+0x37/0x40
> [  275.680900]  ? ldsem_down_read+0x37/0x40
> [  275.680903]  tty_ioctl+0x5e1/0x1870
> [  275.680906]  ? commit_echoes+0x1d0/0x1d0
> [  275.680909]  ? tty_vhangup+0x30/0x30
> [  275.680913]  ? rcu_is_watching+0x85/0x140
> [  275.680916]  ? rcu_report_qs_rnp+0x790/0x790
> [  275.680919]  ? __fget+0x40c/0x650
> [  275.680922]  ? find_held_lock+0x31/0x1c0
> [  275.680926]  ? expand_files.part.8+0x9a0/0x9a0
> [  275.680929]  ? kasan_check_write+0x14/0x20
> [  275.680933]  ? __mutex_unlock_slowpath+0x180/0x8a0
> [  275.680936]  ? wait_for_completion+0x870/0x870
> [  275.680939]  ? tty_vhangup+0x30/0x30
> [  275.680942]  do_vfs_ioctl+0x1cf/0x16f0
> [  275.680945]  ? ioctl_preallocate+0x2e0/0x2e0
> [  275.680948]  ? fget_raw+0x20/0x20
> [  275.680951]  ? __sb_end_write+0xac/0xe0
> [  275.680955]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
> [  275.680958]  ? fput+0x130/0x1a0
> [  275.680961]  ? ksys_write+0x1a6/0x250
> [  275.680965]  ? security_file_ioctl+0x94/0xc0
> [  275.680968]  ksys_ioctl+0xa9/0xd0
> [  275.680970]  __x64_sys_ioctl+0x73/0xb0
> [  275.680974]  do_syscall_64+0x1b1/0x800
> [  275.680977]  ? finish_task_switch+0x1ca/0x840
> [  275.680981]  ? syscall_return_slowpath+0x5c0/0x5c0
> [  275.680984]  ? syscall_return_slowpath+0x30f/0x5c0
> [  275.680988]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
> [  275.680992]  ? trace_hardirqs_off_thunk+0x1a/0x1c
> [  275.680996]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [  275.680999] RIP: 0033:0x4559f9
> [  275.681001] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff
> 
> >>  /*
> >> @@ -773,7 +774,13 @@ 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__)
> >> +	do {						\
> >> +		unsigned long flags;			\
> >> +							\
> >> +		printk_safe_enter_irqsave(flags);	\
> >> +		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
> >> +		printk_safe_exit_irqrestore(flags);	\
> >> +	} while (0)
> > 
> > There is no need to call single printk() in printk_safe() context.
> > printk_deferred() is enough.
> 
> Then, regarding tty_msg() we can update
> 
>   #define tty_msg(fn, tty, f, ...) \
>           fn("%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_info_ratelimited(tty, f, ...) \
>                   tty_msg(pr_info_ratelimited, tty, f, ##__VA_ARGS__)
> 
> to use printk_deferred().
> 
> > Just note that printk_deferred()/printk_safe() is only temporary
> > solution. It will get obsoleted by offloading the console handling
> > to kthreads. It goes slowly because it is not trivial. We want
> > to do it a clean way and carefully. Any historic or new
> > workarounds/hacks would only slow it down.
> > 
> > My estimation is that we could have the offloaded consoles
> > within the next 3-4 development cycles.
> > 
> > Please, consider whether it is really worth adding these workarounds.
> 
> 1000+ days have elapsed since this problem was reported. Given that
> offloading the console handling to kthreads needs big changes which
> are not suitable for backporting, what can we offer for current and
> stable kernels?

As it can't be triggered without fault injections, is this even a "real"
issue?  Let's let the printk developers get this right.

thnaks,

greg k-h

Re: [PATCH] tty: use printk_safe context at tty_msg()

[Petr Mladek]

On Tue 2021-04-06 21:10:48, Greg Kroah-Hartman wrote:
> On Wed, Apr 07, 2021 at 01:22:34AM +0900, Tetsuo Handa wrote:
> > On 2021/04/07 0:10, Petr Mladek wrote:
> > >> diff --git a/drivers/tty/tty_buffer.c b/drivers/tty/tty_buffer.c
> > >> index 6d4995a5f318..d59f7873bc49 100644
> > >> --- a/drivers/tty/tty_buffer.c
> > >> +++ b/drivers/tty/tty_buffer.c
> > >> @@ -156,6 +156,7 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
> > >>  {
> > >>  	struct llist_node *free;
> > >>  	struct tty_buffer *p;
> > >> +	unsigned long flags;
> > >>  
> > >>  	/* Round the buffer size out */
> > >>  	size = __ALIGN_MASK(size, TTYB_ALIGN_MASK);
> > >> @@ -172,7 +173,9 @@ static struct tty_buffer *tty_buffer_alloc(struct tty_port *port, size_t size)
> > >>  	   have queued and recycle that ? */
> > >>  	if (atomic_read(&port->buf.mem_used) > port->buf.mem_limit)
> > >>  		return NULL;
> > >> -	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC);
> > >> +	printk_safe_enter_irqsave(flags);
> > >> +	p = kmalloc(sizeof(struct tty_buffer) + 2 * size, GFP_ATOMIC | __GFP_NOWARN);
> > >> +	printk_safe_exit_irqrestore(flags);
> > > 
> > > I do not see tty_buffer_alloc() anywhere at
> > > https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> > > 
> > > Could you please provide more details why this is needed?
> > 
> > Quoting from https://syzkaller.appspot.com/text?tag=CrashLog&x=131d4ddf800000 at https://syzkaller.appspot.com/bug?id=bda1a87bea05a9072003e6447c44b03ca1492b1c :
> > 
> > [  274.992629] FAULT_INJECTION: forcing a failure.
> > [  274.992629] name failslab, interval 1, probability 0, space 0, times 0
> > [  274.994085] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
> > [  274.994094] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> > [  274.994099] Call Trace:
> > [  274.994120]  dump_stack+0x1b9/0x294
> > [  274.994145]  ? dump_stack_print_info.cold.2+0x52/0x52
> > [  275.270563]  should_fail.cold.4+0xa/0x1a
> > [  275.274639]  ? fault_create_debugfs_attr+0x1f0/0x1f0
> > [  275.279747]  ? graph_lock+0x170/0x170
> > [  275.283541]  ? check_noncircular+0x20/0x20
> > [  275.287788]  ? debug_check_no_locks_freed+0x310/0x310
> > [  275.292983]  ? lock_acquire+0x1dc/0x520
> > [  275.296961]  ? process_echoes+0xb6/0x170
> > [  275.301021]  ? check_same_owner+0x320/0x320
> > [  275.305347]  ? print_usage_bug+0xc0/0xc0
> > [  275.309404]  ? __might_sleep+0x95/0x190
> > [  275.313394]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.318934]  __should_failslab+0x124/0x180
> > [  275.323168]  should_failslab+0x9/0x14
> > [  275.326974]  __kmalloc+0x63/0x760
> > [  275.330423]  ? mutex_trylock+0x2a0/0x2a0
> > [  275.334479]  ? print_usage_bug+0xc0/0xc0
> > [  275.338539]  ? __tty_buffer_request_room+0x2d2/0x7f0
> > [  275.343648]  __tty_buffer_request_room+0x2d2/0x7f0
> > [  275.348576]  ? flush_to_ldisc+0x560/0x560
> > [  275.352717]  ? lock_acquire+0x1dc/0x520
> > [  275.356698]  ? pty_write+0xf9/0x1f0
> > [  275.360325]  ? lock_release+0xa10/0xa10
> > [  275.364293]  ? kasan_check_read+0x11/0x20
> > [  275.368434]  ? do_raw_spin_unlock+0x9e/0x2e0
> > [  275.372831]  ? do_raw_spin_trylock+0x1b0/0x1b0
> > [  275.377411]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> > [  275.382942]  ? do_raw_spin_lock+0xc1/0x200
> > [  275.387174]  pty_write+0x12c/0x1f0
> > [  275.390720]  tty_put_char+0x129/0x150
> > [  275.394525]  ? dev_match_devt+0x90/0x90
> > [  275.398498]  ? pty_write_room+0xc9/0xf0
> > [  275.402485]  ? __sanitizer_cov_trace_switch+0x53/0x90
> > [  275.407684]  __process_echoes+0x4d9/0x8d0
> > [  275.411829]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
> > [  275.416936]  process_echoes+0xfc/0x170
> > [  275.420816]  n_tty_set_termios+0xb56/0xe80
> > [  275.425047]  ? n_tty_receive_signal_char+0x120/0x120
> > [  275.430148]  tty_set_termios+0x7a0/0xac0
> > [  275.434201]  ? tty_wait_until_sent+0x5b0/0x5b0
> > [  275.438782]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.444318]  set_termios+0x41e/0x7d0
> > [  275.448026]  ? tty_perform_flush+0x80/0x80
> > [  275.452256]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.457845]  tty_mode_ioctl+0x535/0xb50
> > [  275.461821]  ? set_termios+0x7d0/0x7d0
> > [  275.465740]  ? check_same_owner+0x320/0x320
> > [  275.470059]  ? graph_lock+0x170/0x170
> > [  275.473857]  n_tty_ioctl_helper+0x54/0x3b0
> > [  275.478085]  n_tty_ioctl+0x54/0x320
> > [  275.481711]  ? ldsem_down_read+0x37/0x40
> > [  275.485760]  ? ldsem_down_read+0x37/0x40
> > [  275.489836]  tty_ioctl+0x5e1/0x1870
> > [  275.493454]  ? commit_echoes+0x1d0/0x1d0
> > [  275.497506]  ? tty_vhangup+0x30/0x30
> > [  275.501212]  ? rcu_is_watching+0x85/0x140
> > [  275.505353]  ? rcu_report_qs_rnp+0x790/0x790
> > [  275.509757]  ? __fget+0x40c/0x650
> > [  275.513243]  ? find_held_lock+0x31/0x1c0
> > [  275.517439]  ? expand_files.part.8+0x9a0/0x9a0
> > [  275.522033]  ? kasan_check_write+0x14/0x20
> > [  275.526389]  ? __mutex_unlock_slowpath+0x180/0x8a0
> > [  275.531314]  ? wait_for_completion+0x870/0x870
> > [  275.535907]  ? tty_vhangup+0x30/0x30
> > [  275.539616]  do_vfs_ioctl+0x1cf/0x16f0
> > [  275.543522]  ? ioctl_preallocate+0x2e0/0x2e0
> > [  275.547934]  ? fget_raw+0x20/0x20
> > [  275.551554]  ? __sb_end_write+0xac/0xe0
> > [  275.555525]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
> > [  275.561064]  ? fput+0x130/0x1a0
> > [  275.564345]  ? ksys_write+0x1a6/0x250
> > [  275.568144]  ? security_file_ioctl+0x94/0xc0
> > [  275.572576]  ksys_ioctl+0xa9/0xd0
> > [  275.576028]  __x64_sys_ioctl+0x73/0xb0
> > [  275.579911]  do_syscall_64+0x1b1/0x800
> > [  275.583789]  ? finish_task_switch+0x1ca/0x840
> > [  275.588301]  ? syscall_return_slowpath+0x5c0/0x5c0
> > [  275.593310]  ? syscall_return_slowpath+0x30f/0x5c0
> > [  275.598239]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
> > [  275.603605]  ? trace_hardirqs_off_thunk+0x1a/0x1c
> > [  275.608463]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> > [  275.613649] RIP: 0033:0x4559f9
> > [  275.616823] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 eb b9 fb ff c3 66 2e 0f 1f 84 00 00 00 00 
> > [  275.636056] RSP: 002b:00007f7ad0e91c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> > [  275.643775] RAX: ffffffffffffffda RBX: 00007f7ad0e926d4 RCX: 00000000004559f9
> > [  275.651034] RDX: 0000000020002000 RSI: 0000000000005403 RDI: 0000000000000015
> > [  275.658293] RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
> > [  275.665554] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000016
> > [  275.672819] R13: 00000000004be500 R14: 00000000004ccad8 R15: 0000000000000000
> > [  275.680137] CPU: 0 PID: 19202 Comm: syz-executor2 Not tainted 4.17.0+ #89
> > [  275.680139] 
> > [  275.680149] ======================================================
> > [  275.680154] WARNING: possible circular locking dependency detected
> > [  275.680156] 4.17.0+ #89 Not tainted
> > [  275.680160] ------------------------------------------------------
> > [  275.680163] syz-executor6/19187 is trying to acquire lock:
> > [  275.680165] 000000006e810651 (console_owner){-.-.}, at: vprintk_emit+0x826/0xde0
> > [  275.680175] 
> > [  275.680178] but task is already holding lock:
> > [  275.680181] 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
> > [  275.680192] 
> > [  275.680196] which lock already depends on the new lock.
> > [  275.680197] 
> > [  275.680199] 
> > [  275.680203] the existing dependency chain (in reverse order) is:
> > [  275.680205] 
> > [  275.680207] -> #2 (&(&port->lock)->rlock){-.-.}:
> > [  275.680219]        _raw_spin_lock_irqsave+0x96/0xc0
> > [  275.680222]        tty_port_tty_get+0x20/0x80
> > [  275.680226]        tty_port_default_wakeup+0x15/0x40
> > [  275.680230]        tty_port_tty_wakeup+0x5d/0x70
> > [  275.680233]        uart_write_wakeup+0x44/0x60
> > [  275.680237]        serial8250_tx_chars+0x4be/0xb60
> > [  275.680241]        serial8250_handle_irq.part.25+0x1ee/0x280
> > [  275.680245]        serial8250_default_handle_irq+0xc8/0x150
> > [  275.680248]        serial8250_interrupt+0xfa/0x1d0
> > [  275.680252]        __handle_irq_event_percpu+0x1c0/0xad0
> > [  275.680256]        handle_irq_event_percpu+0x98/0x1c0
> > [  275.680259]        handle_irq_event+0xa7/0x135
> > [  275.680262]        handle_edge_irq+0x20f/0x870
> > [  275.680265]        handle_irq+0x18c/0x2e7
> > [  275.680268]        do_IRQ+0x78/0x190
> > [  275.680271]        ret_from_intr+0x0/0x1e
> > [  275.680274]        native_safe_halt+0x6/0x10
> > [  275.680277]        default_idle+0xc2/0x440
> > [  275.680280]        arch_cpu_idle+0x10/0x20
> > [  275.680283]        default_idle_call+0x6d/0x90
> > [  275.680286]        do_idle+0x395/0x560
> > [  275.680289]        cpu_startup_entry+0x104/0x120
> > [  275.680293]        start_secondary+0x42b/0x5c0
> > [  275.680296]        secondary_startup_64+0xa5/0xb0
> > [  275.680298] 
> > [  275.680300] -> #1 (&port_lock_key){-.-.}:
> > [  275.680312]        _raw_spin_lock_irqsave+0x96/0xc0
> > [  275.680315]        serial8250_console_write+0x8d5/0xb00
> > [  275.680319]        univ8250_console_write+0x5f/0x70
> > [  275.680322]        console_unlock+0xa9d/0x10a0
> > [  275.680325]        vprintk_emit+0x6b2/0xde0
> > [  275.680329]        vprintk_default+0x28/0x30
> > [  275.680332]        vprintk_func+0x7a/0xe7
> > [  275.680335]        printk+0x9e/0xba
> > [  275.680338]        register_console+0x7e7/0xc00
> > [  275.680341]        univ8250_console_init+0x3f/0x4b
> > [  275.680344]        console_init+0x6d9/0xa38
> > [  275.680348]        start_kernel+0x608/0x92d
> > [  275.680351]        x86_64_start_reservations+0x29/0x2b
> > [  275.680354]        x86_64_start_kernel+0x76/0x79
> > [  275.680358]        secondary_startup_64+0xa5/0xb0
> > [  275.680359] 
> > [  275.680361] -> #0 (console_owner){-.-.}:
> > [  275.680372]        lock_acquire+0x1dc/0x520
> > [  275.680375]        vprintk_emit+0x884/0xde0
> > [  275.680379]        vprintk_default+0x28/0x30
> > [  275.680382]        vprintk_func+0x7a/0xe7
> > [  275.680384]        printk+0x9e/0xba
> > [  275.680388]        should_fail+0x97a/0xbcd
> > [  275.680391]        __should_failslab+0x124/0x180
> > [  275.680394]        should_failslab+0x9/0x14
> > [  275.680397]        __kmalloc+0x63/0x760
> > [  275.680401]        __tty_buffer_request_room+0x2d2/0x7f0
> > [  275.680405]        tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> > [  275.680408]        pty_write+0x12c/0x1f0
> > [  275.680411]        tty_put_char+0x129/0x150
> > [  275.680414]        __process_echoes+0x4d9/0x8d0
> > [  275.680418]        process_echoes+0xfc/0x170
> > [  275.680421]        n_tty_set_termios+0xb56/0xe80
> > [  275.680424]        tty_set_termios+0x7a0/0xac0
> > [  275.680427]        set_termios+0x41e/0x7d0
> > [  275.680430]        tty_mode_ioctl+0x535/0xb50
> > [  275.680434]        n_tty_ioctl_helper+0x54/0x3b0
> > [  275.680437]        n_tty_ioctl+0x54/0x320
> > [  275.680440]        tty_ioctl+0x5e1/0x1870
> > [  275.680443]        do_vfs_ioctl+0x1cf/0x16f0
> > [  275.680446]        ksys_ioctl+0xa9/0xd0
> > [  275.680449]        __x64_sys_ioctl+0x73/0xb0
> > [  275.680452]        do_syscall_64+0x1b1/0x800
> > [  275.680456]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
> > [  275.680458] 
> > [  275.680461] other info that might help us debug this:
> > [  275.680463] 
> > [  275.680466] Chain exists of:
> > [  275.680467]   console_owner --> &port_lock_key --> &(&port->lock)->rlock
> > [  275.680482] 
> > [  275.680485]  Possible unsafe locking scenario:
> > [  275.680487] 
> > [  275.680490]        CPU0                    CPU1
> > [  275.680493]        ----                    ----
> > [  275.680495]   lock(&(&port->lock)->rlock);
> > [  275.680503]                                lock(&port_lock_key);
> > [  275.680511]                                lock(&(&port->lock)->rlock);
> > [  275.680517]   lock(console_owner);
> > [  275.680524] 
> > [  275.680526]  *** DEADLOCK ***
> > [  275.680528] 
> > [  275.680531] 5 locks held by syz-executor6/19187:
> > [  275.680533]  #0: 000000007080a3ba (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40
> > [  275.680547]  #1: 000000006fe00659 (&o_tty->termios_rwsem/1){++++}, at: tty_set_termios+0xfd/0xac0
> > [  275.680563]  #2: 000000007080a3ba (&tty->ldisc_sem){++++}, at: tty_ldisc_ref+0x22/0x90
> > [  275.680576]  #3: 00000000f8d1ab16 (&ldata->output_lock){+.+.}, at: process_echoes+0xb6/0x170
> > [  275.680589]  #4: 000000004ec3be2c (&(&port->lock)->rlock){-.-.}, at: pty_write+0xf9/0x1f0
> > [  275.680603] 
> > [  275.680605] stack backtrace:
> > [  275.680610] CPU: 1 PID: 19187 Comm: syz-executor6 Not tainted 4.17.0+ #89
> > [  275.680616] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> > [  275.680618] Call Trace:
> > [  275.680621]  dump_stack+0x1b9/0x294
> > [  275.680625]  ? dump_stack_print_info.cold.2+0x52/0x52
> > [  275.680628]  ? vprintk_func+0xd0/0xe7
> > [  275.680632]  print_circular_bug.isra.36.cold.56+0x1bd/0x27d
> > [  275.680636]  ? save_trace+0xe0/0x290
> > [  275.680639]  __lock_acquire+0x343e/0x5140
> > [  275.680643]  ? debug_check_no_locks_freed+0x310/0x310
> > [  275.680646]  ? check_noncircular+0x20/0x20
> > [  275.680649]  ? dentry_name+0x687/0x930
> > [  275.680653]  ? restricted_pointer+0x400/0x400
> > [  275.680656]  ? __lock_acquire+0x7f5/0x5140
> > [  275.680659]  ? print_usage_bug+0xc0/0xc0
> > [  275.680662]  ? graph_lock+0x170/0x170
> > [  275.680665]  ? graph_lock+0x170/0x170
> > [  275.680668]  ? graph_lock+0x170/0x170
> > [  275.680672]  ? find_held_lock+0x36/0x1c0
> > [  275.680675]  lock_acquire+0x1dc/0x520
> > [  275.680678]  ? vprintk_emit+0x826/0xde0
> > [  275.680681]  ? lock_release+0xa10/0xa10
> > [  275.680684]  ? kasan_check_read+0x11/0x20
> > [  275.680687]  ? do_raw_spin_unlock+0x9e/0x2e0
> > [  275.680691]  ? do_raw_spin_trylock+0x1b0/0x1b0
> > [  275.680694]  ? kasan_check_write+0x14/0x20
> > [  275.680698]  ? do_raw_spin_lock+0xc1/0x200
> > [  275.680701]  vprintk_emit+0x884/0xde0
> > [  275.680704]  ? vprintk_emit+0x826/0xde0
> > [  275.680707]  ? wake_up_klogd+0x100/0x100
> > [  275.680711]  ? debug_check_no_locks_freed+0x310/0x310
> > [  275.680714]  ? print_usage_bug+0xc0/0xc0
> > [  275.680717]  ? print_usage_bug+0xc0/0xc0
> > [  275.680720]  vprintk_default+0x28/0x30
> > [  275.680723]  vprintk_func+0x7a/0xe7
> > [  275.680726]  printk+0x9e/0xba
> > [  275.680730]  ? kmsg_dump_rewind_nolock+0xe4/0xe4
> > [  275.680733]  should_fail+0x97a/0xbcd
> > [  275.680737]  ? fault_create_debugfs_attr+0x1f0/0x1f0
> > [  275.680740]  ? graph_lock+0x170/0x170
> > [  275.680743]  ? check_noncircular+0x20/0x20
> > [  275.680747]  ? debug_check_no_locks_freed+0x310/0x310
> > [  275.680750]  ? lock_acquire+0x1dc/0x520
> > [  275.680753]  ? process_echoes+0xb6/0x170
> > [  275.680757]  ? check_same_owner+0x320/0x320
> > [  275.680760]  ? print_usage_bug+0xc0/0xc0
> > [  275.680763]  ? __might_sleep+0x95/0x190
> > [  275.680767]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.680770]  __should_failslab+0x124/0x180
> > [  275.680774]  should_failslab+0x9/0x14
> > [  275.680776]  __kmalloc+0x63/0x760
> > [  275.680780]  ? mutex_trylock+0x2a0/0x2a0
> > [  275.680783]  ? print_usage_bug+0xc0/0xc0
> > [  275.680787]  ? __tty_buffer_request_room+0x2d2/0x7f0
> > [  275.680790]  __tty_buffer_request_room+0x2d2/0x7f0
> > [  275.680794]  ? flush_to_ldisc+0x560/0x560
> > [  275.680797]  ? lock_acquire+0x1dc/0x520
> > [  275.680800]  ? pty_write+0xf9/0x1f0
> > [  275.680803]  ? lock_release+0xa10/0xa10
> > [  275.680806]  ? kasan_check_read+0x11/0x20
> > [  275.680810]  ? do_raw_spin_unlock+0x9e/0x2e0
> > [  275.680813]  ? do_raw_spin_trylock+0x1b0/0x1b0
> > [  275.680817]  tty_insert_flip_string_fixed_flag+0x8d/0x1f0
> > [  275.680821]  ? do_raw_spin_lock+0xc1/0x200
> > [  275.680823]  pty_write+0x12c/0x1f0
> > [  275.680827]  tty_put_char+0x129/0x150
> > [  275.680830]  ? dev_match_devt+0x90/0x90
> > [  275.680833]  ? pty_write_room+0xc9/0xf0
> > [  275.680837]  ? __sanitizer_cov_trace_switch+0x53/0x90
> > [  275.680840]  __process_echoes+0x4d9/0x8d0
> > [  275.680844]  ? _raw_spin_unlock_irqrestore+0x74/0xc0
> > [  275.680847]  process_echoes+0xfc/0x170
> > [  275.680850]  n_tty_set_termios+0xb56/0xe80
> > [  275.680854]  ? n_tty_receive_signal_char+0x120/0x120
> > [  275.680857]  tty_set_termios+0x7a0/0xac0
> > [  275.680861]  ? tty_wait_until_sent+0x5b0/0x5b0
> > [  275.680865]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.680868]  set_termios+0x41e/0x7d0
> > [  275.680871]  ? tty_perform_flush+0x80/0x80
> > [  275.680875]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
> > [  275.680878]  tty_mode_ioctl+0x535/0xb50
> > [  275.680881]  ? set_termios+0x7d0/0x7d0
> > [  275.680885]  ? check_same_owner+0x320/0x320
> > [  275.680887]  ? graph_lock+0x170/0x170
> > [  275.680891]  n_tty_ioctl_helper+0x54/0x3b0
> > [  275.680894]  n_tty_ioctl+0x54/0x320
> > [  275.680897]  ? ldsem_down_read+0x37/0x40
> > [  275.680900]  ? ldsem_down_read+0x37/0x40
> > [  275.680903]  tty_ioctl+0x5e1/0x1870
> > [  275.680906]  ? commit_echoes+0x1d0/0x1d0
> > [  275.680909]  ? tty_vhangup+0x30/0x30
> > [  275.680913]  ? rcu_is_watching+0x85/0x140
> > [  275.680916]  ? rcu_report_qs_rnp+0x790/0x790
> > [  275.680919]  ? __fget+0x40c/0x650
> > [  275.680922]  ? find_held_lock+0x31/0x1c0
> > [  275.680926]  ? expand_files.part.8+0x9a0/0x9a0
> > [  275.680929]  ? kasan_check_write+0x14/0x20
> > [  275.680933]  ? __mutex_unlock_slowpath+0x180/0x8a0
> > [  275.680936]  ? wait_for_completion+0x870/0x870
> > [  275.680939]  ? tty_vhangup+0x30/0x30
> > [  275.680942]  do_vfs_ioctl+0x1cf/0x16f0
> > [  275.680945]  ? ioctl_preallocate+0x2e0/0x2e0
> > [  275.680948]  ? fget_raw+0x20/0x20
> > [  275.680951]  ? __sb_end_write+0xac/0xe0
> > [  275.680955]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
> > [  275.680958]  ? fput+0x130/0x1a0
> > [  275.680961]  ? ksys_write+0x1a6/0x250
> > [  275.680965]  ? security_file_ioctl+0x94/0xc0
> > [  275.680968]  ksys_ioctl+0xa9/0xd0
> > [  275.680970]  __x64_sys_ioctl+0x73/0xb0
> > [  275.680974]  do_syscall_64+0x1b1/0x800
> > [  275.680977]  ? finish_task_switch+0x1ca/0x840
> > [  275.680981]  ? syscall_return_slowpath+0x5c0/0x5c0
> > [  275.680984]  ? syscall_return_slowpath+0x30f/0x5c0
> > [  275.680988]  ? entry_SYSCALL_64_after_hwframe+0x59/0xbe
> > [  275.680992]  ? trace_hardirqs_off_thunk+0x1a/0x1c
> > [  275.680996]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> > [  275.680999] RIP: 0033:0x4559f9
> > [  275.681001] Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff
> > 
> > >>  /*
> > >> @@ -773,7 +774,13 @@ 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__)
> > >> +	do {						\
> > >> +		unsigned long flags;			\
> > >> +							\
> > >> +		printk_safe_enter_irqsave(flags);	\
> > >> +		fn("%s %s: " f, tty_driver_name(tty), tty_name(tty), ##__VA_ARGS__); \
> > >> +		printk_safe_exit_irqrestore(flags);	\
> > >> +	} while (0)
> > > 
> > > There is no need to call single printk() in printk_safe() context.
> > > printk_deferred() is enough.
> > 
> > Then, regarding tty_msg() we can update
> > 
> >   #define tty_msg(fn, tty, f, ...) \
> >           fn("%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_info_ratelimited(tty, f, ...) \
> >                   tty_msg(pr_info_ratelimited, tty, f, ##__VA_ARGS__)
> > 
> > to use printk_deferred().
> > 
> > > Just note that printk_deferred()/printk_safe() is only temporary
> > > solution. It will get obsoleted by offloading the console handling
> > > to kthreads. It goes slowly because it is not trivial. We want
> > > to do it a clean way and carefully. Any historic or new
> > > workarounds/hacks would only slow it down.
> > > 
> > > My estimation is that we could have the offloaded consoles
> > > within the next 3-4 development cycles.
> > > 
> > > Please, consider whether it is really worth adding these workarounds.
> > 
> > 1000+ days have elapsed since this problem was reported. Given that
> > offloading the console handling to kthreads needs big changes which
> > are not suitable for backporting, what can we offer for current and
> > stable kernels?

Note that any deadlocks caused by printk were invisible for lockdep before
the commit f975237b76827956fe13ecfe9 ("printk: use printk_safe buffers
in printk"). It appeared in 4.11-rc1.

Some reported deadlocks are possible in reality but pretty hard to hit.
There are also many false positives caused by printk() messages in
the init code. They can't cause deadlock because the messages are
printed before the given console is registered.

I see three possible solutions:

1. Disable the lockdep in printk() and hide all these problems.

2. Do end-less number of hacks in the console drivers code to
   calm down these reports.

3. Keep the status quo and focus on doing the console offload
   properly.


We are working hard on the rework. Note that offloading console
work is being discussed minimally since 2013, see
https://lore.kernel.org/lkml/1358272714-23375-1-git-send-email-jack@suse.cz/
And I think that we are really getting close now. I believe that
we will have it on 90% this year.

I am not fully comfortable with disabling the lockdep. We accepted
some fixes because we considered the problems important enough.

IMHO, the workarounds are not always worth it. Some proposed patches
shuffled the locking or printk() and made the code more tricky.
printk_deferred() or printk_safe context are less evil. But they would
need to get reverted once the printk rework is done.

It might be acceptable to use printk_deferred/printk_safe on few
most visible code paths. But I would really like to avoid storm
of patches adding them all over the kernel.


> As it can't be triggered without fault injections, is this even a "real"
> issue?  Let's let the printk developers get this right.

+1

Best Regards,
Petr

[PATCH v2] tty: use printk_deferred() at tty_msg()

[Tetsuo Handa]

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

Re: [PATCH v2] tty: use printk_deferred() at tty_msg()

[Greg Kroah-Hartman]

On Wed, Apr 07, 2021 at 10:26:21PM +0900, Tetsuo Handa wrote:
> 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().

I view that if it is trivial to fix a warning/issue caused by an
artificial memory fault inject, wonderful.  Otherwise, just let it go,
we have way too many other "real" issues that syzbot is finding to fix
up first before we go after the "in theory this might cause a problem"
type of stuff...

> 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"))

Odd, how can ttyprintk() generate that mess?

These old tty_* functions need to just be cleaned up to use the "real"
kernel logging functions, and taken out of tty.h as none belong there.

Then how about we track down the "real" messages that are causing syzbot
problems and fix that up on a case-by-case basis instead of trying to
just whack all of these at once for no good reason?

thanks,

greg k-h

Re: [PATCH v2] tty: use printk_deferred() at tty_msg()

[Tetsuo Handa]

On 2021/04/07 22:48, Greg Kroah-Hartman wrote:
>> 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"))
> 
> Odd, how can ttyprintk() generate that mess?

So far three tests and results:

  https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/WifLgadvAAAJ
  https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/w2_MiMmAAAAJ
  https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/hfsQqSOPAAAJ

Patch https://syzkaller.appspot.com/x/patch.diff?x=145e4c9ad00000 generated
console output https://syzkaller.appspot.com/x/log.txt?x=162f9fced00000 .

Patch https://syzkaller.appspot.com/x/patch.diff?x=14839931d00000 did not
flood the console output enough to fire khungtaskd.

Maybe it is because /dev/ttyprintk can be opened/closed by multiple processes
without serialization?

Running

  for i in $(seq 1 100); do sleep 1 > /dev/ttyprintk & done

results in

  tty_port_close_start: tty->count = 1 port count = 100

. If tty_port_open() from tpk_open() can do

  spin_lock_irq(&port->lock);
  ++port->count;
  spin_unlock_irq(&port->lock);

when tty_port_close_start() from tty_port_close() from tpk_close() is doing

  spin_lock_irqsave(&port->lock, flags);
  if (tty->count == 1 && port->count != 1) {
    tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
             port->count);
    port->count = 1;
  }
  if (--port->count < 0) {
    tty_warn(tty, "%s: bad port count (%d)\n", __func__,
             port->count);
    port->count = 0;
  }

  if (port->count) {
    spin_unlock_irqrestore(&port->lock, flags);
    return 0;
  }
  spin_unlock_irqrestore(&port->lock, flags);

, what prevents port->count from getting larger than 1 ?

How to handle concurrent access to /dev/ttyprintk ?

[Tetsuo Handa]

What is the intended usage of /dev/ttyprintk ?

It seems that drivers/char/ttyprintk.c was not designed to be opened by
multiple processes. As a result, syzbot can trigger tty_warn() flooding
enough to fire khungtaskd warning due to tty_port_close().

Do we need to allow concurrent access to /dev/ttyprintk ?
If we can't change /dev/ttyprintk exclusively open()able by only
one thread, how to handle concurrent access to /dev/ttyprintk ?

On 2021/04/07 23:24, Tetsuo Handa wrote:
> On 2021/04/07 22:48, Greg Kroah-Hartman wrote:
>>> 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"))
>>
>> Odd, how can ttyprintk() generate that mess?
> 
> So far three tests and results:
> 
>   https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/WifLgadvAAAJ
>   https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/w2_MiMmAAAAJ
>   https://groups.google.com/g/syzkaller-bugs/c/yRLYijD2tbw/m/hfsQqSOPAAAJ
> 
> Patch https://syzkaller.appspot.com/x/patch.diff?x=145e4c9ad00000 generated
> console output https://syzkaller.appspot.com/x/log.txt?x=162f9fced00000 .
> 
> Patch https://syzkaller.appspot.com/x/patch.diff?x=14839931d00000 did not
> flood the console output enough to fire khungtaskd.
> 
> Maybe it is because /dev/ttyprintk can be opened/closed by multiple processes
> without serialization?
> 
> Running
> 
>   for i in $(seq 1 100); do sleep 1 > /dev/ttyprintk & done
> 
> results in
> 
>   tty_port_close_start: tty->count = 1 port count = 100
> 
> . If tty_port_open() from tpk_open() can do
> 
>   spin_lock_irq(&port->lock);
>   ++port->count;
>   spin_unlock_irq(&port->lock);
> 
> when tty_port_close_start() from tty_port_close() from tpk_close() is doing
> 
>   spin_lock_irqsave(&port->lock, flags);
>   if (tty->count == 1 && port->count != 1) {
>     tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
>              port->count);
>     port->count = 1;
>   }
>   if (--port->count < 0) {
>     tty_warn(tty, "%s: bad port count (%d)\n", __func__,
>              port->count);
>     port->count = 0;
>   }
> 
>   if (port->count) {
>     spin_unlock_irqrestore(&port->lock, flags);
>     return 0;
>   }
>   spin_unlock_irqrestore(&port->lock, flags);
> 
> , what prevents port->count from getting larger than 1 ?
> 

Re: How to handle concurrent access to /dev/ttyprintk ?

[Greg Kroah-Hartman]

On Mon, Apr 12, 2021 at 07:39:04PM +0900, Tetsuo Handa wrote:
> What is the intended usage of /dev/ttyprintk ?
> 
> It seems that drivers/char/ttyprintk.c was not designed to be opened by
> multiple processes. As a result, syzbot can trigger tty_warn() flooding
> enough to fire khungtaskd warning due to tty_port_close().
> 
> Do we need to allow concurrent access to /dev/ttyprintk ?
> If we can't change /dev/ttyprintk exclusively open()able by only
> one thread, how to handle concurrent access to /dev/ttyprintk ?

Like any tty port, if you have multiple accesses, all bets are off and
hilarity ensues.  Just don't do that and expect things to be working
well.

And trying to "open exclusive only" just does not work, the kernel can
not enforce that at all, sorry.  Any driver that you see trying to do
that is trivial to work around in userspace, making the kernel code
pointless.

That being said, triggering warning messages is not good, we should fix
that where possible as what's preventing any other tty device from doing
the same?

thanks,

greg k-h

Re: How to handle concurrent access to /dev/ttyprintk ?

[Tetsuo Handa]

On 2021/04/12 19:44, Greg Kroah-Hartman wrote:
> And trying to "open exclusive only" just does not work, the kernel can
> not enforce that at all, sorry.  Any driver that you see trying to do
> that is trivial to work around in userspace, making the kernel code
> pointless.

You mean something like below cannot be used?

diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
index 6a0059e508e3..57200569918a 100644
--- a/drivers/char/ttyprintk.c
+++ b/drivers/char/ttyprintk.c
@@ -84,14 +84,26 @@ static int tpk_printk(const unsigned char *buf, int count)
 	return count;
 }
 
+static DEFINE_MUTEX(open_close_lock);
+
 /*
  * TTY operations open function.
  */
 static int tpk_open(struct tty_struct *tty, struct file *filp)
 {
-	tty->driver_data = &tpk_port;
+	int ret;
+
+	if (mutex_lock_killable(&open_close_lock))
+		return -EINTR;
 
-	return tty_port_open(&tpk_port.port, tty, filp);
+	if (tpk_port.port.count) {
+		ret = -EBUSY;
+	} else {
+		tty->driver_data = &tpk_port;
+		ret = tty_port_open(&tpk_port.port, tty, filp);
+	}
+	mutex_unlock(&open_close_lock);
+	return ret;
 }
 
 /*
@@ -102,12 +114,14 @@ static void tpk_close(struct tty_struct *tty, struct file *filp)
 	struct ttyprintk_port *tpkp = tty->driver_data;
 	unsigned long flags;
 
+	mutex_lock(&open_close_lock);
 	spin_lock_irqsave(&tpkp->spinlock, flags);
 	/* flush tpk_printk buffer */
 	tpk_printk(NULL, 0);
 	spin_unlock_irqrestore(&tpkp->spinlock, flags);
 
 	tty_port_close(&tpkp->port, tty, filp);
+	mutex_unlock(&open_close_lock);
 }
 
 /*

> Like any tty port, if you have multiple accesses, all bets are off and
> hilarity ensues.  Just don't do that and expect things to be working
> well.

Since syzkaller is a fuzzer, syzkaller happily opens /dev/ttyprintk from
multiple threads. Should we update syzkaller to use CONFIG_TTY_PRINTK=n ?

Re: How to handle concurrent access to /dev/ttyprintk ?

[Greg Kroah-Hartman]

On Mon, Apr 12, 2021 at 08:25:27PM +0900, Tetsuo Handa wrote:
> On 2021/04/12 19:44, Greg Kroah-Hartman wrote:
> > And trying to "open exclusive only" just does not work, the kernel can
> > not enforce that at all, sorry.  Any driver that you see trying to do
> > that is trivial to work around in userspace, making the kernel code
> > pointless.
> 
> You mean something like below cannot be used?
> 
> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> index 6a0059e508e3..57200569918a 100644
> --- a/drivers/char/ttyprintk.c
> +++ b/drivers/char/ttyprintk.c
> @@ -84,14 +84,26 @@ static int tpk_printk(const unsigned char *buf, int count)
>  	return count;
>  }
>  
> +static DEFINE_MUTEX(open_close_lock);

Hah, nope, does not work at all!

Think about sending an open file descriptor all around the system, or
through a pipe, your "open only once" check does not prevent that at
all.

> > Like any tty port, if you have multiple accesses, all bets are off and
> > hilarity ensues.  Just don't do that and expect things to be working
> > well.
> 
> Since syzkaller is a fuzzer, syzkaller happily opens /dev/ttyprintk from
> multiple threads. Should we update syzkaller to use CONFIG_TTY_PRINTK=n ?

Why?  Can you not hit the same tty code paths from any other tty driver
being open multiple times?  Why is ttyprintk somehow "special" here?

thanks,

greg k-h

Re: How to handle concurrent access to /dev/ttyprintk ?

[Tetsuo Handa]

On 2021/04/12 21:04, Greg Kroah-Hartman wrote:
>> Since syzkaller is a fuzzer, syzkaller happily opens /dev/ttyprintk from
>> multiple threads. Should we update syzkaller to use CONFIG_TTY_PRINTK=n ?
> 
> Why?  Can you not hit the same tty code paths from any other tty driver
> being open multiple times?  Why is ttyprintk somehow "special" here?

I found a simplified reproducer. If we call ioctl(TIOCVHANGUP) on /dev/ttyprintk ,
"struct ttyprintk_port tpk_port".port.count cannot be decremented by
tty_port_close() from tpk_close() due to tty_hung_up_p() == true when
close() is called. As a result, tty->count and port count gets out of sync.

Then, when /dev/ttyprintk is opened again and then closed without calling
ioctl(TIOCVHANGUP), this message is printed due to tty_hung_up_p() == false.

---------- Debug print patch start ----------
diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
index 391bada4cedb..42d54368adac 100644
--- a/drivers/tty/tty_io.c
+++ b/drivers/tty/tty_io.c
@@ -113,7 +113,7 @@
 #ifdef TTY_DEBUG_HANGUP
 # define tty_debug_hangup(tty, f, args...)	tty_debug(tty, f, ##args)
 #else
-# define tty_debug_hangup(tty, f, args...)	do { } while (0)
+# define tty_debug_hangup(tty, f, args...)	tty_info(tty, f, ##args)
 #endif
 
 #define TTY_PARANOIA_CHECK 1
@@ -628,6 +628,7 @@ static void __tty_hangup(struct tty_struct *tty, int exit_session)
 		closecount++;
 		__tty_fasync(-1, filp, 0);	/* can't block */
 		filp->f_op = &hung_up_tty_fops;
+		tty_warn(tty, "Set hung_up_tty_fops on %px\n", filp);
 	}
 	spin_unlock(&tty->files_lock);
 
diff --git a/drivers/tty/tty_port.c b/drivers/tty/tty_port.c
index 346d20f4a486..032fc58203ea 100644
--- a/drivers/tty/tty_port.c
+++ b/drivers/tty/tty_port.c
@@ -561,8 +561,10 @@ int tty_port_close_start(struct tty_port *port,
 {
 	unsigned long flags;
 
-	if (tty_hung_up_p(filp))
+	if (tty_hung_up_p(filp)) {
+		tty_warn(tty, "Skipped by hung_up_tty_fops on %px\n", filp);
 		return 0;
+	}
 
 	spin_lock_irqsave(&port->lock, flags);
 	if (tty->count == 1 && port->count != 1) {
---------- Debug print patch end ----------

---------- Reproducer start ----------
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sys/ioctl.h>
#include <unistd.h>

int main(int argc, char *argv[])
{
	int i;
	int fd[10];

	for (i = 0; i < 10; i++)
		fd[i] = open("/dev/ttyprintk", O_WRONLY);
	ioctl(fd[0], TIOCVHANGUP);
	for (i = 0; i < 10; i++)
		close(fd[i]);
	close(open("/dev/ttyprintk", O_WRONLY));
	return 0;
}
---------- Reproducer end ----------

---------- Console output start ----------
[   31.885820] ttyprintk ttyprintk: opening (count=1)
[   31.885859] ttyprintk ttyprintk: opening (count=2)
[   31.885876] ttyprintk ttyprintk: opening (count=3)
[   31.885892] ttyprintk ttyprintk: opening (count=4)
[   31.885907] ttyprintk ttyprintk: opening (count=5)
[   31.885923] ttyprintk ttyprintk: opening (count=6)
[   31.885939] ttyprintk ttyprintk: opening (count=7)
[   31.885956] ttyprintk ttyprintk: opening (count=8)
[   31.885971] ttyprintk ttyprintk: opening (count=9)
[   31.885988] ttyprintk ttyprintk: opening (count=10)
[   31.885999] ttyprintk ttyprintk: vhangup
[   31.886005] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed1000
[   31.886009] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed2000
[   31.886012] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed0c00
[   31.886016] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed0e00
[   31.886019] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed2c00
[   31.886023] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed3a00
[   31.886026] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed3400
[   31.886029] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed3c00
[   31.886033] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed0200
[   31.886036] ttyprintk ttyprintk: Set hung_up_tty_fops on ffff97c38eed3e00
[   31.886055] ttyprintk ttyprintk: releasing (count=10)
[   31.886106] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed3e00
[   31.886117] ttyprintk ttyprintk: releasing (count=9)
[   31.886121] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed0200
[   31.886128] ttyprintk ttyprintk: releasing (count=8)
[   31.886131] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed3c00
[   31.886138] ttyprintk ttyprintk: releasing (count=7)
[   31.886141] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed3400
[   31.886148] ttyprintk ttyprintk: releasing (count=6)
[   31.886151] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed3a00
[   31.886158] ttyprintk ttyprintk: releasing (count=5)
[   31.886161] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed2c00
[   31.886168] ttyprintk ttyprintk: releasing (count=4)
[   31.886171] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed0e00
[   31.886178] ttyprintk ttyprintk: releasing (count=3)
[   31.886181] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed0c00
[   31.886188] ttyprintk ttyprintk: releasing (count=2)
[   31.886191] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed2000
[   31.886198] ttyprintk ttyprintk: releasing (count=1)
[   31.886201] ttyprintk ttyprintk: Skipped by hung_up_tty_fops on ffff97c38eed1000
[   31.886205] ttyprintk ttyprintk: final close
[   31.886211] ttyprintk ttyprintk: freeing structure
[   31.886277] ttyprintk ttyprintk: opening (count=1)
[   31.886531] ttyprintk ttyprintk: releasing (count=1)
[   31.886535] ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 11
[   31.886543] ttyprintk ttyprintk: final close
[   31.886552] ttyprintk ttyprintk: freeing structure
---------- Console output end ----------

If I replace /dev/ttyprintk with /dev/ttyS0 in the reproducer shown above,
this message is not printed.

---------- Console output start ----------
[   10.794802] ttyS ttyS0: opening (count=1)
[   10.795851] ttyS ttyS0: opening (count=2)
[   10.795872] ttyS ttyS0: opening (count=3)
[   10.795890] ttyS ttyS0: opening (count=4)
[   10.795908] ttyS ttyS0: opening (count=5)
[   10.795925] ttyS ttyS0: opening (count=6)
[   10.795943] ttyS ttyS0: opening (count=7)
[   10.795960] ttyS ttyS0: opening (count=8)
[   10.795978] ttyS ttyS0: opening (count=9)
[   10.795995] ttyS ttyS0: opening (count=10)
[   10.796007] ttyS ttyS0: vhangup
[   10.796014] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc5600
[   10.796020] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc6400
[   10.796025] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc4a00
[   10.796030] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc6800
[   10.796035] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc6200
[   10.796039] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc5a00
[   10.796044] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc6600
[   10.796048] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc7600
[   10.796053] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc5e00
[   10.796058] ttyS ttyS0: Set hung_up_tty_fops on ffff9cb044dc6000
[   10.796401] ttyS ttyS0: releasing (count=10)
[   10.796408] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc6000
[   10.796434] ttyS ttyS0: releasing (count=9)
[   10.796439] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc5e00
[   10.796447] ttyS ttyS0: releasing (count=8)
[   10.796451] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc7600
[   10.796459] ttyS ttyS0: releasing (count=7)
[   10.796463] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc6600
[   10.796472] ttyS ttyS0: releasing (count=6)
[   10.796476] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc5a00
[   10.796484] ttyS ttyS0: releasing (count=5)
[   10.796488] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc6200
[   10.796496] ttyS ttyS0: releasing (count=4)
[   10.796500] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc6800
[   10.796508] ttyS ttyS0: releasing (count=3)
[   10.796512] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc4a00
[   10.796521] ttyS ttyS0: releasing (count=2)
[   10.796525] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc6400
[   10.796533] ttyS ttyS0: releasing (count=1)
[   10.796537] ttyS ttyS0: Skipped by hung_up_tty_fops on ffff9cb044dc5600
[   10.796542] ttyS ttyS0: final close
[   10.796548] ttyS ttyS0: freeing structure
[   10.796634] ttyS ttyS0: opening (count=1)
[   10.797192] ttyS ttyS0: releasing (count=1)
[   10.797413] ttyS ttyS0: final close
[   10.797427] ttyS ttyS0: freeing structure
---------- Console output end ----------

Re: How to handle concurrent access to /dev/ttyprintk ?

[Tetsuo Handa]

On 2021/04/14 9:45, Tetsuo Handa wrote:
> On 2021/04/12 21:04, Greg Kroah-Hartman wrote:
>>> Since syzkaller is a fuzzer, syzkaller happily opens /dev/ttyprintk from
>>> multiple threads. Should we update syzkaller to use CONFIG_TTY_PRINTK=n ?
>>
>> Why?  Can you not hit the same tty code paths from any other tty driver
>> being open multiple times?  Why is ttyprintk somehow "special" here?
> 
> I found a simplified reproducer. If we call ioctl(TIOCVHANGUP) on /dev/ttyprintk ,
> "struct ttyprintk_port tpk_port".port.count cannot be decremented by
> tty_port_close() from tpk_close() due to tty_hung_up_p() == true when
> close() is called. As a result, tty->count and port count gets out of sync.
> 
> Then, when /dev/ttyprintk is opened again and then closed without calling
> ioctl(TIOCVHANGUP), this message is printed due to tty_hung_up_p() == false.
> 
> If I replace /dev/ttyprintk with /dev/ttyS0 in the reproducer shown above,
> this message is not printed.
> 

The difference between /dev/ttyS0 and /dev/ttyprintk is that
the former provides uart_hangup() as "struct tty_operations"->hangup
while the latter does not provide "struct tty_operations"->hangup .

It seems to me that below patch avoids this message, but I'm not familiar
with tty code. Is this fix correct? Don't we need to enforce all drivers
to provide "struct tty_operations"->hangup in order to reset port count ?

diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
index 6a0059e508e3..ff3b9a41b91b 100644
--- a/drivers/char/ttyprintk.c
+++ b/drivers/char/ttyprintk.c
@@ -158,12 +158,26 @@ static int tpk_ioctl(struct tty_struct *tty,
 	return 0;
 }
 
+/*
+ * TTY operations hangup function.
+ */
+static void tpk_hangup(struct tty_struct *tty)
+{
+	struct ttyprintk_port *tpkp = tty->driver_data;
+	unsigned long flags;
+
+	spin_lock_irqsave(&tpkp->port.lock, flags);
+	tpkp->port.count = 0;
+	spin_unlock_irqrestore(&tpkp->port.lock, flags);
+}
+
 static const struct tty_operations ttyprintk_ops = {
 	.open = tpk_open,
 	.close = tpk_close,
 	.write = tpk_write,
 	.write_room = tpk_write_room,
 	.ioctl = tpk_ioctl,
+	.hangup = tpk_hangup,
 };
 
 static const struct tty_port_operations null_ops = { };

Re: How to handle concurrent access to /dev/ttyprintk ?

[Samo Pogačnik]

Dne 14.04.2021 (sre) ob 20:11 +0900 je Tetsuo Handa napisal(a):
> On 2021/04/14 9:45, Tetsuo Handa wrote:
> > On 2021/04/12 21:04, Greg Kroah-Hartman wrote:
> > > > Since syzkaller is a fuzzer, syzkaller happily opens /dev/ttyprintk from
> > > > multiple threads. Should we update syzkaller to use CONFIG_TTY_PRINTK=n
> > > > ?
> > > 
> > > Why?  Can you not hit the same tty code paths from any other tty driver
> > > being open multiple times?  Why is ttyprintk somehow "special" here?
> > 
> > I found a simplified reproducer. If we call ioctl(TIOCVHANGUP) on
> > /dev/ttyprintk ,
> > "struct ttyprintk_port tpk_port".port.count cannot be decremented by
> > tty_port_close() from tpk_close() due to tty_hung_up_p() == true when
> > close() is called. As a result, tty->count and port count gets out of sync.
> > 
> > Then, when /dev/ttyprintk is opened again and then closed without calling
> > ioctl(TIOCVHANGUP), this message is printed due to tty_hung_up_p() == false.
> > 
> > If I replace /dev/ttyprintk with /dev/ttyS0 in the reproducer shown above,
> > this message is not printed.
> > 
> 
> The difference between /dev/ttyS0 and /dev/ttyprintk is that
> the former provides uart_hangup() as "struct tty_operations"->hangup
> while the latter does not provide "struct tty_operations"->hangup .
> 
> It seems to me that below patch avoids this message, but I'm not familiar
> with tty code. Is this fix correct? Don't we need to enforce all drivers
> to provide "struct tty_operations"->hangup in order to reset port count ?
> 
> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> index 6a0059e508e3..ff3b9a41b91b 100644
> --- a/drivers/char/ttyprintk.c
> +++ b/drivers/char/ttyprintk.c
> @@ -158,12 +158,26 @@ static int tpk_ioctl(struct tty_struct *tty,
>  	return 0;
>  }
>  
> +/*
> + * TTY operations hangup function.
> + */
> +static void tpk_hangup(struct tty_struct *tty)
> +{
> +	struct ttyprintk_port *tpkp = tty->driver_data;
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&tpkp->port.lock, flags);
> +	tpkp->port.count = 0;
> +	spin_unlock_irqrestore(&tpkp->port.lock, flags);
> +}
> +
>  static const struct tty_operations ttyprintk_ops = {
>  	.open = tpk_open,
>  	.close = tpk_close,
>  	.write = tpk_write,
>  	.write_room = tpk_write_room,
>  	.ioctl = tpk_ioctl,
> +	.hangup = tpk_hangup,
>  };
>  
>  static const struct tty_port_operations null_ops = { };

Wish i could be of more help here, especially around locking.

If this addition is needed, i'd probably do something similar.
However, when comparing the code around other drivers it seems that
'tty_port_hangup()' should be used instead explicit 'port.count'
reset.

best regards, Samo

[PATCH] ttyprintk: Add TTY hangup callback.

[Tetsuo Handa]

syzbot is reporting hung task due to flood of

  tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
           port->count);

message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
decrementing port->count due to tty_hung_up_p() == true.

----------
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sys/ioctl.h>
#include <unistd.h>

int main(int argc, char *argv[])
{
	int i;
	int fd[10];

	for (i = 0; i < 10; i++)
		fd[i] = open("/dev/ttyprintk", O_WRONLY);
	ioctl(fd[0], TIOCVHANGUP);
	for (i = 0; i < 10; i++)
		close(fd[i]);
	close(open("/dev/ttyprintk", O_WRONLY));
	return 0;
}
----------

When TTY hangup happens, port->count needs to be reset via
"struct tty_operations"->hangup callback.

[1] https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a

Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com>
Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
---
 drivers/char/ttyprintk.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
index 6a0059e508e3..93f5d11c830b 100644
--- a/drivers/char/ttyprintk.c
+++ b/drivers/char/ttyprintk.c
@@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
 	return 0;
 }
 
+/*
+ * TTY operations hangup function.
+ */
+static void tpk_hangup(struct tty_struct *tty)
+{
+	struct ttyprintk_port *tpkp = tty->driver_data;
+
+	tty_port_hangup(&tpkp->port);
+}
+
 static const struct tty_operations ttyprintk_ops = {
 	.open = tpk_open,
 	.close = tpk_close,
 	.write = tpk_write,
 	.write_room = tpk_write_room,
 	.ioctl = tpk_ioctl,
+	.hangup = tpk_hangup,
 };
 
 static const struct tty_port_operations null_ops = { };
-- 
2.18.4

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
> syzbot is reporting hung task due to flood of
> 
>   tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
>            port->count);
> 
> message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
> decrementing port->count due to tty_hung_up_p() == true.
> 
> ----------
> #include <sys/types.h>
> #include <sys/stat.h>
> #include <fcntl.h>
> #include <sys/ioctl.h>
> #include <unistd.h>
> 
> int main(int argc, char *argv[])
> {
> 	int i;
> 	int fd[10];
> 
> 	for (i = 0; i < 10; i++)
> 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
> 	ioctl(fd[0], TIOCVHANGUP);
> 	for (i = 0; i < 10; i++)
> 		close(fd[i]);
> 	close(open("/dev/ttyprintk", O_WRONLY));
> 	return 0;
> }
> ----------
> 
> When TTY hangup happens, port->count needs to be reset via
> "struct tty_operations"->hangup callback.
> 
> [1] 
> https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> 
> Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com>
> Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
> ---
>  drivers/char/ttyprintk.c | 11 +++++++++++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> index 6a0059e508e3..93f5d11c830b 100644
> --- a/drivers/char/ttyprintk.c
> +++ b/drivers/char/ttyprintk.c
> @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
>  	return 0;
>  }
>  
> +/*
> + * TTY operations hangup function.
> + */
> +static void tpk_hangup(struct tty_struct *tty)
> +{
> +	struct ttyprintk_port *tpkp = tty->driver_data;
> +
> +	tty_port_hangup(&tpkp->port);
> +}
> +
>  static const struct tty_operations ttyprintk_ops = {
>  	.open = tpk_open,
>  	.close = tpk_close,
>  	.write = tpk_write,
>  	.write_room = tpk_write_room,
>  	.ioctl = tpk_ioctl,
> +	.hangup = tpk_hangup,
>  };
>  
>  static const struct tty_port_operations null_ops = { };

Using the supplied test code, i've tested the patch on my desktop running the
5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
tty_port_close_start: tty->count = 1 port count = 11" do not appear any more,
when the test code is run.
I think the patch is ok.

best regards, Samo

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Greg Kroah-Hartman]

On Sun, Apr 18, 2021 at 01:16:05PM +0200, Samo Pogačnik wrote:
> Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
> > syzbot is reporting hung task due to flood of
> > 
> >   tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
> >            port->count);
> > 
> > message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
> > decrementing port->count due to tty_hung_up_p() == true.
> > 
> > ----------
> > #include <sys/types.h>
> > #include <sys/stat.h>
> > #include <fcntl.h>
> > #include <sys/ioctl.h>
> > #include <unistd.h>
> > 
> > int main(int argc, char *argv[])
> > {
> > 	int i;
> > 	int fd[10];
> > 
> > 	for (i = 0; i < 10; i++)
> > 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
> > 	ioctl(fd[0], TIOCVHANGUP);
> > 	for (i = 0; i < 10; i++)
> > 		close(fd[i]);
> > 	close(open("/dev/ttyprintk", O_WRONLY));
> > 	return 0;
> > }
> > ----------
> > 
> > When TTY hangup happens, port->count needs to be reset via
> > "struct tty_operations"->hangup callback.
> > 
> > [1] 
> > https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> > 
> > Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> > Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com>
> > Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> > Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> > Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
> > ---
> >  drivers/char/ttyprintk.c | 11 +++++++++++
> >  1 file changed, 11 insertions(+)
> > 
> > diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> > index 6a0059e508e3..93f5d11c830b 100644
> > --- a/drivers/char/ttyprintk.c
> > +++ b/drivers/char/ttyprintk.c
> > @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
> >  	return 0;
> >  }
> >  
> > +/*
> > + * TTY operations hangup function.
> > + */
> > +static void tpk_hangup(struct tty_struct *tty)
> > +{
> > +	struct ttyprintk_port *tpkp = tty->driver_data;
> > +
> > +	tty_port_hangup(&tpkp->port);
> > +}
> > +
> >  static const struct tty_operations ttyprintk_ops = {
> >  	.open = tpk_open,
> >  	.close = tpk_close,
> >  	.write = tpk_write,
> >  	.write_room = tpk_write_room,
> >  	.ioctl = tpk_ioctl,
> > +	.hangup = tpk_hangup,
> >  };
> >  
> >  static const struct tty_port_operations null_ops = { };
> 
> Using the supplied test code, i've tested the patch on my desktop running the
> 5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
> tty_port_close_start: tty->count = 1 port count = 11" do not appear any more,
> when the test code is run.
> I think the patch is ok.

Thanks for the review, I'll go queue this up.

greg k-h

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Jiri Slaby]

On 18. 04. 21, 13:16, Samo Pogačnik wrote:
> Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
>> syzbot is reporting hung task due to flood of
>>
>>    tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
>>             port->count);
>>
>> message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
>> decrementing port->count due to tty_hung_up_p() == true.
>>
>> ----------
>> #include <sys/types.h>
>> #include <sys/stat.h>
>> #include <fcntl.h>
>> #include <sys/ioctl.h>
>> #include <unistd.h>
>>
>> int main(int argc, char *argv[])
>> {
>> 	int i;
>> 	int fd[10];
>>
>> 	for (i = 0; i < 10; i++)
>> 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
>> 	ioctl(fd[0], TIOCVHANGUP);
>> 	for (i = 0; i < 10; i++)
>> 		close(fd[i]);
>> 	close(open("/dev/ttyprintk", O_WRONLY));
>> 	return 0;
>> }
>> ----------
>>
>> When TTY hangup happens, port->count needs to be reset via
>> "struct tty_operations"->hangup callback.
>>
>> [1]
>> https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
>>
>> Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
>> Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com>
>> Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
>> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
>> Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
>> ---
>>   drivers/char/ttyprintk.c | 11 +++++++++++
>>   1 file changed, 11 insertions(+)
>>
>> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
>> index 6a0059e508e3..93f5d11c830b 100644
>> --- a/drivers/char/ttyprintk.c
>> +++ b/drivers/char/ttyprintk.c
>> @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
>>   	return 0;
>>   }
>>   
>> +/*
>> + * TTY operations hangup function.
>> + */
>> +static void tpk_hangup(struct tty_struct *tty)
>> +{
>> +	struct ttyprintk_port *tpkp = tty->driver_data;
>> +
>> +	tty_port_hangup(&tpkp->port);
>> +}
>> +
>>   static const struct tty_operations ttyprintk_ops = {
>>   	.open = tpk_open,
>>   	.close = tpk_close,
>>   	.write = tpk_write,
>>   	.write_room = tpk_write_room,
>>   	.ioctl = tpk_ioctl,
>> +	.hangup = tpk_hangup,
>>   };
>>   
>>   static const struct tty_port_operations null_ops = { };
> 
> Using the supplied test code, i've tested the patch on my desktop running the
> 5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
> tty_port_close_start: tty->count = 1 port count = 11" do not appear any more,
> when the test code is run.
> I think the patch is ok.

I wonder if the buffer shouldn't be flushed in hangup too? Or better, 
the flush moved from tty_ops->close to tty_port->ops->shutdown?

thanks,
-- 
js
suse labs

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 23.04.2021 (pet) ob 06:22 +0200 je Jiri Slaby napisal(a):
> On 18. 04. 21, 13:16, Samo Pogačnik wrote:
> > Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
> > > syzbot is reporting hung task due to flood of
> > > 
> > >    tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
> > >             port->count);
> > > 
> > > message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
> > > decrementing port->count due to tty_hung_up_p() == true.
> > > 
> > > ----------
> > > #include <sys/types.h>
> > > #include <sys/stat.h>
> > > #include <fcntl.h>
> > > #include <sys/ioctl.h>
> > > #include <unistd.h>
> > > 
> > > int main(int argc, char *argv[])
> > > {
> > > 	int i;
> > > 	int fd[10];
> > > 
> > > 	for (i = 0; i < 10; i++)
> > > 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
> > > 	ioctl(fd[0], TIOCVHANGUP);
> > > 	for (i = 0; i < 10; i++)
> > > 		close(fd[i]);
> > > 	close(open("/dev/ttyprintk", O_WRONLY));
> > > 	return 0;
> > > }
> > > ----------
> > > 
> > > When TTY hangup happens, port->count needs to be reset via
> > > "struct tty_operations"->hangup callback.
> > > 
> > > [1]
> > > 
https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> > > 
> > > Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com
> > > >
> > > Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com
> > > >
> > > Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> > > Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> > > Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
> > > ---
> > >   drivers/char/ttyprintk.c | 11 +++++++++++
> > >   1 file changed, 11 insertions(+)
> > > 
> > > diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> > > index 6a0059e508e3..93f5d11c830b 100644
> > > --- a/drivers/char/ttyprintk.c
> > > +++ b/drivers/char/ttyprintk.c
> > > @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
> > >   	return 0;
> > >   }
> > >   
> > > +/*
> > > + * TTY operations hangup function.
> > > + */
> > > +static void tpk_hangup(struct tty_struct *tty)
> > > +{
> > > +	struct ttyprintk_port *tpkp = tty->driver_data;
> > > +
> > > +	tty_port_hangup(&tpkp->port);
> > > +}
> > > +
> > >   static const struct tty_operations ttyprintk_ops = {
> > >   	.open = tpk_open,
> > >   	.close = tpk_close,
> > >   	.write = tpk_write,
> > >   	.write_room = tpk_write_room,
> > >   	.ioctl = tpk_ioctl,
> > > +	.hangup = tpk_hangup,
> > >   };
> > >   
> > >   static const struct tty_port_operations null_ops = { };
> > 
> > Using the supplied test code, i've tested the patch on my desktop running
> > the
> > 5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
> > tty_port_close_start: tty->count = 1 port count = 11" do not appear any
> > more,
> > when the test code is run.
> > I think the patch is ok.
> 
> I wonder if the buffer shouldn't be flushed in hangup too? Or better, 
> the flush moved from tty_ops->close to tty_port->ops->shutdown?
> 
> thanks,

Good point. I tried the following additional change, which seems to do the
trick. What do you think?

thanks, Samo
---
 drivers/char/ttyprintk.c | 26 ++++++++++++++++++--------
 1 file changed, 18 insertions(+), 8 deletions(-)

diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
index 93f5d11c8..420222a92 100644
--- a/drivers/char/ttyprintk.c
+++ b/drivers/char/ttyprintk.c
@@ -100,12 +100,6 @@ static int tpk_open(struct tty_struct *tty, struct file
*filp)
 static void tpk_close(struct tty_struct *tty, struct file *filp)
 {
 	struct ttyprintk_port *tpkp = tty->driver_data;
-	unsigned long flags;
-
-	spin_lock_irqsave(&tpkp->spinlock, flags);
-	/* flush tpk_printk buffer */
-	tpk_printk(NULL, 0);
-	spin_unlock_irqrestore(&tpkp->spinlock, flags);
 
 	tty_port_close(&tpkp->port, tty, filp);
 }
@@ -168,6 +162,20 @@ static void tpk_hangup(struct tty_struct *tty)
 	tty_port_hangup(&tpkp->port);
 }
 
+/*
+ * TTY port operations shutdown function.
+ */
+static void tpk_port_shutdown(struct tty_port *tport)
+{
+	struct ttyprintk_port *tpkp =
+		container_of(tport, struct ttyprintk_port, port);
+	unsigned long flags;
+
+	spin_lock_irqsave(&tpkp->spinlock, flags);
+	tpk_flush();
+	spin_unlock_irqrestore(&tpkp->spinlock, flags);
+}
+
 static const struct tty_operations ttyprintk_ops = {
 	.open = tpk_open,
 	.close = tpk_close,
@@ -177,7 +185,9 @@ static const struct tty_operations ttyprintk_ops = {
 	.hangup = tpk_hangup,
 };
 
-static const struct tty_port_operations null_ops = { };
+static const struct tty_port_operations tpk_port_ops = {
+	.shutdown = tpk_port_shutdown,
+};
 
 static struct tty_driver *ttyprintk_driver;
 
@@ -195,7 +205,7 @@ static int __init ttyprintk_init(void)
 		return PTR_ERR(ttyprintk_driver);
 
 	tty_port_init(&tpk_port.port);
-	tpk_port.port.ops = &null_ops;
+	tpk_port.port.ops = &tpk_port_ops;
 
 	ttyprintk_driver->driver_name = "ttyprintk";
 	ttyprintk_driver->name = "ttyprintk";
-- 
2.17.1

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Tetsuo Handa]

On 2021/04/23 18:55, Samo Pogačnik wrote:
>>> Using the supplied test code, i've tested the patch on my desktop running
>>> the
>>> 5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
>>> tty_port_close_start: tty->count = 1 port count = 11" do not appear any
>>> more,
>>> when the test code is run.
>>> I think the patch is ok.
>>
>> I wonder if the buffer shouldn't be flushed in hangup too? Or better, 
>> the flush moved from tty_ops->close to tty_port->ops->shutdown?
>>
>> thanks,
> 
> Good point. I tried the following additional change, which seems to do the
> trick. What do you think?
> 

Shouldn't the tpk_printk buffer be per a "struct file" (i.e. allocated upon
open() and released upon close() in order to allow multiple users) ?

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 23.04.2021 (pet) ob 19:12 +0900 je Tetsuo Handa napisal(a):
> On 2021/04/23 18:55, Samo Pogačnik wrote:
> > > > Using the supplied test code, i've tested the patch on my desktop
> > > > running
> > > > the
> > > > 5.4 kernel. After applying the patch, the kernel warnings like
> > > > "ttyprintk:
> > > > tty_port_close_start: tty->count = 1 port count = 11" do not appear any
> > > > more,
> > > > when the test code is run.
> > > > I think the patch is ok.
> > > 
> > > I wonder if the buffer shouldn't be flushed in hangup too? Or better, 
> > > the flush moved from tty_ops->close to tty_port->ops->shutdown?
> > > 
> > > thanks,
> > 
> > Good point. I tried the following additional change, which seems to do the
> > trick. What do you think?
> > 
> 
> Shouldn't the tpk_printk buffer be per a "struct file" (i.e. allocated upon
> open() and released upon close() in order to allow multiple users) ?

Final destination of the ttyprintk is printk(), which is a single destination.
The tpk_printk buffer is a common representation of what is yet to be printk-ed
depending on the formatting conditions within the buffer.

At any point the tpk_buffer is potentially multiplexed/interleaved by parts of
required output of any concurrent user, as buffs are being delivered by the
scheduled writes.

As per user buffers look promising with output formatting, the FDs passing
between tasks lead to the same single buffer (Greg already mentioned that). The
other thing which is important to me is the console redirection to ttyprintk,
which automatically brings all concurrent console users to the single open of
ttyprintk.

best regards, Samo

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Tetsuo Handa]

On 2021/04/24 4:47, Samo Pogačnik wrote:
> At any point the tpk_buffer is potentially multiplexed/interleaved by parts of
> required output of any concurrent user, as buffs are being delivered by the
> scheduled writes.

As long as one line is printed by one printk() call, CONFIG_PRINTK_CALLER=y is
helpful enough to distinguish multilplexed/interleaved messages. I consider that
ttyprintk offers additional advantage over printk() for allow buffering one line
of message from userspace.

> 
> As per user buffers look promising with output formatting, the FDs passing
> between tasks lead to the same single buffer (Greg already mentioned that).

Those programs which use FD passing know what they are doing. If they still want
one line of message printed via ttyprintk interface, they must do their buffering
before trying to write() to ttyprintk's file descriptor.

Use of per "struct file" buffer gives those programs which does not use
FD passing a guarantee that one line of message from those programs won't be
multilplexed/interleaved (with the aid of CONFIG_PRINTK_CALLER=y).
I consider it an improvement.

>                                                                             The
> other thing which is important to me is the console redirection to ttyprintk,
> which automatically brings all concurrent console users to the single open of
> ttyprintk.

Gathering whole console output into one FD is similar to FD passing; that is
inevitable. But use of per "struct file" buffer allows /dev/ttyprintk users
 from outside of "gather whole console output into one FD" case to avoid
multilplexed/interleaved messages. I tried /dev/ttyprintk like
https://lkml.kernel.org/r/be9e80b1-5be1-842e-538e-d69a3995d567@i-love.sakura.ne.jp .

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 24.04.2021 (sob) ob 10:16 +0900 je Tetsuo Handa napisal(a):
> On 2021/04/24 4:47, Samo Pogačnik wrote:
> > At any point the tpk_buffer is potentially multiplexed/interleaved by parts
> > of
> > required output of any concurrent user, as buffs are being delivered by the
> > scheduled writes.
> 
> As long as one line is printed by one printk() call, CONFIG_PRINTK_CALLER=y is
> helpful enough to distinguish multilplexed/interleaved messages. I consider
> that
> ttyprintk offers additional advantage over printk() for allow buffering one
> line
> of message from userspace.
> 
> > 
> > As per user buffers look promising with output formatting, the FDs passing
> > between tasks lead to the same single buffer (Greg already mentioned that).
> 
> Those programs which use FD passing know what they are doing. If they still
> want
> one line of message printed via ttyprintk interface, they must do their
> buffering
> before trying to write() to ttyprintk's file descriptor.
> 
> Use of per "struct file" buffer gives those programs which does not use
> FD passing a guarantee that one line of message from those programs won't be
> multilplexed/interleaved (with the aid of CONFIG_PRINTK_CALLER=y).
> I consider it an improvement.
> 
> >                                                                             
> > The
> > other thing which is important to me is the console redirection to
> > ttyprintk,
> > which automatically brings all concurrent console users to the single open
> > of
> > ttyprintk.
> 
> Gathering whole console output into one FD is similar to FD passing; that is
> inevitable. But use of per "struct file" buffer allows /dev/ttyprintk users
>  from outside of "gather whole console output into one FD" case to avoid
> multilplexed/interleaved messages. I tried /dev/ttyprintk like
> 
https://lkml.kernel.org/r/be9e80b1-5be1-842e-538e-d69a3995d567@i-love.sakura.ne.jp
>  .
> 

I think i understand, what would you like to achieve, however implementation
wise there seems to be no reference point available in tty write operation that
would relate to its tty open/close operations (i.e. open() and close() provide
filp while write() does not - probably for a reason) or is there such a relation
available?

On the other hand, my main concern is how to provide a reliable system wide
collection of all console output via ttyprintk console redirection, while normal
operation of system console is preserved (except its output being detoured via
printk and as such logged together with kernel output). Such logging is
particularly useful for after-the-fact inspection of system operation.

That being said i am thinking about how to permanently enable this redirection
as early as possible (i.e. via kernel command line option). I had a working
prototype for that some time ago (never posted). Would anybody like to see such
functionality?

best regards, Samo

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Petr Mladek]

On Sat 2021-04-24 11:57:47, Samo Pogačnik wrote:
> Dne 24.04.2021 (sob) ob 10:16 +0900 je Tetsuo Handa napisal(a):
> > On 2021/04/24 4:47, Samo Pogačnik wrote:
> > > At any point the tpk_buffer is potentially multiplexed/interleaved by parts
> > > of
> > > required output of any concurrent user, as buffs are being delivered by the
> > > scheduled writes.
> > 
> > As long as one line is printed by one printk() call, CONFIG_PRINTK_CALLER=y is
> > helpful enough to distinguish multilplexed/interleaved messages. I consider
> > that
> > ttyprintk offers additional advantage over printk() for allow buffering one
> > line
> > of message from userspace.

It does not matter how much buffering games you play. As long as you
use printk() to store single lines into the kernel logbuffer they
alway could be interleaved with lines from other processes/CPUs.

> > > 
> > > As per user buffers look promising with output formatting, the FDs passing
> > > between tasks lead to the same single buffer (Greg already mentioned that).
> > 
> > Those programs which use FD passing know what they are doing. If they still
> > want
> > one line of message printed via ttyprintk interface, they must do their
> > buffering
> > before trying to write() to ttyprintk's file descriptor.

Lines might get interleaved when using printk().
What is special about messages passed via ttyprintk()?
How many processes are using it?
Do they print many lines?
Is it really worth any added complexity?


> > Use of per "struct file" buffer gives those programs which does not use
> > FD passing a guarantee that one line of message from those programs won't be
> > multilplexed/interleaved (with the aid of CONFIG_PRINTK_CALLER=y).

How huge bugffer would be needed?

IMHO, even a 80-bytes big per-task buffer is not acceptable. And even
such a buffer would hold only 1-3 lines.

> I think i understand, what would you like to achieve, however implementation
> wise there seems to be no reference point available in tty write operation that
> would relate to its tty open/close operations (i.e. open() and close() provide
> filp while write() does not - probably for a reason) or is there such a relation
> available?
<
> On the other hand, my main concern is how to provide a reliable system wide
> collection of all console output via ttyprintk console redirection, while normal
> operation of system console is preserved (except its output being detoured via
> printk and as such logged together with kernel output). Such logging is
> particularly useful for after-the-fact inspection of system operation.

I am not sure if I understand the problem. But why does ttyprintk need
any buffer at all. AFAIK, the use-case is to pass any written data into the
kernel logbuffer via printk()?

Why tpk_write() does not call printk() directly?

If you call printk() directly, the caller_id would be from the process
that really wrote the data/message.

> That being said i am thinking about how to permanently enable this redirection
> as early as possible (i.e. via kernel command line option). I had a working
> prototype for that some time ago (never posted). Would anybody like to see such
> functionality?

Please, do not add any complex code if it does not cause real life
problems.

There seems to be only few commits that suggest that anyone is using
this driver and the latest is 7 year old.

+ (2014) acef6660d3aaf18813143
	("ttyprintk: make the printk log level configurable")
+ (2014) b24313a82cf24e9017067
	("ttyprintk: Allow built as a module")
+ (2014) 7d1c2858c49095ab748f5
	("ttyprintk: Fix wrong tty_unregister_driver() call in the error path")
+ (2014) db50d2f65b7c2bcdfb931
	("drivers/char: don't use module_init in non-modular ttyprintk.c")
+ (2013) b5325a02aa84c794cf520
	("ttyprintk: Fix NULL pointer deref by setting tty_port ops
	  after	initializing port")
+ (2012) ee8b593affdf893012e57
	("TTY: ttyprintk, don't touch behind tty->write_buf")
+ (2012) f06fb543c1d0cbd721250
	("TTY: ttyprintk, unregister tty driver on failure")
+ (2012) 2f16669d322e05171c9e1
	("TTY: remove re-assignments to tty_driver members")
+ (2010) 24b4b67d17c308aaa956b
	("add ttyprintk driver")

Best Regards,
Petr

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 26.04.2021 (pon) ob 12:00 +0200 je Petr Mladek napisal(a):
> On Sat 2021-04-24 11:57:47, Samo Pogačnik wrote:
> > Dne 24.04.2021 (sob) ob 10:16 +0900 je Tetsuo Handa napisal(a):
> > > On 2021/04/24 4:47, Samo Pogačnik wrote:
> > > > At any point the tpk_buffer is potentially multiplexed/interleaved by
> > > > parts
> > > > of
> > > > required output of any concurrent user, as buffs are being delivered by
> > > > the
> > > > scheduled writes.
> > > 
> > > As long as one line is printed by one printk() call,
> > > CONFIG_PRINTK_CALLER=y is
> > > helpful enough to distinguish multilplexed/interleaved messages. I
> > > consider
> > > that
> > > ttyprintk offers additional advantage over printk() for allow buffering
> > > one
> > > line
> > > of message from userspace.
> 
> It does not matter how much buffering games you play. As long as you
> use printk() to store single lines into the kernel logbuffer they
> alway could be interleaved with lines from other processes/CPUs.

Exactly. The only purpose of ttyprintk buffering is to mark any begining of
lines occurring within the userspace-string written into ttyprintk TTY. The
marked lines do not originate in the kernel source code, which is not obvious
otherwise (imho this is importannt). Even the CONFIG_PRINTK_CALLER=y does not
give this information, if the task ID printed does not live anymore.

> 
> > > > 
> > > > As per user buffers look promising with output formatting, the FDs
> > > > passing
> > > > between tasks lead to the same single buffer (Greg already mentioned
> > > > that).
> > > 
> > > Those programs which use FD passing know what they are doing. If they
> > > still
> > > want
> > > one line of message printed via ttyprintk interface, they must do their
> > > buffering
> > > before trying to write() to ttyprintk's file descriptor.
> 
> Lines might get interleaved when using printk().
> What is special about messages passed via ttyprintk()?
They do not originate in the kernel code.

> How many processes are using it?
In case of redirection any proces, that is writing to console.

> Do they print many lines?
?

> Is it really worth any added complexity?
No.

> 
> > On the other hand, my main concern is how to provide a reliable system wide
> > collection of all console output via ttyprintk console redirection, while
> > normal
> > operation of system console is preserved (except its output being detoured
> > via
> > printk and as such logged together with kernel output). Such logging is
> > particularly useful for after-the-fact inspection of system operation.
> 
> I am not sure if I understand the problem. But why does ttyprintk need
> any buffer at all. AFAIK, the use-case is to pass any written data into the
> kernel logbuffer via printk()?
(see above - it is not something the kernel is telling you)
> 
> Why tpk_write() does not call printk() directly?
(see above)
> 
> If you call printk() directly, the caller_id would be from the process
> that really wrote the data/message.
It can be a kernel-code originating message printk-ed on behalf of a user task
or a kernel-code originating message on behalf of a kernel task. Or it may be a
user-code originating message on behalf of its task, when printk-ed via
ttyprintk.

> 
> > That being said i am thinking about how to permanently enable this
> > redirection
> > as early as possible (i.e. via kernel command line option). I had a working
> > prototype for that some time ago (never posted). Would anybody like to see
> > such
> > functionality?
> 
> Please, do not add any complex code if it does not cause real life
> problems.
> 
Noted, thanks.

Best regards, Samo

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Petr Mladek]

On Mon 2021-04-26 18:42:05, Samo Pogačnik wrote:
> Dne 26.04.2021 (pon) ob 12:00 +0200 je Petr Mladek napisal(a):
> > It does not matter how much buffering games you play. As long as you
> > use printk() to store single lines into the kernel logbuffer they
> > alway could be interleaved with lines from other processes/CPUs.
> 
> Exactly. The only purpose of ttyprintk buffering is to mark any begining of
> lines occurring within the userspace-string written into ttyprintk TTY. The
> marked lines do not originate in the kernel source code, which is not obvious
> otherwise (imho this is importannt). Even the CONFIG_PRINTK_CALLER=y does not
> give this information, if the task ID printed does not live anymore.

I guess that you mean TPK_PREFIX + "[U] ".

> > I am not sure if I understand the problem. But why does ttyprintk need
> > any buffer at all. AFAIK, the use-case is to pass any written data into the
> > kernel logbuffer via printk()?
> (see above - it is not something the kernel is telling you)

But you could do this already in tpk_write(). I mean that you could
parse the given buffer, copy each line to a temporary buffer,
and call printk(TPK_PREFIX "[U] %s\n", tmp_buf).

Why is it postponed to tpk_close()?

IMHO, the printk() in tpk_write() might simplify the logic a bit.


> > Why tpk_write() does not call printk() directly?
> (see above)
> > 
> > If you call printk() directly, the caller_id would be from the process
> > that really wrote the data/message.
> It can be a kernel-code originating message printk-ed on behalf of a user task
> or a kernel-code originating message on behalf of a kernel task. Or it may be a
> user-code originating message on behalf of its task, when printk-ed via
> ttyprintk.

Exactly. Now, I am not sure if you think that this good or bad.

IMHO, it is much better to use caller_id of the process/context that
wrote the data/message instead of the process that caused the final
tpk_close().

Anyway, it is not a big deal. We could leave the code as is if it
works for you. My mine intention was to stop the ideas of per-task
buffers and additional complexity. It was just an idea how to
simplify the code instead.

Best Regards,
Petr

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Samo Pogačnik]

Dne 27.04.2021 (tor) ob 12:08 +0200 je Petr Mladek napisal(a):
> 
> I guess that you mean TPK_PREFIX + "[U] ".
yes

> 
> But you could do this already in tpk_write(). I mean that you could
> parse the given buffer, copy each line to a temporary buffer,
> and call printk(TPK_PREFIX "[U] %s\n", tmp_buf).
> 
> Why is it postponed to tpk_close()?
> 
> IMHO, the printk() in tpk_write() might simplify the logic a bit.
The string received in tpk_write() has no guaranties, that it represents a
complete output line. It has to be treated as a sub-string of a potentially
multi-line massage produced by the userspace code/process. 

The tpk_close() only produces additional output (flush), if the last tpk_write()
string does not end with some end-of-line indication.

> 
> 
> > > 
> > > If you call printk() directly, the caller_id would be from the process
> > > that really wrote the data/message.
> > 
> > It can be a kernel-code originating message printk-ed on behalf of a user
> > task
> > or a kernel-code originating message on behalf of a kernel task. Or it may
> > be a
> > user-code originating message on behalf of its task, when printk-ed via
> > ttyprintk.
> 
> Exactly. Now, I am not sure if you think that this good or bad.
> 
> IMHO, it is much better to use caller_id of the process/context that
> wrote the data/message instead of the process that caused the final
> tpk_close().
> 
IMHO, it is good that output provides info about all the above cases and
especially that particular output is not produced by the kernel code itself.

best regards, samo

Re: [PATCH] ttyprintk: Add TTY hangup callback.

[Jiri Slaby]

On 23. 04. 21, 11:55, Samo Pogačnik wrote:
> Dne 23.04.2021 (pet) ob 06:22 +0200 je Jiri Slaby napisal(a):
>> On 18. 04. 21, 13:16, Samo Pogačnik wrote:
>>> Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
>>>> syzbot is reporting hung task due to flood of
>>>>
>>>>     tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
>>>>              port->count);
>>>>
>>>> message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
>>>> decrementing port->count due to tty_hung_up_p() == true.
>>>>
>>>> ----------
>>>> #include <sys/types.h>
>>>> #include <sys/stat.h>
>>>> #include <fcntl.h>
>>>> #include <sys/ioctl.h>
>>>> #include <unistd.h>
>>>>
>>>> int main(int argc, char *argv[])
>>>> {
>>>> 	int i;
>>>> 	int fd[10];
>>>>
>>>> 	for (i = 0; i < 10; i++)
>>>> 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
>>>> 	ioctl(fd[0], TIOCVHANGUP);
>>>> 	for (i = 0; i < 10; i++)
>>>> 		close(fd[i]);
>>>> 	close(open("/dev/ttyprintk", O_WRONLY));
>>>> 	return 0;
>>>> }
>>>> ----------
>>>>
>>>> When TTY hangup happens, port->count needs to be reset via
>>>> "struct tty_operations"->hangup callback.
>>>>
>>>> [1]
>>>>
> https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
>>>>
>>>> Reported-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com
>>>>>
>>>> Reported-by: syzbot <syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com
>>>>>
>>>> Tested-by: syzbot <syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
>>>> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
>>>> Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
>>>> ---
>>>>    drivers/char/ttyprintk.c | 11 +++++++++++
>>>>    1 file changed, 11 insertions(+)
>>>>
>>>> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
>>>> index 6a0059e508e3..93f5d11c830b 100644
>>>> --- a/drivers/char/ttyprintk.c
>>>> +++ b/drivers/char/ttyprintk.c
>>>> @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
>>>>    	return 0;
>>>>    }
>>>>    
>>>> +/*
>>>> + * TTY operations hangup function.
>>>> + */
>>>> +static void tpk_hangup(struct tty_struct *tty)
>>>> +{
>>>> +	struct ttyprintk_port *tpkp = tty->driver_data;
>>>> +
>>>> +	tty_port_hangup(&tpkp->port);
>>>> +}
>>>> +
>>>>    static const struct tty_operations ttyprintk_ops = {
>>>>    	.open = tpk_open,
>>>>    	.close = tpk_close,
>>>>    	.write = tpk_write,
>>>>    	.write_room = tpk_write_room,
>>>>    	.ioctl = tpk_ioctl,
>>>> +	.hangup = tpk_hangup,
>>>>    };
>>>>    
>>>>    static const struct tty_port_operations null_ops = { };
>>>
>>> Using the supplied test code, i've tested the patch on my desktop running
>>> the
>>> 5.4 kernel. After applying the patch, the kernel warnings like "ttyprintk:
>>> tty_port_close_start: tty->count = 1 port count = 11" do not appear any
>>> more,
>>> when the test code is run.
>>> I think the patch is ok.
>>
>> I wonder if the buffer shouldn't be flushed in hangup too? Or better,
>> the flush moved from tty_ops->close to tty_port->ops->shutdown?
>>
>> thanks,
> 
> Good point. I tried the following additional change, which seems to do the
> trick. What do you think?
> 
> thanks, Samo
> ---
>   drivers/char/ttyprintk.c | 26 ++++++++++++++++++--------
>   1 file changed, 18 insertions(+), 8 deletions(-)
> 
> diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> index 93f5d11c8..420222a92 100644
> --- a/drivers/char/ttyprintk.c
> +++ b/drivers/char/ttyprintk.c
> @@ -100,12 +100,6 @@ static int tpk_open(struct tty_struct *tty, struct file
> *filp)
>   static void tpk_close(struct tty_struct *tty, struct file *filp)
>   {
>   	struct ttyprintk_port *tpkp = tty->driver_data;
> -	unsigned long flags;
> -
> -	spin_lock_irqsave(&tpkp->spinlock, flags);
> -	/* flush tpk_printk buffer */
> -	tpk_printk(NULL, 0);

And now, you can drop NULL buf handling from tpk_printk, right?

> -	spin_unlock_irqrestore(&tpkp->spinlock, flags);
>   
>   	tty_port_close(&tpkp->port, tty, filp);



-- 
js
suse labs

[PATCH] ttyprintk: Add TTY port shutdown callback.

[Samo Pogačnik]

Dne 23.04.2021 (pet) ob 12:28 +0200 je Jiri Slaby napisal(a):
> On 23. 04. 21, 11:55, Samo Pogačnik wrote:
> > Dne 23.04.2021 (pet) ob 06:22 +0200 je Jiri Slaby napisal(a):
> > > On 18. 04. 21, 13:16, Samo Pogačnik wrote:
> > > > Dne 15.04.2021 (čet) ob 09:22 +0900 je Tetsuo Handa napisal(a):
> > > > > syzbot is reporting hung task due to flood of
> > > > > 
> > > > >     tty_warn(tty, "%s: tty->count = 1 port count = %d\n", __func__,
> > > > >              port->count);
> > > > > 
> > > > > message [1], for ioctl(TIOCVHANGUP) prevents tty_port_close() from
> > > > > decrementing port->count due to tty_hung_up_p() == true.
> > > > > 
> > > > > ----------
> > > > > #include <sys/types.h>
> > > > > #include <sys/stat.h>
> > > > > #include <fcntl.h>
> > > > > #include <sys/ioctl.h>
> > > > > #include <unistd.h>
> > > > > 
> > > > > int main(int argc, char *argv[])
> > > > > {
> > > > > 	int i;
> > > > > 	int fd[10];
> > > > > 
> > > > > 	for (i = 0; i < 10; i++)
> > > > > 		fd[i] = open("/dev/ttyprintk", O_WRONLY);
> > > > > 	ioctl(fd[0], TIOCVHANGUP);
> > > > > 	for (i = 0; i < 10; i++)
> > > > > 		close(fd[i]);
> > > > > 	close(open("/dev/ttyprintk", O_WRONLY));
> > > > > 	return 0;
> > > > > }
> > > > > ----------
> > > > > 
> > > > > When TTY hangup happens, port->count needs to be reset via
> > > > > "struct tty_operations"->hangup callback.
> > > > > 
> > > > > [1]
> > > > > 
> > 
> > 
https://syzkaller.appspot.com/bug?id=39ea6caa479af471183997376dc7e90bc7d64a6a
> > > > > 
> > > > > Reported-by: syzbot <
> > > > > syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com
> > > > > > 
> > > > > 
> > > > > Reported-by: syzbot <
> > > > > syzbot+3ed715090790806d8b18@syzkaller.appspotmail.com
> > > > > > 
> > > > > 
> > > > > Tested-by: syzbot <
> > > > > syzbot+43e93968b964e369db0b@syzkaller.appspotmail.com>
> > > > > Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> > > > > Fixes: 24b4b67d17c308aa ("add ttyprintk driver")
> > > > > ---
> > > > >    drivers/char/ttyprintk.c | 11 +++++++++++
> > > > >    1 file changed, 11 insertions(+)
> > > > > 
> > > > > diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> > > > > index 6a0059e508e3..93f5d11c830b 100644
> > > > > --- a/drivers/char/ttyprintk.c
> > > > > +++ b/drivers/char/ttyprintk.c
> > > > > @@ -158,12 +158,23 @@ static int tpk_ioctl(struct tty_struct *tty,
> > > > >    	return 0;
> > > > >    }
> > > > >    
> > > > > +/*
> > > > > + * TTY operations hangup function.
> > > > > + */
> > > > > +static void tpk_hangup(struct tty_struct *tty)
> > > > > +{
> > > > > +	struct ttyprintk_port *tpkp = tty->driver_data;
> > > > > +
> > > > > +	tty_port_hangup(&tpkp->port);
> > > > > +}
> > > > > +
> > > > >    static const struct tty_operations ttyprintk_ops = {
> > > > >    	.open = tpk_open,
> > > > >    	.close = tpk_close,
> > > > >    	.write = tpk_write,
> > > > >    	.write_room = tpk_write_room,
> > > > >    	.ioctl = tpk_ioctl,
> > > > > +	.hangup = tpk_hangup,
> > > > >    };
> > > > >    
> > > > >    static const struct tty_port_operations null_ops = { };
> > > > 
> > > > Using the supplied test code, i've tested the patch on my desktop
> > > > running
> > > > the
> > > > 5.4 kernel. After applying the patch, the kernel warnings like
> > > > "ttyprintk:
> > > > tty_port_close_start: tty->count = 1 port count = 11" do not appear any
> > > > more,
> > > > when the test code is run.
> > > > I think the patch is ok.
> > > 
> > > I wonder if the buffer shouldn't be flushed in hangup too? Or better,
> > > the flush moved from tty_ops->close to tty_port->ops->shutdown?
> > > 
> > > thanks,
> > 
> > Good point. I tried the following additional change, which seems to do the
> > trick. What do you think?
> > 
> > thanks, Samo
> > ---
> >   drivers/char/ttyprintk.c | 26 ++++++++++++++++++--------
> >   1 file changed, 18 insertions(+), 8 deletions(-)
> > 
> > diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
> > index 93f5d11c8..420222a92 100644
> > --- a/drivers/char/ttyprintk.c
> > +++ b/drivers/char/ttyprintk.c
> > @@ -100,12 +100,6 @@ static int tpk_open(struct tty_struct *tty, struct file
> > *filp)
> >   static void tpk_close(struct tty_struct *tty, struct file *filp)
> >   {
> >   	struct ttyprintk_port *tpkp = tty->driver_data;
> > -	unsigned long flags;
> > -
> > -	spin_lock_irqsave(&tpkp->spinlock, flags);
> > -	/* flush tpk_printk buffer */
> > -	tpk_printk(NULL, 0);
> 
> And now, you can drop NULL buf handling from tpk_printk, right?

Exactly!

thanks, Samo

---
 drivers/char/ttyprintk.c | 31 ++++++++++++++++++-------------
 1 file changed, 18 insertions(+), 13 deletions(-)

diff --git a/drivers/char/ttyprintk.c b/drivers/char/ttyprintk.c
index 93f5d11c8..6f616cb7c 100644
--- a/drivers/char/ttyprintk.c
+++ b/drivers/char/ttyprintk.c
@@ -54,11 +54,6 @@ static int tpk_printk(const unsigned char *buf, int count)
 {
 	int i = tpk_curr;
 
-	if (buf == NULL) {
-		tpk_flush();
-		return i;
-	}
-
 	for (i = 0; i < count; i++) {
 		if (tpk_curr >= TPK_STR_SIZE) {
 			/* end of tmp buffer reached: cut the message in two */
@@ -100,12 +95,6 @@ static int tpk_open(struct tty_struct *tty, struct file
*filp)
 static void tpk_close(struct tty_struct *tty, struct file *filp)
 {
 	struct ttyprintk_port *tpkp = tty->driver_data;
-	unsigned long flags;
-
-	spin_lock_irqsave(&tpkp->spinlock, flags);
-	/* flush tpk_printk buffer */
-	tpk_printk(NULL, 0);
-	spin_unlock_irqrestore(&tpkp->spinlock, flags);
 
 	tty_port_close(&tpkp->port, tty, filp);
 }
@@ -168,6 +157,20 @@ static void tpk_hangup(struct tty_struct *tty)
 	tty_port_hangup(&tpkp->port);
 }
 
+/*
+ * TTY port operations shutdown function.
+ */
+static void tpk_port_shutdown(struct tty_port *tport)
+{
+	struct ttyprintk_port *tpkp =
+		container_of(tport, struct ttyprintk_port, port);
+	unsigned long flags;
+
+	spin_lock_irqsave(&tpkp->spinlock, flags);
+	tpk_flush();
+	spin_unlock_irqrestore(&tpkp->spinlock, flags);
+}
+
 static const struct tty_operations ttyprintk_ops = {
 	.open = tpk_open,
 	.close = tpk_close,
@@ -177,7 +180,9 @@ static const struct tty_operations ttyprintk_ops = {
 	.hangup = tpk_hangup,
 };
 
-static const struct tty_port_operations null_ops = { };
+static const struct tty_port_operations tpk_port_ops = {
+	.shutdown = tpk_port_shutdown,
+};
 
 static struct tty_driver *ttyprintk_driver;
 
@@ -195,7 +200,7 @@ static int __init ttyprintk_init(void)
 		return PTR_ERR(ttyprintk_driver);
 
 	tty_port_init(&tpk_port.port);
-	tpk_port.port.ops = &null_ops;
+	tpk_port.port.ops = &tpk_port_ops;
 
 	ttyprintk_driver->driver_name = "ttyprintk";
 	ttyprintk_driver->name = "ttyprintk";
-- 
2.17.1

Re: How to handle concurrent access to /dev/ttyprintk ?

[Samo Pogačnik]

Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> What is the intended usage of /dev/ttyprintk ?
> 

The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
via the TIOCCONS ioctl. After successfull redirection, all console
messages get "merged" with kernel messages and as such automatically processed
(stored/transferred) by the syslog service for example.

best regards, Samo

Re: How to handle concurrent access to /dev/ttyprintk ?

[Petr Mladek]

On Mon 2021-04-12 14:41:27, Samo Pogačnik wrote:
> Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> > What is the intended usage of /dev/ttyprintk ?
> > 
> 
> The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
> via the TIOCCONS ioctl. After successfull redirection, all console
> messages get "merged" with kernel messages and as such automatically processed
> (stored/transferred) by the syslog service for example.

The same can be achieved by /dev/kmsg that was created by systemd
developers.

systemd is able to flood the kernel buffer and consoles.
It can be protected by ratelimiting, see the commit
750afe7babd117daabebf ("printk: add kernel parameter
to control writes to /dev/kmsg").

/dev/kmsg ratelimit is a "must-to-have". systemd enables debug
messages using the same "debug" parameter passed on the kernel
commandline. The ratelimit allows to see the kernel messages.

Note that the ratelimit is enabled by default by kernel. But it
it disabled by default by systemd. So, it is effectively disabled
by default.

It might be possible to add retalimiting also for /dev/ttyprintk.
But does it make sense just because of an artifical test case?


History:

/dev/ttyprintk has been added in v2.6.37 (2010)  by commit 24b4b67d17c308aaa956b
("add ttyprintk driver")

/dev/kmsg has been add in v3.5-rc1 (2012) by commit e11fea92e13fb91c50ba
("kmsg: export printk records to the /dev/kmsg interface")

Another solution might be to obsolete /dev/ttyprintk by /dev/kmsg.
We have to preserve /dev/kmsg because of systemd.
Is anyone really using /dev/ttyprintk these days?

Best Regards,
Petr

Re: How to handle concurrent access to /dev/ttyprintk ?

[Samo Pogačnik]

Dne 13.04.2021 (tor) ob 11:41 +0200 je Petr Mladek napisal(a):
> On Mon 2021-04-12 14:41:27, Samo Pogačnik wrote:
> > Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> > > What is the intended usage of /dev/ttyprintk ?
> > > 
> > 
> > The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
> > via the TIOCCONS ioctl. After successfull redirection, all console
> > messages get "merged" with kernel messages and as such automatically
> > processed
> > (stored/transferred) by the syslog service for example.
> 
> The same can be achieved by /dev/kmsg that was created by systemd
> developers.
> 
'kmsg' and 'ttyprintk' are different types of drivers and as such rather
complementary than exclusive. The 'ttyprintk' being a tty driver allows 
for a system wide automatic redirection of anything written to the console.
On the other hand 'kmsg' is probably better suited for a per process
output redirection/injection of its output into kernel messages.

Maybe i am wrong, but 'systemd' could also find 'ttyprintk' usefull?

best regards, Samo

Re: How to handle concurrent access to /dev/ttyprintk ?

[Petr Mladek]

On Tue 2021-04-13 13:10:50, Samo Pogačnik wrote:
> Dne 13.04.2021 (tor) ob 11:41 +0200 je Petr Mladek napisal(a):
> > On Mon 2021-04-12 14:41:27, Samo Pogačnik wrote:
> > > Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> > > > What is the intended usage of /dev/ttyprintk ?
> > > > 
> > > 
> > > The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
> > > via the TIOCCONS ioctl. After successfull redirection, all console
> > > messages get "merged" with kernel messages and as such automatically
> > > processed
> > > (stored/transferred) by the syslog service for example.
> > 
> > The same can be achieved by /dev/kmsg that was created by systemd
> > developers.
> > 
> 'kmsg' and 'ttyprintk' are different types of drivers and as such rather
> complementary than exclusive. The 'ttyprintk' being a tty driver allows 
> for a system wide automatic redirection of anything written to the
> console.

I might miss something. But how can one setup ttyprintk as the system
wide console? I do not see any code that would use ttyprintk
in struct console.

Or am I too focused on the printk/kernel-side of view?

> On the other hand 'kmsg' is probably better suited for a per process
> output redirection/injection of its output into kernel messages.

> Maybe i am wrong, but 'systemd' could also find 'ttyprintk' usefull?

/dev/kmsg allows both read and write from/to the kernel log buffer.

The write callback allows to pass a certain loglevel from the
user space in the format "<level>message"

The read callback passes a lot of meta information in the format
"<level>,<sequnum>,<timestamp>,<contflag>[,additional_values,
... ];<message text>\n"

IMHO, /dev/kmsg provides a super set of functionality
over /dev/ttyprintk. But I am not familiar with the tty layer
and all its use-cases.

To make it clear. I do not resist on removing ttyprintk by any means.
It was just an idea. I am not even sure if it is possible to obsolete
tty drivers.

Best Regards,
Petr

Re: How to handle concurrent access to /dev/ttyprintk ?

[Samo Pogačnik]

Dne 13.04.2021 (tor) ob 16:32 +0200 je Petr Mladek napisal(a):
> On Tue 2021-04-13 13:10:50, Samo Pogačnik wrote:
> > Dne 13.04.2021 (tor) ob 11:41 +0200 je Petr Mladek napisal(a):
> > > On Mon 2021-04-12 14:41:27, Samo Pogačnik wrote:
> > > > Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> > > > > What is the intended usage of /dev/ttyprintk ?
> > > > > 
> > > > 
> > > > The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
> > > > via the TIOCCONS ioctl. After successfull redirection, all console
> > > > messages get "merged" with kernel messages and as such automatically
> > > > processed
> > > > (stored/transferred) by the syslog service for example.
> > > 
> > > The same can be achieved by /dev/kmsg that was created by systemd
> > > developers.
> > > 
> > 
> > 'kmsg' and 'ttyprintk' are different types of drivers and as such rather
> > complementary than exclusive. The 'ttyprintk' being a tty driver allows 
> > for a system wide automatic redirection of anything written to the
> > console.
> 
> I might miss something. But how can one setup ttyprintk as the system
> wide console? I do not see any code that would use ttyprintk
> in struct console.
> 

You can compile this simple code below and call:

# ./tioccons /dev/ttyprintk

... from now on all console output interleaves the kernel log  (you can check
dmesg or logs)

# ./tioccons /dev/console

... sets things back they were.

You will be able to recognize console messages by preceding "[U]" tag (meaning
User).

-------------------
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <errno.h>
#include <fcntl.h>
#include <sys/ioctl.h>

int main(int argc, char **argv)
{
	int fd;

	if (argc != 2) {
		printf("Wrong usage!\n");
		exit(1);
	}

	if ((fd = open(argv[1], O_WRONLY)) == -1) {
		perror(argv[1]);
		exit(1);
	}

	if (ioctl(fd, TIOCCONS, NULL) == -1) {
		printf("ioctl: %s\n", strerror(errno));
		exit(1);
	}

	exit(0);
}
--------------------

best regards, Samo

Re: How to handle concurrent access to /dev/ttyprintk ?

[Petr Mladek]

On Tue 2021-04-13 17:22:46, Samo Pogačnik wrote:
> Dne 13.04.2021 (tor) ob 16:32 +0200 je Petr Mladek napisal(a):
> > On Tue 2021-04-13 13:10:50, Samo Pogačnik wrote:
> > > Dne 13.04.2021 (tor) ob 11:41 +0200 je Petr Mladek napisal(a):
> > > > On Mon 2021-04-12 14:41:27, Samo Pogačnik wrote:
> > > > > Dne 12.04.2021 (pon) ob 19:39 +0900 je Tetsuo Handa napisal(a):
> > > > > > What is the intended usage of /dev/ttyprintk ?
> > > > > > 
> > > > > 
> > > > > The intended use of 'ttyprintk' is to redirect console to /dev/ttyprintk
> > > > > via the TIOCCONS ioctl. After successfull redirection, all console
> > > > > messages get "merged" with kernel messages and as such automatically
> > > > > processed
> > > > > (stored/transferred) by the syslog service for example.
> > > > 
> > > > The same can be achieved by /dev/kmsg that was created by systemd
> > > > developers.
> > > > 
> > > 
> > > 'kmsg' and 'ttyprintk' are different types of drivers and as such rather
> > > complementary than exclusive. The 'ttyprintk' being a tty driver allows 
> > > for a system wide automatic redirection of anything written to the
> > > console.
> > 
> > I might miss something. But how can one setup ttyprintk as the system
> > wide console? I do not see any code that would use ttyprintk
> > in struct console.
> > 
> 
> You can compile this simple code below and call:
> 
> # ./tioccons /dev/ttyprintk

Thanks a lot for the example.

My head is still spinning around it. I have troubles to update
my mental model around /dev/console with this use case.

My original model is that kernel or processes write into
/dev/console so that a human could see and read it
on the device attached to the console.

kernel is calling console->write() callback when showing new messages
on consoles. The write to the redirected /dev/console
makes the messages appear in the kernel log. It feels like
it should create an infinite loop. Except that it doesn't
work this way. Sigh.

Best Regards,
Petr