Re: WARNING: locking bug in tomoyo_supervisor

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