Skip to contentSkip to conversation

printk, netconsole: implement reliable netconsole

PATCH In review Tejun Heo 7 participants 46 messages Apr 16, 2015 – Apr 28, 2015

Subsystems (6)
lore
Share & tools
lore

Tejun Heo

author
#0 lore raw

PATCH 1/1 printk, netconsole: implement reliable netconsole

In a lot of configurations, netconsole is a useful way to collect system logs; however, all netconsole does is simply emitting UDP packets for the raw messages and there's no way for the receiver to find out whether the packets were lost and/or reordered in flight.

printk already keeps log metadata which contains enough information to make netconsole reliable. This patchset does the followings.

* Make printk metadata available to console drivers. A console driver can request this mode by setting CON_EXTENDED. The metadata is emitted in the same format as /dev/kmsg. This also makes all logging metadata including facility, loglevel and dictionary available to console receivers.

* Implement extended mode support in netconsole. When enabled, netconsole transmits messages with extended header which is enough for the receiver to detect missing messages.

* Implement netconsole retransmission support. Matching rx socket on the source port is automatically created for extended targets and the log receiver can request retransmission by sending reponse packets. This is completely decoupled from the main write path and doesn't make netconsole less robust when things start go south.

* Implement netconsole ack support. The response packet can optionally contain ack which enables emergency transmission timer. If acked sequence lags the current sequence for over 10s, netconsole repeatedly re-sends unacked messages with increasing interval. This ensures that the receiver has the latest messages and also that all messages are transferred even while the kernel is failing as long as timer and netpoll are operational. This too is completely decoupled from the main write path and doesn't make netconsole less robust.

* Implement the receiver library and simple receiver using it respectively in tools/lib/netconsole/libncrx.a and tools/ncrx/ncrx. In a simulated test with heavy packet loss (50%), ncrx logs all messages reliably and handle exceptional conditions including reboots as expected.

An obvious alternative for reliable loggin would be using a separate TCP connection in addition to the UDP packets; however, I decided for UDP based retransmission and ack mechanism for the following reasons.

* kernel side doesn't get simpler by using TCP. It'd still need to transmit extended format messages, which BTW are useful regardless of reliable transmission, to match up UDP and TCP messages and detect missing ones from TCP send buffer filling up. Also, the timeout and emergency transmission support would still be necessary to ensure that messages are transmitted in case of, e.g., network stack faiure. It'd at least be about the same amount of code as the UDP based implementation.

* Receiver side might be a bit simpler but not by much. It'd still need to keep track of the UDP based messages and then match them up with TCP messages and put messages from both sources in order (each stream may miss different ones) and would have to deal with reestablishing connections after reboots. The only part which can completely go away would be the actual ack and retransmission part and that isn't a lot of logic.

* When the network condition is good, the only thing the UDP based implementation adds is occassional ack messages. TCP based implementation would end up transmitting all messages twice which still isn't much but kinda silly given that using TCP doesn't lower the complexity in meaningful ways.

This patchset contains the following 16 patches.

0001-printk-guard-the-amount-written-per-line-by-devkmsg_.patch 0002-printk-factor-out-message-formatting-from-devkmsg_re.patch 0003-printk-move-LOG_NOCONS-skipping-into-call_console_dr.patch 0004-printk-implement-support-for-extended-console-driver.patch 0005-printk-implement-log_seq_range-and-ext_log_from_seq.patch 0006-netconsole-make-netconsole_target-enabled-a-bool.patch 0007-netconsole-factor-out-alloc_netconsole_target.patch 0008-netconsole-punt-disabling-to-workqueue-from-netdevic.patch 0009-netconsole-replace-target_list_lock-with-console_loc.patch 0010-netconsole-introduce-netconsole_mutex.patch 0011-netconsole-consolidate-enable-disable-and-create-des.patch 0012-netconsole-implement-extended-console-support.patch 0013-netconsole-implement-retransmission-support-for-exte.patch 0014-netconsole-implement-ack-handling-and-emergency-tran.patch 0015-netconsole-implement-netconsole-receiver-library.patch 0016-netconsole-update-documentation-for-extended-netcons.patch

0001-0005 implement extended console support in printk.

0006-0011 are prep patches for netconsole.

0012-0014 implement extended mode, retransmission and ack support.

0015 implements receiver library, libncrx, and a simple receiver using the library, ncrx.

0016 updates documentation.

As the patchset touches both printk and netconsole, I'm not sure how these patches should be routed once acked. Either -mm or net should work, I think.

This patchset is on top of linus#master[1] and available in the following git branch.

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

diffstat follows. Thanks.

 Documentation/networking/netconsole.txt |   95 +++
 drivers/net/netconsole.c                |  800 +++++++++++++++++++++++-----
 include/linux/console.h                 |    1 
 include/linux/printk.h                  |   16 
 kernel/printk/printk.c                  |  411 +++++++++++---
 tools/Makefile                          |   16 
 tools/lib/netconsole/Makefile           |   36 +
 tools/lib/netconsole/ncrx.c             |  906 ++++++++++++++++++++++++++++++++
 tools/lib/netconsole/ncrx.h             |  204 +++++++
 tools/ncrx/Makefile                     |   14 
 tools/ncrx/ncrx.c                       |  143 +++++
 11 files changed, 2419 insertions(+), 223 deletions(-)

--
tejun

[1] 497a5df7bf6f ("Merge tag 'stable/for-linus-4.1-rc0-tag' of git://git.kernel.org/pub/scm/linux/kernel/git/xen/tip")

author
#1 lore raw

PATCH 1/16 printk: guard the amount written per line by devkmsg_read()

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.

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 include/linux/printk.h |  2 ++
 kernel/printk/printk.c | 35 +++++++++++++++++++++++------------
 2 files changed, 25 insertions(+), 12 deletions(-)
include/linux/printk.h +2 -0
index 9b30871..58b1fec 100644
@@ -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
 
kernel/printk/printk.c +23 -12
index 879edfc..b6e24af 100644
@@ -512,7 +512,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)
@@ -565,11 +565,18 @@ static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
 	return ret;
 }
 
+static void append_char(char **pp, char *e, char c)
+{
+	if (*pp < e)
+		*(*pp)++ = c;
+}
+
 static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			    size_t count, loff_t *ppos)
 {
 	struct devkmsg_user *user = file->private_data;
 	struct printk_log *msg;
+	char *p, *e;
 	u64 ts_usec;
 	size_t i;
 	char cont = '-';
@@ -579,6 +586,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 +635,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 +645,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 +658,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;
Signature · 1 line
2.1.0
Reviewed-by on v1 1/16
#2 lore raw

Re: [PATCH 01/16] printk: guard the amount written per line by devkmsg_read()

Quoted 10 lines · 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.

It is just a refactoring and does not modify the current behavior.

Quoted 12 lines
Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 include/linux/printk.h |  2 ++
 kernel/printk/printk.c | 35 +++++++++++++++++++++++------------
 2 files changed, 25 insertions(+), 12 deletions(-)
include/linux/printk.h +0 -0
index 9b30871..58b1fec 100644

include/linux/printk.h static inline const char *printk_skip_level(const char *buffer) · line 33

Quoted 4 lines
include/linux/printk.h +1 -0
@@ -30,6 +30,8 @@ static inline const char *printk_skip_level(const char *buffer)
 	return buffer;
 }
 
+#define CONSOLE_EXT_LOG_MAX	8192

If you do a respin from some reason. I would suggest to remove "CONSOLE_" because it is used also for devkmsg.

Best Regards,
Petr

Quoted 114 lines
include/linux/printk.h +1 -0
+
 /* printk's without a loglevel use this.. */
 #define MESSAGE_LOGLEVEL_DEFAULT CONFIG_MESSAGE_LOGLEVEL_DEFAULT
 
kernel/printk/printk.c +23 -12
index 879edfc..b6e24af 100644
@@ -512,7 +512,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)
@@ -565,11 +565,18 @@ static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
 	return ret;
 }
 
+static void append_char(char **pp, char *e, char c)
+{
+	if (*pp < e)
+		*(*pp)++ = c;
+}
+
 static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			    size_t count, loff_t *ppos)
 {
 	struct devkmsg_user *user = file->private_data;
 	struct printk_log *msg;
+	char *p, *e;
 	u64 ts_usec;
 	size_t i;
 	char cont = '-';
@@ -579,6 +586,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 +635,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 +645,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 +658,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;
Signature · 1 line
2.1.0
#3 lore raw

Re: [PATCH 01/16] printk: guard the amount written per line by devkmsg_read()

Quoted 7 lines · Petr Mladek
Quoted 6 lines · 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.

Quoted 8 lines
Quoted 4 lines

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

It is just a refactoring and does not modify the current behavior.

Ah, to make it clear. It did not modify the behavior except for adding the check for potential buffer overflow.

Best Regards,
Petr

author
#4 lore raw

PATCH 2/16 printk: factor out message formatting from devkmsg_read()

In reply to 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.

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 kernel/printk/printk.c | 157 ++++++++++++++++++++++++++-----------------------
 1 file changed, 85 insertions(+), 72 deletions(-)
kernel/printk/printk.c +85 -72
index b6e24af..5ea6709 100644
@@ -505,6 +505,86 @@ 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;
+}
+
+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 {
@@ -565,30 +645,17 @@ static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
 	return ret;
 }
 
-static void append_char(char **pp, char *e, char c)
-{
-	if (*pp < e)
-		*(*pp)++ = c;
-}
-
 static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			    size_t count, loff_t *ppos)
 {
 	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;
@@ -618,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);
-
-	/*
-	 * 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 = '+';
+	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);
 
-	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;
Signature · 1 line
2.1.0
Reviewed-by on v1 2/16
#5 lore raw

Re: [PATCH 02/16] printk: factor out message formatting from devkmsg_read()

Quoted 7 lines · 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.

I like the split of the long function.

Best Regards,
Petr

Quoted 208 lines
Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 kernel/printk/printk.c | 157 ++++++++++++++++++++++++++-----------------------
 1 file changed, 85 insertions(+), 72 deletions(-)
kernel/printk/printk.c +85 -72
index b6e24af..5ea6709 100644
@@ -505,6 +505,86 @@ 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;
+}
+
+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 {
@@ -565,30 +645,17 @@ static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
 	return ret;
 }
 
-static void append_char(char **pp, char *e, char c)
-{
-	if (*pp < e)
-		*(*pp)++ = c;
-}
-
 static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			    size_t count, loff_t *ppos)
 {
 	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;
@@ -618,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);
-
-	/*
-	 * 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 = '+';
+	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);
 
-	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;
Signature · 1 line
2.1.0
author
#6 lore raw

PATCH 3/16 printk: move LOG_NOCONS skipping into call_console_drivers()

In reply to Tejun Heo

When a line is printed by multiple printk invocations, each chunk is directly sent out to console drivers so that they don't get lost. When the line is completed and stored in the log buffer, the line is suppressed from going out to consoles as that'd lead to duplicate outputs. This is tracked with LOG_NOCONS flag.

The suppression is currently implemented in console_unlock() which skips invoking call_console_drivers() for LOG_NOCONS messages. This patch moves the filtering into call_console_drivers() in preparation of the planned extended console drivers which will deal with the duplicate messages themselves.

While this makes call_console_drivers() iterate over LOG_NOCONS messages, this is extremely unlikely to matter especially given that continuation lines aren't that common and also simplifies console_unlock() a bit.

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 kernel/printk/printk.c | 46 ++++++++++++++++++++++++----------------------
 1 file changed, 24 insertions(+), 22 deletions(-)
kernel/printk/printk.c +24 -22
index 5ea6709..0175c46 100644
@@ -1417,7 +1417,8 @@ 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, bool nocons,
+				 const char *text, size_t len)
 {
 	struct console *con;
 
@@ -1438,6 +1439,13 @@ static void call_console_drivers(int level, const char *text, size_t len)
 		if (!cpu_online(smp_processor_id()) &&
 		    !(con->flags & CON_ANYTIME))
 			continue;
+		/*
+		 * Skip record we have buffered and already printed
+		 * directly to the console when we received it.
+		 */
+		if (nocons)
+			continue;
+
 		con->write(con, text, len);
 	}
 }
@@ -1919,7 +1927,8 @@ static struct cont {
 } cont;
 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 void call_console_drivers(int level, bool nocons,
+				 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; }
@@ -2190,7 +2199,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, false, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
@@ -2234,6 +2243,7 @@ again:
 		struct printk_log *msg;
 		size_t len;
 		int level;
+		bool nocons;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2252,38 +2262,30 @@ again:
 		} else {
 			len = 0;
 		}
-skip:
+
 		if (console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
-			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it.
-			 */
-			console_idx = log_next(console_idx);
-			console_seq++;
-			/*
-			 * We will get here again when we register a new
-			 * CON_PRINTBUFFER console. Clear the flag so we
-			 * will properly dump everything later.
-			 */
-			msg->flags &= ~LOG_NOCONS;
-			console_prev = msg->flags;
-			goto skip;
-		}
-
 		level = msg->level;
+		nocons = msg->flags & LOG_NOCONS;
 		len += msg_print_text(msg, console_prev, false,
 				      text + len, sizeof(text) - len);
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
+
+		/*
+		 * The log will be processed again when we register a new
+		 * CON_PRINTBUFFER console. Clear the flag so we will
+		 * properly dump everything later.
+		 */
+		msg->flags &= ~LOG_NOCONS;
+
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, text, len);
+		call_console_drivers(level, nocons, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 	}
Signature · 1 line
2.1.0
Reviewed-by on v1 3/16
#7 lore raw

Re: [PATCH 03/16] printk: move LOG_NOCONS skipping into call_console_drivers()

Quoted 110 lines · Tejun Heo

When a line is printed by multiple printk invocations, each chunk is directly sent out to console drivers so that they don't get lost. When the line is completed and stored in the log buffer, the line is suppressed from going out to consoles as that'd lead to duplicate outputs. This is tracked with LOG_NOCONS flag.

The suppression is currently implemented in console_unlock() which skips invoking call_console_drivers() for LOG_NOCONS messages. This patch moves the filtering into call_console_drivers() in preparation of the planned extended console drivers which will deal with the duplicate messages themselves.

While this makes call_console_drivers() iterate over LOG_NOCONS messages, this is extremely unlikely to matter especially given that continuation lines aren't that common and also simplifies console_unlock() a bit.

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 kernel/printk/printk.c | 46 ++++++++++++++++++++++++----------------------
 1 file changed, 24 insertions(+), 22 deletions(-)
kernel/printk/printk.c +15 -21
index 5ea6709..0175c46 100644
@@ -1417,7 +1417,8 @@ 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, bool nocons,
+				 const char *text, size_t len)
 {
 	struct console *con;
 
@@ -1438,6 +1439,13 @@ static void call_console_drivers(int level, const char *text, size_t len)
 		if (!cpu_online(smp_processor_id()) &&
 		    !(con->flags & CON_ANYTIME))
 			continue;
+		/*
+		 * Skip record we have buffered and already printed
+		 * directly to the console when we received it.
+		 */
+		if (nocons)
+			continue;
+
 		con->write(con, text, len);
 	}
 }
@@ -1919,7 +1927,8 @@ static struct cont {
 } cont;
 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 void call_console_drivers(int level, bool nocons,
+				 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; }
@@ -2190,7 +2199,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, false, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
@@ -2234,6 +2243,7 @@ again:
 		struct printk_log *msg;
 		size_t len;
 		int level;
+		bool nocons;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2252,38 +2262,30 @@ again:
 		} else {
 			len = 0;
 		}
-skip:
+
 		if (console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
-			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it.
-			 */
-			console_idx = log_next(console_idx);
-			console_seq++;
-			/*
-			 * We will get here again when we register a new
-			 * CON_PRINTBUFFER console. Clear the flag so we
-			 * will properly dump everything later.
-			 */
-			msg->flags &= ~LOG_NOCONS;
-			console_prev = msg->flags;
-			goto skip;
-		}
-
 		level = msg->level;
+		nocons = msg->flags & LOG_NOCONS;
 		len += msg_print_text(msg, console_prev, false,
 				      text + len, sizeof(text) - len);

kernel/printk/printk.c again: · line 2283

Quoted 10 lines
kernel/printk/printk.c +7 -0
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
+
+		/*
+		 * The log will be processed again when we register a new
+		 * CON_PRINTBUFFER console. Clear the flag so we will
+		 * properly dump everything later.
+		 */
+		msg->flags &= ~LOG_NOCONS;

The previous code cleared LOG_NOCONS before saving flags into console_prev. Well, the change does not have any real effect. And the new order makes more sense.

This patch looks fine to me.

Best Regards,
Petr

Quoted 11 lines
kernel/printk/printk.c +1 -1
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, text, len);
+		call_console_drivers(level, nocons, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 	}
Signature · 1 line
2.1.0
author
#8 lore raw

PATCH 4/16 printk: implement support for extended console drivers

In reply to 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. Immediately, it's to implement reliable netconsole but may be useful for other console devices too.

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

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

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

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

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

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

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

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

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

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 include/linux/console.h |   1 +
 kernel/printk/printk.c  | 141 +++++++++++++++++++++++++++++++++++++++++-------
 2 files changed, 123 insertions(+), 19 deletions(-)
include/linux/console.h +1 -0
index 7571a16..04bbd09 100644
@@ -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];
kernel/printk/printk.c +122 -19

296 lines not on this page · raw message

Signature · 1 line
2.1.0
#9 lore raw

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

Quoted 25 lines · 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. Immediately, it's to implement reliable netconsole but may be useful for other console devices too.

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

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

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

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

Quoted 7 lines

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

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

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

* Extended message formatting for console drivers is enabled iff there

                                                               ^^^

s/iff/if/

Quoted 78 lines

are registered extended consoles.

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

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 include/linux/console.h |   1 +
 kernel/printk/printk.c  | 141 +++++++++++++++++++++++++++++++++++++++++-------
 2 files changed, 123 insertions(+), 19 deletions(-)
include/linux/console.h +1 -0
index 7571a16..04bbd09 100644
@@ -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];
kernel/printk/printk.c +19 -2
index 0175c46..349a37b 100644
@@ -84,6 +84,8 @@ static struct lockdep_map console_lock_dep_map = {
 };
 #endif
 
+static int nr_ext_console_drivers;
+
 /*
  * Helper macros to handle lockdep when locking/unlocking console_sem. We use
  * macros instead of functions so that _RET_IP_ contains useful information.
@@ -195,14 +197,28 @@ static int console_may_schedule;
  * need to be changed in the future, when the requirements change.
  *
  * /dev/kmsg exports the structured data in the following line format:
- *   "level,sequnum,timestamp;<message text>\n"
+ *   "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n"
  *
  * The optional key/value pairs are attached as continuation lines starting
  * with a space character and terminated by a newline. All possible
  * non-prinatable characters are escaped in the "\xff" notation.
  *
  * Users of the export format should ignore possible additional values
- * separated by ',', and find the message after the ';' character.
+ * separated by ',', and find the message after the ';' character. All
+ * optional header fields should have the form "<key>=<value>".
+ *
+ * For consoles with CON_EXTENDED set, a message formatted like the
+ * following may also be printed. This is a continuation fragment which are
+ * being assembled and will be re-transmitted with a normal header once
+ * assembly finishes. The fragments are sent out immediately to avoid
+ * losing them over a crash.
+ *   "<level>,-,<timestamp>,-,fragid=<fragid>;<message fragment>\n"
+ *
+ * On completion of assembly, the following is transmitted.
+ *   "<level>,<sequnum>,<timestamp>,<contflag>,fragid=<fragid>;<message text>\n"
+ *
+ * Extended consoles should identify and handle duplicates by matching the
+ * fragids of the fragments and assembled messages.
  */
 
 enum log_flags {
@@ -210,6 +226,7 @@ enum log_flags {
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_PREFIX	= 4,	/* text started with a prefix */
 	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+	LOG_DICT_META	= 16,	/* dict contains console meta information */
 };
 
 struct printk_log {

kernel/printk/printk.c static char *log_dict(const struct printk_log *msg) · line 315

Quoted 7 lines
kernel/printk/printk.c +4 -0
@@ -292,6 +309,12 @@ static char *log_dict(const struct printk_log *msg)
 	return (char *)msg + sizeof(struct printk_log) + msg->text_len;
 }
 
+/* if LOG_DICT_META is set, the dict buffer carries printk internal info */
+static size_t log_dict_len(const struct printk_log *msg)
+{
+	return (msg->flags & LOG_DICT_META) ? 0 : msg->dict_len;

We should document somewhere that the internal info and user-provided dictionary newer could by stored in the same message.

It is because the internal info is used only with cont buffers. And cont buffer is always stored into the log buffer separately, see cont_flush() in vprintk_emit(). It took me a lot of time to confirm this by reading the code.

Quoted 16 lines
kernel/printk/printk.c +4 -0
+}
+
 /* get record by index; idx must point to valid msg */
 static struct printk_log *log_from_idx(u32 idx)
 {
@@ -516,7 +539,9 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
 				    enum log_flags prev_flags)
 {
 	u64 ts_usec = msg->ts_nsec;
+	u64 fragid;
 	char cont = '-';
+	char fragid_buf[32] = "";
 
 	do_div(ts_usec, 1000);
 

kernel/printk/printk.c static ssize_t msg_print_ext_header(char *buf, size_t size, · line 564

Quoted 8 lines
kernel/printk/printk.c +3 -2
@@ -534,8 +559,14 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
 		 ((prev_flags & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
 		cont = '+';
 
-	return scnprintf(buf, size, "%u,%llu,%llu,%c;",
-		       (msg->facility << 3) | msg->level, seq, ts_usec, cont);
+	/* see cont_flush() */
+	if ((msg->flags & LOG_DICT_META) && msg->dict_len &&
+	    sscanf(log_dict(msg), "FRAGID=%llu", &fragid))

I was afraid that there might be a potential buffer overflow because the user-provided dict need not be limited by '\0'. But LOG_DICT_META is used only with the internal data that are safe. We might document this as well.

BTW: Do you want to print the internal dict when calling this function in devkmsg_read()?

kernel/printk/printk.c static ssize_t msg_print_ext_header(char *buf, size_t size, · line 569

Quoted 5 lines
kernel/printk/printk.c +5 -0
+		scnprintf(fragid_buf, sizeof(fragid_buf),
+			  ",fragid=%llu", fragid);
+	return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+			 (msg->facility << 3) | msg->level, seq, ts_usec, cont,
+			 fragid_buf);

The above comment suggests that "cont" and "fragid_buf" are delimited by a comma but it is not used here. Is it by intention.

Quoted 65 lines
kernel/printk/printk.c +18 -8
 }
 
 static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -688,7 +719,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	len = msg_print_ext_header(user->buf, sizeof(user->buf),
 				   msg, user->seq, user->prev);
 	len += msg_print_ext_body(user->buf + len, sizeof(user->buf) - len,
-				  log_dict(msg), msg->dict_len,
+				  log_dict(msg), log_dict_len(msg),
 				  log_text(msg), msg->text_len);
 
 	user->prev = msg->flags;
@@ -1418,6 +1449,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
  * The console_lock must be held.
  */
 static void call_console_drivers(int level, bool nocons,
+				 const char *ext_text, size_t ext_len,
 				 const char *text, size_t len)
 {
 	struct console *con;
@@ -1440,13 +1472,16 @@ static void call_console_drivers(int level, bool nocons,
 		    !(con->flags & CON_ANYTIME))
 			continue;
 		/*
-		 * Skip record we have buffered and already printed
-		 * directly to the console when we received it.
+		 * For !ext consoles, skip record we have buffered and
+		 * already printed directly when we received it.  Ext
+		 * consoles are responsible for filtering on their ends.
 		 */
-		if (nocons)
-			continue;
-
-		con->write(con, text, len);
+		if (con->flags & CON_EXTENDED) {
+			if (ext_len)
+				con->write(con, ext_text, ext_len);
+		} else if (!nocons) {
+			con->write(con, text, len);
+		}
 	}
 }
 
@@ -1546,6 +1581,7 @@ static inline void printk_delay(void)
  */
 static struct cont {
 	char buf[LOG_LINE_MAX];
+	u64 fragid;			/* unique fragment id */
 	size_t len;			/* length == 0 means unused buffer */
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
@@ -1564,13 +1600,23 @@ static void cont_flush(enum log_flags flags)
 		return;
 
 	if (cont.cons) {
+		char dict_buf[32];
+		size_t dict_len;
+
 		/*
 		 * If a fragment of this line was directly flushed to the
 		 * console; wait for the console to pick up the rest of the
-		 * line. LOG_NOCONS suppresses a duplicated output.
+		 * line. LOG_NOCONS suppresses a duplicated output for !ext
+		 * consoles. ext consoles handle the duplicates themselves
+		 * and expect fragid in the header of the duplicate

kernel/printk/printk.c static void cont_flush(enum log_flags flags) · line 1619

Quoted 10 lines
kernel/printk/printk.c +7 -2
+		 * messages for that. Record the fragid in the dict buffer
+		 * which fragmented messages never use.
 		 */
-		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
-			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+		dict_len = scnprintf(dict_buf, sizeof(dict_buf), "FRAGID=%llu",
+				     cont.fragid);
+		log_store(cont.facility, cont.level,
+			  flags | LOG_NOCONS | LOG_DICT_META,
+			  cont.ts_nsec, dict_buf, dict_len, cont.buf, cont.len);

I wonder if it would make sense to restart fragid here. Another line will get distinguished by "seqnum".

By other words, the first fragment for each seqnum would be "0". The whole lines (without cont buffer) could always print "0".

Sigh, the whole mess is caused by the fact that we could not extend struct printk_log easily. It would be much better if we could put fragid there. I finally understand why you need to reuse the dict.

Sigh, it adds another twist into the already complex printk code.

Another solution would be to allow to disable the continuous buffer via some boot option or /sys/kernel/debug entry if you want to debug such a problem and have problem with the partial flushing.

Hmm, I wonder what are the typical values passed via "dict" and if we need to handle this entry such a special way. It would make sense to always print dict values to the ext consoles and handle this as a yet another "normal" dict value. It would allow us to remove some hacks at least.

Best Regards,
Petr

Quoted 160 lines
kernel/printk/printk.c +62 -5
 		cont.flags = flags;
 		cont.flushed = true;
 	} else {
@@ -1596,6 +1642,9 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	}
 
 	if (!cont.len) {
+		static u64 fragid;
+
+		cont.fragid = fragid++;
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
@@ -1920,14 +1969,28 @@ static u32 log_first_idx;
 static u64 log_next_seq;
 static enum log_flags console_prev;
 static struct cont {
+	char buf[1];
+	u64 fragid;
 	size_t len;
 	size_t cons;
+	u64 ts_nsec;
 	u8 level;
+	u8 facility;
 	bool flushed:1;
 } cont;
+static char *log_text(const struct printk_log *msg) { return NULL; }
+static char *log_dict(const struct printk_log *msg) { return NULL; }
+static size_t log_dict_len(const struct printk_log *msg) { return 0; }
 static struct printk_log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
+static ssize_t msg_print_ext_header(char *buf, size_t size,
+				    struct printk_log *msg, u64 seq,
+				    enum log_flags prev_flags) { return 0; }
+static ssize_t msg_print_ext_body(char *buf, size_t size,
+				  char *dict, size_t dict_len,
+				  char *text, size_t text_len) { return 0; }
 static void call_console_drivers(int level, bool nocons,
+				 const char *ext_text, size_t ext_len,
 				 const char *text, size_t len) {}
 static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 			     bool syslog, char *buf, size_t size) { return 0; }
@@ -2178,10 +2241,11 @@ int is_console_locked(void)
 	return console_locked;
 }
 
-static void console_cont_flush(char *text, size_t size)
+static void console_cont_flush(char *ext_text, size_t ext_size,
+			       char *text, size_t size)
 {
 	unsigned long flags;
-	size_t len;
+	size_t len, ext_len = 0;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
@@ -2196,10 +2260,30 @@ static void console_cont_flush(char *text, size_t size)
 	if (console_seq < log_next_seq && !cont.cons)
 		goto out;
 
+	/*
+	 * Fragment dump for consoles. Will be printed again when the
+	 * assembly is complete.
+	 */
+	if (nr_ext_console_drivers && cont.len > cont.cons) {
+		u64 ts_usec = cont.ts_nsec;
+
+		do_div(ts_usec, 1000);
+
+		ext_len = scnprintf(ext_text, ext_size,
+				    "%u,-,%llu,-,fragid=%llu;",
+				    (cont.facility << 3) | cont.level, ts_usec,
+				    cont.fragid);
+		ext_len += msg_print_ext_body(ext_text + ext_len,
+					      ext_size - ext_len, NULL, 0,
+					      cont.buf + cont.cons,
+					      cont.len - cont.cons);
+	}
+
 	len = cont_print_text(text, size);
+
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
-	call_console_drivers(cont.level, false, text, len);
+	call_console_drivers(cont.level, false, ext_text, ext_len, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
@@ -2223,6 +2307,7 @@ out:
  */
 void console_unlock(void)
 {
+	static char ext_text[CONSOLE_EXT_LOG_MAX];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
 	static u64 seen_seq;
 	unsigned long flags;
@@ -2237,11 +2322,12 @@ void console_unlock(void)
 	console_may_schedule = 0;
 
 	/* flush buffered message fragment immediately to console */
-	console_cont_flush(text, sizeof(text));
+	console_cont_flush(ext_text, sizeof(ext_text), text, sizeof(text));
 again:
 	for (;;) {
 		struct printk_log *msg;
 		size_t len;
+		size_t ext_len = 0;
 		int level;
 		bool nocons;
 
@@ -2271,6 +2357,15 @@ again:
 		nocons = msg->flags & LOG_NOCONS;
 		len += msg_print_text(msg, console_prev, false,
 				      text + len, sizeof(text) - len);
+		if (nr_ext_console_drivers) {
+			ext_len = msg_print_ext_header(ext_text,
+						sizeof(ext_text),
+						msg, console_seq, console_prev);
+			ext_len += msg_print_ext_body(ext_text + ext_len,
+						sizeof(ext_text) - ext_len,
+						log_dict(msg), log_dict_len(msg),
+						log_text(msg), msg->text_len);
+		}
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
@@ -2285,7 +2380,8 @@ again:
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(level, nocons, text, len);
+		call_console_drivers(level, nocons,
+				     ext_text, ext_len, text, len);
 		start_critical_timings();
 		local_irq_restore(flags);
 	}
@@ -2540,6 +2636,10 @@ void register_console(struct console *newcon)
 		newcon->next = console_drivers->next;
 		console_drivers->next = newcon;
 	}
+
+	if (newcon->flags & CON_EXTENDED)
+		nr_ext_console_drivers++;
+
 	if (newcon->flags & CON_PRINTBUFFER) {
 		/*
 		 * console_unlock(); will print out the buffered messages
@@ -2612,6 +2712,9 @@ int unregister_console(struct console *console)
 		}
 	}
 
+	if (!res && (console->flags & CON_EXTENDED))
+		nr_ext_console_drivers--;
+
 	/*
 	 * If this isn't the last console and it has CON_CONSDEV set, we
 	 * need to set it on the next preferred console.
Signature · 1 line
2.1.0
#10 lore raw

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

Quoted 33 lines · Petr Mladek
Quoted 32 lines · 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. Immediately, it's to implement reliable netconsole but may be useful for other console devices too.

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

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

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

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

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

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

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

* Extended message formatting for console drivers is enabled iff there

[...]

Quoted 11 lines

Sigh, it adds another twist into the already complex printk code.

Another solution would be to allow to disable the continuous buffer via some boot option or /sys/kernel/debug entry if you want to debug such a problem and have problem with the partial flushing.

Hmm, I wonder what are the typical values passed via "dict" and if we need to handle this entry such a special way. It would make sense to always print dict values to the ext consoles and handle this as a yet another "normal" dict value. It would allow us to remove some hacks at least.

Another solution would be to always flush cont buffer when it is being printed to the console. Then the messages might by distinguished by the seqnum and fragid won't be needed. The question is if the cont buffer will still have any affect after this change.

Best Regards,
Petr

author
#11 lore raw

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

In reply to Petr Mladek

Hello, Petr.

Sorry about the delay.

On Mon, Apr 20, 2015 at 05:43:07PM +0200, Petr Mladek wrote:
...

Quoted 3 lines
Quoted 1 line

* Extended message formatting for console drivers is enabled iff there

s/iff/if/

if and only if

Quoted 7 lines

I was afraid that there might be a potential buffer overflow because the user-provided dict need not be limited by '\0'. But LOG_DICT_META is used only with the internal data that are safe. We might document this as well.

BTW: Do you want to print the internal dict when calling this function in devkmsg_read()?

No, plesae see below.

Quoted 8 lines

kernel/printk/printk.c static ssize_t msg_print_ext_header(char *buf, size_t size, · line 569

Quoted 5 lines
kernel/printk/printk.c +5 -0
+		scnprintf(fragid_buf, sizeof(fragid_buf),
+			  ",fragid=%llu", fragid);
+	return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+			 (msg->facility << 3) | msg->level, seq, ts_usec, cont,
+			 fragid_buf);

The above comment suggests that "cont" and "fragid_buf" are delimited by a comma but it is not used here. Is it by intention.

Hmm... how is it not? The fragid printf has preceding comma.

Quoted 8 lines

kernel/printk/printk.c static void cont_flush(enum log_flags flags) · line 1619

Quoted 5 lines
kernel/printk/printk.c +5 -0
+		dict_len = scnprintf(dict_buf, sizeof(dict_buf), "FRAGID=%llu",
+				     cont.fragid);
+		log_store(cont.facility, cont.level,
+			  flags | LOG_NOCONS | LOG_DICT_META,
+			  cont.ts_nsec, dict_buf, dict_len, cont.buf, cont.len);

I wonder if it would make sense to restart fragid here. Another line will get distinguished by "seqnum".

That'd assume that there can only ever be a single continuation buffer, which is true now but it's possible that we may want to make it per-cpu in the future.

Quoted 3 lines

Sigh, the whole mess is caused by the fact that we could not extend struct printk_log easily. It would be much better if we could put fragid there. I finally understand why you need to reuse the dict.

I've been thinking about it and using dict area for internal metadata is indeed quite messy. I think a better way to do it is declaring dict_len as a union w/ fragid. This'd limit the fragid to 16bit but that should be more than enough and we can do away with the string formatting and reading back.

Quoted 3 lines

Another solution would be to allow to disable the continuous buffer via some boot option or /sys/kernel/debug entry if you want to debug such a problem and have problem with the partial flushing.

It isn't really about debugging partial flushing itself but rather always being able to push out the messages before the printk invocation finishes.

Thanks.

Signature · 1 line
tejun
#12 lore raw

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

Quoted 3 lines · Tejun Heo

Hello, Petr.

Sorry about the delay.

np

Quoted 10 lines · Petr Mladek
Quoted 7 lines

I was afraid that there might be a potential buffer overflow because the user-provided dict need not be limited by '\0'. But LOG_DICT_META is used only with the internal data that are safe. We might document this as well.

BTW: Do you want to print the internal dict when calling this function in devkmsg_read()?

No, plesae see below.

I see, it is not printed there because the dict_len is zero for the internal info.

Quoted 10 lines
Quoted 8 lines

kernel/printk/printk.c static ssize_t msg_print_ext_header(char *buf, size_t size, · line 569

Quoted 5 lines
kernel/printk/printk.c +5 -0
+		scnprintf(fragid_buf, sizeof(fragid_buf),
+			  ",fragid=%llu", fragid);
+	return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+			 (msg->facility << 3) | msg->level, seq, ts_usec, cont,
+			 fragid_buf);

The above comment suggests that "cont" and "fragid_buf" are delimited by a comma but it is not used here. Is it by intention.

Hmm... how is it not? The fragid printf has preceding comma.

I see it now.

Quoted 9 lines
Quoted 8 lines

kernel/printk/printk.c static void cont_flush(enum log_flags flags) · line 1619

Quoted 5 lines
kernel/printk/printk.c +5 -0
+		dict_len = scnprintf(dict_buf, sizeof(dict_buf), "FRAGID=%llu",
+				     cont.fragid);
+		log_store(cont.facility, cont.level,
+			  flags | LOG_NOCONS | LOG_DICT_META,
+			  cont.ts_nsec, dict_buf, dict_len, cont.buf, cont.len);

I wonder if it would make sense to restart fragid here. Another line will get distinguished by "seqnum".

Quoted 3 lines

That'd assume that there can only ever be a single continuation buffer, which is true now but it's possible that we may want to make it per-cpu in the future.

I am not sure if any more complications will get accepted. Anyway, each CPU should print an independent message. Therefore each pre-CPU cont buffer would be printed on separate line and would get another seqnum. We could have per-CPU fragid counter.

Quoted 9 lines
Quoted 3 lines

Sigh, the whole mess is caused by the fact that we could not extend struct printk_log easily. It would be much better if we could put fragid there. I finally understand why you need to reuse the dict.

I've been thinking about it and using dict area for internal metadata is indeed quite messy. I think a better way to do it is declaring dict_len as a union w/ fragid. This'd limit the fragid to 16bit but that should be more than enough and we can do away with the string formatting and reading back.

Nice idea. I like it much more.

Quoted 7 lines
Quoted 3 lines

Another solution would be to allow to disable the continuous buffer via some boot option or /sys/kernel/debug entry if you want to debug such a problem and have problem with the partial flushing.

It isn't really about debugging partial flushing itself but rather always being able to push out the messages before the printk invocation finishes.

I did not mean cont-buffer debugging. I meant debugging with netconsole.

Note that cont buffer is only a memory optimization. You could put every text snippet into the ring buffer and console immediately. You need to set LOG_CONT instead of LOG_NEWLINE flag. This is already used when the line is too long for the cont buffer or when there is printed a message from another cpu in the middle of a continuing message.

Best Regards,
Petr

author
#13 lore raw

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

Hello, Petr.

Quoted 6 lines · Petr Mladek

Note that cont buffer is only a memory optimization. You could put every text snippet into the ring buffer and console immediately. You need to set LOG_CONT instead of LOG_NEWLINE flag. This is already used when the line is too long for the cont buffer or when there is printed a message from another cpu in the middle of a continuing message.

Yeah, hmmm, I wonder whether the right solution here is to bypass cont buffer if ext_console is present. This would use a bit more memory and hurt users catting /proc/kmsg but everyone else should be able to get the same result and things get a lot simpler on both sending and receiving sides. What do you think?

Thanks.

Signature · 1 line
tejun
#14 lore raw

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

Quoted 10 lines · Tejun Heo

Hello, Petr.

Quoted 6 lines · Petr Mladek

Note that cont buffer is only a memory optimization. You could put every text snippet into the ring buffer and console immediately. You need to set LOG_CONT instead of LOG_NEWLINE flag. This is already used when the line is too long for the cont buffer or when there is printed a message from another cpu in the middle of a continuing message.

Quoted 5 lines

Yeah, hmmm, I wonder whether the right solution here is to bypass cont buffer if ext_console is present. This would use a bit more memory and hurt users catting /proc/kmsg but everyone else should be able to get the same result and things get a lot simpler on both sending and receiving sides. What do you think?

I would personally give it a try. If it works well, we might eventually get rid of the cont buffer completely and make the printk code a bit easier again.

Best Regards,
Petr

author
#15 lore raw

PATCH 5/16 printk: implement log_seq_range() and ext_log_from_seq()

In reply to Tejun Heo

Implement two functions to access log messages by their sequence numbers.

* log_seq_range() determines the currently available sequence number range.

* ext_log_from_seq() outputs log message identified by a given sequence number in the extended format.

These will be used to implement reliable netconsole.

Cc Kay Sievers <[email protected]>
Cc Petr Mladek <[email protected]>
---
 include/linux/printk.h | 14 ++++++++
 kernel/printk/printk.c | 96 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 110 insertions(+)
include/linux/printk.h +14 -0
index 58b1fec..4fd3bb4 100644
@@ -6,6 +6,7 @@
 #include <linux/kern_levels.h>
 #include <linux/linkage.h>
 #include <linux/cache.h>
+#include <linux/errno.h>
 
 extern const char linux_banner[];
 extern const char linux_proc_banner[];
@@ -169,6 +170,8 @@ void __init setup_log_buf(int early);
 void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+void log_seq_range(u64 *beginp, u64 *endp);
+ssize_t ext_log_from_seq(char *buf, size_t size, u64 log_seq);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -228,6 +231,17 @@ static inline void dump_stack_print_info(const char *log_lvl)
 static inline void show_regs_print_info(const char *log_lvl)
 {
 }
+
+static inline void log_seq_range(u64 *begin_seqp, u64 *end_seqp)
+{
+	*begin_seqp = 0;
+	*end_seqp = 0;
+}
+
+static inline ssize_t ext_log_from_seq(char *buf, size_t size, u64 log_seq)
+{
+	return -ERANGE;
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
kernel/printk/printk.c +96 -0

102 lines not on this page · raw message

Signature · 1 line
2.1.0
author
#16 lore raw

PATCH 6/16 netconsole: make netconsole_target->enabled a bool

In reply to Tejun Heo

We'll add more bool's to netconsole_target. Let's convert ->enabled to bool first so that things stay consistent.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)
drivers/net/netconsole.c +9 -9
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;
Signature · 1 line
2.1.0
author
#17 lore raw

PATCH 7/16 netconsole: factor out alloc_netconsole_target()

In reply to Tejun Heo

alloc_param_target() and make_netconsole_target() were duplicating the same allocation and init logic. Factor it out to alloc_netconsole_target().

This is pure reorganization.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 40 ++++++++++++++++++++--------------------
 1 file changed, 20 insertions(+), 20 deletions(-)
drivers/net/netconsole.c +20 -20
index 09d4e12..17692b8 100644
@@ -167,19 +167,17 @@ static void netconsole_target_put(struct netconsole_target *nt)
 
 #endif	/* CONFIG_NETCONSOLE_DYNAMIC */
 
-/* Allocate new target (from boot/module param) and setup netpoll for it */
-static struct netconsole_target *alloc_param_target(char *target_config)
+/*
+ * Allocate and initialize with defaults.  Note that these targets get
+ * their config_item fields zeroed-out.
+ */
+static struct netconsole_target *alloc_netconsole_target(void)
 {
-	int err = -ENOMEM;
 	struct netconsole_target *nt;
 
-	/*
-	 * Allocate and initialize with defaults.
-	 * Note that these targets get their config_item fields zeroed-out.
-	 */
 	nt = kzalloc(sizeof(*nt), GFP_KERNEL);
 	if (!nt)
-		goto fail;
+		return NULL;
 
 	nt->np.name = "netconsole";
 	strlcpy(nt->np.dev_name, "eth0", IFNAMSIZ);
@@ -188,6 +186,19 @@ static struct netconsole_target *alloc_param_target(char *target_config)
 	mutex_init(&nt->mutex);
 	eth_broadcast_addr(nt->np.remote_mac);
 
+	return nt;
+}
+
+/* Allocate new target (from boot/module param) and setup netpoll for it */
+static struct netconsole_target *alloc_param_target(char *target_config)
+{
+	int err = -ENOMEM;
+	struct netconsole_target *nt;
+
+	nt = alloc_netconsole_target();
+	if (!nt)
+		goto fail;
+
 	/* Parse parameters and setup netpoll */
 	err = netpoll_parse_options(&nt->np, target_config);
 	if (err)
@@ -592,21 +603,10 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 	unsigned long flags;
 	struct netconsole_target *nt;
 
-	/*
-	 * Allocate and initialize with defaults.
-	 * Target is disabled at creation (!enabled).
-	 */
-	nt = kzalloc(sizeof(*nt), GFP_KERNEL);
+	nt = alloc_netconsole_target();
 	if (!nt)
 		return ERR_PTR(-ENOMEM);
 
-	nt->np.name = "netconsole";
-	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 */
 	config_item_init_type_name(&nt->item, name, &netconsole_target_type);
 
Signature · 1 line
2.1.0
author
#18 lore raw

PATCH 8/16 netconsole: punt disabling to workqueue from netdevice_notifier

In reply to Tejun Heo

The netdevice_notifier callback, netconsole_netdev_event(), needs to perform netpoll_cleanup() for the affected targets; however, the notifier is called with rtnl_lock held which the netpoll_cleanup() path also grabs. To avoid deadlock, the path uses __netpoll_cleanup() instead and making the code path different from others.

The planned reliable netconsole support will add more logic to the cleanup path making the slightly different paths painful. Let's punt netconsole_target disabling to workqueue so that it can later share the same cleanup path. This would also allow ditching target_list_lock and depending on console_lock for synchronization.

Note that this introduces a narrow race window where the asynchronous disabling may race against disabling from configfs ending up executing netpoll_cleanup() more than once on the same instance. The follow up patches will fix it by introducing a mutex to protect overall enable / disable operations; unfortunately, the locking update couldn't be ordered before this change due to the locking order with rtnl_lock.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 58 ++++++++++++++++++++++++++++++++++--------------
 1 file changed, 41 insertions(+), 17 deletions(-)
drivers/net/netconsole.c +41 -17
index 17692b8..d355776 100644
@@ -105,6 +105,7 @@ struct netconsole_target {
 	struct config_item	item;
 #endif
 	bool			enabled;
+	bool			disable_scheduled;
 	struct mutex		mutex;
 	struct netpoll		np;
 };
@@ -660,6 +661,39 @@ static struct configfs_subsystem netconsole_subsys = {
 
 #endif	/* CONFIG_NETCONSOLE_DYNAMIC */
 
+static void netconsole_deferred_disable_work_fn(struct work_struct *work)
+{
+	struct netconsole_target *nt, *to_disable;
+	unsigned long flags;
+
+repeat:
+	to_disable = NULL;
+	spin_lock_irqsave(&target_list_lock, flags);
+	list_for_each_entry(nt, &target_list, list) {
+		if (!nt->disable_scheduled)
+			continue;
+		nt->disable_scheduled = false;
+
+		if (!nt->enabled)
+			continue;
+
+		netconsole_target_get(nt);
+		nt->enabled = false;
+		to_disable = nt;
+		break;
+	}
+	spin_unlock_irqrestore(&target_list_lock, flags);
+
+	if (to_disable) {
+		netpoll_cleanup(&to_disable->np);
+		netconsole_target_put(to_disable);
+		goto repeat;
+	}
+}
+
+static DECLARE_WORK(netconsole_deferred_disable_work,
+		    netconsole_deferred_disable_work_fn);
+
 /* Handle network interface device notifications */
 static int netconsole_netdev_event(struct notifier_block *this,
 				   unsigned long event, void *ptr)
@@ -674,9 +708,7 @@ static int netconsole_netdev_event(struct notifier_block *this,
 		goto done;
 
 	spin_lock_irqsave(&target_list_lock, flags);
-restart:
 	list_for_each_entry(nt, &target_list, list) {
-		netconsole_target_get(nt);
 		if (nt->np.dev == dev) {
 			switch (event) {
 			case NETDEV_CHANGENAME:
@@ -685,23 +717,14 @@ restart:
 			case NETDEV_RELEASE:
 			case NETDEV_JOIN:
 			case NETDEV_UNREGISTER:
-				/* rtnl_lock already held
-				 * we might sleep in __netpoll_cleanup()
-				 */
-				spin_unlock_irqrestore(&target_list_lock, flags);
-
-				__netpoll_cleanup(&nt->np);
-
-				spin_lock_irqsave(&target_list_lock, flags);
-				dev_put(nt->np.dev);
-				nt->np.dev = NULL;
-				nt->enabled = false;
+				/* rtnl_lock already held, punt to workqueue */
+				if (nt->enabled && !nt->disable_scheduled) {
+					nt->disable_scheduled = true;
+					schedule_work(&netconsole_deferred_disable_work);
+				}
 				stopped = true;
-				netconsole_target_put(nt);
-				goto restart;
 			}
 		}
-		netconsole_target_put(nt);
 	}
 	spin_unlock_irqrestore(&target_list_lock, flags);
 	if (stopped) {
@@ -810,7 +833,7 @@ static int __init init_netconsole(void)
 
 undonotifier:
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
-
+	cancel_work_sync(&netconsole_deferred_disable_work);
 fail:
 	pr_err("cleaning up\n");
 
@@ -834,6 +857,7 @@ static void __exit cleanup_netconsole(void)
 	unregister_console(&netconsole);
 	dynamic_netconsole_exit();
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
+	cancel_work_sync(&netconsole_deferred_disable_work);
 
 	/*
 	 * Targets created via configfs pin references on our module
Signature · 1 line
2.1.0
author
#19 lore raw

PATCH 9/16 netconsole: replace target_list_lock with console_lock

In reply to Tejun Heo

netconsole has been using a spinlock - target_list_lock - to protect the list of configured netconsole targets and their enable/disable states. With the disabling from netdevice_notifier moved off to a workqueue by the previous patch and thus outside of rtnl_lock, target_list_lock can be replaced with console_lock, which allows us to avoid grabbing an extra lock in the log write path and can simplify locking when involving other subsystems as console_lock is only trylocked from printk path.

This patch replaces target_list_lock with console_lock. The conversion is one-to-one except for write_msg(). The function is called with console_lock() already held so no further locking is necessary; however, as netpoll_send_udp() expects irq to be disabled, explicit irq save/restore pair is added around it.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 50 ++++++++++++++++++------------------------------
 1 file changed, 19 insertions(+), 31 deletions(-)
drivers/net/netconsole.c +19 -31
index d355776..57c02ab 100644
@@ -73,12 +73,12 @@ static int __init option_setup(char *opt)
 __setup("netconsole=", option_setup);
 #endif	/* MODULE */
 
-/* Linked list of all configured targets */
+/*
+ * Linked list of all configured targets.  The list and each target's
+ * enable/disable state are protected by console_lock.
+ */
 static LIST_HEAD(target_list);
 
-/* This needs to be a spinlock because write_msg() cannot sleep */
-static DEFINE_SPINLOCK(target_list_lock);
-
 /**
  * struct netconsole_target - Represents a configured netconsole target.
  * @list:	Links this target into the target_list.
@@ -325,7 +325,6 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 			     const char *buf,
 			     size_t count)
 {
-	unsigned long flags;
 	int enabled;
 	int err;
 
@@ -357,9 +356,9 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 		 * otherwise we might end up in write_msg() with
 		 * nt->np.dev == NULL and nt->enabled == true
 		 */
-		spin_lock_irqsave(&target_list_lock, flags);
+		console_lock();
 		nt->enabled = false;
-		spin_unlock_irqrestore(&target_list_lock, flags);
+		console_unlock();
 		netpoll_cleanup(&nt->np);
 	}
 
@@ -601,7 +600,6 @@ static struct config_item_type netconsole_target_type = {
 static struct config_item *make_netconsole_target(struct config_group *group,
 						  const char *name)
 {
-	unsigned long flags;
 	struct netconsole_target *nt;
 
 	nt = alloc_netconsole_target();
@@ -612,9 +610,9 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 	config_item_init_type_name(&nt->item, name, &netconsole_target_type);
 
 	/* Adding, but it is disabled */
-	spin_lock_irqsave(&target_list_lock, flags);
+	console_lock();
 	list_add(&nt->list, &target_list);
-	spin_unlock_irqrestore(&target_list_lock, flags);
+	console_unlock();
 
 	return &nt->item;
 }
@@ -622,12 +620,11 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 static void drop_netconsole_target(struct config_group *group,
 				   struct config_item *item)
 {
-	unsigned long flags;
 	struct netconsole_target *nt = to_target(item);
 
-	spin_lock_irqsave(&target_list_lock, flags);
+	console_lock();
 	list_del(&nt->list);
-	spin_unlock_irqrestore(&target_list_lock, flags);
+	console_unlock();
 
 	/*
 	 * The target may have never been enabled, or was manually disabled
@@ -664,11 +661,10 @@ static struct configfs_subsystem netconsole_subsys = {
 static void netconsole_deferred_disable_work_fn(struct work_struct *work)
 {
 	struct netconsole_target *nt, *to_disable;
-	unsigned long flags;
 
 repeat:
 	to_disable = NULL;
-	spin_lock_irqsave(&target_list_lock, flags);
+	console_lock();
 	list_for_each_entry(nt, &target_list, list) {
 		if (!nt->disable_scheduled)
 			continue;
@@ -682,7 +678,7 @@ repeat:
 		to_disable = nt;
 		break;
 	}
-	spin_unlock_irqrestore(&target_list_lock, flags);
+	console_unlock();
 
 	if (to_disable) {
 		netpoll_cleanup(&to_disable->np);
@@ -698,7 +694,6 @@ static DECLARE_WORK(netconsole_deferred_disable_work,
 static int netconsole_netdev_event(struct notifier_block *this,
 				   unsigned long event, void *ptr)
 {
-	unsigned long flags;
 	struct netconsole_target *nt;
 	struct net_device *dev = netdev_notifier_info_to_dev(ptr);
 	bool stopped = false;
@@ -707,7 +702,7 @@ static int netconsole_netdev_event(struct notifier_block *this,
 	      event == NETDEV_RELEASE || event == NETDEV_JOIN))
 		goto done;
 
-	spin_lock_irqsave(&target_list_lock, flags);
+	console_lock();
 	list_for_each_entry(nt, &target_list, list) {
 		if (nt->np.dev == dev) {
 			switch (event) {
@@ -726,7 +721,7 @@ static int netconsole_netdev_event(struct notifier_block *this,
 			}
 		}
 	}
-	spin_unlock_irqrestore(&target_list_lock, flags);
+	console_unlock();
 	if (stopped) {
 		const char *msg = "had an event";
 		switch (event) {
@@ -755,7 +750,6 @@ static struct notifier_block netconsole_netdev_notifier = {
 static void write_msg(struct console *con, const char *msg, unsigned int len)
 {
 	int frag, left;
-	unsigned long flags;
 	struct netconsole_target *nt;
 	const char *tmp;
 
@@ -765,9 +759,7 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 	if (list_empty(&target_list))
 		return;
 
-	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
@@ -783,9 +775,7 @@ 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);
 }
 
 static struct console netconsole = {
@@ -798,7 +788,6 @@ static int __init init_netconsole(void)
 {
 	int err;
 	struct netconsole_target *nt, *tmp;
-	unsigned long flags;
 	char *target_config;
 	char *input = config;
 
@@ -812,9 +801,9 @@ static int __init init_netconsole(void)
 			/* Dump existing printks when we register */
 			netconsole.flags |= CON_PRINTBUFFER;
 
-			spin_lock_irqsave(&target_list_lock, flags);
+			console_lock();
 			list_add(&nt->list, &target_list);
-			spin_unlock_irqrestore(&target_list_lock, flags);
+			console_unlock();
 		}
 	}
 
@@ -839,8 +828,8 @@ fail:
 
 	/*
 	 * Remove all targets and destroy them (only targets created
-	 * from the boot/module option exist here). Skipping the list
-	 * lock is safe here, and netpoll_cleanup() will sleep.
+	 * from the boot/module option exist here). Skipping the console
+	 * lock is safe here.
 	 */
 	list_for_each_entry_safe(nt, tmp, &target_list, list) {
 		list_del(&nt->list);
@@ -864,8 +853,7 @@ static void __exit cleanup_netconsole(void)
 	 * and would first be rmdir(2)'ed from userspace. We reach
 	 * here only when they are already destroyed, and only those
 	 * created from the boot/module option are left, so remove and
-	 * destroy them. Skipping the list lock is safe here, and
-	 * netpoll_cleanup() will sleep.
+	 * destroy them. Skipping the console lock is safe here.
 	 */
 	list_for_each_entry_safe(nt, tmp, &target_list, list) {
 		list_del(&nt->list);
Signature · 1 line
2.1.0
author
#20 lore raw

PATCH 10/16 netconsole: introduce netconsole_mutex

In reply to Tejun Heo

console_lock protects the target_list itself and setting and clearing of its ->enabled flag; however, nothing protects the overall enable/disable operations which we'll need to make netconsole management more dynamic for the scheduled reliable transmission support. Also, an earlier patch introduced a small race window where dynamic console disable may compete against asynchronous disable kicked off from netdevice_notifier.

This patch adds netconsole_mutex which protects all target create/destroy and enable/disable operations. It also replaces netconsole_target->mutex used by dynamic consoles. The above mentioned race is removed by this change.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 48 ++++++++++++++++++++++++++++--------------------
 1 file changed, 28 insertions(+), 20 deletions(-)
drivers/net/netconsole.c +28 -20
index 57c02ab..f0ac9f6 100644
@@ -75,10 +75,14 @@ __setup("netconsole=", option_setup);
 
 /*
  * Linked list of all configured targets.  The list and each target's
- * enable/disable state are protected by console_lock.
+ * enable/disable state are protected by both netconsole_mutex and
+ * console_lock.
  */
 static LIST_HEAD(target_list);
 
+/* protects target creation/destruction and enable/disable */
+static DEFINE_MUTEX(netconsole_mutex);
+
 /**
  * struct netconsole_target - Represents a configured netconsole target.
  * @list:	Links this target into the target_list.
@@ -106,7 +110,6 @@ struct netconsole_target {
 #endif
 	bool			enabled;
 	bool			disable_scheduled;
-	struct mutex		mutex;
 	struct netpoll		np;
 };
 
@@ -184,7 +187,6 @@ static struct netconsole_target *alloc_netconsole_target(void)
 	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);
 
 	return nt;
@@ -196,6 +198,8 @@ static struct netconsole_target *alloc_param_target(char *target_config)
 	int err = -ENOMEM;
 	struct netconsole_target *nt;
 
+	lockdep_assert_held(&netconsole_mutex);
+
 	nt = alloc_netconsole_target();
 	if (!nt)
 		goto fail;
@@ -573,10 +577,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(&netconsole_mutex);
 	if (na->store)
 		ret = na->store(nt, buf, count);
-	mutex_unlock(&nt->mutex);
+	mutex_unlock(&netconsole_mutex);
 
 	return ret;
 }
@@ -610,9 +614,11 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 	config_item_init_type_name(&nt->item, name, &netconsole_target_type);
 
 	/* Adding, but it is disabled */
+	mutex_lock(&netconsole_mutex);
 	console_lock();
 	list_add(&nt->list, &target_list);
 	console_unlock();
+	mutex_unlock(&netconsole_mutex);
 
 	return &nt->item;
 }
@@ -622,6 +628,7 @@ static void drop_netconsole_target(struct config_group *group,
 {
 	struct netconsole_target *nt = to_target(item);
 
+	mutex_lock(&netconsole_mutex);
 	console_lock();
 	list_del(&nt->list);
 	console_unlock();
@@ -634,6 +641,7 @@ static void drop_netconsole_target(struct config_group *group,
 		netpoll_cleanup(&nt->np);
 
 	config_item_put(&nt->item);
+	mutex_unlock(&netconsole_mutex);
 }
 
 static struct configfs_group_operations netconsole_subsys_group_ops = {
@@ -662,6 +670,7 @@ static void netconsole_deferred_disable_work_fn(struct work_struct *work)
 {
 	struct netconsole_target *nt, *to_disable;
 
+	mutex_lock(&netconsole_mutex);
 repeat:
 	to_disable = NULL;
 	console_lock();
@@ -685,6 +694,8 @@ repeat:
 		netconsole_target_put(to_disable);
 		goto repeat;
 	}
+
+	mutex_unlock(&netconsole_mutex);
 }
 
 static DECLARE_WORK(netconsole_deferred_disable_work,
@@ -791,6 +802,8 @@ static int __init init_netconsole(void)
 	char *target_config;
 	char *input = config;
 
+	mutex_lock(&netconsole_mutex);
+
 	if (strnlen(input, MAX_PARAM_LENGTH)) {
 		while ((target_config = strsep(&input, ";"))) {
 			nt = alloc_param_target(target_config);
@@ -818,24 +831,21 @@ static int __init init_netconsole(void)
 	register_console(&netconsole);
 	pr_info("network logging started\n");
 
+	mutex_unlock(&netconsole_mutex);
 	return err;
 
 undonotifier:
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
-	cancel_work_sync(&netconsole_deferred_disable_work);
 fail:
 	pr_err("cleaning up\n");
 
-	/*
-	 * Remove all targets and destroy them (only targets created
-	 * from the boot/module option exist here). Skipping the console
-	 * lock is safe here.
-	 */
+	/* targets are already inactive, skipping the console lock is safe */
 	list_for_each_entry_safe(nt, tmp, &target_list, list) {
 		list_del(&nt->list);
 		free_param_target(nt);
 	}
-
+	mutex_unlock(&netconsole_mutex);
+	cancel_work_sync(&netconsole_deferred_disable_work);
 	return err;
 }
 
@@ -843,22 +853,20 @@ static void __exit cleanup_netconsole(void)
 {
 	struct netconsole_target *nt, *tmp;
 
+	mutex_lock(&netconsole_mutex);
+
 	unregister_console(&netconsole);
 	dynamic_netconsole_exit();
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
-	cancel_work_sync(&netconsole_deferred_disable_work);
 
-	/*
-	 * Targets created via configfs pin references on our module
-	 * and would first be rmdir(2)'ed from userspace. We reach
-	 * here only when they are already destroyed, and only those
-	 * created from the boot/module option are left, so remove and
-	 * destroy them. Skipping the console lock is safe here.
-	 */
+	/* targets are already inactive, skipping the console lock is safe */
 	list_for_each_entry_safe(nt, tmp, &target_list, list) {
 		list_del(&nt->list);
 		free_param_target(nt);
 	}
+
+	mutex_unlock(&netconsole_mutex);
+	cancel_work_sync(&netconsole_deferred_disable_work);
 }
 
 /*
Signature · 1 line
2.1.0
author
#21 lore raw

PATCH 11/16 netconsole: consolidate enable/disable and create/destroy paths

In reply to Tejun Heo

netconsole management paths are scattered around in different places. This patch reorganizes them so that

* All enable logic is in netconsole_enable() and disable in netconsole_disable(). Both should be called with netconsole_mutex held and netconsole_disable() may be invoked without intervening enable.

* alloc_param_target() now also handles linking the new target to target_list. It's renamed to create_param_target() and now returns errno.

* store_enabled() now uses netconsole_enable/disable() instead of open-coding the logic. This also fixes the missing synchronization against write path when manipulating ->enabled flag.

* drop_netconsole_target() and netconsole_deferred_disable_work_fn() updated to use netconsole_disable().

* init/cleanup_netconsole()'s destruction paths are consolidated into netconsole_destroy_all() which uses netconsole_disable(). free_param_target() is no longer used and removed.

While the conversions aren't one-to-one equivalent, this patch shouldn't cause any visible behavior differences and makes extension of the enable/disable logic a lot easier.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 147 +++++++++++++++++++++++++----------------------
 1 file changed, 79 insertions(+), 68 deletions(-)
drivers/net/netconsole.c +79 -68
index f0ac9f6..d72d902 100644
@@ -83,6 +83,8 @@ static LIST_HEAD(target_list);
 /* protects target creation/destruction and enable/disable */
 static DEFINE_MUTEX(netconsole_mutex);
 
+static struct console netconsole;
+
 /**
  * struct netconsole_target - Represents a configured netconsole target.
  * @list:	Links this target into the target_list.
@@ -192,8 +194,43 @@ static struct netconsole_target *alloc_netconsole_target(void)
 	return nt;
 }
 
+static int netconsole_enable(struct netconsole_target *nt)
+{
+	int err;
+
+	lockdep_assert_held(&netconsole_mutex);
+	WARN_ON_ONCE(nt->enabled);
+
+	err = netpoll_setup(&nt->np);
+	if (err)
+		return err;
+
+	console_lock();
+	nt->enabled = true;
+	console_unlock();
+	return 0;
+}
+
+static void netconsole_disable(struct netconsole_target *nt)
+{
+	lockdep_assert_held(&netconsole_mutex);
+
+	/*
+	 * We need to disable the netconsole before cleaning it up
+	 * otherwise we might end up in write_msg() with !nt->np.dev &&
+	 * nt->enabled.
+	 */
+	if (nt->enabled) {
+		console_lock();
+		nt->enabled = false;
+		console_unlock();
+
+		netpoll_cleanup(&nt->np);
+	}
+}
+
 /* Allocate new target (from boot/module param) and setup netpoll for it */
-static struct netconsole_target *alloc_param_target(char *target_config)
+static int create_param_target(char *target_config)
 {
 	int err = -ENOMEM;
 	struct netconsole_target *nt;
@@ -209,24 +246,26 @@ static struct netconsole_target *alloc_param_target(char *target_config)
 	if (err)
 		goto fail;
 
-	err = netpoll_setup(&nt->np);
+	console_lock();
+	list_add(&nt->list, &target_list);
+	console_unlock();
+
+	err = netconsole_enable(nt);
 	if (err)
-		goto fail;
+		goto fail_del;
 
-	nt->enabled = true;
+	/* Dump existing printks when we register */
+	netconsole.flags |= CON_PRINTBUFFER;
 
-	return nt;
+	return 0;
 
+fail_del:
+	console_lock();
+	list_del(&nt->list);
+	console_unlock();
 fail:
 	kfree(nt);
-	return ERR_PTR(err);
-}
-
-/* Cleanup netpoll for given target (from boot/module param) and free it */
-static void free_param_target(struct netconsole_target *nt)
-{
-	netpoll_cleanup(&nt->np);
-	kfree(nt);
+	return err;
 }
 
 #ifdef	CONFIG_NETCONSOLE_DYNAMIC
@@ -350,24 +389,15 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 		 */
 		netpoll_print_options(&nt->np);
 
-		err = netpoll_setup(&nt->np);
+		err = netconsole_enable(nt);
 		if (err)
 			return err;
 
 		pr_info("netconsole: network logging started\n");
 	} 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 == true
-		 */
-		console_lock();
-		nt->enabled = false;
-		console_unlock();
-		netpoll_cleanup(&nt->np);
+		netconsole_disable(nt);
 	}
 
-	nt->enabled = enabled;
-
 	return strnlen(buf, count);
 }
 
@@ -633,13 +663,7 @@ static void drop_netconsole_target(struct config_group *group,
 	list_del(&nt->list);
 	console_unlock();
 
-	/*
-	 * The target may have never been enabled, or was manually disabled
-	 * before being removed so netpoll may have already been cleaned up.
-	 */
-	if (nt->enabled)
-		netpoll_cleanup(&nt->np);
-
+	netconsole_disable(nt);
 	config_item_put(&nt->item);
 	mutex_unlock(&netconsole_mutex);
 }
@@ -675,22 +699,16 @@ repeat:
 	to_disable = NULL;
 	console_lock();
 	list_for_each_entry(nt, &target_list, list) {
-		if (!nt->disable_scheduled)
-			continue;
-		nt->disable_scheduled = false;
-
-		if (!nt->enabled)
-			continue;
-
-		netconsole_target_get(nt);
-		nt->enabled = false;
-		to_disable = nt;
-		break;
+		if (nt->disable_scheduled) {
+			nt->disable_scheduled = false;
+			netconsole_target_get(nt);
+			to_disable = nt;
+		}
 	}
 	console_unlock();
 
 	if (to_disable) {
-		netpoll_cleanup(&to_disable->np);
+		netconsole_disable(to_disable);
 		netconsole_target_put(to_disable);
 		goto repeat;
 	}
@@ -795,10 +813,23 @@ static struct console netconsole = {
 	.write	= write_msg,
 };
 
+static void __init_or_module netconsole_destroy_all(void)
+{
+	struct netconsole_target *nt, *tmp;
+
+	lockdep_assert_held(&netconsole_mutex);
+
+	/* targets are already inactive, skipping the console lock is safe */
+	list_for_each_entry_safe(nt, tmp, &target_list, list) {
+		list_del(&nt->list);
+		netconsole_disable(nt);
+		kfree(nt);
+	}
+}
+
 static int __init init_netconsole(void)
 {
 	int err;
-	struct netconsole_target *nt, *tmp;
 	char *target_config;
 	char *input = config;
 
@@ -806,17 +837,9 @@ static int __init init_netconsole(void)
 
 	if (strnlen(input, MAX_PARAM_LENGTH)) {
 		while ((target_config = strsep(&input, ";"))) {
-			nt = alloc_param_target(target_config);
-			if (IS_ERR(nt)) {
-				err = PTR_ERR(nt);
+			err = create_param_target(target_config);
+			if (err)
 				goto fail;
-			}
-			/* Dump existing printks when we register */
-			netconsole.flags |= CON_PRINTBUFFER;
-
-			console_lock();
-			list_add(&nt->list, &target_list);
-			console_unlock();
 		}
 	}
 
@@ -838,12 +861,7 @@ undonotifier:
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
 fail:
 	pr_err("cleaning up\n");
-
-	/* targets are already inactive, skipping the console lock is safe */
-	list_for_each_entry_safe(nt, tmp, &target_list, list) {
-		list_del(&nt->list);
-		free_param_target(nt);
-	}
+	netconsole_destroy_all();
 	mutex_unlock(&netconsole_mutex);
 	cancel_work_sync(&netconsole_deferred_disable_work);
 	return err;
@@ -851,19 +869,12 @@ fail:
 
 static void __exit cleanup_netconsole(void)
 {
-	struct netconsole_target *nt, *tmp;
-
 	mutex_lock(&netconsole_mutex);
 
 	unregister_console(&netconsole);
 	dynamic_netconsole_exit();
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
-
-	/* targets are already inactive, skipping the console lock is safe */
-	list_for_each_entry_safe(nt, tmp, &target_list, list) {
-		list_del(&nt->list);
-		free_param_target(nt);
-	}
+	netconsole_destroy_all();
 
 	mutex_unlock(&netconsole_mutex);
 	cancel_work_sync(&netconsole_deferred_disable_work);
Signature · 1 line
2.1.0
author
#22 lore raw

PATCH 12/16 netconsole: implement extended console support

In reply to Tejun Heo

netconsole transmits raw console messages using one or multiple UDP packets and there's no way to find out whether the packets are lost in transit or received out of order. Depending on the setup, this can make the logging significantly unreliable and untrustworthy.

With the new extended console support, printk now can be told to expose log metadata including the message sequence number to console drivers which can be used by log receivers to determine whether and which messages are missing and reorder messages received out of order.

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.

netconsole may have to split a single messages to multiple fragments. In this case, if the extended mode is enabled, an optional header of the form "ncfrag=OFF@IDX/NR" is added to each fragment where OFF is the byte offset of the message body, IDX is the 0-based fragment index and NR is the number of total fragments for this message.

To avoid unnecessarily forcing printk to format extended messages, extended netconsole is registered with printk iff it's actually used.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 159 ++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 158 insertions(+), 1 deletion(-)
drivers/net/netconsole.c +158 -1
index d72d902..626d9f0 100644
@@ -83,6 +83,10 @@ static LIST_HEAD(target_list);
 /* protects target creation/destruction and enable/disable */
 static DEFINE_MUTEX(netconsole_mutex);
 
+static bool netconsole_ext_used_during_init;
+static bool netconsole_ext_registered;
+static struct console netconsole_ext;
+
 static struct console netconsole;
 
 /**
@@ -112,6 +116,7 @@ struct netconsole_target {
 #endif
 	bool			enabled;
 	bool			disable_scheduled;
+	bool			extended;
 	struct netpoll		np;
 };
 
@@ -194,6 +199,81 @@ static struct netconsole_target *alloc_netconsole_target(void)
 	return nt;
 }
 
+/**
+ * send_ext_msg_udp - send extended log message to target
+ * @nt: target to send message to
+ * @msg: extended log message to send
+ * @msg_len: length of message
+ *
+ * Transfer extended log @msg to @nt.  If @msg is too long, it'll be split
+ * and transmitted in multiple chunks with ncfrag header field added to
+ * enable correct reassembly.
+ */
+static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
+			     int msg_len)
+{
+	static char buf[MAX_PRINT_CHUNK];
+	const int max_extra_len = sizeof(",ncfrag=0000@00/00");
+	const char *header, *body;
+	int header_len = msg_len, body_len = 0;
+	int chunk_len, nr_chunks, i;
+
+	if (!nt->enabled || !netif_running(nt->np.dev))
+		return;
+
+	if (msg_len <= MAX_PRINT_CHUNK) {
+		netpoll_send_udp(&nt->np, msg, msg_len);
+		return;
+	}
+
+	/* need to insert extra header fields, detect header and body */
+	header = msg;
+	body = memchr(msg, ';', msg_len);
+	if (body) {
+		header_len = body - header;
+		body_len = msg_len - header_len - 1;
+		body++;
+	}
+
+	chunk_len = MAX_PRINT_CHUNK - header_len - max_extra_len;
+	if (WARN_ON_ONCE(chunk_len <= 0))
+		return;
+
+	/*
+	 * Transfer possibly multiple chunks with extra header fields.
+	 *
+	 * If @msg needs to be split to fit MAX_PRINT_CHUNK, add
+	 * "ncfrag=<byte-offset>@<0-based-chunk-index>/<total-chunks>" to
+	 * enable proper reassembly on receiver side.
+	 */
+	memcpy(buf, header, header_len);
+	nr_chunks = DIV_ROUND_UP(body_len, chunk_len);
+
+	for (i = 0; i < nr_chunks; i++) {
+		int this_header = header_len;
+		int this_chunk;
+
+		if (nr_chunks > 1)
+			this_header += scnprintf(buf + this_header,
+						 sizeof(buf) - this_header,
+						 ",ncfrag=%d@%d/%d",
+						 i * chunk_len, i, nr_chunks);
+		if (this_header < sizeof(buf))
+			buf[this_header++] = ';';
+
+		if (WARN_ON_ONCE(this_header + chunk_len > MAX_PRINT_CHUNK))
+			return;
+
+		this_chunk = min(body_len, chunk_len);
+		memcpy(buf + this_header, body, this_chunk);
+
+		netpoll_send_udp(&nt->np, buf, this_header + this_chunk);
+
+		body += this_chunk;
+		body_len -= this_chunk;
+	}
+}
+
 static int netconsole_enable(struct netconsole_target *nt)
 {
 	int err;
@@ -241,6 +321,11 @@ static int create_param_target(char *target_config)
 	if (!nt)
 		goto fail;
 
+	if (*target_config == '+') {
+		nt->extended = 1;
+		target_config++;
+	}
+
 	/* Parse parameters and setup netpoll */
 	err = netpoll_parse_options(&nt->np, target_config);
 	if (err)
@@ -255,7 +340,12 @@ static int create_param_target(char *target_config)
 		goto fail_del;
 
 	/* Dump existing printks when we register */
-	netconsole.flags |= CON_PRINTBUFFER;
+	if (nt->extended) {
+		netconsole_ext.flags |= CON_PRINTBUFFER;
+		netconsole_ext_used_during_init = true;
+	} else {
+		netconsole.flags |= CON_PRINTBUFFER;
+	}
 
 	return 0;
 
@@ -313,6 +403,11 @@ static ssize_t show_enabled(struct netconsole_target *nt, char *buf)
 	return snprintf(buf, PAGE_SIZE, "%d\n", nt->enabled);
 }
 
+static ssize_t show_extended(struct netconsole_target *nt, char *buf)
+{
+	return snprintf(buf, PAGE_SIZE, "%d\n", nt->extended);
+}
+
 static ssize_t show_dev_name(struct netconsole_target *nt, char *buf)
 {
 	return snprintf(buf, PAGE_SIZE, "%s\n", nt->np.dev_name);
@@ -401,6 +496,30 @@ static ssize_t store_enabled(struct netconsole_target *nt,
 	return strnlen(buf, count);
 }
 
+static ssize_t store_extended(struct netconsole_target *nt,
+			      const char *buf,
+			      size_t count)
+{
+	int extended;
+	int err;
+
+	if (nt->enabled) {
+		pr_err("target (%s) is enabled, disable to update parameters\n",
+		       config_item_name(&nt->item));
+		return -EINVAL;
+	}
+
+	err = kstrtoint(buf, 10, &extended);
+	if (err < 0)
+		return err;
+	if (extended < 0 || extended > 1)
+		return -EINVAL;
+
+	nt->extended = extended;
+
+	return strnlen(buf, count);
+}
+
 static ssize_t store_dev_name(struct netconsole_target *nt,
 			      const char *buf,
 			      size_t count)
@@ -553,6 +672,7 @@ static struct netconsole_target_attr netconsole_target_##_name =	\
 	__CONFIGFS_ATTR(_name, S_IRUGO | S_IWUSR, show_##_name, store_##_name)
 
 NETCONSOLE_TARGET_ATTR_RW(enabled);
+NETCONSOLE_TARGET_ATTR_RW(extended);
 NETCONSOLE_TARGET_ATTR_RW(dev_name);
 NETCONSOLE_TARGET_ATTR_RW(local_port);
 NETCONSOLE_TARGET_ATTR_RW(remote_port);
@@ -563,6 +683,7 @@ NETCONSOLE_TARGET_ATTR_RW(remote_mac);
 
 static struct configfs_attribute *netconsole_target_attrs[] = {
 	&netconsole_target_enabled.attr,
+	&netconsole_target_extended.attr,
 	&netconsole_target_dev_name.attr,
 	&netconsole_target_local_port.attr,
 	&netconsole_target_remote_port.attr,
@@ -645,9 +766,16 @@ static struct config_item *make_netconsole_target(struct config_group *group,
 
 	/* Adding, but it is disabled */
 	mutex_lock(&netconsole_mutex);
+
 	console_lock();
 	list_add(&nt->list, &target_list);
 	console_unlock();
+
+	if (nt->extended && !netconsole_ext_registered) {
+		register_console(&netconsole_ext);
+		netconsole_ext_registered = true;
+	}
+
 	mutex_unlock(&netconsole_mutex);
 
 	return &nt->item;
@@ -776,6 +904,19 @@ static struct notifier_block netconsole_netdev_notifier = {
 	.notifier_call  = netconsole_netdev_event,
 };
 
+static void write_ext_msg(struct console *con, const char *msg,
+			  unsigned int len)
+{
+	struct netconsole_target *nt;
+
+	if ((oops_only && !oops_in_progress) || list_empty(&target_list))
+		return;
+
+	list_for_each_entry(nt, &target_list, list)
+		if (nt->extended)
+			send_ext_msg_udp(nt, msg, len);
+}
+
 static void write_msg(struct console *con, const char *msg, unsigned int len)
 {
 	int frag, left;
@@ -789,6 +930,8 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 		return;
 
 	list_for_each_entry(nt, &target_list, list) {
+		if (nt->extended)
+			continue;
 		if (nt->enabled && netif_running(nt->np.dev)) {
 			/*
 			 * We nest this inside the for-each-target loop above
@@ -807,6 +950,12 @@ static void write_msg(struct console *con, const char *msg, unsigned int len)
 	}
 }
 
+static struct console netconsole_ext = {
+	.name	= "netcon_ext",
+	.flags	= CON_ENABLED | CON_EXTENDED,
+	.write	= write_ext_msg,
+};
+
 static struct console netconsole = {
 	.name	= "netcon",
 	.flags	= CON_ENABLED,
@@ -851,6 +1000,11 @@ static int __init init_netconsole(void)
 	if (err)
 		goto undonotifier;
 
+	if (netconsole_ext_used_during_init) {
+		register_console(&netconsole_ext);
+		netconsole_ext_registered = true;
+	}
+
 	register_console(&netconsole);
 	pr_info("network logging started\n");
 
@@ -871,6 +1025,9 @@ static void __exit cleanup_netconsole(void)
 {
 	mutex_lock(&netconsole_mutex);
 
+	if (netconsole_ext_registered)
+		unregister_console(&netconsole_ext);
+
 	unregister_console(&netconsole);
 	dynamic_netconsole_exit();
 	unregister_netdevice_notifier(&netconsole_netdev_notifier);
Signature · 1 line
2.1.0
author
#23 lore raw

PATCH 13/16 netconsole: implement retransmission support for extended consoles

In reply to Tejun Heo

With extended netconsole, the logger can reliably determine which messages are missing. This patch implements receiver for extended netconsole which accepts retransmission request packets coming into the the netconsole source port and sends back the requested messages.

The receiving socket is automatically created when an extended console is enabled. A poll_table with a custom callback is queued on the socket. When a packet is received on the socket, a work item is scheduled which reads and parses the payload and sends back the requested ones. A retransmission packet looks like the following.

nca <missing-seq> <missing-seq>...

The receiver doesn't interfere with the normal transmission path. Even if something goes wrong with the network stack or receiver itself, the normal transmission path should keep working.

This can be used to implement reliable netconsole logger.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 238 +++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 238 insertions(+)
drivers/net/netconsole.c +238 -0
index 626d9f0..b2763e0 100644
@@ -45,7 +45,10 @@
 #include <linux/kernel.h>
 #include <linux/string.h>
 #include <linux/netpoll.h>
+#include <linux/net.h>
 #include <linux/inet.h>
+#include <linux/file.h>
+#include <linux/poll.h>
 #include <linux/configfs.h>
 #include <linux/etherdevice.h>
 
@@ -89,6 +92,14 @@ static struct console netconsole_ext;
 
 static struct console netconsole;
 
+union sockaddr_in46 {
+	struct sockaddr		addr;
+	struct sockaddr_in6	in6;
+	struct sockaddr_in	in4;
+};
+
+static char *netconsole_ext_tx_buf;	/* CONSOLE_EXT_LOG_MAX */
+
 /**
  * struct netconsole_target - Represents a configured netconsole target.
  * @list:	Links this target into the target_list.
@@ -118,6 +129,14 @@ struct netconsole_target {
 	bool			disable_scheduled;
 	bool			extended;
 	struct netpoll		np;
+
+	/* response packet handling for extended netconsoles */
+	union sockaddr_in46	raddr;		/* logging target address */
+	struct file		*rx_file;	/* sock to receive responses */
+	poll_table		rx_ptable;	/* for polling the socket */
+	wait_queue_t		rx_wait;	/* ditto */
+	wait_queue_head_t	*rx_waitq;	/* ditto */
+	struct work_struct	rx_work;	/* receive & process packets */
 };
 
 #ifdef	CONFIG_NETCONSOLE_DYNAMIC
@@ -274,6 +293,219 @@ static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
 	}
 }
 
+static bool sockaddr_in46_equal(union sockaddr_in46 *a, union sockaddr_in46 *b)
+{
+	if (a->addr.sa_family != b->addr.sa_family)
+		return false;
+	if (a->in4.sin_port != b->in4.sin_port)
+		return false;
+	if (a->addr.sa_family == AF_INET &&
+	    memcmp(&a->in4.sin_addr, &b->in4.sin_addr, sizeof(a->in4.sin_addr)))
+		return false;
+	if (a->addr.sa_family == AF_INET6 &&
+	    memcmp(&a->in6.sin6_addr, &b->in6.sin6_addr, sizeof(a->in6.sin6_addr)))
+		return false;
+	return true;
+}
+
+/**
+ * netconsole_rx_work_fn - work function to handle netconsole ack packets
+ * @work: netconsole_target->rx_work
+ *
+ * This function is scheduled when packets are received on the source port
+ * of extended netconsole target and responds to ack messages from the
+ * remote logger.  An ack message has the following format.
+ *
+ * nca <missing-seq> <missing-seq> ...
+ *
+ * There can be any number of missing-seq's as long as the whole payload
+ * fits inside MAX_PRINT_CHUNK.  This function re-transmits each message
+ * matching the missing-seq's if available.  This can be used to implement
+ * reliable logging from the receiver side.
+ *
+ * The rx path doesn't interfere with the normal tx path except for when it
+ * actually sends out the messages, and that path doesn't depend on
+ * anything more working compared to the normal tx path.  As such, this
+ * shouldn't make netconsole any less robust when things start going south.
+ */
+static void netconsole_rx_work_fn(struct work_struct *work)
+{
+	struct netconsole_target *nt =
+		container_of(work, struct netconsole_target, rx_work);
+	union sockaddr_in46 raddr;
+	struct msghdr msgh = { .msg_name = &raddr.addr, };
+	struct kvec iov;
+	char *tx_buf = netconsole_ext_tx_buf;
+	char *rx_buf, *pos, *tok;
+	u64 seq;
+	int len;
+
+	rx_buf = kmalloc(MAX_PRINT_CHUNK + 1, GFP_KERNEL);
+	if (!rx_buf && printk_ratelimit()) {
+		pr_warning("failed to allocate RX buffer\n");
+		return;
+	}
+
+	iov.iov_base = rx_buf;
+	iov.iov_len = MAX_PRINT_CHUNK;
+repeat:
+	msgh.msg_namelen = sizeof(raddr);
+	len = kernel_recvmsg(sock_from_file(nt->rx_file, &len), &msgh, &iov, 1,
+			     MAX_PRINT_CHUNK, MSG_DONTWAIT);
+	if (len < 0) {
+		if (len != -EAGAIN && printk_ratelimit())
+			pr_warning("RX failed err=%d\n", len);
+		kfree(rx_buf);
+		return;
+	}
+
+	if (!sockaddr_in46_equal(msgh.msg_name, &nt->raddr)) {
+		if (printk_ratelimit())
+			pr_warning("stray packet from %pIS:%u\n",
+				   &raddr.addr, ntohs(raddr.in4.sin_port));
+		goto repeat;
+	}
+
+	rx_buf[len] = '\0';
+	pos = rx_buf;
+	tok = strsep(&pos, " ");
+
+	/* nca header */
+	if (strncmp(tok, "nca", 3)) {
+		if (printk_ratelimit())
+			pr_warning("malformed packet from %pIS:%u\n",
+				   &nt->raddr, ntohs(nt->raddr.in4.sin_port));
+		goto repeat;
+	}
+	tok += 3;
+
+	console_lock();
+
+	/* <missing-seq>... */
+	while ((tok = strsep(&pos, " "))) {
+		if (sscanf(tok, "%llu", &seq)) {
+			len = ext_log_from_seq(tx_buf, CONSOLE_EXT_LOG_MAX, seq);
+			if (len >= 0)
+				send_ext_msg_udp(nt, tx_buf, len);
+		}
+	}
+
+	console_unlock();
+	goto repeat;
+}
+
+static int netconsole_rx_wait_fn(wait_queue_t *wait, unsigned mode, int flags,
+				 void *key)
+{
+	struct netconsole_target *nt =
+		container_of(wait, struct netconsole_target, rx_wait);
+
+	schedule_work(&nt->rx_work);
+	return 0;
+}
+
+static void netconsole_rx_ptable_queue_fn(struct file *file,
+					  wait_queue_head_t *waitq,
+					  poll_table *ptable)
+{
+	struct netconsole_target *nt =
+		container_of(ptable, struct netconsole_target, rx_ptable);
+
+	nt->rx_waitq = waitq;
+	add_wait_queue(waitq, &nt->rx_wait);
+}
+
+static void netconsole_enable_rx(struct netconsole_target *nt)
+{
+	union sockaddr_in46 laddr = { }, raddr = { };
+	struct socket *sock;
+	struct file *file;
+	int addr_len, ret;
+
+	if (!netconsole_ext_tx_buf) {
+		char *buf;
+
+		buf = kmalloc(CONSOLE_EXT_LOG_MAX, GFP_KERNEL);
+		if (!buf) {
+			kfree(buf);
+			pr_warning("failed to allocate TX buffer\n");
+			return;
+		}
+
+		if (cmpxchg(&netconsole_ext_tx_buf, NULL, buf))
+			kfree(buf);
+	}
+
+	if (!nt->np.ipv6) {
+		laddr.in4.sin_family = AF_INET;
+		laddr.in4.sin_port = htons(nt->np.local_port);
+		laddr.in4.sin_addr = nt->np.local_ip.in;
+		raddr.in4.sin_family = AF_INET;
+		raddr.in4.sin_port = htons(nt->np.remote_port);
+		raddr.in4.sin_addr = nt->np.remote_ip.in;
+		addr_len = sizeof(laddr.in4);
+	} else {
+		laddr.in6.sin6_family = AF_INET6;
+		laddr.in6.sin6_port = htons(nt->np.local_port);
+		laddr.in6.sin6_addr = nt->np.local_ip.in6;
+		raddr.in6.sin6_family = AF_INET6;
+		raddr.in6.sin6_port = htons(nt->np.remote_port);
+		raddr.in6.sin6_addr = nt->np.remote_ip.in6;
+		addr_len = sizeof(laddr.in6);
+	}
+
+	ret = sock_create_kern(laddr.addr.sa_family, SOCK_DGRAM, IPPROTO_UDP,
+			       &sock);
+	if (ret) {
+		pr_warning("failed to create rx socket, err=%d\n", ret);
+		return;
+	}
+
+	file = sock_alloc_file(sock, 0, NULL);
+	if (IS_ERR(file)) {
+		pr_warning("failed to rx socket file, err=%ld\n", PTR_ERR(file));
+		sock_release(sock);
+		return;
+	}
+
+	ret = sock->ops->bind(sock, &laddr.addr, addr_len);
+	if (ret) {
+		pr_warning("failed to bind rx socket at %pIS:%u, err=%d\n",
+			   &laddr.addr, ntohs(laddr.in4.sin_port), ret);
+		fput(file);
+		return;
+	}
+
+	nt->raddr = raddr;
+	init_poll_funcptr(&nt->rx_ptable, netconsole_rx_ptable_queue_fn);
+	init_waitqueue_func_entry(&nt->rx_wait, netconsole_rx_wait_fn);
+	INIT_WORK(&nt->rx_work, netconsole_rx_work_fn);
+
+	ret = file->f_op->poll(file, &nt->rx_ptable);
+	if (ret < 0) {
+		pr_warning("failed to poll rx socket, err=%d\n", ret);
+		fput(file);
+		return;
+	}
+
+	if (ret & POLLIN)
+		schedule_work(&nt->rx_work);
+
+	nt->rx_file = file;
+}
+
+static void netconsole_disable_rx(struct netconsole_target *nt)
+{
+	if (!nt->rx_file)
+		return;
+
+	remove_wait_queue(nt->rx_waitq, &nt->rx_wait);
+	cancel_work_sync(&nt->rx_work);
+
+	fput(nt->rx_file);
+	nt->rx_file = NULL;
+}
+
 static int netconsole_enable(struct netconsole_target *nt)
 {
 	int err;
@@ -285,6 +517,9 @@ static int netconsole_enable(struct netconsole_target *nt)
 	if (err)
 		return err;
 
+	if (nt->extended)
+		netconsole_enable_rx(nt);
+
 	console_lock();
 	nt->enabled = true;
 	console_unlock();
@@ -305,6 +540,7 @@ static void netconsole_disable(struct netconsole_target *nt)
 		nt->enabled = false;
 		console_unlock();
 
+		netconsole_disable_rx(nt);
 		netpoll_cleanup(&nt->np);
 	}
 }
@@ -974,6 +1210,8 @@ static void __init_or_module netconsole_destroy_all(void)
 		netconsole_disable(nt);
 		kfree(nt);
 	}
+
+	kfree(netconsole_ext_tx_buf);
 }
 
 static int __init init_netconsole(void)
Signature · 1 line
2.1.0
author
#24 lore raw

PATCH 14/16 netconsole: implement ack handling and emergency transmission

In reply to Tejun Heo

While the retransmission support added by the previous patch goes a long way towards enabling implementation of reliable remote logger, it depends on a lot larger part of the kernel working and there's no non-polling way of discovering whether the latest messages have been lost.

This patch implements an optional ack handling. An extended remote logger can respond with a message formatted like the following.

nca[<ack-seq>] <missing-seq> <missing-seq>...

The optional <ack-seq> enables ack handling. Whenever ack lags transmission by more than ACK_TIMEOUT (10s), the netconsole target will retransmit all unacked messages with increasing interval (100ms between message at the beginning, exponentially backing out to 10s). This ensures that the remote logger has a very high chance of getting all the messages even after severe failures as long as the timer and netpoll are working.

This doesn't interfere with the normal transmission path. Even if something goes wrong with timer, the normal transmission path should keep working.

Emergency transmissions are marked with "emg=1" header.

Cc David Miller <[email protected]>
---
 drivers/net/netconsole.c | 136 +++++++++++++++++++++++++++++++++++++++++++----
 1 file changed, 127 insertions(+), 9 deletions(-)
drivers/net/netconsole.c +127 -9
index b2763e0..82c8be0 100644
@@ -49,6 +49,7 @@
 #include <linux/inet.h>
 #include <linux/file.h>
 #include <linux/poll.h>
+#include <linux/timer.h>
 #include <linux/configfs.h>
 #include <linux/etherdevice.h>
 
@@ -59,6 +60,10 @@ MODULE_LICENSE("GPL");
 #define MAX_PARAM_LENGTH	256
 #define MAX_PRINT_CHUNK		1000
 
+#define ACK_TIMEOUT		(10 * HZ)
+#define EMG_TX_MIN_INTV		(HZ / 10)
+#define EMG_TX_MAX_INTV		HZ
+
 static char config[MAX_PARAM_LENGTH];
 module_param_string(netconsole, config, MAX_PARAM_LENGTH, 0);
 MODULE_PARM_DESC(netconsole, " netconsole=[src-port]@[src-ip]/[dev],[tgt-port]@<tgt-ip>/[tgt-macaddr]");
@@ -137,6 +142,13 @@ struct netconsole_target {
 	wait_queue_t		rx_wait;	/* ditto */
 	wait_queue_head_t	*rx_waitq;	/* ditto */
 	struct work_struct	rx_work;	/* receive & process packets */
+
+	/* ack handling and emergency transmission for extended netconsoles */
+	unsigned long		ack_tstmp;	/* pending ack timestamp */
+	u64			ack_seq;	/* last acked sequence */
+	struct timer_list	ack_timer;	/* ack timeout */
+	unsigned long		emg_tx_intv;	/* emergency tx interval */
+	u64			emg_tx_seq;	/* current emg tx sequence */
 };
 
 #ifdef	CONFIG_NETCONSOLE_DYNAMIC
@@ -223,16 +235,17 @@ static struct netconsole_target *alloc_netconsole_target(void)
  * @nt: target to send message to
  * @msg: extended log message to send
  * @msg_len: length of message
+ * @emg_tx: is it for emergency transmission?
  *
  * Transfer extended log @msg to @nt.  If @msg is too long, it'll be split
  * and transmitted in multiple chunks with ncfrag header field added to
- * enable correct reassembly.
+ * enable correct reassembly.  If @emg_tx, emg header field is added.
  */
 static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
-			     int msg_len)
+			     int msg_len, bool emg_tx)
 {
 	static char buf[MAX_PRINT_CHUNK];
-	const int max_extra_len = sizeof(",ncfrag=0000@00/00");
+	const int max_extra_len = sizeof(",emg=1,ncfrag=0000@00/00");
 	const char *header, *body;
 	int header_len = msg_len, body_len = 0;
 	int chunk_len, nr_chunks, i;
@@ -240,7 +253,7 @@ static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
 	if (!nt->enabled || !netif_running(nt->np.dev))
 		return;
 
-	if (msg_len <= MAX_PRINT_CHUNK) {
+	if (!emg_tx && msg_len <= MAX_PRINT_CHUNK) {
 		netpoll_send_udp(&nt->np, msg, msg_len);
 		return;
 	}
@@ -261,6 +274,8 @@ static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
 	/*
 	 * Transfer possibly multiple chunks with extra header fields.
 	 *
+	 * For emergency transfers due to missing acks, add "emg=1".
+	 *
 	 * If @msg needs to be split to fit MAX_PRINT_CHUNK, add
 	 * "ncfrag=<byte-offset>@<0-based-chunk-index>/<total-chunks>" to
 	 * enable proper reassembly on receiver side.
@@ -272,6 +287,10 @@ static void send_ext_msg_udp(struct netconsole_target *nt, const char *msg,
 		int this_header = header_len;
 		int this_chunk;
 
+		if (emg_tx)
+			this_header += scnprintf(buf + this_header,
+						 sizeof(buf) - this_header,
+						 ",emg=1");
 		if (nr_chunks > 1)
 			this_header += scnprintf(buf + this_header,
 						 sizeof(buf) - this_header,
@@ -309,6 +328,78 @@ static bool sockaddr_in46_equal(union sockaddr_in46 *a, union sockaddr_in46 *b)
 }
 
 /**
+ * netconsole_ack_timer_fn - timer function to handle netconsole ack timeouts
+ * @data: netconsole_target
+ *
+ * For an extended netconsole, if the remote logger acked messages
+ * previously but is failing to ack new messages for over ACK_TIMEOUT, this
+ * timer kicks in for emergency transmission.
+ *
+ * The lack of ack may be caused by a number of things including the ack
+ * packet being dropped or the network stack oopsing.  Whatever the cause
+ * may be, we repeatedly retransmit the unacked message at increasing
+ * interval which should allow the remote logger to eventually obtain all
+ * messages as long as the packets are going out.
+ *
+ * This mechanism depends only on the timer and netpoll working.
+ */
+static void netconsole_ack_timer_fn(unsigned long data)
+{
+	struct netconsole_target *nt = (void *)data;
+	unsigned long now = jiffies;
+	unsigned long next_at;
+	char *buf = netconsole_ext_tx_buf;
+	u64 begin_seq, end_seq, seq;
+	int len;
+
+	if (!console_trylock()) {
+		mod_timer(&nt->ack_timer, now + 1);
+		return;
+	}
+
+	log_seq_range(&begin_seq, &end_seq);
+	if (nt->ack_seq == end_seq - 1) {
+		nt->ack_tstmp = 0;
+		next_at = now + ACK_TIMEOUT;
+		goto out_unlock;
+	}
+	if (time_before(now, nt->ack_tstmp + ACK_TIMEOUT)) {
+		next_at = nt->ack_tstmp + ACK_TIMEOUT;
+		goto out_unlock;
+	}
+
+	/* zero emg_tx_intv indicates that we're starting emergency tx */
+	if (!nt->emg_tx_intv) {
+		nt->emg_tx_intv = EMG_TX_MIN_INTV;
+		nt->emg_tx_seq = nt->ack_seq + 1;
+	}
+
+	seq = nt->emg_tx_seq;
+	do {
+		len = ext_log_from_seq(buf, CONSOLE_EXT_LOG_MAX, seq);
+	} while (len < 0 && ++seq < end_seq);
+
+	if (len >= 0) {
+		send_ext_msg_udp(nt, buf, len, true);
+		seq++;
+	}
+
+	nt->emg_tx_seq = seq;
+
+	if (nt->emg_tx_seq >= end_seq) {
+		/* all messages transferred, bump up intv and repeat */
+		nt->emg_tx_intv = min_t(unsigned long, 2 * nt->emg_tx_intv,
+					EMG_TX_MAX_INTV);
+		nt->emg_tx_seq = nt->ack_seq + 1;
+	}
+
+	next_at = now + nt->emg_tx_intv;
+out_unlock:
+	console_unlock();
+	mod_timer(&nt->ack_timer, next_at);
+}
+
+/**
  * netconsole_rx_work_fn - work function to handle netconsole ack packets
  * @work: netconsole_target->rx_work
  *
@@ -316,7 +407,7 @@ static bool sockaddr_in46_equal(union sockaddr_in46 *a, union sockaddr_in46 *b)
  * of extended netconsole target and responds to ack messages from the
  * remote logger.  An ack message has the following format.
  *
- * nca <missing-seq> <missing-seq> ...
+ * nca[<ack-seq>] <missing-seq> <missing-seq> ...
  *
  * There can be any number of missing-seq's as long as the whole payload
  * fits inside MAX_PRINT_CHUNK.  This function re-transmits each message
@@ -327,6 +418,10 @@ static bool sockaddr_in46_equal(union sockaddr_in46 *a, union sockaddr_in46 *b)
  * actually sends out the messages, and that path doesn't depend on
  * anything more working compared to the normal tx path.  As such, this
  * shouldn't make netconsole any less robust when things start going south.
+ *
+ * If <ack-seq> exists, emergency tx is enabled.  Whenever ack is lagging
+ * by more than ACK_TIMEOUT, netconsole will repeatedly send out unacked
+ * messages with increasing interval.  See netconsole_ack_timer_fn().
  */
 static void netconsole_rx_work_fn(struct work_struct *work)
 {
@@ -335,6 +430,7 @@ static void netconsole_rx_work_fn(struct work_struct *work)
 	union sockaddr_in46 raddr;
 	struct msghdr msgh = { .msg_name = &raddr.addr, };
 	struct kvec iov;
+	bool ack_was_enabled = nt->ack_seq;
 	char *tx_buf = netconsole_ext_tx_buf;
 	char *rx_buf, *pos, *tok;
 	u64 seq;
@@ -355,6 +451,9 @@ repeat:
 	if (len < 0) {
 		if (len != -EAGAIN && printk_ratelimit())
 			pr_warning("RX failed err=%d\n", len);
+		if (!ack_was_enabled && nt->ack_seq)
+			pr_info("ACK timeout enabled for %pIS:%d\n",
+				&nt->raddr.addr, ntohs(nt->raddr.in4.sin_port));
 		kfree(rx_buf);
 		return;
 	}
@@ -381,12 +480,25 @@ repeat:
 
 	console_lock();
 
+	/* <ack-seq> */
+	if (sscanf(tok, "%llu", &seq)) {
+		u64 begin_seq, end_seq;
+
+		log_seq_range(&begin_seq, &end_seq);
+		if (seq && seq < end_seq) {
+			nt->ack_seq = max(seq, nt->ack_seq);
+			nt->emg_tx_intv = 0;
+			if (!ack_was_enabled)
+				mod_timer(&nt->ack_timer, jiffies);
+		}
+	}
+
 	/* <missing-seq>... */
 	while ((tok = strsep(&pos, " "))) {
 		if (sscanf(tok, "%llu", &seq)) {
 			len = ext_log_from_seq(tx_buf, CONSOLE_EXT_LOG_MAX, seq);
 			if (len >= 0)
-				send_ext_msg_udp(nt, tx_buf, len);
+				send_ext_msg_udp(nt, tx_buf, len, false);
 		}
 	}
 
@@ -480,6 +592,7 @@ static void netconsole_enable_rx(struct netconsole_target *nt)
 	init_poll_funcptr(&nt->rx_ptable, netconsole_rx_ptable_queue_fn);
 	init_waitqueue_func_entry(&nt->rx_wait, netconsole_rx_wait_fn);
 	INIT_WORK(&nt->rx_work, netconsole_rx_work_fn);
+	setup_timer(&nt->ack_timer, netconsole_ack_timer_fn, (unsigned long)nt);
 
 	ret = file->f_op->poll(file, &nt->rx_ptable);
 	if (ret < 0) {
@@ -501,6 +614,7 @@ static void netconsole_disable_rx(struct netconsole_target *nt)
 
 	remove_wait_queue(nt->rx_waitq, &nt->rx_wait);
 	cancel_work_sync(&nt->rx_work);
+	del_timer_sync(&nt->ack_timer);
 
 	fput(nt->rx_file);
 	nt->rx_file = NULL;
@@ -1148,9 +1262,13 @@ static void write_ext_msg(struct console *con, const char *msg,
 	if ((oops_only && !oops_in_progress) || list_empty(&target_list))
 		return;
 
-	list_for_each_entry(nt, &target_list, list)
-		if (nt->extended)
-			send_ext_msg_udp(nt, msg, len);
+	list_for_each_entry(nt, &target_list, list) {
+		if (nt->extended) {
+			send_ext_msg_udp(nt, msg, len, false);
+			if (!nt->ack_tstmp)
+				nt->ack_tstmp = jiffies ?: 1;
+		}
+	}
 }
 
 static void write_msg(struct console *con, const char *msg, unsigned int len)
Signature · 1 line
2.1.0
author
#25 lore raw

PATCH 15/16 netconsole: implement netconsole receiver library

In reply to Tejun Heo

This patch implements libncrx.a and a simple receiver program ncrx using the library. The library makes use of the extended header, retransmission and ack support to implement reliable netconsole receiver. The library is structured as a pure state machine leaving all IO and timing handling to the library user and should be easy to fit into any environment.

The reordering and retransmission mechanisms are fairly simple. Each receiver instance has a ring buffer where messages are slotted according to their sequence number. A hole in sequence numbers trigger retransmission after the sequence progresses certain number of slots or certain amount of duration has passed.

See tools/lib/netconsole/ncrx.h for information on usage.

Tested with simulated heavy packet loss (50%). Messages are transferred without loss and all the common scenarios including reboots are handled correctly.

Cc David Miller <[email protected]>
---
 tools/Makefile                |  16 +-
 tools/lib/netconsole/Makefile |  36 ++
 tools/lib/netconsole/ncrx.c   | 906 ++++++++++++++++++++++++++++++++++++++++++
 tools/lib/netconsole/ncrx.h   | 204 ++++++++++
 tools/ncrx/Makefile           |  14 +
 tools/ncrx/ncrx.c             | 143 +++++++
 6 files changed, 1318 insertions(+), 1 deletion(-)
 create mode 100644 tools/lib/netconsole/Makefile
 create mode 100644 tools/lib/netconsole/ncrx.c
 create mode 100644 tools/lib/netconsole/ncrx.h
 create mode 100644 tools/ncrx/Makefile
 create mode 100644 tools/ncrx/ncrx.c
tools/Makefile +15 -1
index 9a617ad..9f588f7 100644
@@ -9,6 +9,7 @@ help:
 	@echo '  firewire   - the userspace part of nosy, an IEEE-1394 traffic sniffer'
 	@echo '  hv         - tools used when in Hyper-V clients'
 	@echo '  lguest     - a minimal 32-bit x86 hypervisor'
+	@echo '  ncrx       - simple reliable netconsole logger'
 	@echo '  perf       - Linux performance measurement and analysis tool'
 	@echo '  selftests  - various kernel selftests'
 	@echo '  turbostat  - Intel CPU idle stats and freq reporting tool'
@@ -50,6 +51,12 @@ liblockdep: FORCE
 libapikfs: FORCE
 	$(call descend,lib/api)
 
+libncrx: FORCE
+	$(call descend,lib/netconsole)
+
+ncrx: libncrx FORCE
+	$(call descend,$@)
+
 perf: libapikfs FORCE
 	$(call descend,$@)
 
@@ -100,6 +107,12 @@ liblockdep_clean:
 libapikfs_clean:
 	$(call descend,lib/api,clean)
 
+libncrx_clean:
+	$(call descend,lib/netconsole,clean)
+
+ncrx_clean: libncrx_clean
+	$(call descend,$(@:_clean=),clean)
+
 perf_clean: libapikfs_clean
 	$(call descend,$(@:_clean=),clean)
 
@@ -114,6 +127,7 @@ tmon_clean:
 
 clean: acpi_clean cgroup_clean cpupower_clean hv_clean firewire_clean lguest_clean \
 		perf_clean selftests_clean turbostat_clean usb_clean virtio_clean \
-		vm_clean net_clean x86_energy_perf_policy_clean tmon_clean
+		vm_clean net_clean x86_energy_perf_policy_clean tmon_clean \
+		ncrx_clean
 
 .PHONY: FORCE
tools/lib/netconsole/Makefile new file +36 -0
new file mode 100644
index 0000000..6bc7997
@@ -0,0 +1,36 @@
+include ../../scripts/Makefile.include
+
+CC = $(CROSS_COMPILE)gcc
+AR = $(CROSS_COMPILE)ar
+
+# guard against environment variables
+LIB_H=
+LIB_OBJS=
+
+LIB_H += ncrx.h
+LIB_OBJS += $(OUTPUT)ncrx.o
+
+LIBFILE = libncrx.a
+
+CFLAGS = -g -Wall -O2 $(EXTRA_WARNINGS) $(EXTRA_CFLAGS) -fPIC
+ALL_CFLAGS = $(CFLAGS) $(BASIC_CFLAGS)
+ALL_LDFLAGS = $(LDFLAGS)
+
+RM = rm -f
+
+$(LIBFILE): $(LIB_OBJS)
+	$(QUIET_AR)$(RM) $@ && $(AR) rcs $(OUTPUT)$@ $(LIB_OBJS)
+
+$(LIB_OBJS): $(LIB_H)
+
+$(OUTPUT)%.o: %.c
+	$(QUIET_CC)$(CC) -o $@ -c $(ALL_CFLAGS) $<
+$(OUTPUT)%.s: %.c
+	$(QUIET_CC)$(CC) -S $(ALL_CFLAGS) $<
+$(OUTPUT)%.o: %.S
+	$(QUIET_CC)$(CC) -o $@ -c $(ALL_CFLAGS) $<
+
+clean:
+	$(call QUIET_CLEAN, libncrx) $(RM) $(LIB_OBJS) $(LIBFILE)
+
+.PHONY: clean
tools/lib/netconsole/ncrx.c new file +906 -0

906 lines not on this page · raw message

tools/lib/netconsole/ncrx.h new file +204 -0

204 lines not on this page · raw message

tools/ncrx/Makefile new file +14 -0
new file mode 100644
index 0000000..f3e9859
@@ -0,0 +1,14 @@
+# Makefile for ncrx
+
+CC = $(CROSS_COMPILE)gcc
+CFLAGS += -Wall -O2 -I../lib
+
+LIBS = ../lib/netconsole/libncrx.a
+LDFLAGS += $(LIBS)
+
+all: ncrx
+%: %.c $(LIBS)
+	$(CC) $(CFLAGS) -o $@ $^
+
+clean:
+	$(RM) ncrx
tools/ncrx/ncrx.c new file +143 -0

143 lines not on this page · raw message

Signature · 1 line
2.1.0
author
#26 lore raw

PATCH 16/16 netconsole: update documentation for extended netconsole

In reply to Tejun Heo
Cc David Miller <[email protected]>
---
 Documentation/networking/netconsole.txt | 95 ++++++++++++++++++++++++++++++++-
 1 file changed, 94 insertions(+), 1 deletion(-)
Documentation/networking/netconsole.txt +94 -1
index a5d574a..e7a57c2 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
+Reliable extended console support by Tejun Heo <[email protected]>, Apr 16 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 reliable 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,96 @@ 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).
 
+Reliable extended console:
+==========================
+
+If '+' is prefixed to the configuration line or "extended" config file
+is set to 1, reliable extended console support is enabled. An example
+boot param follows.
+
+ linux [email protected]/eth1,[email protected]/12:34:56:78:9a:bc
+
+Reliable extended console support is consisted of three parts.
+
+1. Extended format messages
+---------------------------
+
+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. printk fragments from KERN_CONT
+messages are transmitted in the following form.
+
+ <level>,-,<timestamp>,-,fragid=<fragid>;<message fragment>
+
+Where <fragid> uniquely identifies the message being assembled. Later
+when the assembly is complete, the completed message with sequence
+number is transmitted. The receiver is responsible for handling the
+overlaps between fragements and the final assembled message.
+
+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>@<0-based-chunk-index>/<total-chunks>
+
+For example,
+
+ 6,416,1758426,-,ncfrag=0@0/2;the first chunk,
+ 6,416,1758426,-,ncfrag=16@1/2;the second chunk
+
+2. Retransmission requests
+--------------------------
+
+If extended console support is enabled, netconsole listens for packets
+arriving on the source port. The receiver can send the packets of the
+following form to request messages with specific sequence numbers.
+
+ nca <missing-seq> <missing-seq>...
+
+There can be any number of <missing-seq> as long as they fit inside
+1000 bytes. If the messages with the matching sequence numbers exist,
+netconsole will retransmit them immediately.
+
+3. ACK and emergency transmission
+---------------------------------
+
+If the receiver sends back a packet with the following format,
+netconsole enables ACK support.
+
+ nca<ack-seq> <missing-seq> <missing-seq>...
+
+If the ack sequence lags the current sequence by more than 10s,
+emergency transmission is started and all the unacked messages are
+retransmitted periodically with increasing interval. In the first
+round, each unacked message is transmitted every 100ms. In the next,
+every 200ms. The interval doubles until it reaches 1s and stays there.
+
+Each emergency transmitted message has "emg=1" header field added to
+it. For example,
+
+ 6,416,1758426,-,emg=1;netpoll: netconsole: local port 6666
+
+This exists to ensure that messages reach the destination even when
+things went pear-shaped. As long as netpoll and timer are working, the
+logging target has pretty good chance of receiving all messages.
+
+Receiver
+--------
+
+libncrx is a library which implements reliable remote logger using the
+above features. The library is available under tools/lib/netconsole.
+The library is a pure state machine with packet and timer plumbing
+left to the library user to ease integration into larger framework.
+See tools/lib/netconsole/ncrx.h for details.
+
+tools/ncrx/ncrx is a simple receiver program using libncrx which can
+be used as an example.
+
 Miscellaneous notes:
 ====================
 
Signature · 1 line
2.1.0
#27 lore raw
In reply to Tejun Heo
Quoted 5 lines · Tejun Heo

* Implement netconsole retransmission support. Matching rx socket on the source port is automatically created for extended targets and the log receiver can request retransmission by sending reponse packets. This is completely decoupled from the main write path and doesn't make netconsole less robust when things start go south.

If the sender side can wait for retransmission, why can't we use userspace programs (e.g. rsyslogd)?

For me, netconsole is mainly for saving kernel messages which cannot be waited for a few deciseconds (e.g. system reset by softdog's timeout) and for saving kernel messages (e.g. SysRq-t) during disk I/O hang up. I have a logger for receiving netconsole messages at
http://sourceforge.jp/projects/akari/scm/svn/tree/head/branches/udplogger/
and things I expect for netconsole are shown below.

(a) spool the message to send up to "1 line" or "adimn configured size" so that total number of small UDP packets can be reduced

(b) don't hesitate to send the spooled message immediately if either kernel panic or system reset is in progress

(c) allow different console log level for different console drivers so that I can send kernel messages via netconsole without making local console noisy

author
#28 lore raw

Hello,

Quoted 2 lines · Tetsuo Handa

If the sender side can wait for retransmission, why can't we use userspace programs (e.g. rsyslogd)?

Because the system may be oopsing, ooming or threshing excessively rendering the userland inoperable and that's exactly when we want those log messages to be transmitted out of the system. This will get log out as long as timer and netpoll are running which is the case under a lot of circumstances.

Thanks.

Signature · 1 line
tejun
maintainer
#29 lore raw

From: Tejun Heo <[email protected]>
Date: Fri, 17 Apr 2015 12:28:26 -0400

Quoted 7 lines · Tetsuo Handa
Quoted 2 lines

If the sender side can wait for retransmission, why can't we use userspace programs (e.g. rsyslogd)?

Because the system may be oopsing, ooming or threshing excessively rendering the userland inoperable and that's exactly when we want those log messages to be transmitted out of the system.

If userland cannot run properly, it is almost certain that neither will your complex reliability layer logic.

I tend to agree with Tetsuo, that in-kernel netconsole should remain as simple as possible and once it starts to have any smarts and less trivial logic the job belongs in userspace.

author
#30 lore raw

Hello, David.

Quoted 2 lines · David Miller

If userland cannot run properly, it is almost certain that neither will your complex reliability layer logic.

* The bulk of patches are to pipe extended log messages to console drivers and let netconsole relay them to the receiver (and quite a bit of refactoring in the process), which, regardless of the reliability logic, is beneficial as we're currently losing structured logging (dictionary) and other metadata over consoles and regardless of where the reliability logic is implemented, it's a lot easier to have messages IDs.

* The only thing necessary for reliable transmission are timer and netpoll. There sure are cases where they go down too but there's a pretty big gap between those two going down and userland getting hosed, but where to put the retransmission and reliability logic definitely is debatable.

* That said, the "reliability" part of the patch series are just two patches - 13 and 14, both of which are actually pretty simple.

Quoted 3 lines

I tend to agree with Tetsuo, that in-kernel netconsole should remain as simple as possible and once it starts to have any smarts and less trivial logic the job belongs in userspace.

Upto patch 12, it's just the same mechanism transferring extended messages. It doesn't add any smartness to netconsole per-se except that it can now emit messages with metadata headers. What do you think about them?

Thanks.

Signature · 1 line
tejun
#31 lore raw
Quoted 23 lines · Tejun Heo

Hello, David.

Quoted 2 lines · David Miller

If userland cannot run properly, it is almost certain that neither will your complex reliability layer logic.

* The bulk of patches are to pipe extended log messages to console drivers and let netconsole relay them to the receiver (and quite a bit of refactoring in the process), which, regardless of the reliability logic, is beneficial as we're currently losing structured logging (dictionary) and other metadata over consoles and regardless of where the reliability logic is implemented, it's a lot easier to have messages IDs.

* The only thing necessary for reliable transmission are timer and netpoll. There sure are cases where they go down too but there's a pretty big gap between those two going down and userland getting hosed, but where to put the retransmission and reliability logic definitely is debatable.

* That said, the "reliability" part of the patch series are just two patches - 13 and 14, both of which are actually pretty simple.

Quoted 8 lines
Quoted 3 lines

I tend to agree with Tetsuo, that in-kernel netconsole should remain as simple as possible and once it starts to have any smarts and less trivial logic the job belongs in userspace.

Upto patch 12, it's just the same mechanism transferring extended messages. It doesn't add any smartness to netconsole per-se except that it can now emit messages with metadata headers. What do you think about them?

So, this patchset aims for obtaining kernel messages under problematic condition. You have to hold messages until ack is delivered. This means that printk buffer can become full before burst messages (e.g. SysRq-t) are acked due to packet loss in the network.

printk() cannot wait for ack. Trying to wait for ack would break something. How can you transmit subsequent kernel messages which failed to enqueue due to waiting for ack for previous kernel messages?

Quoted 5 lines

Thanks.

Signature · 1 line
tejun
author
#32 lore raw
Quoted 5 lines · Tetsuo Handa
Quoted 4 lines

Upto patch 12, it's just the same mechanism transferring extended messages. It doesn't add any smartness to netconsole per-se except that it can now emit messages with metadata headers. What do you think about them?

Quoted 8 lines

So, this patchset aims for obtaining kernel messages under problematic condition. You have to hold messages until ack is delivered. This means that printk buffer can become full before burst messages (e.g. SysRq-t) are acked due to packet loss in the network.

printk() cannot wait for ack. Trying to wait for ack would break something. How can you transmit subsequent kernel messages which failed to enqueue due to waiting for ack for previous kernel messages?

Well, if log buffer overflows and the messages aren't at the logging target yet, they're lost. It's the same as doing dmesg on localhost, isn't it? This doesn't have much to do with where the reliability logic is implemented and is exactly the same with local logging too.

Thanks.

Signature · 1 line
tejun
#33 lore raw
Quoted 8 lines · Tejun Heo
Quoted 3 lines

printk() cannot wait for ack. Trying to wait for ack would break something. How can you transmit subsequent kernel messages which failed to enqueue due to waiting for ack for previous kernel messages?

Well, if log buffer overflows and the messages aren't at the logging target yet, they're lost. It's the same as doing dmesg on localhost, isn't it? This doesn't have much to do with where the reliability logic is implemented and is exactly the same with local logging too.

If you tolerate loss of kernel messages, adding sequence number to each UDP packet will be sufficient for finding out whether the packets were lost and/or reordered in flight.

  printk("Hello");
   => netconsole sends "00000000 Hello" using UDP
  printk("netconsole");
   => netconsole sends "00000001 netconsole" using UDP
  printk("world\n");
   => netconsole sends "00000002 world\n" using UDP

It might be nice to allow administrator to prefix a sequence number to netconsole messages for those who are using special receiver program (e.g. ncrx) which checks that sequence number.

Quoted 6 lines

Thanks.

Signature · 1 line
tejun
author
#34 lore raw
Quoted 1 line · Tetsuo Handa

If you tolerate loss of kernel messages, adding sequence number to each UDP

Well, there's a difference between accepting loss when log buffer overflows and when any packets get lost.

Quoted 10 lines

packet will be sufficient for finding out whether the packets were lost and/or reordered in flight.

  printk("Hello");
   => netconsole sends "00000000 Hello" using UDP
  printk("netconsole");
   => netconsole sends "00000001 netconsole" using UDP
  printk("world\n");
   => netconsole sends "00000002 world\n" using UDP
Quoted 3 lines

It might be nice to allow administrator to prefix a sequence number to netconsole messages for those who are using special receiver program (e.g. ncrx) which checks that sequence number.

That said, this is pretty much what the first 12 patches do (except for the last printk patch, which can be taken out). We already have sequencing and established format to expose them to userland - try cat /dev/kmsg, which btw is what local loggers on modern systems use anyway. Why introduce netconsole's own version of metadata?

Thanks.

Signature · 1 line
tejun
#35 lore raw
Quoted 15 lines · Tejun Heo
Quoted 10 lines · Tetsuo Handa

packet will be sufficient for finding out whether the packets were lost and/or reordered in flight.

  printk("Hello");
   => netconsole sends "00000000 Hello" using UDP
  printk("netconsole");
   => netconsole sends "00000001 netconsole" using UDP
  printk("world\n");
   => netconsole sends "00000002 world\n" using UDP
Quoted 3 lines

It might be nice to allow administrator to prefix a sequence number to netconsole messages for those who are using special receiver program (e.g. ncrx) which checks that sequence number.

Quoted 5 lines

That said, this is pretty much what the first 12 patches do (except for the last printk patch, which can be taken out). We already have sequencing and established format to expose them to userland - try cat /dev/kmsg, which btw is what local loggers on modern systems use anyway. Why introduce netconsole's own version of metadata?

I didn't mean to introduce netconsole's own version of metadata. I meant we don't need to implement in-kernel retry logic.

If we can assume that scheduler is working, adding a kernel thread that does

while (1) {
read messages with metadata from /dev/kmsg
send them using UDP network
}

might be easier than modifying netconsole module.

Quoted 6 lines

Thanks.

Signature · 1 line
tejun
author
#36 lore raw

Hello,

Quoted 2 lines · Tetsuo Handa

I didn't mean to introduce netconsole's own version of metadata. I meant we don't need to implement in-kernel retry logic.

Hmmm? I'm not really following where this discussion is headed. No, we don't have to put it in the kernel. We can punt the retry part to userland as I wrote in another message at some cost to robustness.

Quoted 9 lines

If we can assume that scheduler is working, adding a kernel thread that does

while (1) {
read messages with metadata from /dev/kmsg
send them using UDP network
}

might be easier than modifying netconsole module.

But, I mean, if we are gonna do that in kernel, we better do it properly where it belongs. What's up with "easier than modifying netconsole module"? Why is netconsole special? And how would the above be any less complex than a single timer function? What am I missing?

Thanks.

Signature · 1 line
tejun
#37 lore raw
Quoted 8 lines · Tejun Heo
Quoted 8 lines

If we can assume that scheduler is working, adding a kernel thread that does

while (1) {
read messages with metadata from /dev/kmsg
send them using UDP network
}

Quoted 7 lines
Quoted 1 line

might be easier than modifying netconsole module.

But, I mean, if we are gonna do that in kernel, we better do it properly where it belongs. What's up with "easier than modifying netconsole module"? Why is netconsole special? And how would the above be any less complex than a single timer function? What am I missing?

User space daemon is sometimes disturbed unexpectedly due to

(a) SIGKILL by OOM-killer
(b) spurious ptrace() by somebody
(c) spurious signals such as SIGSTOP / SIGINT
(d) stalls triggered by page faults under OOM condition
(e) other problems such as scheduler being not working

We have built-in protection for (a) named /proc/$pid/oom_score_adj , but we need to configure access control modules for protecting (b) and (c), and we don't have protection for (d). Thinking from OOM stall discussion,
(d) is fatal when trying to obtain kernel messages under problematic condition. I thought that a kernel thread that does

while (1) {
read messages with metadata from /dev/kmsg
send them using UDP network
}

is automatically protected from (a), (b), (c) and (d), and it could be implemented outside of netconsole module.

author
#38 lore raw
In reply to Tejun Heo

Just a bit of addition.

Quoted 4 lines · Tejun Heo

Upto patch 12, it's just the same mechanism transferring extended messages. It doesn't add any smartness to netconsole per-se except that it can now emit messages with metadata headers. What do you think about them?

So, as long as netconsole can send messages with metadata header, moving the reliability part to userland is trivial. All that's necessary is a program which follows /dev/kmsg, keeps the unacked sequences and implement the same retransmission mechanism. It'd be less reobust in certain failure scenarios and a bit more cumbersome to set up but nothing major and if we do that there'd be no reason to keep the userland part in the kernel tree.

If the retransmission and timer parts are bothering, moving those to userland sounds like an acceptable compromise.

Thanks.

Signature · 1 line
tejun
maintainer
#39 lore raw
In reply to Tejun Heo

From: Tejun Heo <[email protected]>
Date: Fri, 17 Apr 2015 13:37:54 -0400

Quoted 6 lines

Hello, David.

Quoted 2 lines · David Miller

If userland cannot run properly, it is almost certain that neither will your complex reliability layer logic.

Quoted 7 lines

* The bulk of patches are to pipe extended log messages to console drivers and let netconsole relay them to the receiver (and quite a bit of refactoring in the process), which, regardless of the reliability logic, is beneficial as we're currently losing structured logging (dictionary) and other metadata over consoles and regardless of where the reliability logic is implemented, it's a lot easier to have messages IDs.

I do not argue against cleanups and good restructuring of the existing code. But you have decided to mix that up with something that is not exactly non-controversial.

You'd do well to seperate the cleanups from the fundamental changes, so they can be handled separately.

Quoted 5 lines

* The only thing necessary for reliable transmission are timer and netpoll. There sure are cases where they go down too but there's a pretty big gap between those two going down and userland getting hosed, but where to put the retransmission and reliability logic definitely is debatable.

I fundamentally disagree, exactly on this point.

If you take an OOPS in a software interrupt handler (basically, all of the networking receive paths and part of the transmit paths, for example) you're not going to be taking timer interrupts.

And that's the value of netconsole, the chance (albeit not %100) of getting messages in those scenerios.

author
#40 lore raw

Hello,

Quoted 11 lines · David Miller
Quoted 7 lines

* The bulk of patches are to pipe extended log messages to console drivers and let netconsole relay them to the receiver (and quite a bit of refactoring in the process), which, regardless of the reliability logic, is beneficial as we're currently losing structured logging (dictionary) and other metadata over consoles and regardless of where the reliability logic is implemented, it's a lot easier to have messages IDs.

I do not argue against cleanups and good restructuring of the existing code. But you have decided to mix that up with something that is not exactly non-controversial.

Is the controlversial part referring to sending extended messages or the reliability part or both?

Quoted 2 lines

You'd do well to seperate the cleanups from the fundamental changes, so they can be handled separately.

Hmmm... yeah, probably would have been a better idea. FWIW, the patches are stacked roughly in the order of escalating controversiness. Will split the series up.

Quoted 11 lines
Quoted 5 lines

* The only thing necessary for reliable transmission are timer and netpoll. There sure are cases where they go down too but there's a pretty big gap between those two going down and userland getting hosed, but where to put the retransmission and reliability logic definitely is debatable.

I fundamentally disagree, exactly on this point.

If you take an OOPS in a software interrupt handler (basically, all of the networking receive paths and part of the transmit paths, for example) you're not going to be taking timer interrupts.

Sure, if irq handling is hosed, this won't work but I think there are enough other failure modes like oopsing while holding a mutex or falling into infinite loop while holding task_list lock (IIRC we had something simliar a while ago due to iterator bug). Whether being more robust in those cases is worthwhile is definitely debatable. I thought the added complexity was small enough but the judgement can easily fall on the other side.

Quoted 2 lines

And that's the value of netconsole, the chance (albeit not %100) of getting messages in those scenerios.

None of the changes harm that in any way. Anyways, I'll split up the extended message and the rest.

Thanks.

Signature · 1 line
tejun
maintainer
#41 lore raw

From: Tejun Heo <[email protected]>
Date: Fri, 17 Apr 2015 15:52:38 -0400

Quoted 11 lines

Hello,

Quoted 8 lines · David Miller
Quoted 7 lines

* The bulk of patches are to pipe extended log messages to console drivers and let netconsole relay them to the receiver (and quite a bit of refactoring in the process), which, regardless of the reliability logic, is beneficial as we're currently losing structured logging (dictionary) and other metadata over consoles and regardless of where the reliability logic is implemented, it's a lot easier to have messages IDs.

Quoted 6 lines
Quoted 3 lines

I do not argue against cleanups and good restructuring of the existing code. But you have decided to mix that up with something that is not exactly non-controversial.

Is the controlversial part referring to sending extended messages or the reliability part or both?

Anything outside of the non-side-effect cleanups.

Quoted 3 lines

Hmmm... yeah, probably would have been a better idea. FWIW, the patches are stacked roughly in the order of escalating controversiness. Will split the series up.

Thanks.

Quoted 4 lines

Sure, if irq handling is hosed, this won't work but I think there are enough other failure modes like oopsing while holding a mutex or falling into infinite loop while holding task_list lock (IIRC we had something simliar a while ago due to iterator bug).

If you oops while holding a mutex, unless it's the console mutex the logging process can schedule and likely get the message transmitted.

What we're going to keep discussing is the fact that in return for all of your unnecessary added complexity, we get something that only applies in an extremely narrow scope of situations.

That is a very poor value proposition.

It took nearly two decades to get rid of all of the races and locking problems with current netpoll/netconsole, and it's as simple as can possibly be. I do not want to even think about having to worry about a reliability layer on top of it, that's just too much.

#42 lore raw
In reply to David Miller
Quoted 11 lines · On Fri, 17 Apr 2015 13:17:12 -0400 (EDT) David Miller <[email protected]>…

From: Tejun Heo <[email protected]>
Date: Fri, 17 Apr 2015 12:28:26 -0400

Quoted 7 lines · Tetsuo Handa
Quoted 2 lines

If the sender side can wait for retransmission, why can't we use userspace programs (e.g. rsyslogd)?

Because the system may be oopsing, ooming or threshing excessively rendering the userland inoperable and that's exactly when we want those log messages to be transmitted out of the system.

Quoted 6 lines

If userland cannot run properly, it is almost certain that neither will your complex reliability layer logic.

I tend to agree with Tetsuo, that in-kernel netconsole should remain as simple as possible and once it starts to have any smarts and less trivial logic the job belongs in userspace.

Keep existing netconsole as simple as possible. It is not meant as reliable, secure logging.

"Those who do not understand TCP are doomed to reinvent it"

#43 lore raw
In reply to Tejun Heo
Quoted 4 lines · Tejun Heo

In a lot of configurations, netconsole is a useful way to collect system logs; however, all netconsole does is simply emitting UDP packets for the raw messages and there's no way for the receiver to find out whether the packets were lost and/or reordered in flight.

Except a modern nonsaturated LAN shouldn't do that.

If you have two machines plugged into a hub, and that's _all_ that's plugged in, packets should never get dropped. This was the original use case of netconsole was that the sender and the receiver were plugged into the same router.

However, even on a quite active LAN the days of ethernet doing CDMA requiring retransmits are long gone, even 100baseT routers have been cacheing and retransmitting data internally so each connection can go at the full 11 megabytes/second with the backplane running fast enough to keep them all active at the same time. (That's why it's so hard to find a _hub_ anymore, it's all routers. The point of routers is they cache internally and send the packet only out the connection they should go, based on an internal routing table because they listened to incoming packets to figure out who lives where and do arp-like things.)

And of course gigabit is a point to point protocol that has nothing to do with conventional ethernet at _all_ other than the name, as far as I know it can't _not_ do this.

So are you trying to program around a problem you've actually _seen_, or are you attempting to reinvent TCP/IP yet again based on top of UDP (Drink!) because of a purely theoretical issue?

Or are you trying to route netconsole, unencapsulated, across the internet? Of course the internet itself refusing to drop packets but instead buffering and retransmitting them even when doing so turns out to be a really bad idea is sort of where this whole "bufferbloat" thing came from. So again, even in that context, is this a problem you've actually _seen_?

Quoted 2 lines

printk already keeps log metadata which contains enough information to make netconsole reliable. This patchset does the followings.

Adds a giant amount of complexity without quite explaining why.

Rob

#44 lore raw

From: Of Rob Landley

Quoted 14 lines

Sent: 19 April 2015 08:25

Quoted 4 lines · Tejun Heo

In a lot of configurations, netconsole is a useful way to collect system logs; however, all netconsole does is simply emitting UDP packets for the raw messages and there's no way for the receiver to find out whether the packets were lost and/or reordered in flight.

Except a modern nonsaturated LAN shouldn't do that.

If you have two machines plugged into a hub, and that's _all_ that's plugged in, packets should never get dropped. This was the original use case of netconsole was that the sender and the receiver were plugged into the same router.

Quoted 6 lines

However, even on a quite active LAN the days of ethernet doing CDMA requiring retransmits are long gone, even 100baseT routers have been cacheing and retransmitting data internally so each connection can go at the full 11 megabytes/second with the backplane running fast enough to keep them all active at the same time. (That's why it's so hard to find a _hub_ anymore, it's all routers

...

Most machines are plugged into switches (not routers), many of them will send 'pause' frames which the host mac may act on.
In which case packet loss is not expected (unless you have broadcast storms when all bets are off).

Additionally, within a local network you shouldn't really get any packet loss since no segments should be 100% loaded.
So for testing it is not unreasonable to expect no lost packets in netconsole traffic.

David

author
#45 lore raw
In reply to Rob Landley

Hello, Rob.

Quoted 4 lines · Rob Landley

If you have two machines plugged into a hub, and that's _all_ that's plugged in, packets should never get dropped. This was the original use case of netconsole was that the sender and the receiver were plugged into the same router.

Development aid on local network hasn't been the only use case for a very long time now. I haven't seen too many large scale setups and two of them were using netconsole as a way to collect kernel messages cluster-wide and having issues with lost messages. One was running it over a separate lower speed network from the main one which they used for most managerial tasks including deployment and packet losses weren't that unusual.

The other is running on the same network but the log collector isn't per-rack so the packets end up getting routed through congested parts of the network again experiencing messages losses.

Quoted 3 lines

So are you trying to program around a problem you've actually _seen_, or are you attempting to reinvent TCP/IP yet again based on top of UDP (Drink!) because of a purely theoretical issue?

At larger scale, the problem is very real. Let's forget about the reliability part. The main thing is being able to identify message sequences so that the receiver can put the message streams back together.

That said, once that's there, whether the "reliability" part is done with TCP doesn't make that much of difference as it'd still need to put back the two message streams together, but again this doesn't matter. Let's just ignore this part.

Quoted 4 lines
Quoted 2 lines

printk already keeps log metadata which contains enough information to make netconsole reliable. This patchset does the followings.

Adds a giant amount of complexity without quite explaining why.

The only signficant complexity is on the receiver side and it doesn't even have to be in the kernel. CON_EXTENDED and emitting extended messages are pretty straight-forward changes.

Thanks.

Signature · 1 line
tejun