[PATCH 04/16] printk: implement support for extended console drivers

From: Tejun Heo
Date: Thu Apr 16 2015 - 19:10:06 EST

printk log_buf keeps various metadata for each message including its
sequence number and timestamp. The metadata is currently available
only through /dev/kmsg and stripped out before passed onto console
drivers. We want this metadata to be available to console drivers
too. Immediately, it's to implement reliable netconsole but may be
useful for other console devices too.

This patch implements support for extended console drivers. Consoles
can indicate that they process extended messages by setting the new
CON_EXTENDED flag and they'll fed messages formatted the same way as
/dev/kmsg output as follows.

<level>,<sequnum>,<timestamp>,<contflag>;<message text>

One special case is fragments. Message fragments are output
immediately to consoles to avoid losing them in case of crashes. For
normal consoles, this is handled by later suppressing the assembled
result and /dev/kmsg only shows fully assembled message; however,
extended consoles would need both the fragments, to avoid losing
message in case of a crash, and the assembled result, to tell how the
fragments are assembled and which sequence number got assigned to it.

To help matching up the fragments with the resulting message,
fragments are emitted in the following format.

<level>,-,<timestamp>,-,fragid=<fragid>;<message fragment>

And later when the assembly is complete, the following is transmitted,

<level>,<sequnum>,<timestamp>,<contflag>,fragid=<fragid>;<message text>

* Extended message formatting for console drivers is enabled iff there
are registered extended consoles.

* Comment describing extended message formats updated to help
distinguishing variable with verbatim terms.

Signed-off-by: Tejun Heo <tj@xxxxxxxxxx>
Cc: Kay Sievers <kay@xxxxxxxx>
Cc: Petr Mladek <pmladek@xxxxxxx>
---
include/linux/console.h | 1 +
kernel/printk/printk.c | 141 +++++++++++++++++++++++++++++++++++++++++-------
2 files changed, 123 insertions(+), 19 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 7571a16..04bbd09 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -115,6 +115,7 @@ static inline int con_debug_leave(void)
#define CON_BOOT (8)
#define CON_ANYTIME (16) /* Safe to call when cpu is offline */
#define CON_BRL (32) /* Used for a braille device */
+#define CON_EXTENDED (64) /* Use the extended output format a la /dev/kmsg */

struct console {
char name[16];
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0175c46..349a37b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -84,6 +84,8 @@ static struct lockdep_map console_lock_dep_map = {
};
#endif

+static int nr_ext_console_drivers;
+
/*
* Helper macros to handle lockdep when locking/unlocking console_sem. We use
* macros instead of functions so that _RET_IP_ contains useful information.
@@ -195,14 +197,28 @@ static int console_may_schedule;
* need to be changed in the future, when the requirements change.
*
* /dev/kmsg exports the structured data in the following line format:
- * "level,sequnum,timestamp;<message text>\n"
+ * "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n"
*
* The optional key/value pairs are attached as continuation lines starting
* with a space character and terminated by a newline. All possible
* non-prinatable characters are escaped in the "\xff" notation.
*
* Users of the export format should ignore possible additional values
- * separated by ',', and find the message after the ';' character.
+ * separated by ',', and find the message after the ';' character. All
+ * optional header fields should have the form "<key>=<value>".
+ *
+ * For consoles with CON_EXTENDED set, a message formatted like the
+ * following may also be printed. This is a continuation fragment which are
+ * being assembled and will be re-transmitted with a normal header once
+ * assembly finishes. The fragments are sent out immediately to avoid
+ * losing them over a crash.
+ * "<level>,-,<timestamp>,-,fragid=<fragid>;<message fragment>\n"
+ *
+ * On completion of assembly, the following is transmitted.
+ * "<level>,<sequnum>,<timestamp>,<contflag>,fragid=<fragid>;<message text>\n"
+ *
+ * Extended consoles should identify and handle duplicates by matching the
+ * fragids of the fragments and assembled messages.
*/

enum log_flags {
@@ -210,6 +226,7 @@ enum log_flags {
LOG_NEWLINE = 2, /* text ended with a newline */
LOG_PREFIX = 4, /* text started with a prefix */
LOG_CONT = 8, /* text is a fragment of a continuation line */
+ LOG_DICT_META = 16, /* dict contains console meta information */
};

struct printk_log {
@@ -292,6 +309,12 @@ static char *log_dict(const struct printk_log *msg)
return (char *)msg + sizeof(struct printk_log) + msg->text_len;
}

+/* if LOG_DICT_META is set, the dict buffer carries printk internal info */
+static size_t log_dict_len(const struct printk_log *msg)
+{
+ return (msg->flags & LOG_DICT_META) ? 0 : msg->dict_len;
+}
+
/* get record by index; idx must point to valid msg */
static struct printk_log *log_from_idx(u32 idx)
{
@@ -516,7 +539,9 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
enum log_flags prev_flags)
{
u64 ts_usec = msg->ts_nsec;
+ u64 fragid;
char cont = '-';
+ char fragid_buf[32] = "";

do_div(ts_usec, 1000);

@@ -534,8 +559,14 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
((prev_flags & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
cont = '+';

- return scnprintf(buf, size, "%u,%llu,%llu,%c;",
- (msg->facility << 3) | msg->level, seq, ts_usec, cont);
+ /* see cont_flush() */
+ if ((msg->flags & LOG_DICT_META) && msg->dict_len &&
+ sscanf(log_dict(msg), "FRAGID=%llu", &fragid))
+ scnprintf(fragid_buf, sizeof(fragid_buf),
+ ",fragid=%llu", fragid);
+ return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+ (msg->facility << 3) | msg->level, seq, ts_usec, cont,
+ fragid_buf);
}

static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -688,7 +719,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
len = msg_print_ext_header(user->buf, sizeof(user->buf),
msg, user->seq, user->prev);
len += msg_print_ext_body(user->buf + len, sizeof(user->buf) - len,
- log_dict(msg), msg->dict_len,
+ log_dict(msg), log_dict_len(msg),
log_text(msg), msg->text_len);

user->prev = msg->flags;
@@ -1418,6 +1449,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
* The console_lock must be held.
*/
static void call_console_drivers(int level, bool nocons,
+ const char *ext_text, size_t ext_len,
const char *text, size_t len)
{
struct console *con;
@@ -1440,13 +1472,16 @@ static void call_console_drivers(int level, bool nocons,
!(con->flags & CON_ANYTIME))
continue;
/*
- * Skip record we have buffered and already printed
- * directly to the console when we received it.
+ * For !ext consoles, skip record we have buffered and
+ * already printed directly when we received it. Ext
+ * consoles are responsible for filtering on their ends.
*/
- if (nocons)
- continue;
-
- con->write(con, text, len);
+ if (con->flags & CON_EXTENDED) {
+ if (ext_len)
+ con->write(con, ext_text, ext_len);
+ } else if (!nocons) {
+ con->write(con, text, len);
+ }
}
}

@@ -1546,6 +1581,7 @@ static inline void printk_delay(void)
*/
static struct cont {
char buf[LOG_LINE_MAX];
+ u64 fragid; /* unique fragment id */
size_t len; /* length == 0 means unused buffer */
size_t cons; /* bytes written to console */
struct task_struct *owner; /* task of first print*/
@@ -1564,13 +1600,23 @@ static void cont_flush(enum log_flags flags)
return;

if (cont.cons) {
+ char dict_buf[32];
+ size_t dict_len;
+
/*
* If a fragment of this line was directly flushed to the
* console; wait for the console to pick up the rest of the
- * line. LOG_NOCONS suppresses a duplicated output.
+ * line. LOG_NOCONS suppresses a duplicated output for !ext
+ * consoles. ext consoles handle the duplicates themselves
+ * and expect fragid in the header of the duplicate
+ * messages for that. Record the fragid in the dict buffer
+ * which fragmented messages never use.
*/
- log_store(cont.facility, cont.level, flags | LOG_NOCONS,
- cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+ dict_len = scnprintf(dict_buf, sizeof(dict_buf), "FRAGID=%llu",
+ cont.fragid);
+ log_store(cont.facility, cont.level,
+ flags | LOG_NOCONS | LOG_DICT_META,
+ cont.ts_nsec, dict_buf, dict_len, cont.buf, cont.len);
cont.flags = flags;
cont.flushed = true;
} else {
@@ -1596,6 +1642,9 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
}

if (!cont.len) {
+ static u64 fragid;
+
+ cont.fragid = fragid++;
cont.facility = facility;
cont.level = level;
cont.owner = current;
@@ -1920,14 +1969,28 @@ static u32 log_first_idx;
static u64 log_next_seq;
static enum log_flags console_prev;
static struct cont {
+ char buf[1];
+ u64 fragid;
size_t len;
size_t cons;
+ u64 ts_nsec;
u8 level;
+ u8 facility;
bool flushed:1;
} cont;
+static char *log_text(const struct printk_log *msg) { return NULL; }
+static char *log_dict(const struct printk_log *msg) { return NULL; }
+static size_t log_dict_len(const struct printk_log *msg) { return 0; }
static struct printk_log *log_from_idx(u32 idx) { return NULL; }
static u32 log_next(u32 idx) { return 0; }
+static ssize_t msg_print_ext_header(char *buf, size_t size,
+ struct printk_log *msg, u64 seq,
+ enum log_flags prev_flags) { return 0; }
+static ssize_t msg_print_ext_body(char *buf, size_t size,
+ char *dict, size_t dict_len,
+ char *text, size_t text_len) { return 0; }
static void call_console_drivers(int level, bool nocons,
+ const char *ext_text, size_t ext_len,
const char *text, size_t len) {}
static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
bool syslog, char *buf, size_t size) { return 0; }
@@ -2178,10 +2241,11 @@ int is_console_locked(void)
return console_locked;
}

-static void console_cont_flush(char *text, size_t size)
+static void console_cont_flush(char *ext_text, size_t ext_size,
+ char *text, size_t size)
{
unsigned long flags;
- size_t len;
+ size_t len, ext_len = 0;

raw_spin_lock_irqsave(&logbuf_lock, flags);

@@ -2196,10 +2260,30 @@ static void console_cont_flush(char *text, size_t size)
if (console_seq < log_next_seq && !cont.cons)
goto out;

+ /*
+ * Fragment dump for consoles. Will be printed again when the
+ * assembly is complete.
+ */
+ if (nr_ext_console_drivers && cont.len > cont.cons) {
+ u64 ts_usec = cont.ts_nsec;
+
+ do_div(ts_usec, 1000);
+
+ ext_len = scnprintf(ext_text, ext_size,
+ "%u,-,%llu,-,fragid=%llu;",
+ (cont.facility << 3) | cont.level, ts_usec,
+ cont.fragid);
+ ext_len += msg_print_ext_body(ext_text + ext_len,
+ ext_size - ext_len, NULL, 0,
+ cont.buf + cont.cons,
+ cont.len - cont.cons);
+ }
+
len = cont_print_text(text, size);
+
raw_spin_unlock(&logbuf_lock);
stop_critical_timings();
- call_console_drivers(cont.level, false, text, len);
+ call_console_drivers(cont.level, false, ext_text, ext_len, text, len);
start_critical_timings();
local_irq_restore(flags);
return;
@@ -2223,6 +2307,7 @@ out:
*/
void console_unlock(void)
{
+ static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
static u64 seen_seq;
unsigned long flags;
@@ -2237,11 +2322,12 @@ void console_unlock(void)
console_may_schedule = 0;

/* flush buffered message fragment immediately to console */
- console_cont_flush(text, sizeof(text));
+ console_cont_flush(ext_text, sizeof(ext_text), text, sizeof(text));
again:
for (;;) {
struct printk_log *msg;
size_t len;
+ size_t ext_len = 0;
int level;
bool nocons;

@@ -2271,6 +2357,15 @@ again:
nocons = msg->flags & LOG_NOCONS;
len += msg_print_text(msg, console_prev, false,
text + len, sizeof(text) - len);
+ if (nr_ext_console_drivers) {
+ ext_len = msg_print_ext_header(ext_text,
+ sizeof(ext_text),
+ msg, console_seq, console_prev);
+ ext_len += msg_print_ext_body(ext_text + ext_len,
+ sizeof(ext_text) - ext_len,
+ log_dict(msg), log_dict_len(msg),
+ log_text(msg), msg->text_len);
+ }
console_idx = log_next(console_idx);
console_seq++;
console_prev = msg->flags;
@@ -2285,7 +2380,8 @@ again:
raw_spin_unlock(&logbuf_lock);

stop_critical_timings(); /* don't trace print latency */
- call_console_drivers(level, nocons, text, len);
+ call_console_drivers(level, nocons,
+ ext_text, ext_len, text, len);
start_critical_timings();
local_irq_restore(flags);
}
@@ -2540,6 +2636,10 @@ void register_console(struct console *newcon)
newcon->next = console_drivers->next;
console_drivers->next = newcon;
}
+
+ if (newcon->flags & CON_EXTENDED)
+ nr_ext_console_drivers++;
+
if (newcon->flags & CON_PRINTBUFFER) {
/*
* console_unlock(); will print out the buffered messages
@@ -2612,6 +2712,9 @@ int unregister_console(struct console *console)
}
}

+ if (!res && (console->flags & CON_EXTENDED))
+ nr_ext_console_drivers--;
+
/*
* If this isn't the last console and it has CON_CONSDEV set, we
* need to set it on the next preferred console.
--
2.1.0

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/