[PATCH v6 1/3] printk: Add line-buffered printk() API.

[Tetsuo Handa]

Sometimes we want to print a whole line without being disturbed by
concurrent printk() from interrupts and/or other threads, for printk()
which does not end with '\n' can be disturbed.

Since mixed printk() output makes it hard to interpret, this patch
introduces API for line-buffered printk() output (so that we can make
sure that printk() ends with '\n').

Since functions introduced by this patch are merely wrapping
printk()/vprintk() calls in order to minimize possibility of using
"struct cont", it is safe to replace printk()/vprintk() with this API.
Since we want to remove "struct cont" eventually, we will try to remove
both "implicit printk() users who are expecting KERN_CONT behavior" and
"explicit pr_cont()/printk(KERN_CONT) users". Therefore, converting to
this API is recommended.

Details:

  A structure named "struct printk_buffer" is introduced for buffering
  up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.

  get_printk_buffer() tries to assign a "struct printk_buffer" from
  statically preallocated array. get_printk_buffer() returns NULL if
  all "struct printk_buffer" are in use, but the caller does not need to
  check for NULL.

  put_printk_buffer() flushes and releases the "struct printk_buffer".
  put_printk_buffer() must match corresponding get_printk_buffer() as with
  rcu_read_unlock() must match corresponding rcu_read_lock().

  Three functions vprintk_buffered(), printk_buffered() and
  flush_printk_buffer() are provided for using "struct printk_buffer".
  These are like vfprintf(), fprintf(), fflush() except that these receive
  "struct printk_buffer *" for the first argument.

  vprintk_buffered() and printk_buffered() fall back to vprintk() and
  printk() respectively if "struct printk_buffer *" argument is NULL.
  flush_printk_buffer() and put_printk_buffer() become no-op if
  "struct printk_buffer *" argument is NULL. Therefore, the caller of
  get_printk_buffer() does not need to check for NULL.

How to use this API:

  (1) Call get_printk_buffer() and acquire "struct printk_buffer *".

  (2) Rewrite printk() calls in the following way. The "ptr" is
      "struct printk_buffer *" obtained in step (1).

      printk(fmt, ...)     => printk_buffered(ptr, fmt, ...)
      vprintk(fmt, args)   => vprintk_buffered(ptr, fmt, args)
      pr_emerg(fmt, ...)   => bpr_emerg(ptr, fmt, ...)
      pr_alert(fmt, ...)   => bpr_alert(ptr, fmt, ...)
      pr_crit(fmt, ...)    => bpr_crit(ptr, fmt, ...)
      pr_err(fmt, ...)     => bpr_err(ptr, fmt, ...)
      pr_warning(fmt, ...) => bpr_warning(ptr, fmt, ...)
      pr_warn(fmt, ...)    => bpr_warn(ptr, fmt, ...)
      pr_notice(fmt, ...)  => bpr_notice(ptr, fmt, ...)
      pr_info(fmt, ...)    => bpr_info(ptr, fmt, ...)
      pr_cont(fmt, ...)    => bpr_cont(ptr, fmt, ...)

  (3) Release "struct printk_buffer" by calling put_printk_buffer().

Note that since "struct printk_buffer" buffers only up to one line, there
is no need to rewrite if it is known that the "struct printk_buffer" is
empty and printk() ends with '\n'.

  Good example:

    printk("Hello ");    =>  buf = get_printk_buffer();
    pr_cont("world.\n");     printk_buffered(buf, "Hello ");
                             printk_buffered(buf, "world.\n");
                             put_printk_buffer(buf);

  Pointless example:

    printk("Hello\n");   =>  buf = get_printk_buffer();
    printk("World.\n");      printk_buffered(buf, "Hello\n");
                             printk_buffered(buf, "World.\n");
                             put_printk_buffer(buf);

Note that bpr_devel() and bpr_debug() are not defined. This is
because pr_devel()/pr_debug() should not be followed by pr_cont()
because pr_devel()/pr_debug() are conditionally enabled; output from
pr_devel()/pr_debug() should always end with '\n'.

Previous version was proposed at
https://lkml.kernel.org/r/1540375870-6235-1-git-send-email-penguin-kernel@xxxxxxxxxxxxxxxxxxx .

Signed-off-by: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
---
 include/linux/printk.h          |  43 ++++++++++
 kernel/printk/Makefile          |   2 +-
 kernel/printk/internal.h        |   3 +
 kernel/printk/printk.c          |   3 -
 kernel/printk/printk_buffered.c | 179 ++++++++++++++++++++++++++++++++++++++++
 5 files changed, 226 insertions(+), 4 deletions(-)
 create mode 100644 kernel/printk/printk_buffered.c

diff --git a/include/linux/printk.h b/include/linux/printk.h
index cf3eccf..92af345 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -157,6 +157,7 @@ static inline void printk_nmi_direct_enter(void) { }
 static inline void printk_nmi_direct_exit(void) { }
 #endif /* PRINTK_NMI */
 
+struct printk_buffer;
 #ifdef CONFIG_PRINTK
 asmlinkage __printf(5, 0)
 int vprintk_emit(int facility, int level,
@@ -173,6 +174,20 @@ int printk_emit(int facility, int level,
 
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
+struct printk_buffer *get_printk_buffer(void);
+bool flush_printk_buffer(struct printk_buffer *ptr);
+__printf(2, 3)
+int printk_buffered(struct printk_buffer *ptr, const char *fmt, ...);
+__printf(2, 0)
+int vprintk_buffered(struct printk_buffer *ptr, const char *fmt, va_list args);
+/*
+ * In order to avoid accidentally reusing "ptr" after put_printk_buffer("ptr"),
+ * put_printk_buffer() is defined as a macro which explicitly resets "ptr" to
+ * NULL.
+ */
+void __put_printk_buffer(struct printk_buffer *ptr);
+#define put_printk_buffer(ptr)					\
+	do { __put_printk_buffer(ptr); ptr = NULL; } while (0)
 
 /*
  * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
@@ -220,6 +235,17 @@ int printk(const char *s, ...)
 {
 	return 0;
 }
+static inline struct printk_buffer *get_printk_buffer(void)
+{
+	return NULL;
+}
+static inline bool flush_printk_buffer(struct printk_buffer *ptr)
+{
+	return false;
+}
+#define printk_buffered(ptr, fmt, ...) printk(fmt, ##__VA_ARGS__)
+#define vprintk_buffered(ptr, fmt, args) vprintk(fmt, args)
+#define put_printk_buffer(ptr) do { ptr = NULL; } while (0)
 static inline __printf(1, 2) __cold
 int printk_deferred(const char *s, ...)
 {
@@ -330,6 +356,23 @@ static inline void printk_safe_flush_on_panic(void)
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+#define bpr_emerg(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_alert(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_crit(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_err(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_warning(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_warn bpr_warning
+#define bpr_notice(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_info(ptr, fmt, ...) \
+	printk_buffered(ptr, KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_cont(ptr, fmt, ...) \
+	printk_buffered(ptr, 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/Makefile b/kernel/printk/Makefile
index 4a2ffc3..23b1547 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -1,3 +1,3 @@
 obj-y	= printk.o
-obj-$(CONFIG_PRINTK)	+= printk_safe.o
+obj-$(CONFIG_PRINTK)	+= printk_safe.o printk_buffered.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 0f18988..5e8c048 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -22,6 +22,9 @@
 #define PRINTK_NMI_DIRECT_CONTEXT_MASK	 0x40000000
 #define PRINTK_NMI_CONTEXT_MASK		 0x80000000
 
+#define PREFIX_MAX		32
+#define LOG_LINE_MAX		(1024 - PREFIX_MAX)
+
 extern raw_spinlock_t logbuf_lock;
 
 __printf(5, 0)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1b2a029..0b06211 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -421,9 +421,6 @@ __packed __aligned(4)
 static u64 clear_seq;
 static u32 clear_idx;
 
-#define PREFIX_MAX		32
-#define LOG_LINE_MAX		(1024 - PREFIX_MAX)
-
 #define LOG_LEVEL(v)		((v) & 0x07)
 #define LOG_FACILITY(v)		((v) >> 3 & 0xff)
 
diff --git a/kernel/printk/printk_buffered.c b/kernel/printk/printk_buffered.c
new file mode 100644
index 0000000..d181d31
--- /dev/null
+++ b/kernel/printk/printk_buffered.c
@@ -0,0 +1,179 @@
+/* SPDX-License-Identifier: GPL-2.0+ */
+
+#include <linux/types.h> /* DECLARE_BITMAP() */
+#include <linux/printk.h>
+#include "internal.h"
+
+/* A structure for line-buffered printk() output. */
+struct printk_buffer {
+	unsigned short int len; /* Valid bytes in buf[]. */
+	char buf[LOG_LINE_MAX];
+} __aligned(1024);
+
+/*
+ * Number of statically preallocated buffers.
+ *
+ * We can introduce a kernel config option if someone wants to tune this value.
+ * But since "struct printk_buffer" makes difference only when there are
+ * multiple threads concurrently calling printk() which does not end with '\n',
+ * and this API will fallback to normal printk() when all buffers are in use,
+ * it is possible that nobody needs to tune this value.
+ */
+#define NUM_LINE_BUFFERS 16
+
+static struct printk_buffer printk_buffers[NUM_LINE_BUFFERS];
+static DECLARE_BITMAP(printk_buffers_in_use, NUM_LINE_BUFFERS);
+
+/**
+ * get_printk_buffer - Try to get printk_buffer.
+ *
+ * Returns pointer to "struct printk_buffer" on success, NULL otherwise.
+ *
+ * If this function returned "struct printk_buffer", the caller is responsible
+ * for passing it to put_printk_buffer() so that "struct printk_buffer" can be
+ * reused in the future.
+ *
+ * Even if this function returned NULL, the caller does not need to check for
+ * NULL, for passing NULL to printk_buffered() simply acts like normal printk()
+ * and passing NULL to flush_printk_buffer()/put_printk_buffer() is a no-op.
+ */
+struct printk_buffer *get_printk_buffer(void)
+{
+	long i;
+
+	for (i = 0; i < NUM_LINE_BUFFERS; i++) {
+		if (test_and_set_bit_lock(i, printk_buffers_in_use))
+			continue;
+		printk_buffers[i].len = 0;
+		return &printk_buffers[i];
+	}
+	return NULL;
+}
+EXPORT_SYMBOL(get_printk_buffer);
+
+/**
+ * vprintk_buffered - Try to vprintk() in line buffered mode.
+ *
+ * @ptr:  Pointer to "struct printk_buffer". It can be NULL.
+ * @fmt:  printk() format string.
+ * @args: va_list structure.
+ *
+ * Returns the return value of vprintk().
+ *
+ * Try to store to @ptr first. If it fails, flush @ptr and then try to store to
+ * @ptr again. If it still fails, use unbuffered printing.
+ */
+int vprintk_buffered(struct printk_buffer *ptr, const char *fmt, va_list args)
+{
+	va_list tmp_args;
+	int r;
+	int pos;
+
+	if (!ptr)
+		return vprintk(fmt, args);
+	/*
+	 * Skip KERN_CONT here based on an assumption that KERN_CONT will be
+	 * given via "fmt" argument when KERN_CONT is given.
+	 */
+	pos = (printk_get_level(fmt) == 'c') ? 2 : 0;
+	while (true) {
+		va_copy(tmp_args, args);
+		r = vsnprintf(ptr->buf + ptr->len, sizeof(ptr->buf) - ptr->len,
+			      fmt + pos, tmp_args);
+		va_end(tmp_args);
+		if (likely(r + ptr->len < sizeof(ptr->buf)))
+			break;
+		if (!flush_printk_buffer(ptr))
+			return vprintk(fmt, args);
+	}
+	ptr->len += r;
+	/* Flush already completed lines if any. */
+	for (pos = ptr->len - 1; pos >= 0; pos--) {
+		if (ptr->buf[pos] != '\n')
+			continue;
+		ptr->buf[pos++] = '\0';
+		printk("%s\n", ptr->buf);
+		ptr->len -= pos;
+		memmove(ptr->buf, ptr->buf + pos, ptr->len);
+		/* This '\0' will be overwritten by next vsnprintf() above. */
+		ptr->buf[ptr->len] = '\0';
+		break;
+	}
+	return r;
+}
+
+/**
+ * printk_buffered - Try to printk() in line buffered mode.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ * @fmt: printk() format string, followed by arguments.
+ *
+ * Returns the return value of printk().
+ *
+ * Try to store to @ptr first. If it fails, flush @ptr and then try to store to
+ * @ptr again. If it still fails, use unbuffered printing.
+ */
+int printk_buffered(struct printk_buffer *ptr, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = vprintk_buffered(ptr, fmt, args);
+	va_end(args);
+	return r;
+}
+EXPORT_SYMBOL(printk_buffered);
+
+/**
+ * flush_printk_buffer - Flush incomplete line in printk_buffer.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ *
+ * Returns true if flushed something, false otherwise.
+ *
+ * Flush if @ptr contains partial data. But usually there is no need to call
+ * this function because @ptr is flushed by put_printk_buffer().
+ */
+bool flush_printk_buffer(struct printk_buffer *ptr)
+{
+	if (!ptr || !ptr->len)
+		return false;
+	/*
+	 * vprintk_buffered() keeps 0 <= ptr->len < sizeof(ptr->buf) true.
+	 * But ptr->buf[ptr->len] != '\0' if this function is called due to
+	 * vsnprintf() + ptr->len >= sizeof(ptr->buf).
+	 */
+	ptr->buf[ptr->len] = '\0';
+	printk("%s", ptr->buf);
+	ptr->len = 0;
+	return true;
+}
+EXPORT_SYMBOL(flush_printk_buffer);
+
+/**
+ * __put_printk_buffer - Release printk_buffer.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ *
+ * Returns nothing.
+ *
+ * Flush and release @ptr.
+ * Please use put_printk_buffer() in order to catch use-after-free bugs.
+ */
+void __put_printk_buffer(struct printk_buffer *ptr)
+{
+	long i = (unsigned long) ptr - (unsigned long) printk_buffers;
+
+	if (!ptr)
+		return;
+	if (WARN_ON_ONCE(i % sizeof(struct printk_buffer)))
+		return;
+	i /= sizeof(struct printk_buffer);
+	if (WARN_ON_ONCE(i < 0 || i >= NUM_LINE_BUFFERS))
+		return;
+	if (ptr->len)
+		flush_printk_buffer(ptr);
+	clear_bit_unlock(i, printk_buffers_in_use);
+}
+EXPORT_SYMBOL(__put_printk_buffer);
-- 
1.8.3.1