* Re: WARNING: locking bug in tomoyo_supervisor
2020-04-23 1:50 ` Sergey Senozhatsky
@ 2020-04-23 1:57 ` Tetsuo Handa
2020-04-23 2:58 ` Sergey Senozhatsky
0 siblings, 1 reply; 4+ messages in thread
From: Tetsuo Handa @ 2020-04-23 1:57 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: syzbot, linux-kernel, syzkaller-bugs, Network Development,
James Chapman, Petr Mladek
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();
}
/**
^ permalink raw reply related [flat|nested] 4+ messages in thread