netconsole: implement extended console support

This patchset is v2 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 dependant upon.

Changes from the last last posting are

* Dynamic ext console de-registration is dropped. This made most of lock restructuring and refactoring in enable/disable path unnecessary. Ext netconsole is now registered on first use and stay registered. While this means that ext console support will stay enabled even after a dynamic extended console is disabled, such scenarios are likely very rare and the incurred overhead isn't drastic enough to justify the complexity.

* Retransmission handling is removed from the patchset. Handling retransmission in kernel doesn't provide enough benefits and is moved to userland.

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-make-netconsole_target-enabled-a-bool.patch 0002-netconsole-make-all-dynamic-netconsoles-share-a-mute.patch 0003-netconsole-implement-extended-console-support.patch

David, the patchset is small enough that I don't think splitting it makes much sense. While the first two patches are mostly independent cleanups, they can be ignored w/o the third patch.

diffstat follows. Thanks.

 Documentation/networking/netconsole.txt |   34 ++++++
 drivers/net/netconsole.c                |  175 +++++++++++++++++++++++++++++---
 2 files changed, 192 insertions(+), 17 deletions(-)

--
tejun

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

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 15731d1..09d4e12 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 09d4e12..d9f0f85 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.

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 |  34 +++++++-
 drivers/net/netconsole.c                | 149 +++++++++++++++++++++++++++++++-
 2 files changed, 180 insertions(+), 3 deletions(-)

index a5d574a..76c2640 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,35 @@ 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 1000 bytes, 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,
+
+ 6,416,1758426,-,ncfrag=0/33;the first chunk,
+ 6,416,1758426,-,ncfrag=16/33;the second chunk.
+
 Miscellaneous notes:
 ====================
 

2.1.0

Hello, Tetsuo.

It's trying to give an example on how the ncfrag header looks like but yeah I'll tweak it a bit and add further explanation.

Yeah, extended consoles should be fed messages w/ proper headers. If not, we warn and bail.

Ah, I dropped the patch which removed it from write_msg() but the following pattern doesn't do anything. It's just pure confusion.

	lock;
	ref++ on an item on the index;
	do something w/o releasing lock;
	ref-- on the item;
	unlock;

netconsole_netdev_event() has to release lock to process the item so refcnting is needed there. It got duplicated in write_msg() for no reason. I'll add a patch to remove it.

Thanks.

tejun

From: Tejun Heo <[email protected]>
Date: Mon, 4 May 2015 15:57:54 -0400

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.

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.

---
Hello,

If anyone wants the whole series to be reposted, please let me know. The updated patchset is available in the following git branch.

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

Thanks.

 Documentation/networking/netconsole.txt |  35 +++++++-
 drivers/net/netconsole.c                | 149 +++++++++++++++++++++++++++++++-
 2 files changed, 181 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

Hi Tejun,

2015-05-04, 16:04:56 -0400, Tejun Heo wrote:

[...]

Sabrina

Hello, Sabrina.

Yeap, the absolute maximum is 8k.

Hmm... ';' would be accounted for in the length of the original message. This function just needs to count the extra number of bytes to be added which means that sizeof() - 1 would be the precise count here. Do we care?

Indeed, this is a remnant of earlier code which emitted total number of chunks. Will restructure.

Ditto, earlier code had two types of conditions which trigger this code path. Will remove.

I think it'd be better to keep it tho. It's one unlikely branch in an already unlikely path. It doesn't really cost anything. Stuff happens, code changes and it'd suck if e.g. netconsole ends up causing memory corruption following changes / failures in upper layers.

The splitting is a very rare event. I don't think we need to be worrying about its performance at this level.

Thanks.

tejun

From: Tejun Heo <[email protected]>
Date: Mon, 4 May 2015 15:57:54 -0400

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.

---
Hello,

If anyone wants the whole series to be reposted, please let me know. The updated patchset is available in the following git branch.

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

Thanks.

 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

Ping?

Thanks.

tejun