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

Sergey Senozhatsky
2017-09-01T13:24:06Z

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