netconsole: implement extended console support

This patchset is v3 of netconsole extended console support. v1 was part of "printk, netconsole: implement reliable netconsole" patchset[1]. The printk part is broken off to a separate patchset[2] "printk: implement extended console support" which this patchset is dependent upon.

Changes from the last version[3] are

* 0001-netconsole-remove-unnecessary-netconsole_target_get-.patch added so that we don't end up adding unnecessary get/put to write_ext_msg() for consistency.

* In 0004-netconsole-implement-extended-console-support.patch, send_ext_msg_udp() restructured to address Tetsuo and Sabrina's review points.

netconsole emits one or more udp messages per each log message and only transmits the body, which works fine when it's used as a debugging tool on local network; however, netconsole, due to its advantages for troubleshooting kernel issues, is also used as a mechanism to collect kernel messages at larger scale where the packets may have to travel across congested networks or networks with multiple paths.

Of the handful large cluster setups that I've seen, two were using netconsole for fleet-wide kernel logging and having problem with lost messages. One was a HPC cluster which had a dedicated slower management network which was used for all management traffic where packet losses were fairly common for several different reasons - the network itself could get fairly overloaded at times and IPMI sharing the interface didn't seem to help either. The other is a large web service cluster where the aggregator is some hops away and packet losses do happen from time to time.

Because netconsole packets don't carry any metadata, it's impossible to tell what happened to the messages during transit and even combining it with messages transmitted via a separate reliable mechanism is challenging as it boils down to matching message content textually.

The "printk, netconsole: implement reliable netconsole" patchset[1] implements extended console support. If a console driver sets CON_EXTENDED, printk formats each message in the same way /dev/kmsg messages are formatted which includes all metadata and, for structured log messages, KEY=VALUE dictionary.

This patchset implements extended console support for netconsole, which allows log consumers access to complete log information and to tell which messages are missing and/or reordered, which can be used to implement reliable kernel message logging when combined with userland helpers.

Changes to netconsole are straight-forward. It optionally registers a separate extended console driver. printk passes in extended format messages which are transmitted the same way. The only complication is when the message is longer than the maximum payload size (1k). As each message should have proper header and the log receiver should be able to tell which part the fragment is, netconsole duplicates full header on each fragment and also adds an extra ncfrag=OFF/LEN header.

0001-netconsole-remove-unnecessary-netconsole_target_get-.patch 0002-netconsole-make-netconsole_target-enabled-a-bool.patch 0003-netconsole-make-all-dynamic-netconsoles-share-a-mute.patch 0004-netconsole-implement-extended-console-support.patch

diffstat follows. Thanks.

 Documentation/networking/netconsole.txt |   35 ++++++
 drivers/net/netconsole.c                |  169 ++++++++++++++++++++++++++++----
 2 files changed, 185 insertions(+), 19 deletions(-)

--
tejun

[1] http://lkml.kernel.org/g/[email protected]
[2] http://lkml.kernel.org/g/[email protected]
[3] http://lkml.kernel.org/g/[email protected]

write_msg() grabs target_list_lock and walks target_list invoking netpool_send_udp() on each target. Curiously, it protects each iteration with netconsole_target_get/put() even though it never releases target_list_lock which protects all the members.

While this doesn't harm anything, it doesn't serve any purpose either. The items on the list can't go away while target_list_lock is held. Remove the unnecessary get/put pair.

---
 drivers/net/netconsole.c | 2 --
 1 file changed, 2 deletions(-)

index 15731d1..30c0524 100644
@@ -744,7 +744,6 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 
 	spin_lock_irqsave(&target_list_lock, flags);
 	list_for_each_entry(nt, &target_list, list) {
-		netconsole_target_get(nt);
 		if (nt->enabled && netif_running(nt->np.dev)) {
 			/*
 			 * We nest this inside the for-each-target loop above

@@ -760,7 +759,6 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 				left -= frag;
 			}
 		}
-		netconsole_target_put(nt);
 	}
 	spin_unlock_irqrestore(&target_list_lock, flags);
 }

2.1.0

netconsole uses both bool and int for boolean values. Let's convert nt->enabled to bool for consistency.

---
 drivers/net/netconsole.c | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

index 30c0524..8dd1e55 100644
@@ -104,7 +104,7 @@ struct netconsole_target {
 #ifdef	CONFIG_NETCONSOLE_DYNAMIC
 	struct config_item	item;
 #endif
-	int			enabled;
+	bool			enabled;
 	struct mutex		mutex;
 	struct netpoll		np;
 };

@@ -197,7 +197,7 @@ static struct netconsole_target *alloc_param_target(char *target_config)
 	if (err)
 		goto fail;
 
-	nt->enabled = 1;
+	nt->enabled = true;
 
 	return nt;
 

@@ -322,13 +322,13 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 		return err;
 	if (enabled < 0 || enabled > 1)
 		return -EINVAL;
-	if (enabled == nt->enabled) {
+	if ((bool)enabled == nt->enabled) {
 		pr_info("network logging has already %s\n",
 			nt->enabled ? "started" : "stopped");
 		return -EINVAL;
 	}
 
-	if (enabled) {	/* 1 */
+	if (enabled) {	/* true */
 		/*
 		 * Skip netpoll_parse_options() -- all the attributes are
 		 * already configured via configfs. Just print them out.

@@ -340,13 +340,13 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 			return err;
 
 		pr_info("netconsole: network logging started\n");
-	} else {	/* 0 */
+	} else {	/* false */
 		/* We need to disable the netconsole before cleaning it up
 		 * otherwise we might end up in write_msg() with
-		 * nt->np.dev == NULL and nt->enabled == 1
+		 * nt->np.dev == NULL and nt->enabled == true
 		 */
 		spin_lock_irqsave(&target_list_lock, flags);
-		nt->enabled = 0;
+		nt->enabled = false;
 		spin_unlock_irqrestore(&target_list_lock, flags);
 		netpoll_cleanup(&nt->np);
 	}

@@ -594,7 +594,7 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 
 	/*
 	 * Allocate and initialize with defaults.
-	 * Target is disabled at creation (enabled == 0).
+	 * Target is disabled at creation (!enabled).
 	 */
 	nt = kzalloc(sizeof(*nt), GFP_KERNEL);
 	if (!nt)

@@ -695,7 +695,7 @@ restart:
 				spin_lock_irqsave(&target_list_lock, flags);
 				dev_put(nt->np.dev);
 				nt->np.dev = NULL;
-				nt->enabled = 0;
+				nt->enabled = false;
 				stopped = true;
 				netconsole_target_put(nt);
 				goto restart;

2.1.0

Currently, each dynamic netconsole_target uses its own separate mutex to synchronize the configuration operations. This patch replaces the per-netconsole_target mutexes with a single mutex - dynamic_netconsole_mutex. The reduced granularity doesn't hurt anything, the code is minutely simpler and this'd allow adding operations which should be synchronized across all dynamic netconsoles.

---
 drivers/net/netconsole.c | 8 +++-----
 1 file changed, 3 insertions(+), 5 deletions(-)

index 8dd1e55..9b0c81e 100644
@@ -105,13 +105,13 @@ struct netconsole_target {
 	struct config_item	item;
 #endif
 	bool			enabled;
-	struct mutex		mutex;
 	struct netpoll		np;
 };
 
 #ifdef	CONFIG_NETCONSOLE_DYNAMIC
 
 static struct configfs_subsystem netconsole_subsys;
+static DEFINE_MUTEX(dynamic_netconsole_mutex);
 
 static int __init dynamic_netconsole_init(void)
 {

@@ -185,7 +185,6 @@ static struct netconsole_target *alloc_param_target(char *target_config)
 	strlcpy(nt->np.dev_name, "eth0", IFNAMSIZ);
 	nt->np.local_port = 6665;
 	nt->np.remote_port = 6666;
-	mutex_init(&nt->mutex);
 	eth_broadcast_addr(nt->np.remote_mac);
 
 	/* Parse parameters and setup netpoll */

@@ -562,10 +561,10 @@ static ssize_t netconsole_target_attr_store(struct config_item *item,
 	struct netconsole_target_attr *na =
 		container_of(attr, struct netconsole_target_attr, attr);
 
-	mutex_lock(&nt->mutex);
+	mutex_lock(&dynamic_netconsole_mutex);
 	if (na->store)
 		ret = na->store(nt, buf, count);
-	mutex_unlock(&nt->mutex);
+	mutex_unlock(&dynamic_netconsole_mutex);
 
 	return ret;
 }

@@ -604,7 +603,6 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 	strlcpy(nt->np.dev_name, "eth0", IFNAMSIZ);
 	nt->np.local_port = 6665;
 	nt->np.remote_port = 6666;
-	mutex_init(&nt->mutex);
 	eth_broadcast_addr(nt->np.remote_mac);
 
 	/* Initialize the config_item member */

2.1.0

printk logbuf keeps various metadata and optional key=value dictionary for structured messages, both of which are stripped when messages are handed to regular console drivers.

It can be useful to have this metadata and dictionary available to netconsole consumers. This obviously makes logging via netconsole more complete and the sequence number in particular is useful in environments where messages may be lost or reordered in transit - e.g. when netconsole is used to collect messages in a large cluster where packets may have to travel congested hops to reach the aggregator. The lost and reordered messages can easily be identified and handled accordingly using the sequence numbers.

printk recently added extended console support which can be selected by setting CON_EXTENDED flag. From console driver side, not much changes. The only difference is that the text passed to the write callback is formatted the same way as /dev/kmsg.

This patch implements extended console support for netconsole which can be enabled by either prepending "+" to a netconsole boot param entry or echoing 1 to "extended" file in configfs. When enabled, netconsole transmits extended log messages with headers identical to /dev/kmsg output.

There's one complication due to message fragments. netconsole limits the maximum message size to 1k and messages longer than that are split into multiple fragments. As all extended console messages should carry matching headers and be uniquely identifiable, each extended message fragment carries full copy of the metadata and an extra header field to identify the specific fragment. The optional header is of the form "ncfrag=OFF/LEN" where OFF is the byte offset into the message body and LEN is the total length.

To avoid unnecessarily making printk format extended messages, Extended netconsole is registered with printk when the first extended netconsole is configured.

v4: send_ext_msg_udp() restructured.

v3: Tweaked documentation to make clarify that the example assumes a
lot smaller chunk size. Updated to apply on top of spurious target get/put removal in write_msg().

v2: Dropped dynamic unregistration of extended console driver, which
added complexity while not being too beneficial given that most netconsole configurations are static. ncfrag updated to use just byte offset and message length.

---
 Documentation/networking/netconsole.txt |  35 +++++++-
 drivers/net/netconsole.c                | 141 +++++++++++++++++++++++++++++++-
 2 files changed, 173 insertions(+), 3 deletions(-)

index a5d574a..30409a3 100644
@@ -2,6 +2,7 @@
 started by Ingo Molnar <[email protected]>, 2001.09.17
 2.6 port and netpoll api by Matt Mackall <[email protected]>, Sep 9 2003
 IPv6 support by Cong Wang <[email protected]>, Jan 1 2013
+Extended console support by Tejun Heo <[email protected]>, May 1 2015
 
 Please send bug reports to Matt Mackall <[email protected]>
 Satyam Sharma <[email protected]>, and Cong Wang <[email protected]>

@@ -24,9 +25,10 @@ Sender and receiver configuration:
 It takes a string configuration parameter "netconsole" in the
 following format:
 
- netconsole=[src-port]@[src-ip]/[<dev>],[tgt-port]@<tgt-ip>/[tgt-macaddr]
+ netconsole=[+][src-port]@[src-ip]/[<dev>],[tgt-port]@<tgt-ip>/[tgt-macaddr]
 
    where
+        +             if present, enable extended console support
         src-port      source for UDP packets (defaults to 6665)
         src-ip        source IP to use (interface address)
         dev           network interface (eth0)

@@ -107,6 +109,7 @@ To remove a target:
 The interface exposes these parameters of a netconsole target to userspace:
 
 	enabled		Is this target currently enabled?	(read-write)
+	extended	Extended mode enabled			(read-write)
 	dev_name	Local network interface name		(read-write)
 	local_port	Source UDP port to use			(read-write)
 	remote_port	Remote agent's UDP port			(read-write)

@@ -132,6 +135,36 @@ You can also update the local interface dynamically. This is especially
 useful if you want to use interfaces that have newly come up (and may not
 have existed when netconsole was loaded / initialized).
 
+Extended console:
+=================
+
+If '+' is prefixed to the configuration line or "extended" config file
+is set to 1, extended console support is enabled. An example boot
+param follows.
+
+ linux [email protected]/eth1,[email protected]/12:34:56:78:9a:bc
+
+Log messages are transmitted with extended metadata header in the
+following format which is the same as /dev/kmsg.
+
+ <level>,<sequnum>,<timestamp>,<contflag>;<message text>
+
+Non printable characters in <message text> are escaped using "\xff"
+notation. If the message contains optional dictionary, verbatim
+newline is used as the delimeter.
+
+If a message doesn't fit in certain number of bytes (currently 1000),
+the message is split into multiple fragments by netconsole. These
+fragments are transmitted with "ncfrag" header field added.
+
+ ncfrag=<byte-offset>/<total-bytes>
+
+For example, assuming a lot smaller chunk size, a message "the first
+chunk, the 2nd chunk." may be split as follows.
+
+ 6,416,1758426,-,ncfrag=0/31;the first chunk,
+ 6,416,1758426,-,ncfrag=16/31; the 2nd chunk.
+
 Miscellaneous notes:
 ====================
 

2.1.0

From: Tejun Heo <[email protected]>
Date: Mon, 11 May 2015 12:41:34 -0400

	<level>,<sequnum>,<timestamp>,<contflag>;,ncfrag=x/y;

	<level>,<sequnum>,<timestamp>,<contflag>,ncfrag=x/y;

Hello,

The current code does produce the latter outcome.

	header = msg;
	body = memchr(msg, ';', msg_len);
	if (WARN_ON_ONCE(!body))
		return;

	header_len = body - header;
	body_len = msg_len - header_len - 1;
	body++;

@body points to ';' after memchr(), so @header_len doesn't include ';'. @body is incremented after calculating @header_len.

Thanks.

tejun

From: Tejun Heo <[email protected]>
Date: Mon, 11 May 2015 16:37:45 -0400

Ok, thanks for explaining, it is clear to me now.

Second question, is there an upper bound on this header size?

Because if there is, it seems to me that there is no reason why we can't just avoid the fragmentation support altogether.

The current code limits to 1000 bytes, and that limit seems arbitrary. Obviously this code is meant to work on interfaces with an ethernet MTU or larger. So you could bump the limit enough to accomodate the new header size, yet still be within the real constraints.

What do you think?

Hello, David.

Yeah, if we can bump the tx size enough to accomodate all messages, it'd be great. It can get fairly large tho. The absolute maximum right now is 8k. While regular prink message bodies are capped slightly below 1k, the dictionary printed through vprintk_emit() doesn't have such length limit. Another factor is that non-printables are escaped using \xXX and vprintk_emit() is supposed to be useable with transmitting binary data (like low level device error descriptors) although I'm not sure anybody is doing that yet.

Thanks.

tejun

From: Tejun Heo <[email protected]>
Date: Wed, 13 May 2015 11:46:20 -0400

Yeah, 8K is too much to handle, oh well.

Ok I'm fine with this series from my end, and you can merge this wherever the extended console support bits go.

Thanks.

Hello, David.

Awesome, thanks. Andrew, I think it'd be best to route this with the extended printk patchset through -mm. I'll repost the combined patchset with the suggested comment added.

Thanks.

tejun

There's no such thing as CON_EXTENDED. Not sure what this is trying to say.

From: Andrew Morton <[email protected]>
Date: Tue, 12 May 2015 16:36:02 -0700

Please read the patch series that, in the title posting of this series, Tejun explains this series depends upon.

Hello, Andrew.

Yeah, I ended up splitting the original patchset into two. One implementing CON_EXTENDED and this set updating netconsole to use it. The patchset head message contains the link to the prerequisite patchset.

http://article.gmane.org/gmane.linux.kernel/1940567

So, there are configfs dynamic netconsole targets which is created by mkdir, configured through interface files there and enabled by echoing 1 to the enable file. The parameters can't be changed while the target is enabled. This is the standard warning used for all other knobs and I think what the warning message means is pretty clear given the context. Right?

Yeah, the whole send path is serialized by console_sem and target_list_lock. I'll add the comment.

The retransmission part was the most contentious point and Dave pointed out that there isn't much to be gained by doing that from the kernel side, so that part got dropped from the patchset and will become a separate userland program, so the only remaining parts are support for sending out extended messages from netconsole which shouldn't be too controversial.

Thanks.

tejun