[PATCHSET] printk: implement extended console support

[PATCHSET] printk: implement extended console support

[Tejun Heo]

This patchset is v2 of printk extended console support.  v1 was part
of "printk, netconsole: implement reliable netconsole" patchset [1].
The biggest change is dropping of cont buffer handling as hinted by
Petr's hint.  This made it unnecessary to change LOG_NOCONS handling
and made the actual extended console support a lot simpler as now each
printk invocation always maps to a single log entry.

The kernel keeps quite a bit of metadata for each printk message in
its log buffer, all of which are accessible through /dev/kmsg;
however, when the messages are transmitted to consoles, a lot of
metadata is lost along with dictionary for structured logging.

Allowing consoles access to full log message information can be useful
for multiple reasons.  The consumer of the console output can identify
the orginating facility, make use of structured logging, determine
whether any message got lost if the medium isn't reliable and so on.
This will be further discussed in the netconsole patchset which will
follow soon.

Thanks to /dev/kmsg, printk already implements most of logic necessary
for extended console support.  The header is well defined and the
formatting code is already there.  The only possible complication is
handling of cont buffer.

This is dealt with by simply disabling in-kernel KERN_CONT
concatenation when extended consoles are registered.  This makes
message fragments consume more memory as each gets assigned a separate
log entry, but this greatly simplifies extended console support and
provided that /dev/kmsg and extended consumers perform trivial
concatenation directed by the <contflag> field, the end results are
the same.  In the long term, we might want to drop in-kernel
concatenation entirely.

Note that currently neither dmesg nor journald implements <contflag>
handling but this is trivial to add and this patchset doesn't change
the kernel behavior when no external console is registered.

This patchset contains the following three patches.

0001-printk-guard-the-amount-written-per-line-by-devkmsg_.patch
0002-printk-factor-out-message-formatting-from-devkmsg_re.patch
0003-printk-implement-support-for-extended-console-driver.patch

0001-0002 are straight-forward prep patches.  0003 implements the
extended console support.

The patches are also available in the following git branch.

 git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git review-printk-ext-console

diffstat follows.  Thanks.

 include/linux/console.h |    1
 include/linux/printk.h  |    2
 kernel/printk/printk.c  |  213 ++++++++++++++++++++++++++++++++----------------
 3 files changed, 146 insertions(+), 70 deletions(-)

--
tejun

[1] http://lkml.kernel.org/g/1429225433-11946-1-git-send-email-tj@kernel.org

[PATCH 1/3] printk: guard the amount written per line by devkmsg_read()

[Tejun Heo]

devkmsg_read() uses 8k buffer and assumes that the formatted output
message won't overrun which seems safe given LOG_LINE_MAX, the current
use of dict and the escaping method being used; however, we're
planning to use devkmsg formatting wider and accounting for the buffer
size properly isn't that complicated.

This patch defines CONSOLE_EXT_LOG_MAX as 8192 and updates
devkmsg_read() so that it limits output accordingly.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Petr Mladek <pmladek@suse.cz>
---
 include/linux/printk.h |  2 ++
 kernel/printk/printk.c | 34 ++++++++++++++++++++++------------
 2 files changed, 24 insertions(+), 12 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 9b30871..58b1fec 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -30,6 +30,8 @@ static inline const char *printk_skip_level(const char *buffer)
 	return buffer;
 }
 
+#define CONSOLE_EXT_LOG_MAX	8192
+
 /* printk's without a loglevel use this.. */
 #define MESSAGE_LOGLEVEL_DEFAULT CONFIG_MESSAGE_LOGLEVEL_DEFAULT
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c099b08..a115490 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -505,6 +505,11 @@ int check_syslog_permissions(int type, bool from_file)
 	return security_syslog(type);
 }
 
+static void append_char(char **pp, char *e, char c)
+{
+	if (*pp < e)
+		*(*pp)++ = c;
+}
 
 /* /dev/kmsg - userspace message inject/listen interface */
 struct devkmsg_user {
@@ -512,7 +517,7 @@ struct devkmsg_user {
 	u32 idx;
 	enum log_flags prev;
 	struct mutex lock;
-	char buf[8192];
+	char buf[CONSOLE_EXT_LOG_MAX];
 };
 
 static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
@@ -570,6 +575,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 {
 	struct devkmsg_user *user = file->private_data;
 	struct printk_log *msg;
+	char *p, *e;
 	u64 ts_usec;
 	size_t i;
 	char cont = '-';
@@ -579,6 +585,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	if (!user)
 		return -EBADF;
 
+	p = user->buf;
+	e = user->buf + sizeof(user->buf);
+
 	ret = mutex_lock_interruptible(&user->lock);
 	if (ret)
 		return ret;
@@ -625,9 +634,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
 		cont = '+';
 
-	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
-		      (msg->facility << 3) | msg->level,
-		      user->seq, ts_usec, cont);
+	p += scnprintf(p, e - p, "%u,%llu,%llu,%c;",
+		       (msg->facility << 3) | msg->level,
+		       user->seq, ts_usec, cont);
 	user->prev = msg->flags;
 
 	/* escape non-printable characters */
@@ -635,11 +644,11 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 		unsigned char c = log_text(msg)[i];
 
 		if (c < ' ' || c >= 127 || c == '\\')
-			len += sprintf(user->buf + len, "\\x%02x", c);
+			p += scnprintf(p, e - p, "\\x%02x", c);
 		else
-			user->buf[len++] = c;
+			append_char(&p, e, c);
 	}
-	user->buf[len++] = '\n';
+	append_char(&p, e, '\n');
 
 	if (msg->dict_len) {
 		bool line = true;
@@ -648,30 +657,31 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			unsigned char c = log_dict(msg)[i];
 
 			if (line) {
-				user->buf[len++] = ' ';
+				append_char(&p, e, ' ');
 				line = false;
 			}
 
 			if (c == '\0') {
-				user->buf[len++] = '\n';
+				append_char(&p, e, '\n');
 				line = true;
 				continue;
 			}
 
 			if (c < ' ' || c >= 127 || c == '\\') {
-				len += sprintf(user->buf + len, "\\x%02x", c);
+				p += scnprintf(p, e - p, "\\x%02x", c);
 				continue;
 			}
 
-			user->buf[len++] = c;
+			append_char(&p, e, c);
 		}
-		user->buf[len++] = '\n';
+		append_char(&p, e, '\n');
 	}
 
 	user->idx = log_next(user->idx);
 	user->seq++;
 	raw_spin_unlock_irq(&logbuf_lock);
 
+	len = p - user->buf;
 	if (len > count) {
 		ret = -EINVAL;
 		goto out;
-- 
2.1.0

[PATCH 2/3] printk: factor out message formatting from devkmsg_read()

[Tejun Heo]

The extended message formatting used for /dev/kmsg will be used
implement extended consoles.  Factor out msg_print_ext_header() and
msg_print_ext_body() from devkmsg_read().

This is pure restructuring.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Petr Mladek <pmladek@suse.cz>
---
 kernel/printk/printk.c | 146 +++++++++++++++++++++++++++----------------------
 1 file changed, 80 insertions(+), 66 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a115490..51ce4f1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -511,6 +511,81 @@ static void append_char(char **pp, char *e, char c)
 		*(*pp)++ = c;
 }
 
+static ssize_t msg_print_ext_header(char *buf, size_t size,
+				    struct printk_log *msg, u64 seq,
+				    enum log_flags prev_flags)
+{
+	u64 ts_usec = msg->ts_nsec;
+	char cont = '-';
+
+	do_div(ts_usec, 1000);
+
+	/*
+	 * If we couldn't merge continuation line fragments during the print,
+	 * export the stored flags to allow an optional external merge of the
+	 * records. Merging the records isn't always neccessarily correct, like
+	 * when we hit a race during printing. In most cases though, it produces
+	 * better readable output. 'c' in the record flags mark the first
+	 * fragment of a line, '+' the following.
+	 */
+	if (msg->flags & LOG_CONT && !(prev_flags & LOG_CONT))
+		cont = 'c';
+	else if ((msg->flags & LOG_CONT) ||
+		 ((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);
+}
+
+static ssize_t msg_print_ext_body(char *buf, size_t size,
+				  char *dict, size_t dict_len,
+				  char *text, size_t text_len)
+{
+	char *p = buf, *e = buf + size;
+	size_t i;
+
+	/* escape non-printable characters */
+	for (i = 0; i < text_len; i++) {
+		unsigned char c = text[i];
+
+		if (c < ' ' || c >= 127 || c == '\\')
+			p += scnprintf(p, e - p, "\\x%02x", c);
+		else
+			append_char(&p, e, c);
+	}
+	append_char(&p, e, '\n');
+
+	if (dict_len) {
+		bool line = true;
+
+		for (i = 0; i < dict_len; i++) {
+			unsigned char c = dict[i];
+
+			if (line) {
+				append_char(&p, e, ' ');
+				line = false;
+			}
+
+			if (c == '\0') {
+				append_char(&p, e, '\n');
+				line = true;
+				continue;
+			}
+
+			if (c < ' ' || c >= 127 || c == '\\') {
+				p += scnprintf(p, e - p, "\\x%02x", c);
+				continue;
+			}
+
+			append_char(&p, e, c);
+		}
+		append_char(&p, e, '\n');
+	}
+
+	return p - buf;
+}
+
 /* /dev/kmsg - userspace message inject/listen interface */
 struct devkmsg_user {
 	u64 seq;
@@ -575,19 +650,12 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 {
 	struct devkmsg_user *user = file->private_data;
 	struct printk_log *msg;
-	char *p, *e;
-	u64 ts_usec;
-	size_t i;
-	char cont = '-';
 	size_t len;
 	ssize_t ret;
 
 	if (!user)
 		return -EBADF;
 
-	p = user->buf;
-	e = user->buf + sizeof(user->buf);
-
 	ret = mutex_lock_interruptible(&user->lock);
 	if (ret)
 		return ret;
@@ -617,71 +685,17 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	}
 
 	msg = log_from_idx(user->idx);
-	ts_usec = msg->ts_nsec;
-	do_div(ts_usec, 1000);
+	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_text(msg), msg->text_len);
 
-	/*
-	 * If we couldn't merge continuation line fragments during the print,
-	 * export the stored flags to allow an optional external merge of the
-	 * records. Merging the records isn't always neccessarily correct, like
-	 * when we hit a race during printing. In most cases though, it produces
-	 * better readable output. 'c' in the record flags mark the first
-	 * fragment of a line, '+' the following.
-	 */
-	if (msg->flags & LOG_CONT && !(user->prev & LOG_CONT))
-		cont = 'c';
-	else if ((msg->flags & LOG_CONT) ||
-		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
-		cont = '+';
-
-	p += scnprintf(p, e - p, "%u,%llu,%llu,%c;",
-		       (msg->facility << 3) | msg->level,
-		       user->seq, ts_usec, cont);
 	user->prev = msg->flags;
-
-	/* escape non-printable characters */
-	for (i = 0; i < msg->text_len; i++) {
-		unsigned char c = log_text(msg)[i];
-
-		if (c < ' ' || c >= 127 || c == '\\')
-			p += scnprintf(p, e - p, "\\x%02x", c);
-		else
-			append_char(&p, e, c);
-	}
-	append_char(&p, e, '\n');
-
-	if (msg->dict_len) {
-		bool line = true;
-
-		for (i = 0; i < msg->dict_len; i++) {
-			unsigned char c = log_dict(msg)[i];
-
-			if (line) {
-				append_char(&p, e, ' ');
-				line = false;
-			}
-
-			if (c == '\0') {
-				append_char(&p, e, '\n');
-				line = true;
-				continue;
-			}
-
-			if (c < ' ' || c >= 127 || c == '\\') {
-				p += scnprintf(p, e - p, "\\x%02x", c);
-				continue;
-			}
-
-			append_char(&p, e, c);
-		}
-		append_char(&p, e, '\n');
-	}
-
 	user->idx = log_next(user->idx);
 	user->seq++;
 	raw_spin_unlock_irq(&logbuf_lock);
 
-	len = p - user->buf;
 	if (len > count) {
 		ret = -EINVAL;
 		goto out;
-- 
2.1.0

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

[Tejun Heo]

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
so that console consumers can get full information including the
metadata and dictionary, which among other things can be used to
detect whether messages got lost in transit.

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

 "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n"

If extended consoles exist, in-kernel fragment assembly is disabled.
This ensures that all messages emitted to consoles have full metadata
including sequence number.  The contflag carries enough information to
reassemble the fragments from the reader side trivially.  Note that
this only affects /dev/kmsg.  Regular console and /proc/kmsg outputs
are not affected by this change.

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

* Comment describing /dev/kmsg message format updated to add missing
  contflag field and help distinguishing variable from verbatim terms.

v2: Disable in-kernel cont buffer if extended consoles are present
    which simplifies things quite a bit.  Hinted by Petr.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Petr Mladek <pmladek@suse.cz>
---
 include/linux/console.h |  1 +
 kernel/printk/printk.c  | 65 +++++++++++++++++++++++++++++++++++++++++++------
 2 files changed, 58 insertions(+), 8 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 9f50fb4..bd19434 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 51ce4f1..9cc2664 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -85,6 +85,18 @@ static struct lockdep_map console_lock_dep_map = {
 #endif
 
 /*
+ * Number of registered extended console drivers.
+ *
+ * If extended consoles are present, in-kernel cont reassembly is disabled
+ * and each fragment is stored as a separate log entry with proper
+ * continuation flag so that every emitted message has full metadata.  This
+ * doesn't change the result for regular consoles or /proc/kmsg.  For
+ * /dev/kmsg, as long as the reader concatenates messages according to
+ * consecutive continuation flags, the end result should be the same too.
+ */
+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,7 +207,7 @@ 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
@@ -1417,7 +1429,9 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
  * log_buf[start] to log_buf[end - 1].
  * The console_lock must be held.
  */
-static void call_console_drivers(int level, const char *text, size_t len)
+static void call_console_drivers(int level,
+				 const char *ext_text, size_t ext_len,
+				 const char *text, size_t len)
 {
 	struct console *con;
 
@@ -1438,7 +1452,10 @@ static void call_console_drivers(int level, const char *text, size_t len)
 		if (!cpu_online(smp_processor_id()) &&
 		    !(con->flags & CON_ANYTIME))
 			continue;
-		con->write(con, text, len);
+		if (con->flags & CON_EXTENDED)
+			con->write(con, ext_text, ext_len);
+		else
+			con->write(con, text, len);
 	}
 }
 
@@ -1581,8 +1598,12 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	if (cont.len && cont.flushed)
 		return false;
 
-	if (cont.len + len > sizeof(cont.buf)) {
-		/* the line gets too long, split it up in separate records */
+	/*
+	 * If ext consoles are present, flush and skip in-kernel
+	 * continuation.  See nr_ext_console_drivers definition.  Also, if
+	 * the line gets too long, split it up in separate records.
+	 */
+	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
 		cont_flush(LOG_CONT);
 		return false;
 	}
@@ -1917,9 +1938,19 @@ static struct cont {
 	u8 level;
 	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 struct printk_log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
-static void call_console_drivers(int level, const char *text, size_t len) {}
+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,
+				 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; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
@@ -2172,7 +2203,7 @@ static void console_cont_flush(char *text, size_t size)
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
-	call_console_drivers(cont.level, text, len);
+	call_console_drivers(cont.level, NULL, 0, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
@@ -2196,6 +2227,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;
@@ -2214,6 +2246,7 @@ void console_unlock(void)
 again:
 	for (;;) {
 		struct printk_log *msg;
+		size_t ext_len = 0;
 		size_t len;
 		int level;
 
@@ -2259,13 +2292,22 @@ skip:
 		level = msg->level;
 		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), msg->dict_len,
+						log_text(msg), msg->text_len);
+		}
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, text, len);
+		call_console_drivers(level, ext_text, ext_len, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 	}
@@ -2521,6 +2563,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
@@ -2593,6 +2639,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

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Andrew Morton]

On Wed, 29 Apr 2015 10:45:04 -0400 Tejun Heo <tj@kernel.org> wrote:

> 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
> so that console consumers can get full information including the
> metadata and dictionary, which among other things can be used to
> detect whether messages got lost in transit.
> 
> This patch implements support for extended console drivers.  Consoles
> can indicate that they want extended messages by setting the new
> CON_EXTENDED flag and they'll be fed messages formatted the same way
> as /dev/kmsg.
> 
>  "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n"
> 
> If extended consoles exist, in-kernel fragment assembly is disabled.
> This ensures that all messages emitted to consoles have full metadata
> including sequence number.  The contflag carries enough information to
> reassemble the fragments from the reader side trivially.  Note that
> this only affects /dev/kmsg.  Regular console and /proc/kmsg outputs
> are not affected by this change.
> 
> * Extended message formatting for console drivers is enabled iff there
>   are registered extended consoles.
> 
> * Comment describing /dev/kmsg message format updated to add missing
>   contflag field and help distinguishing variable from verbatim terms.

So if I'm understanding this correctly, the /dev/kmsg output is altered
(different cont handling) if some console registers with CON_EXTENDED
(and there are no such consoles yet, so the patch is a no-op).

If correct, this seems undesirable - registration of a CON_EXTENDED
console collaterally damages the /dev/kmsg interface?  If the user has
an app which depends on the original /dev/kmsg format then they'll be
wondered what-the-heck-just-happened?

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Tejun Heo]

Hello, Andrew.

On Thu, Apr 30, 2015 at 02:31:28PM -0700, Andrew Morton wrote:
> So if I'm understanding this correctly, the /dev/kmsg output is altered
> (different cont handling) if some console registers with CON_EXTENDED
> (and there are no such consoles yet, so the patch is a no-op).

Yeah, that's mostly right.  /dev/kmsg output already has
"continuation" flag which indicates whether a message should be
concatenated which gets triggered occassionally currently.  This would
make use of that behavior a lot more frequently.

> If correct, this seems undesirable - registration of a CON_EXTENDED
> console collaterally damages the /dev/kmsg interface?  If the user has
> an app which depends on the original /dev/kmsg format then they'll be
> wondered what-the-heck-just-happened?

For applications which ignore the continuation flags, this would lead
to a different output.  We can fake it for /dev/kmsg (concatenate from
the kernel side and then output empty message for the later fragments)
but that'd be piling more hacks on top of already unnecessary hack
which is the cont buffer.

We can generate a log message indicating that the new mode is enabled
to make it easier to figure out why it changed.  Given that this is
not an entirely new behavior and the usage of extended console is
likely to stay fairly specific, transitioning this way is unlikely to
cause too much trouble especially given that most traditional tools
use the older interfaces w/o metadata which aren't affected by this
change.

What do you think?

Thanks.

-- 
tejun

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Andrew Morton]

On Thu, 30 Apr 2015 18:12:31 -0400 Tejun Heo <tj@kernel.org> wrote:

> Hello, Andrew.
> 
> On Thu, Apr 30, 2015 at 02:31:28PM -0700, Andrew Morton wrote:
> > So if I'm understanding this correctly, the /dev/kmsg output is altered
> > (different cont handling) if some console registers with CON_EXTENDED
> > (and there are no such consoles yet, so the patch is a no-op).
> 
> Yeah, that's mostly right.  /dev/kmsg output already has
> "continuation" flag which indicates whether a message should be
> concatenated which gets triggered occassionally currently.  This would
> make use of that behavior a lot more frequently.

OK, sounds reasonable.

> > If correct, this seems undesirable - registration of a CON_EXTENDED
> > console collaterally damages the /dev/kmsg interface?  If the user has
> > an app which depends on the original /dev/kmsg format then they'll be
> > wondered what-the-heck-just-happened?
> 
> For applications which ignore the continuation flags, this would lead
> to a different output.  We can fake it for /dev/kmsg (concatenate from
> the kernel side and then output empty message for the later fragments)
> but that'd be piling more hacks on top of already unnecessary hack
> which is the cont buffer.
> 
> We can generate a log message indicating that the new mode is enabled
> to make it easier to figure out why it changed.  Given that this is
> not an entirely new behavior and the usage of extended console is
> likely to stay fairly specific, transitioning this way is unlikely to
> cause too much trouble especially given that most traditional tools
> use the older interfaces w/o metadata which aren't affected by this
> change.
> 
> What do you think?

Yes, I suppose a printk is worthwhile.  Maybe a paragraph in
Documentation/ABI/testing/dev-kmsg also.

[PATCH v3 3/3] printk: implement support for extended console drivers

[Tejun Heo]

>From a69336f8df52f9ccdf33dfb5410108eec4d27742 Mon Sep 17 00:00:00 2001
From: Tejun Heo <tj@kernel.org>
Date: Fri, 1 May 2015 12:21:01 -0400

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
so that console consumers can get full information including the
metadata and dictionary, which among other things can be used to
detect whether messages got lost in transit.

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

 "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n"

If extended consoles exist, in-kernel fragment assembly is disabled.
This ensures that all messages emitted to consoles have full metadata
including sequence number.  The contflag carries enough information to
reassemble the fragments from the reader side trivially.  Note that
this only affects /dev/kmsg.  Regular console and /proc/kmsg outputs
are not affected by this change.

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

* Comment describing /dev/kmsg message format updated to add missing
  contflag field and help distinguishing variable from verbatim terms.

v3: Added pr_info() to inform the user to expect more fragments when
    ext console is enabled.  Also, Documentation/ABI/testing/dev-kmsg
    is updated accordingly as suggested by Andrew.

v2: Disable in-kernel cont buffer if extended consoles are present
    which simplifies things quite a bit.  Hinted by Petr.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Petr Mladek <pmladek@suse.cz>
Cc: Andrew Morton <akpm@linux-foundation.org>
---
 Documentation/ABI/testing/dev-kmsg |  9 ++++++
 include/linux/console.h            |  1 +
 kernel/printk/printk.c             | 66 +++++++++++++++++++++++++++++++++-----
 3 files changed, 68 insertions(+), 8 deletions(-)

diff --git a/Documentation/ABI/testing/dev-kmsg b/Documentation/ABI/testing/dev-kmsg
index bb820be..fff817e 100644
--- a/Documentation/ABI/testing/dev-kmsg
+++ b/Documentation/ABI/testing/dev-kmsg
@@ -98,4 +98,13 @@ Description:	The /dev/kmsg character device node provides userspace access
 		logic is used internally when messages are printed to the
 		console, /proc/kmsg or the syslog() syscall.
 
+		By default, kernel tries to avoid fragments by concatenating
+		when it can and fragments are rare; however, when extended
+		console support is enabled, the in-kernel concatenation is
+		disabled and /dev/kmsg output will contain more fragments. If
+		the log consumer performs concatenation, the end result
+		should be the same. In the future, the in-kernel concatenation
+		may be removed entirely and /dev/kmsg users are recommended to
+		implement fragment handling.
+
 Users:		dmesg(1), userspace kernel log consumers
diff --git a/include/linux/console.h b/include/linux/console.h
index 9f50fb4..bd19434 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 51ce4f1..ae980dc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -85,6 +85,18 @@ static struct lockdep_map console_lock_dep_map = {
 #endif
 
 /*
+ * Number of registered extended console drivers.
+ *
+ * If extended consoles are present, in-kernel cont reassembly is disabled
+ * and each fragment is stored as a separate log entry with proper
+ * continuation flag so that every emitted message has full metadata.  This
+ * doesn't change the result for regular consoles or /proc/kmsg.  For
+ * /dev/kmsg, as long as the reader concatenates messages according to
+ * consecutive continuation flags, the end result should be the same too.
+ */
+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,7 +207,7 @@ 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
@@ -1417,7 +1429,9 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
  * log_buf[start] to log_buf[end - 1].
  * The console_lock must be held.
  */
-static void call_console_drivers(int level, const char *text, size_t len)
+static void call_console_drivers(int level,
+				 const char *ext_text, size_t ext_len,
+				 const char *text, size_t len)
 {
 	struct console *con;
 
@@ -1438,7 +1452,10 @@ static void call_console_drivers(int level, const char *text, size_t len)
 		if (!cpu_online(smp_processor_id()) &&
 		    !(con->flags & CON_ANYTIME))
 			continue;
-		con->write(con, text, len);
+		if (con->flags & CON_EXTENDED)
+			con->write(con, ext_text, ext_len);
+		else
+			con->write(con, text, len);
 	}
 }
 
@@ -1581,8 +1598,12 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	if (cont.len && cont.flushed)
 		return false;
 
-	if (cont.len + len > sizeof(cont.buf)) {
-		/* the line gets too long, split it up in separate records */
+	/*
+	 * If ext consoles are present, flush and skip in-kernel
+	 * continuation.  See nr_ext_console_drivers definition.  Also, if
+	 * the line gets too long, split it up in separate records.
+	 */
+	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
 		cont_flush(LOG_CONT);
 		return false;
 	}
@@ -1917,9 +1938,19 @@ static struct cont {
 	u8 level;
 	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 struct printk_log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
-static void call_console_drivers(int level, const char *text, size_t len) {}
+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,
+				 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; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
@@ -2172,7 +2203,7 @@ static void console_cont_flush(char *text, size_t size)
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
-	call_console_drivers(cont.level, text, len);
+	call_console_drivers(cont.level, NULL, 0, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
@@ -2196,6 +2227,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;
@@ -2214,6 +2246,7 @@ void console_unlock(void)
 again:
 	for (;;) {
 		struct printk_log *msg;
+		size_t ext_len = 0;
 		size_t len;
 		int level;
 
@@ -2259,13 +2292,22 @@ skip:
 		level = msg->level;
 		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), msg->dict_len,
+						log_text(msg), msg->text_len);
+		}
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, text, len);
+		call_console_drivers(level, ext_text, ext_len, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 	}
@@ -2521,6 +2563,11 @@ void register_console(struct console *newcon)
 		newcon->next = console_drivers->next;
 		console_drivers->next = newcon;
 	}
+
+	if (newcon->flags & CON_EXTENDED)
+		if (!nr_ext_console_drivers++)
+			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
 		 * console_unlock(); will print out the buffered messages
@@ -2593,6 +2640,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

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Geert Uytterhoeven]

Hi Tejun,

On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote:
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c

> @@ -2196,6 +2227,7 @@ out:
>   */
>  void console_unlock(void)
>  {
> +       static char ext_text[CONSOLE_EXT_LOG_MAX];

Can you please
  a) make this feature optional,
  b) (de)allocate this buffer dynamically when the first/last console with
      CON_EXTENDED set is (un)registered?

Your patch is at the top of the bloat-o-meter output (against v4.1):

add/remove: 388/154 grow/shrink: 1309/269 up/down: 92366/-44878 (47488)
function                                     old     new   delta
ext_text                                       -    8192   +8192
do_con_trol                                    -    4824   +4824
path_openat                                 1416    4224   +2808
tvec_bases                                     4    2080   +2076
ip_do_fragment                                 -    1824   +1824
unix_stream_read_generic                       -    1452   +1452
ext4_ext_shift_extents                         -    1350   +1350
ext4_insert_range                              -    1174   +1174
bpf_prepare_filter                           264    1430   +1166
proc_pid_cmdline_read                          -    1020   +1020

and unlike the others, this one is not that difficult to fix.

Thanks!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Tejun Heo]

Hello,

On Mon, Jun 29, 2015 at 11:20:41AM +0200, Geert Uytterhoeven wrote:
> On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote:
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> 
> > @@ -2196,6 +2227,7 @@ out:
> >   */
> >  void console_unlock(void)
> >  {
> > +       static char ext_text[CONSOLE_EXT_LOG_MAX];
> 
> Can you please
>   a) make this feature optional,

netconsole itself is optional & modular.  I'm not sure making further
splits is called for, especially given the use cases.

>   b) (de)allocate this buffer dynamically when the first/last console with
>       CON_EXTENDED set is (un)registered?

But yeah, making the buffer allocated on demand should be simple
enough.  Will get to it.

Thanks.

-- 
tejun

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Geert Uytterhoeven]

Hi Tejun,

On Mon, Jun 29, 2015 at 5:28 PM, Tejun Heo <tj@kernel.org> wrote:
> On Mon, Jun 29, 2015 at 11:20:41AM +0200, Geert Uytterhoeven wrote:
>> On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote:
>> > --- a/kernel/printk/printk.c
>> > +++ b/kernel/printk/printk.c
>>
>> > @@ -2196,6 +2227,7 @@ out:
>> >   */
>> >  void console_unlock(void)
>> >  {
>> > +       static char ext_text[CONSOLE_EXT_LOG_MAX];
>>
>> Can you please
>>   a) make this feature optional,
>
> netconsole itself is optional & modular.  I'm not sure making further
> splits is called for, especially given the use cases.

It could be a hidden option, selected by its users (e.g. netconsole).

>>   b) (de)allocate this buffer dynamically when the first/last console with
>>       CON_EXTENDED set is (un)registered?
>
> But yeah, making the buffer allocated on demand should be simple
> enough.  Will get to it.

Thanks!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Tejun Heo]

On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote:
> > netconsole itself is optional & modular.  I'm not sure making further
> > splits is called for, especially given the use cases.
> 
> It could be a hidden option, selected by its users (e.g. netconsole).

Hmmm... what do you mean?

Thanks.

-- 
tejun

Re: [PATCH 3/3] printk: implement support for extended console drivers

[josh]

On Mon, Jun 29, 2015 at 11:49:14AM -0400, Tejun Heo wrote:
> On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote:
> > > netconsole itself is optional & modular.  I'm not sure making further
> > > splits is called for, especially given the use cases.
> > 
> > It could be a hidden option, selected by its users (e.g. netconsole).
> 
> Hmmm... what do you mean?

config PRINTK_BITS_THAT_NETCONSOLE_NEEDS

(no help text or prompt)

config NETCONSOLE
    select PRINTK_BITS_THAT_NETCONSOLE_NEEDS

That would ensure that the bits added to printk don't get compiled in
unless CONFIG_NETCONSOLE=y.

- Josh Triplett

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Geert Uytterhoeven]

On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote:
> On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote:
>> > netconsole itself is optional & modular.  I'm not sure making further
>> > splits is called for, especially given the use cases.
>>
>> It could be a hidden option, selected by its users (e.g. netconsole).
>
> Hmmm... what do you mean?

init/Kconfig:

        config PRINTK_EXT_LOG
                bool

drivers/net/Kconfig:

        config NETCONSOLE
                tristate "Network console logging support"
                select PRINTK_EXT_LOG

kernel/printk/printk.c:

        void console_unlock(void)
        {
#ifdef CONFIG_PRINTK_EXT_LOG
                static char ext_text[CONSOLE_EXT_LOG_MAX];
#endif

etc.

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH 3/3] printk: implement support for extended console drivers

[Tejun Heo]

On Mon, Jun 29, 2015 at 06:11:40PM +0200, Geert Uytterhoeven wrote:
> On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote:
> > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote:
> >> > netconsole itself is optional & modular.  I'm not sure making further
> >> > splits is called for, especially given the use cases.
> >>
> >> It could be a hidden option, selected by its users (e.g. netconsole).
> >
> > Hmmm... what do you mean?
> 
> init/Kconfig:
> 
>         config PRINTK_EXT_LOG
>                 bool
> 
> drivers/net/Kconfig:
> 
>         config NETCONSOLE
>                 tristate "Network console logging support"
>                 select PRINTK_EXT_LOG
> 
> kernel/printk/printk.c:
> 
>         void console_unlock(void)
>         {
> #ifdef CONFIG_PRINTK_EXT_LOG
>                 static char ext_text[CONSOLE_EXT_LOG_MAX];
> #endif

OIC, hmmm... yeah, I think doing it on-demand would be better but will
try to find out which way is better.

Thanks!

-- 
tejun

Re: [PATCH 3/3] printk: implement support for extended console drivers

[josh]

On Mon, Jun 29, 2015 at 12:13:55PM -0400, Tejun Heo wrote:
> On Mon, Jun 29, 2015 at 06:11:40PM +0200, Geert Uytterhoeven wrote:
> > On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote:
> > > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote:
> > >> > netconsole itself is optional & modular.  I'm not sure making further
> > >> > splits is called for, especially given the use cases.
> > >>
> > >> It could be a hidden option, selected by its users (e.g. netconsole).
> > >
> > > Hmmm... what do you mean?
> > 
> > init/Kconfig:
> > 
> >         config PRINTK_EXT_LOG
> >                 bool
> > 
> > drivers/net/Kconfig:
> > 
> >         config NETCONSOLE
> >                 tristate "Network console logging support"
> >                 select PRINTK_EXT_LOG
> > 
> > kernel/printk/printk.c:
> > 
> >         void console_unlock(void)
> >         {
> > #ifdef CONFIG_PRINTK_EXT_LOG
> >                 static char ext_text[CONSOLE_EXT_LOG_MAX];
> > #endif
> 
> OIC, hmmm... yeah, I think doing it on-demand would be better but will
> try to find out which way is better.

Allocating the buffer dynamically is fine, but in that case the code to
do so should ideally be compiled out.  Since printk is used by almost
*all* kernels, while netconsole is not, it's more critical to avoid
allowing printk's size to balloon.

- Josh Triplett

[PATCH v4.2-rc1] printk: make extended printk support conditional on netconsole

[Tejun Heo]

6fe29354befe ("printk: implement support for extended console
drivers") implemented extended printk support for extended netconsole.
The code added was miniscule but it added static 8k buffer
unconditionally unnecessarily bloating the kernel for cases where
extended netconsole is not used.

This patch introduces CONFIG_PRINTK_CON_EXTENDED which is selected by
CONFIG_NETCONSOLE.  If the config option is not set, extended printk
support is compiled out along with the static buffer.

Verified 8k reduction in vmlinux bss when !CONFIG_NETCONSOLE.

Signed-off-by: Tejun Heo <tj@kernel.org>
Reported-and-suggested-by: Geert Uytterhoeven <geert@linux-m68k.org>
---
Linus, Andrew.

This removes an unnecessary 8k bss bloat introduced during v4.2-rc1
merge window on certain configs.  The original patch was routed
through -mm.  How should this be routed?

Thanks.

 drivers/net/Kconfig    |    1 +
 init/Kconfig           |    3 +++
 kernel/printk/printk.c |   33 +++++++++++++++++++++++++++++----
 3 files changed, 33 insertions(+), 4 deletions(-)

--- a/drivers/net/Kconfig
+++ b/drivers/net/Kconfig
@@ -195,6 +195,7 @@ config GENEVE
 
 config NETCONSOLE
 	tristate "Network console logging support"
+	select PRINTK_CON_EXTENDED
 	---help---
 	If you want to log kernel messages over the network, enable this.
 	See <file:Documentation/networking/netconsole.txt> for details.
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -1438,6 +1438,9 @@ config PRINTK
 	  very difficult to diagnose system problems, saying N here is
 	  strongly discouraged.
 
+config PRINTK_CON_EXTENDED
+	bool
+
 config BUG
 	bool "BUG() support" if EXPERT
 	default y
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -84,6 +84,10 @@ static struct lockdep_map console_lock_d
 };
 #endif
 
+#ifdef CONFIG_PRINTK_CON_EXTENDED
+
+#define CONSOLE_EXT_LOG_BUF_LEN		CONSOLE_EXT_LOG_MAX
+
 /*
  * Number of registered extended console drivers.
  *
@@ -96,6 +100,25 @@ static struct lockdep_map console_lock_d
  */
 static int nr_ext_console_drivers;
 
+static void inc_nr_ext_console_drivers(void)
+{
+	nr_ext_console_drivers++;
+}
+
+static void dec_nr_ext_console_drivers(void)
+{
+	nr_ext_console_drivers--;
+}
+
+#else	/* CONFIG_PRINTK_CON_EXTENDED */
+
+#define CONSOLE_EXT_LOG_BUF_LEN		0
+#define nr_ext_console_drivers		0
+static void inc_nr_ext_console_drivers(void) { }
+static void dec_nr_ext_console_drivers(void) { }
+
+#endif	/* CONFIG_PRINTK_CON_EXTENDED */
+
 /*
  * Helper macros to handle lockdep when locking/unlocking console_sem. We use
  * macros instead of functions so that _RET_IP_ contains useful information.
@@ -2224,7 +2247,7 @@ out:
  */
 void console_unlock(void)
 {
-	static char ext_text[CONSOLE_EXT_LOG_MAX];
+	static char ext_text[CONSOLE_EXT_LOG_BUF_LEN];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
 	static u64 seen_seq;
 	unsigned long flags;
@@ -2561,9 +2584,11 @@ void register_console(struct console *ne
 		console_drivers->next = newcon;
 	}
 
-	if (newcon->flags & CON_EXTENDED)
-		if (!nr_ext_console_drivers++)
+	if (newcon->flags & CON_EXTENDED) {
+		if (!nr_ext_console_drivers)
 			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+		inc_nr_ext_console_drivers();
+	}
 
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
@@ -2638,7 +2663,7 @@ int unregister_console(struct console *c
 	}
 
 	if (!res && (console->flags & CON_EXTENDED))
-		nr_ext_console_drivers--;
+		dec_nr_ext_console_drivers();
 
 	/*
 	 * If this isn't the last console and it has CON_CONSDEV set, we

Re: [PATCH v4.2-rc1] printk: make extended printk support conditional on netconsole

[Petr Mladek]

On Mon 2015-06-29 19:31:40, Tejun Heo wrote:
> 6fe29354befe ("printk: implement support for extended console
> drivers") implemented extended printk support for extended netconsole.
> The code added was miniscule but it added static 8k buffer
> unconditionally unnecessarily bloating the kernel for cases where
> extended netconsole is not used.
> 
> This patch introduces CONFIG_PRINTK_CON_EXTENDED which is selected by
> CONFIG_NETCONSOLE.  If the config option is not set, extended printk
> support is compiled out along with the static buffer.
> 
> Verified 8k reduction in vmlinux bss when !CONFIG_NETCONSOLE.
> 
> Signed-off-by: Tejun Heo <tj@kernel.org>
> Reported-and-suggested-by: Geert Uytterhoeven <geert@linux-m68k.org>
> ---
> Linus, Andrew.
> 
> This removes an unnecessary 8k bss bloat introduced during v4.2-rc1
> merge window on certain configs.  The original patch was routed
> through -mm.  How should this be routed?
> 
> Thanks.
> 
>  drivers/net/Kconfig    |    1 +
>  init/Kconfig           |    3 +++
>  kernel/printk/printk.c |   33 +++++++++++++++++++++++++++++----
>  3 files changed, 33 insertions(+), 4 deletions(-)

[...]

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
[...]
> @@ -2561,9 +2584,11 @@ void register_console(struct console *ne
>  		console_drivers->next = newcon;
>  	}
>  
> -	if (newcon->flags & CON_EXTENDED)
> -		if (!nr_ext_console_drivers++)
> +	if (newcon->flags & CON_EXTENDED) {
> +		if (!nr_ext_console_drivers)
>  			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
> +		inc_nr_ext_console_drivers();

We should handle also the situation when CON_EXTENDED is set
and CONFIG_PRINTK_CON_EXTENDED is not set by mistake. Otherwise,
we will not increment nr_ext_console_drivers here => ext_text will
not be filled in console_unlock() => call_console_drivers()
will print nothing for the CON_EXTENDED console.

At least, I would print an error here. Something like.

#ifndef CONFIG_PRINTK_CON_EXTENDED
		pr_err("The registered extended console will print nothing because the kernel is not compiled with PRINTK_CON_EXTENDED\n");
#endif

I wonder if there is a good identification of the console that can be printed.

Otherwise, it looks fine to me.

Best Regards,
Petr

[PATCH v2 v4.2-rc1] printk: make extended printk support conditional on netconsole

[Tejun Heo]

6fe29354befe ("printk: implement support for extended console
drivers") implemented extended printk support for extended netconsole.
The code added was miniscule but it added static 8k buffer
unconditionally unnecessarily bloating the kernel for cases where
extended netconsole is not used.

This patch introduces CONFIG_PRINTK_CON_EXTENDED which is selected by
CONFIG_NETCONSOLE.  If the config option is not set, extended printk
support is compiled out along with the static buffer.

Verified 8k reduction in vmlinux bss when !CONFIG_NETCONSOLE.

v2: Added a warning for cases where CON_EXTENDED is requested while
    CONFIG_PRINTK_CON_EXTENDED is disabled as suggested by Petr.

Cc: Petr Mladek <pmladek@suse.com>
Signed-off-by: Tejun Heo <tj@kernel.org>
Reported-and-suggested-by: Geert Uytterhoeven <geert@linux-m68k.org>
---
 drivers/net/Kconfig    |    1 +
 init/Kconfig           |    3 +++
 kernel/printk/printk.c |   40 ++++++++++++++++++++++++++++++++++++----
 3 files changed, 40 insertions(+), 4 deletions(-)

diff --git a/drivers/net/Kconfig b/drivers/net/Kconfig
index 019fcef..39587f1 100644
--- a/drivers/net/Kconfig
+++ b/drivers/net/Kconfig
@@ -195,6 +195,7 @@ config GENEVE
 
 config NETCONSOLE
 	tristate "Network console logging support"
+	select PRINTK_CON_EXTENDED
 	---help---
 	If you want to log kernel messages over the network, enable this.
 	See <file:Documentation/networking/netconsole.txt> for details.
diff --git a/init/Kconfig b/init/Kconfig
index bcc41bd..cd281ab 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -1438,6 +1438,9 @@ config PRINTK
 	  very difficult to diagnose system problems, saying N here is
 	  strongly discouraged.
 
+config PRINTK_CON_EXTENDED
+	bool
+
 config BUG
 	bool "BUG() support" if EXPERT
 	default y
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cf8c242..f719118 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -84,6 +84,10 @@ static struct lockdep_map console_lock_dep_map = {
 };
 #endif
 
+#ifdef CONFIG_PRINTK_CON_EXTENDED
+
+#define CONSOLE_EXT_LOG_BUF_LEN		CONSOLE_EXT_LOG_MAX
+
 /*
  * Number of registered extended console drivers.
  *
@@ -96,6 +100,32 @@ static struct lockdep_map console_lock_dep_map = {
  */
 static int nr_ext_console_drivers;
 
+static void inc_nr_ext_console_drivers(void)
+{
+	nr_ext_console_drivers++;
+}
+
+static void dec_nr_ext_console_drivers(void)
+{
+	nr_ext_console_drivers--;
+}
+
+#else	/* CONFIG_PRINTK_CON_EXTENDED */
+
+#define CONSOLE_EXT_LOG_BUF_LEN		0
+#define nr_ext_console_drivers		0
+
+static void inc_nr_ext_console_drivers(void)
+{
+	WARN_ONCE(true, "printk: CON_EXTENDED requested when !CONFIG_PRINTK_CON_EXTENDED\n");
+}
+
+static void dec_nr_ext_console_drivers(void)
+{
+}
+
+#endif	/* CONFIG_PRINTK_CON_EXTENDED */
+
 /*
  * Helper macros to handle lockdep when locking/unlocking console_sem. We use
  * macros instead of functions so that _RET_IP_ contains useful information.
@@ -2224,7 +2254,7 @@ static void console_cont_flush(char *text, size_t size)
  */
 void console_unlock(void)
 {
-	static char ext_text[CONSOLE_EXT_LOG_MAX];
+	static char ext_text[CONSOLE_EXT_LOG_BUF_LEN];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
 	static u64 seen_seq;
 	unsigned long flags;
@@ -2561,9 +2591,11 @@ void register_console(struct console *newcon)
 		console_drivers->next = newcon;
 	}
 
-	if (newcon->flags & CON_EXTENDED)
-		if (!nr_ext_console_drivers++)
+	if (newcon->flags & CON_EXTENDED) {
+		if (!nr_ext_console_drivers)
 			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+		inc_nr_ext_console_drivers();
+	}
 
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
@@ -2638,7 +2670,7 @@ int unregister_console(struct console *console)
 	}
 
 	if (!res && (console->flags & CON_EXTENDED))
-		nr_ext_console_drivers--;
+		dec_nr_ext_console_drivers();
 
 	/*
 	 * If this isn't the last console and it has CON_CONSDEV set, we

Re: [PATCH v2 v4.2-rc1] printk: make extended printk support conditional on netconsole

[Petr Mladek]

On Thu 2015-07-02 12:21:41, Tejun Heo wrote:
> 6fe29354befe ("printk: implement support for extended console
> drivers") implemented extended printk support for extended netconsole.
> The code added was miniscule but it added static 8k buffer
> unconditionally unnecessarily bloating the kernel for cases where
> extended netconsole is not used.
> 
> This patch introduces CONFIG_PRINTK_CON_EXTENDED which is selected by
> CONFIG_NETCONSOLE.  If the config option is not set, extended printk
> support is compiled out along with the static buffer.
> 
> Verified 8k reduction in vmlinux bss when !CONFIG_NETCONSOLE.
> 
> v2: Added a warning for cases where CON_EXTENDED is requested while
>     CONFIG_PRINTK_CON_EXTENDED is disabled as suggested by Petr.
> 
> Cc: Petr Mladek <pmladek@suse.com>
> Signed-off-by: Tejun Heo <tj@kernel.org>
> Reported-and-suggested-by: Geert Uytterhoeven <geert@linux-m68k.org>

Reviewed-by: Petr Mladek <pmladek@suse.cz>

There is still one small thing that might get improved, see below.
But it is not that important and might be solved later. I am sorry
for not noticing it last time.


> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index cf8c242..f719118 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -84,6 +84,10 @@ static struct lockdep_map console_lock_dep_map = {
>  };
>  #endif
>  
> +#ifdef CONFIG_PRINTK_CON_EXTENDED
> +
> +#define CONSOLE_EXT_LOG_BUF_LEN		CONSOLE_EXT_LOG_MAX
> +
>  /*
>   * Number of registered extended console drivers.
>   *
> @@ -96,6 +100,32 @@ static struct lockdep_map console_lock_dep_map = {
>   */
>  static int nr_ext_console_drivers;
>  
> +static void inc_nr_ext_console_drivers(void)
> +{
> +	nr_ext_console_drivers++;
> +}
> +
> +static void dec_nr_ext_console_drivers(void)
> +{
> +	nr_ext_console_drivers--;
> +}
> +
> +#else	/* CONFIG_PRINTK_CON_EXTENDED */
> +
> +#define CONSOLE_EXT_LOG_BUF_LEN		0
> +#define nr_ext_console_drivers		0
> +
> +static void inc_nr_ext_console_drivers(void)
> +{
> +	WARN_ONCE(true, "printk: CON_EXTENDED requested when !CONFIG_PRINTK_CON_EXTENDED\n");
> +}
> +
> +static void dec_nr_ext_console_drivers(void)
> +{
> +}
> +
> +#endif	/* CONFIG_PRINTK_CON_EXTENDED */
> +
>  /*
>   * Helper macros to handle lockdep when locking/unlocking console_sem. We use
>   * macros instead of functions so that _RET_IP_ contains useful information.
> @@ -2561,9 +2591,11 @@ void register_console(struct console *newcon)
>  		console_drivers->next = newcon;
>  	}
>  
> -	if (newcon->flags & CON_EXTENDED)
> -		if (!nr_ext_console_drivers++)
> +	if (newcon->flags & CON_EXTENDED) {
> +		if (!nr_ext_console_drivers)
>  			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");

I would move the check and the message into
inc_nr_ext_console_drivers() when CONFIG_PRINTK_CON_EXTENDED is
defined. It does not make sense if we do not increment the counter.

Best Regards,
Petr

Re: [PATCH v2 v4.2-rc1] printk: make extended printk support conditional on netconsole

[Tejun Heo]

On Fri, Jul 03, 2015 at 04:07:34PM +0200, Petr Mladek wrote:
> > @@ -2561,9 +2591,11 @@ void register_console(struct console *newcon)
> >  		console_drivers->next = newcon;
> >  	}
> >  
> > -	if (newcon->flags & CON_EXTENDED)
> > -		if (!nr_ext_console_drivers++)
> > +	if (newcon->flags & CON_EXTENDED) {
> > +		if (!nr_ext_console_drivers)
> >  			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
> 
> I would move the check and the message into
> inc_nr_ext_console_drivers() when CONFIG_PRINTK_CON_EXTENDED is
> defined. It does not make sense if we do not increment the counter.

It doesn't make any difference as it gets compiled out anyway but yeah
moving it into the inc function makes more sense.  Updating the patch.

Thanks.

-- 
tejun

[PATCH v3 v4.2-rc1] printk: make extended printk support conditional on netconsole

[Tejun Heo]

6fe29354befe ("printk: implement support for extended console
drivers") implemented extended printk support for extended netconsole.
The code added was miniscule but it added static 8k buffer
unconditionally unnecessarily bloating the kernel for cases where
extended netconsole is not used.

This patch introduces CONFIG_PRINTK_CON_EXTENDED which is selected by
CONFIG_NETCONSOLE.  If the config option is not set, extended printk
support is compiled out along with the static buffer.

Verified 8k reduction in vmlinux bss when !CONFIG_NETCONSOLE.

v2: Added a warning for cases where CON_EXTENDED is requested while
    CONFIG_PRINTK_CON_EXTENDED is disabled as suggested by Petr.

v3: Moved ext console enable info messages into the inc function.

Signed-off-by: Tejun Heo <tj@kernel.org>
Reported-and-suggested-by: Geert Uytterhoeven <geert@linux-m68k.org>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 drivers/net/Kconfig    |    1 +
 init/Kconfig           |    3 +++
 kernel/printk/printk.c |   38 ++++++++++++++++++++++++++++++++++----
 3 files changed, 38 insertions(+), 4 deletions(-)

diff --git a/drivers/net/Kconfig b/drivers/net/Kconfig
index 019fcef..39587f1 100644
--- a/drivers/net/Kconfig
+++ b/drivers/net/Kconfig
@@ -195,6 +195,7 @@ config GENEVE
 
 config NETCONSOLE
 	tristate "Network console logging support"
+	select PRINTK_CON_EXTENDED
 	---help---
 	If you want to log kernel messages over the network, enable this.
 	See <file:Documentation/networking/netconsole.txt> for details.
diff --git a/init/Kconfig b/init/Kconfig
index bcc41bd..cd281ab 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -1438,6 +1438,9 @@ config PRINTK
 	  very difficult to diagnose system problems, saying N here is
 	  strongly discouraged.
 
+config PRINTK_CON_EXTENDED
+	bool
+
 config BUG
 	bool "BUG() support" if EXPERT
 	default y
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cf8c242..841ea4d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -84,6 +84,10 @@ static struct lockdep_map console_lock_dep_map = {
 };
 #endif
 
+#ifdef CONFIG_PRINTK_CON_EXTENDED
+
+#define CONSOLE_EXT_LOG_BUF_LEN		CONSOLE_EXT_LOG_MAX
+
 /*
  * Number of registered extended console drivers.
  *
@@ -96,6 +100,33 @@ static struct lockdep_map console_lock_dep_map = {
  */
 static int nr_ext_console_drivers;
 
+static void inc_nr_ext_console_drivers(void)
+{
+	if (!nr_ext_console_drivers++)
+		pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+}
+
+static void dec_nr_ext_console_drivers(void)
+{
+	nr_ext_console_drivers--;
+}
+
+#else	/* CONFIG_PRINTK_CON_EXTENDED */
+
+#define CONSOLE_EXT_LOG_BUF_LEN		0
+#define nr_ext_console_drivers		0
+
+static void inc_nr_ext_console_drivers(void)
+{
+	WARN_ONCE(true, "printk: CON_EXTENDED requested when !CONFIG_PRINTK_CON_EXTENDED\n");
+}
+
+static void dec_nr_ext_console_drivers(void)
+{
+}
+
+#endif	/* CONFIG_PRINTK_CON_EXTENDED */
+
 /*
  * Helper macros to handle lockdep when locking/unlocking console_sem. We use
  * macros instead of functions so that _RET_IP_ contains useful information.
@@ -2224,7 +2255,7 @@ static void console_cont_flush(char *text, size_t size)
  */
 void console_unlock(void)
 {
-	static char ext_text[CONSOLE_EXT_LOG_MAX];
+	static char ext_text[CONSOLE_EXT_LOG_BUF_LEN];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
 	static u64 seen_seq;
 	unsigned long flags;
@@ -2562,8 +2593,7 @@ void register_console(struct console *newcon)
 	}
 
 	if (newcon->flags & CON_EXTENDED)
-		if (!nr_ext_console_drivers++)
-			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");
+		inc_nr_ext_console_drivers();
 
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
@@ -2638,7 +2668,7 @@ int unregister_console(struct console *console)
 	}
 
 	if (!res && (console->flags & CON_EXTENDED))
-		nr_ext_console_drivers--;
+		dec_nr_ext_console_drivers();
 
 	/*
 	 * If this isn't the last console and it has CON_CONSDEV set, we