Re: printk: what is going on with additional newlines?

[Sergey Senozhatsky <sergey.senozhatsky@gmail.com>]

On (08/29/17 21:10), Steven Rostedt wrote:
[..]
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

so I quickly cooked the first version. like really quickly. just to
check if this is what people might like/use.

RFC.

so wondering if this will suffice. the name is somewhat hideous -- prbuf(),
wanted to keep it short and somehow aligned with pr_foo().

the patch also defines a number of prbuf_err()/prbuf_cont() macros that
call __prbuf_write() -- I don't want people to invoke __prbuf_write()
directly, because we need KERN_FOO prefix for stored messages and people
tend to forget to provide one.

prbuf_init() function inits the seq_buf buffer. it takes size and GFP
mask, just to permit prbuf usage from different contexts. if we fail
to kmalloc() the buffer, then __prbuf_write() does direct printk().

a usage example:


       struct seq_buf s;

       prbuf_init(&s, 256, GFP_KERNEL);

       prbuf_err(&s, "Opps at %lu\n", _RET_IP_);
       prbuf_info(&s, "Start of cont line");
       prbuf_cont(&s, " foo ");
       prbuf_cont(&s, " bar ");
       prbuf_cont(&s, " status: %s\n", "done");

       ret = 0;
       while (ret++ < 10)
               prbuf_err(&s, "%x\n", ret);

       prbuf_flush(&s);
       prbuf_free(&s);


this will store everything in conseq logbuf entries. if the buffer
was too small, we print overflow message.

any comments?

---
 include/linux/printk.h |  58 ++++++++++++++++
 kernel/printk/printk.c | 178 +++++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 209 insertions(+), 27 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..ab39b85cff8e 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -206,6 +206,17 @@ void show_regs_print_info(const char *log_lvl);
 extern void printk_safe_init(void);
 extern void printk_safe_flush(void);
 extern void printk_safe_flush_on_panic(void);
+
+struct seq_buf;
+
+extern int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags);
+
+extern __printf(2, 3) __cold
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...);
+
+extern int prbuf_flush(struct seq_buf *s);
+
+extern void prbuf_free(struct seq_buf *s);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -277,6 +288,29 @@ static inline void printk_safe_flush(void)
 static inline void printk_safe_flush_on_panic(void)
 {
 }
+
+struct seq_buf;
+
+static inline
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	return 0;
+}
+
+static inlin __printf(2, 3) __cold
+static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	return 0;
+}
+
+static inline int prbuf_flush(struct seq_buf *s)
+{
+	return 0;
+}
+
+static inline void prbuf_free(struct seq_buf *s)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
@@ -323,6 +357,30 @@ extern asmlinkage void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Macros for buffered printk. All messages are stored in seq_buf instead of
+ * logbuf, user is required to flush the buffer in order to emit the messages
+ * and move them to the logbuf.
+ *
+ * Please use these macros and never call __prbuf_write() directly.
+ */
+#define prbuf_emerg(s, fmt, ...) \
+	__prbuf_write((s). KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_alert(s, fmt, ...) \
+	__prbuf_write((s), KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_crit(s, fmt, ...) \
+	__prbuf_write((s), KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_err(s, fmt, ...) \
+	__prbuf_write((s), KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warning(s, fmt, ...) \
+	__prbuf_write((s), KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warn pr_buf_warning
+#define prbuf_notice(s, fmt, ...) \
+	__prbuf_write((s), KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_info(s, fmt, ...) \
+	__prbuf_write((s), KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_cont(s, fmt, ...) \
+	__prbuf_write((s), KERN_CONT fmt, ##__VA_ARGS__)
 
 /* If you are writing a driver, please use dev_dbg instead */
 #if defined(CONFIG_DYNAMIC_DEBUG)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2baedd..6ccc7edda3a4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/seq_buf.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -1651,7 +1652,9 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
 	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)
+static size_t log_output(int facility, int level, enum log_flags lflags,
+			 const char *dict, size_t dictlen,
+			 const char *text, size_t text_len)
 {
 	/*
 	 * If an earlier line was buffered, and we're a continuation
@@ -1680,33 +1683,11 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
-asmlinkage int vprintk_emit(int facility, int level,
-			    const char *dict, size_t dictlen,
-			    const char *fmt, va_list args)
+static int process_log(int facility, int level,
+		       const char *dict, size_t dictlen,
+		       const char *text, size_t text_len)
 {
-	static char textbuf[LOG_LINE_MAX];
-	char *text = textbuf;
-	size_t text_len;
 	enum log_flags lflags = 0;
-	unsigned long flags;
-	int printed_len;
-	bool in_sched = false;
-
-	if (level == LOGLEVEL_SCHED) {
-		level = LOGLEVEL_DEFAULT;
-		in_sched = true;
-	}
-
-	boot_delay_msec(level);
-	printk_delay();
-
-	/* This stops the holder of console_sem just where we want him */
-	logbuf_lock_irqsave(flags);
-	/*
-	 * 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);
 
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
@@ -1742,8 +1723,38 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+	return log_output(facility, level, lflags, dict, dictlen, text, text_len);
+}
+
+asmlinkage int vprintk_emit(int facility, int level,
+			    const char *dict, size_t dictlen,
+			    const char *fmt, va_list args)
+{
+	static char textbuf[LOG_LINE_MAX];
+	char *text = textbuf;
+	size_t text_len;
+	unsigned long flags;
+	int printed_len;
+	bool in_sched = false;
+
+	if (level == LOGLEVEL_SCHED) {
+		level = LOGLEVEL_DEFAULT;
+		in_sched = true;
+	}
+
+	boot_delay_msec(level);
+	printk_delay();
 
+	/* This stops the holder of console_sem just where we want him */
+	logbuf_lock_irqsave(flags);
+	/*
+	 * 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);
+	printed_len = process_log(facility, level,
+				  dict, dictlen,
+				  text, text_len);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1833,6 +1844,119 @@ asmlinkage __visible int printk(const char *fmt, ...)
 }
 EXPORT_SYMBOL(printk);
 
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	char *b;
+
+	b = kmalloc(size, flags);
+	seq_buf_init(s, b, size);
+	return !!b;
+}
+EXPORT_SYMBOL(prbuf_init);
+
+/*
+ * Do not use this function directly. Use dedicated macros instead.
+ *
+ * If you'll you use this function, Linus will kindly ask you to
+ * consider other options.
+ */
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	if (likely(s->buffer))
+		r = seq_buf_vprintf(s, fmt, args);
+	else
+		r = vprintk_func(fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(__prbuf_write);
+
+int prbuf_flush(struct seq_buf *s)
+{
+	unsigned long flags;
+	const char *start, *c, *end;
+	bool header;
+	int len = 0;
+
+	if (!s->buffer)
+		return 0;
+
+	start = s->buffer;
+	c = start;
+	end = start + seq_buf_used(s);
+	header = true;
+
+	logbuf_lock_irqsave(flags);
+
+	if (seq_buf_has_overflowed(s)) {
+		static const char *msg = KERN_ERR "Print buffer overflow\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   msg, strlen(msg));
+	}
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   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;
+			}
+
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		static const char *newline = KERN_CONT "\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   start, end - start);
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   newline, strlen(newline));
+	}
+
+	logbuf_unlock_irqrestore(flags);
+
+	seq_buf_clear(s);
+	return len;
+}
+EXPORT_SYMBOL(prbuf_flush);
+
+void prbuf_free(struct seq_buf *s)
+{
+	kfree(s->buffer);
+	seq_buf_init(s, NULL, 0);
+}
+EXPORT_SYMBOL(prbuf_free);
+
 #else /* CONFIG_PRINTK */
 
 #define LOG_LINE_MAX		0
-- 
2.14.1