WARNING: locking bug in tomoyo_supervisor

WARNING: locking bug in tomoyo_supervisor

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    4f8a3cc1 Merge tag 'x86-urgent-2020-04-12' of git://git.ke..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=1599027de00000
kernel config:  https://syzkaller.appspot.com/x/.config?x=3bfbde87e8e65624
dashboard link: https://syzkaller.appspot.com/bug?extid=1c36440b364ea3774701
compiler:       clang version 10.0.0 (https://github.com/llvm/llvm-project/ c2443155a0fb245c8f17f2c1c72b6ea391e86e81)
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=150733cde00000

Bisection is inconclusive: the first bad commit could be any of:

9211bfbf netfilter: add missing IS_ENABLED(CONFIG_BRIDGE_NETFILTER) checks to header-file.
47e640af netfilter: add missing IS_ENABLED(CONFIG_NF_TABLES) check to header-file.
a1b2f04e netfilter: add missing includes to a number of header-files.
0abc8bf4 netfilter: add missing IS_ENABLED(CONFIG_NF_CONNTRACK) checks to some header-files.
bd96b4c7 netfilter: inline four headers files into another one.
43dd16ef netfilter: nf_tables: store data in offload context registers
78458e3e netfilter: add missing IS_ENABLED(CONFIG_NETFILTER) checks to some header-files.
20a9379d netfilter: remove "#ifdef __KERNEL__" guards from some headers.
bd8699e9 netfilter: nft_bitwise: add offload support
2a475c40 kbuild: remove all netfilter headers from header-test blacklist.
7e59b3fe netfilter: remove unnecessary spaces
1b90af29 ipvs: Improve robustness to the ipvs sysctl
5785cf15 netfilter: nf_tables: add missing prototypes.
0a30ba50 netfilter: nf_nat_proto: make tables static
e84fb4b3 netfilter: conntrack: use shared sysctl constants
10533343 netfilter: connlabels: prefer static lock initialiser
8c0bb787 netfilter: synproxy: rename mss synproxy_options field
c162610c Merge git://git.kernel.org/pub/scm/linux/kernel/git/pablo/nf-next

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=10aacf5de00000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+1c36440b364ea3774701@syzkaller.appspotmail.com

------------[ cut here ]------------
WARNING: CPU: 1 PID: 8602 at kernel/locking/lockdep.c:873 look_up_lock_class+0x207/0x280 kernel/locking/lockdep.c:863
Kernel panic - not syncing: panic_on_warn set ...
CPU: 1 PID: 8602 Comm: syz-executor.5 Not tainted 5.6.0-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1e9/0x30e lib/dump_stack.c:118
 panic+0x264/0x7a0 kernel/panic.c:221
 __warn+0x102/0x210 kernel/panic.c:574
 look_up_lock_class+0x207/0x280 kernel/locking/lockdep.c:863
 __warn+0x209/0x210 kernel/panic.c:582
 look_up_lock_class+0x207/0x280 kernel/locking/lockdep.c:863
 report_bug+0x1ac/0x2d0 lib/bug.c:195
 fixup_bug arch/x86/kernel/traps.c:175 [inline]
 do_error_trap+0xca/0x1c0 arch/x86/kernel/traps.c:267
 do_invalid_op+0x32/0x40 arch/x86/kernel/traps.c:286
 look_up_lock_class+0x207/0x280 kernel/locking/lockdep.c:863
 invalid_op+0x23/0x30 arch/x86/entry/entry_64.S:1027
RIP: 0010:look_up_lock_class+0x207/0x280 kernel/locking/lockdep.c:863
Code: 3d 91 8c 12 08 00 0f 85 35 ff ff ff 31 db 48 c7 c7 19 59 e5 88 48 c7 c6 03 ea e6 88 31 c0 e8 10 18 ec ff 0f 0b e9 7b ff ff ff <0f> 0b e9 74 ff ff ff 48 c7 c1 30 4d 55 8b 80 e1 07 80 c1 03 38 c1
RSP: 0018:ffffc90006017a98 EFLAGS: 00010002
RAX: ffffffff8ab05460 RBX: ffffffff8ad678f8 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff888096695860
RBP: ffff888096695878 R08: 0000000000000001 R09: 0000000000000000
R10: fffffbfff12d7735 R11: 0000000000000000 R12: 1ffff11012cd2b0c
R13: ffffffff89063ea9 R14: ffff888096695860 R15: dffffc0000000000
 register_lock_class+0x97/0x10d0 kernel/locking/lockdep.c:1220
 tomoyo_supervisor+0x13d/0x1310 security/tomoyo/common.c:2076
 __lock_acquire+0x102/0x2c30 kernel/locking/lockdep.c:4234
 rcu_lock_release+0x5/0x20 include/linux/rcupdate.h:212
 srcu_read_unlock include/linux/srcu.h:181 [inline]
 tomoyo_read_unlock security/tomoyo/common.h:1123 [inline]
 tomoyo_inet_entry security/tomoyo/network.c:487 [inline]
 tomoyo_check_inet_address+0x661/0x8e0 security/tomoyo/network.c:532
 lock_acquire+0x169/0x480 kernel/locking/lockdep.c:4934
 spin_lock_bh include/linux/spinlock.h:358 [inline]
 lock_sock_nested+0x43/0x110 net/core/sock.c:2959


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
For information about bisection process see: https://goo.gl/tpsmEJ#bisection
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

Re: WARNING: locking bug in tomoyo_supervisor

[Tetsuo Handa]

On 2020/04/17 7:05, syzbot wrote:
> Hello,
> 
> syzbot found the following crash on:
> 
> HEAD commit:    4f8a3cc1 Merge tag 'x86-urgent-2020-04-12' of git://git.ke..
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=1599027de00000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=3bfbde87e8e65624
> dashboard link: https://syzkaller.appspot.com/bug?extid=1c36440b364ea3774701
> compiler:       clang version 10.0.0 (https://github.com/llvm/llvm-project/ c2443155a0fb245c8f17f2c1c72b6ea391e86e81)
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=150733cde00000

This seems to be a misattributed report explained at https://lkml.kernel.org/r/20190924140241.be77u2jne3melzte@pathway.suse.cz .
Petr and Sergey, how is the progress of making printk() asynchronous? When can we expect that work to be merged?
If it is delaying, can we implement storing these metadata into the per-CPU buffers?

Anyway,

> bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=10aacf5de00000

bisection log says this will be a duplicate of

#syz dup: WARNING: locking bug in inet_autobind

. This misattribution by chance served as a reminder for "locking bug in inet_autobind" bug. ;-)

According to https://syzkaller.appspot.com/bug?id=a7d678fba80c34b5770cc1b5638b8a2709ae9f3f ,
this bug is happening on "2020/04/01 19:28", "2020/04/09 06:24" and "2020/04/10 20:48"
which are after the opening of the merge window for 5.7-rc1. Reproducer suggests that
pppl2tp and inet6_udp are relevant.

Re: WARNING: locking bug in tomoyo_supervisor

[Sergey Senozhatsky]

On (20/04/17 13:37), Tetsuo Handa wrote:
> On 2020/04/17 7:05, syzbot wrote:
> > Hello,
> > 
> > syzbot found the following crash on:
> > 
> > HEAD commit:    4f8a3cc1 Merge tag 'x86-urgent-2020-04-12' of git://git.ke..
> > git tree:       upstream
> > console output: https://syzkaller.appspot.com/x/log.txt?x=1599027de00000
> > kernel config:  https://syzkaller.appspot.com/x/.config?x=3bfbde87e8e65624
> > dashboard link: https://syzkaller.appspot.com/bug?extid=1c36440b364ea3774701
> > compiler:       clang version 10.0.0 (https://github.com/llvm/llvm-project/ c2443155a0fb245c8f17f2c1c72b6ea391e86e81)
> > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=150733cde00000
> 
> This seems to be a misattributed report explained at https://lkml.kernel.org/r/20190924140241.be77u2jne3melzte@pathway.suse.cz .
> Petr and Sergey, how is the progress of making printk() asynchronous? When can we expect that work to be merged?

I'd say that lockless logbuf probably will land sometime around 5.8+.
Async printk() - unknown.

	-ss

Re: WARNING: locking bug in tomoyo_supervisor

[Tetsuo Handa]

On 2020/04/23 10:50, Sergey Senozhatsky wrote:
> On (20/04/17 13:37), Tetsuo Handa wrote:
>> On 2020/04/17 7:05, syzbot wrote:
>>> Hello,
>>>
>>> syzbot found the following crash on:
>>>
>>> HEAD commit:    4f8a3cc1 Merge tag 'x86-urgent-2020-04-12' of git://git.ke..
>>> git tree:       upstream
>>> console output: https://syzkaller.appspot.com/x/log.txt?x=1599027de00000
>>> kernel config:  https://syzkaller.appspot.com/x/.config?x=3bfbde87e8e65624
>>> dashboard link: https://syzkaller.appspot.com/bug?extid=1c36440b364ea3774701
>>> compiler:       clang version 10.0.0 (https://github.com/llvm/llvm-project/ c2443155a0fb245c8f17f2c1c72b6ea391e86e81)
>>> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=150733cde00000
>>
>> This seems to be a misattributed report explained at https://lkml.kernel.org/r/20190924140241.be77u2jne3melzte@pathway.suse.cz .
>> Petr and Sergey, how is the progress of making printk() asynchronous? When can we expect that work to be merged?
> 
> I'd say that lockless logbuf probably will land sometime around 5.8+.
> Async printk() - unknown.

I see. Thank you. I've just made a patch for

  A solution would be to store all these metadata (timestamp, caller
  info) already into the per-CPU buffers. I think that it would be
  doable.

part (shown below). Should I propose it? Or, should I just wait for lockless logbuf ?

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index b2b0f526f249..3e7b302d41e8 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -52,6 +52,22 @@ bool printk_percpu_data_ready(void);
 
 void defer_console_output(void);
 
+struct printk_msg {
+	u64 ts_nsec;	/* timestamp in nanoseconds */
+	u32 caller_id;	/* thread id or processor id */
+	u16 len;	/* length of entire record */
+	u16 text_len;	/* length of text buffer */
+	u16 dict_len;	/* length of dictionary buffer */
+	u8 facility;	/* syslog facility */
+	u8 flags;	/* internal record flags */
+	int level;	/* syslog level (maybe LOGLEVEL_DEFAULT upon init) */
+};
+
+void printk_msg_init(struct printk_msg *msg, const u8 facility, const int level,
+		     const u8 flags, const u16 dict_len, const u16 text_len);
+int printk_msg_store(struct printk_msg *msg, const char *text, const char *dict,
+		     const bool logbuf_locked);
+
 #else
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9a9b6156270b..6be45a59d3aa 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -613,12 +613,16 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
 }
 
 /* insert record into the buffer, discard old ones, update heads */
-static int log_store(u32 caller_id, int facility, int level,
-		     enum log_flags flags, u64 ts_nsec,
-		     const char *dict, u16 dict_len,
-		     const char *text, u16 text_len)
-{
-	struct printk_log *msg;
+static int log_store(const struct printk_msg *msg, const char *text, const char *dict)
+{
+	const u32 caller_id = msg->caller_id;
+	const int facility = msg->facility;
+	const int level = msg->level;
+	const enum log_flags flags = msg->flags;
+	const u64 ts_nsec = msg->ts_nsec;
+	u16 dict_len = msg->dict_len;
+	u16 text_len = msg->text_len;
+	struct printk_log *log;
 	u32 size, pad_len;
 	u16 trunc_msg_len = 0;
 
@@ -645,33 +649,30 @@ static int log_store(u32 caller_id, int facility, int level,
 	}
 
 	/* fill message */
-	msg = (struct printk_log *)(log_buf + log_next_idx);
-	memcpy(log_text(msg), text, text_len);
-	msg->text_len = text_len;
+	log = (struct printk_log *)(log_buf + log_next_idx);
+	memcpy(log_text(log), text, text_len);
+	log->text_len = text_len;
 	if (trunc_msg_len) {
-		memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
-		msg->text_len += trunc_msg_len;
-	}
-	memcpy(log_dict(msg), dict, dict_len);
-	msg->dict_len = dict_len;
-	msg->facility = facility;
-	msg->level = level & 7;
-	msg->flags = flags & 0x1f;
-	if (ts_nsec > 0)
-		msg->ts_nsec = ts_nsec;
-	else
-		msg->ts_nsec = local_clock();
+		memcpy(log_text(log) + text_len, trunc_msg, trunc_msg_len);
+		log->text_len += trunc_msg_len;
+	}
+	memcpy(log_dict(log), dict, dict_len);
+	log->dict_len = dict_len;
+	log->facility = facility;
+	log->level = level & 7;
+	log->flags = flags & 0x1f;
+	log->ts_nsec = ts_nsec;
 #ifdef CONFIG_PRINTK_CALLER
-	msg->caller_id = caller_id;
+	log->caller_id = caller_id;
 #endif
-	memset(log_dict(msg) + dict_len, 0, pad_len);
-	msg->len = size;
+	memset(log_dict(log) + dict_len, 0, pad_len);
+	log->len = size;
 
 	/* insert message */
-	log_next_idx += msg->len;
+	log_next_idx += log->len;
 	log_next_seq++;
 
-	return msg->text_len;
+	return log->text_len;
 }
 
 int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT);
@@ -1837,109 +1838,111 @@ static inline u32 printk_caller_id(void)
 		0x80000000 + raw_smp_processor_id();
 }
 
+void printk_msg_init(struct printk_msg *msg, const u8 facility, const int level,
+		     const u8 flags, const u16 dict_len, const u16 text_len)
+{
+	memset(msg, 0, sizeof(*msg));
+#ifdef CONFIG_PRINTK_CALLER
+	msg->caller_id = printk_caller_id();
+#endif
+	msg->facility = facility;
+	msg->level = level;
+	msg->flags = flags;
+	msg->ts_nsec = local_clock();
+	msg->dict_len = dict_len;
+	msg->text_len = text_len;
+}
+
 /*
  * Continuation lines are buffered, and not committed to the record buffer
  * until the line is complete, or a race forces it. The line fragments
  * though, are printed immediately to the consoles to ensure everything has
  * reached the console in case of a kernel crash.
+ *
+ * .text_len == 0 means unused buffer.
+ * .caller_id is printk_caller_id() of first print.
+ * .ts_nsec is time of first print.
+ * .level is log level of first message.
+ * .facility is log facility of first message.
+ * .flags is prefix, newline flags
  */
-static struct cont {
-	char buf[LOG_LINE_MAX];
-	size_t len;			/* length == 0 means unused buffer */
-	u32 caller_id;			/* printk_caller_id() of first print */
-	u64 ts_nsec;			/* time of first print */
-	u8 level;			/* log level of first message */
-	u8 facility;			/* log facility of first message */
-	enum log_flags flags;		/* prefix, newline flags */
-} cont;
+static struct printk_msg cont_msg;
+static char cont_buf[LOG_LINE_MAX];
 
 static void cont_flush(void)
 {
-	if (cont.len == 0)
+	if (cont_msg.text_len == 0)
 		return;
-
-	log_store(cont.caller_id, cont.facility, cont.level, cont.flags,
-		  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-	cont.len = 0;
+	log_store(&cont_msg, cont_buf, NULL);
+	cont_msg.text_len = 0;
 }
 
-static bool cont_add(u32 caller_id, int facility, int level,
-		     enum log_flags flags, const char *text, size_t len)
+static bool cont_add(const struct printk_msg *msg, const char *text)
 {
 	/* If the line gets too long, split it up in separate records. */
-	if (cont.len + len > sizeof(cont.buf)) {
+	if (cont_msg.text_len + msg->text_len > sizeof(cont_buf)) {
 		cont_flush();
 		return false;
 	}
 
-	if (!cont.len) {
-		cont.facility = facility;
-		cont.level = level;
-		cont.caller_id = caller_id;
-		cont.ts_nsec = local_clock();
-		cont.flags = flags;
-	}
+	if (!cont_msg.text_len)
+		printk_msg_init(&cont_msg, msg->facility, msg->level,
+				msg->flags, 0, 0);
 
-	memcpy(cont.buf + cont.len, text, len);
-	cont.len += len;
+	memcpy(cont_buf + cont_msg.text_len, text, msg->text_len);
+	cont_msg.text_len += msg->text_len;
 
 	// The original flags come from the first line,
 	// but later continuations can add a newline.
-	if (flags & LOG_NEWLINE) {
-		cont.flags |= LOG_NEWLINE;
+	if (msg->flags & LOG_NEWLINE) {
+		cont_msg.flags |= LOG_NEWLINE;
 		cont_flush();
 	}
 
 	return true;
 }
 
-static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
-{
-	const u32 caller_id = printk_caller_id();
 
+static size_t log_output(struct printk_msg *msg, const char *text,
+			 const char *dict)
+{
 	/*
 	 * If an earlier line was buffered, and we're a continuation
 	 * write from the same context, try to add it to the buffer.
 	 */
-	if (cont.len) {
-		if (cont.caller_id == caller_id && (lflags & LOG_CONT)) {
-			if (cont_add(caller_id, facility, level, lflags, text, text_len))
-				return text_len;
+	if (cont_msg.text_len) {
+		if (cont_msg.caller_id == msg->caller_id &&
+		    (msg->flags & LOG_CONT)) {
+			if (cont_add(msg, text))
+				return msg->text_len;
 		}
 		/* Otherwise, make sure it's flushed */
 		cont_flush();
 	}
 
 	/* Skip empty continuation lines that couldn't be added - they just flush */
-	if (!text_len && (lflags & LOG_CONT))
+	if (!msg->text_len && (msg->flags & LOG_CONT))
 		return 0;
 
 	/* If it doesn't end in a newline, try to buffer the current line */
-	if (!(lflags & LOG_NEWLINE)) {
-		if (cont_add(caller_id, facility, level, lflags, text, text_len))
-			return text_len;
+	if (!(msg->flags & LOG_NEWLINE)) {
+		if (cont_add(msg, text))
+			return msg->text_len;
 	}
 
 	/* Store it in the record log */
-	return log_store(caller_id, facility, level, lflags, 0,
-			 dict, dictlen, text, text_len);
+	return log_store(msg, text, dict);
 }
 
-/* Must be called under logbuf_lock. */
-int vprintk_store(int facility, int level,
-		  const char *dict, size_t dictlen,
-		  const char *fmt, va_list args)
+int printk_msg_store(struct printk_msg *msg, const char *text, const char *dict,
+		     const bool logbuf_locked)
 {
-	static char textbuf[LOG_LINE_MAX];
-	char *text = textbuf;
-	size_t text_len;
-	enum log_flags lflags = 0;
-
-	/*
-	 * The printf needs to come first; we need the syslog
-	 * prefix which might be passed-in as a parameter.
-	 */
-	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+	unsigned long flags;
+	size_t ret;
+	const int facility = msg->facility;
+	int level = msg->level;
+	size_t text_len = msg->text_len;
+	enum log_flags lflags = msg->flags;
 
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
@@ -1972,8 +1975,32 @@ int vprintk_store(int facility, int level,
 	if (dict)
 		lflags |= LOG_NEWLINE;
 
-	return log_output(facility, level, lflags,
-			  dict, dictlen, text, text_len);
+	msg->flags = lflags;
+	msg->text_len = text_len;
+	msg->level = level;
+	if (!logbuf_locked)
+		logbuf_lock_irqsave(flags);
+	ret = log_output(msg, text, dict);
+	if (!logbuf_locked)
+		logbuf_unlock_irqrestore(flags);
+	return ret;
+}
+
+/* Must be called under logbuf_lock. */
+int vprintk_store(int facility, int level,
+		  const char *dict, size_t dictlen,
+		  const char *fmt, va_list args)
+{
+	static struct printk_msg msg;
+	static char textbuf[LOG_LINE_MAX];
+	/*
+	 * The printf needs to come first; we need the syslog
+	 * prefix which might be passed-in as a parameter.
+	 */
+	size_t text_len = vscnprintf(textbuf, sizeof(textbuf), fmt, args);
+
+	printk_msg_init(&msg, facility, level, 0, dictlen, text_len);
+	return printk_msg_store(&msg, textbuf, dict, true);
 }
 
 asmlinkage int vprintk_emit(int facility, int level,
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index d9a659a686f3..009a9c6892bc 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -67,6 +67,7 @@ static void queue_flush_work(struct printk_safe_seq_buf *s)
 static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
 						const char *fmt, va_list args)
 {
+	struct printk_msg *msg;
 	int add;
 	size_t len;
 	va_list ap;
@@ -89,10 +90,13 @@ static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
 		smp_rmb();
 
 	va_copy(ap, args);
-	add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, ap);
+	add = vscnprintf(s->buffer + len + sizeof(*msg), sizeof(s->buffer) - len - sizeof(*msg), fmt, ap);
 	va_end(ap);
 	if (!add)
 		return 0;
+	msg = (struct printk_msg *) (s->buffer + len);
+	printk_msg_init(msg, 0, LOGLEVEL_DEFAULT, 0, 0, add);
+	add += sizeof(*msg);
 
 	/*
 	 * Do it once again if the buffer has been flushed in the meantime.
@@ -117,51 +121,21 @@ static inline void printk_safe_flush_line(const char *text, int len)
 	printk_deferred("%.*s", len, text);
 }
 
-/* printk part of the temporary buffer line by line */
+/* printk part of the temporary buffer record by record */
 static int printk_safe_flush_buffer(const char *start, size_t len)
 {
-	const char *c, *end;
-	bool header;
+	const char *c = start;
+	const char *end = start + len;
+	struct printk_msg *msg;
 
-	c = start;
-	end = start + len;
-	header = true;
-
-	/* Print line by line. */
 	while (c < end) {
-		if (*c == '\n') {
-			printk_safe_flush_line(start, c - start + 1);
-			start = ++c;
-			header = true;
-			continue;
-		}
-
-		/* Handle continuous lines or missing new line. */
-		if ((c + 1 < end) && printk_get_level(c)) {
-			if (header) {
-				c = printk_skip_level(c);
-				continue;
-			}
-
-			printk_safe_flush_line(start, c - start);
-			start = c++;
-			header = true;
-			continue;
-		}
-
-		header = false;
-		c++;
+		msg = (struct printk_msg *) c;
+		/* printk_msg_store() updates msg->text_len. */
+		len = READ_ONCE(msg->text_len);
+		printk_msg_store(msg, c + sizeof(*msg), NULL, false);
+		c += sizeof(*msg) + len;
 	}
-
-	/* Check if there was a partial line. Ignore pure header. */
-	if (start < end && !header) {
-		static const char newline[] = KERN_CONT "\n";
-
-		printk_safe_flush_line(start, end - start);
-		printk_safe_flush_line(newline, strlen(newline));
-	}
-
-	return len;
+	return end - start;
 }
 
 static void report_message_lost(struct printk_safe_seq_buf *s)
@@ -231,6 +205,7 @@ static void __printk_safe_flush(struct irq_work *work)
 out:
 	report_message_lost(s);
 	raw_spin_unlock_irqrestore(&read_lock, flags);
+	defer_console_output();
 }
 
 /**

Re: WARNING: locking bug in tomoyo_supervisor

[Sergey Senozhatsky]

On (20/04/23 10:57), Tetsuo Handa wrote:
> On 2020/04/23 10:50, Sergey Senozhatsky wrote:
> > On (20/04/17 13:37), Tetsuo Handa wrote:
> >> On 2020/04/17 7:05, syzbot wrote:
> >>> Hello,
> >>>
> >>> syzbot found the following crash on:
> >>>
> >>> HEAD commit:    4f8a3cc1 Merge tag 'x86-urgent-2020-04-12' of git://git.ke..
> >>> git tree:       upstream
> >>> console output: https://syzkaller.appspot.com/x/log.txt?x=1599027de00000
> >>> kernel config:  https://syzkaller.appspot.com/x/.config?x=3bfbde87e8e65624
> >>> dashboard link: https://syzkaller.appspot.com/bug?extid=1c36440b364ea3774701
> >>> compiler:       clang version 10.0.0 (https://github.com/llvm/llvm-project/ c2443155a0fb245c8f17f2c1c72b6ea391e86e81)
> >>> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=150733cde00000
> >>
> >> This seems to be a misattributed report explained at https://lkml.kernel.org/r/20190924140241.be77u2jne3melzte@pathway.suse.cz .
> >> Petr and Sergey, how is the progress of making printk() asynchronous? When can we expect that work to be merged?
> > 
> > I'd say that lockless logbuf probably will land sometime around 5.8+.
> > Async printk() - unknown.
> 
> I see. Thank you. I've just made a patch for
> 
>   A solution would be to store all these metadata (timestamp, caller
>   info) already into the per-CPU buffers. I think that it would be
>   doable.
> 
> part (shown below). Should I propose it? Or, should I just wait for lockless logbuf ?

I think this will be doable with a mix of the lockless buffer and per-CPU
printk context variable. We can store all printk data into the lockless
buffer, but need to avoid calling up()/down()/console_drivers() if per-CPU
printk context is non zero (the existinf printk_safe/printk_nmi enter/exit
functions will help). So I think waiting for lockless printk buffer would
be a better option, effort-wise.

	-ss