printk: Add context information to kernel messages from /dev/kmsg

Hi all,

This patch set adds context information to kernel messages from /dev/kmsg.

Two printk messages connected with KERN_CONT can be divided in multiple lines by a different process context message. This induces two problems.

a) The owner problem
If the different context message seems like the 1st divided message, it is difficult to understand which the 2nd divided message belongs to. This problem can also occur for the situation where multiple message lines without KERN_CONT are broken into by similar messages. When user tools handle printk messages, those mixed messages will create some inconveniences.

- Example of the owner problem

	[110781.736171] sd 2:0:0:0: [sdb]  
	[110781.736170] sd 3:0:0:0: [sdc] Unhandled sense code
	[110781.736172] sd 3:0:0:0: [sdc]  
	[110781.736175] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
	[110781.736177] sd 3:0:0:0: [sdc]  
	[110781.736178] Sense Key : Medium Error [current] 
	[110781.736187] Sense Key : Recovered Error 

b) The reconstruction problem
Even if we solve the owner problem, we don't know the consecutive lines owned by a particular context are whether divided messages with KERN_CONT or simply separate lines from the beginning.

- Example of the reconstruction problem

	[110781.736198] Read(10): 28 00
	 ...[snip]...
	[110781.736204]  00
	[110781.736205]  00 11 e0 00 01 00 00

Which ones should be merged into on line? You may say the right answer, but it's difficult to automate. The expected result is as follows:

[110781.736198] Read(10): 28 00 00 00 11 e0 00 01 00 00

We can consider three solutions for these problems:

1. Store continuous messages in a local buffer, and execute printk This does not induce fragment of messages. There are some related work about error messages in a SCSI layer.

	http://marc.info/?l=linux-scsi&m=135003083808290&w=2
	http://comments.gmane.org/gmane.linux.scsi/88768

This approach will take time for acceptance activities because continuous printk is used in a lot of places. Moreover, this approach
cannot solve the fragment message problem fundamentally, so kernel developers must always take care about continuous printk. Therefore, this solution takes a maintenance cost.

2. Add context information to all kernel messages
This solves a) the owner problem because user tools can separate each owner message from mixed messages by the context information. If multiple message lines without KERN_CONT are broken into by similar messages, this is a good solution. However, this does not indicate which messages with KERN_CONT are fragmented, so this does not solve b) the reconstruction problem for those.

3. Apply 2. and add fragment flag to all fragmented kernel messages This solves a) and b) problems for multiple messages connected with KERN_CONT. The fragmented flag shows which messages with KERN_CONT are fragmented, so user tools can reconstruct to its original state by it after separating each owner message from mixed messages by the context information.

This solves the fragment problem fundamentally by merging those fragment messages on userland, so this solution seems to be a right way. We choose this solution.

Following description makes mention of only fragmented messages with KERN_CONT. This is because if the problems for fragmented messages with KERN_CONT are solved, the owner problem for the mixed messages without KERN_CONT is also solved.

Fragment is induced by different process context messages, so we want to add process context information to each message in order to connect fragmented messages. CPU number is not sufficient because it can change while calling a series of printks in the preemptive kernel. On the other hand, we don't want to change results of dmesg and syslog messages. How do we tackle this problem?

The key idea is to change the header of /dev/kmsg. According to the documentation of /dev/kmsg, we can add comma separated values before ';' as the header information of /dev/kmsg. So, we can change the header information based on the rule.

This patch set solves this problem by following two approaches:

1. Add process context information (PID/interrupt)
Fragment can occur when the process context is different from the previous context stored in the cont buffer. By applying this 1st patch, the context information is indicated to connect fragment messages. Moreover, if the message is output in an interrupt context, the information is also output as s(softIRQ)/h(hardIRQ)/n(NMI).

2. Introduce an exact fragment flag
Current kernel tries to add 'c' flag to the 1st fragmented line and '+' to the following fragmented lines. However, these flags are just a hint; it doesn't guarantee that they are always correct because the kernel can't know the right answer without context information. Current kernel adds fragment flags by guess work, but a user tool can connect fragmented lines exactly by utilizing context information. So, current fragment flag is not appropriate after applying this patch, and we introduced new fragment flag 'f' instead of 'c' and '+'.

To understand how to connect fragmented messages by changing the header of /dev/kmsg, we assume that each two kernel threads executes the following 3 printk():

	pr_info("A1");
    	printk("A2");
    	printk("A3\n");

In current implementation, these threads can output as follows:

	6,3321,31629088,-;A1    <== Who output this message?
    	6,3322,31629091,c;A1         |
    	4,3323,31629094,+;A2    <----+
    	4,3324,31629095,+;A3         | Which?
    	4,3325,31629097,c;A2    <----+
    	4,3326,31629099,+;A3

A1, A2, and A3 messages of two threads are clearly fragmented in this result, but we cannot understand who output the 1st line message and which messages were output by whom. So, the relation of divided messages is unclear from this test. Moreover, although the 4th fields of the header indicate fragment flags, the flag in the 1st line shows not 'c' (fragment) but '-' (no fragment).

By applying this patch set, we can get a following result from /dev/kmsg:

	6,7868,2070756113,f,1185/-;A1
	6,7869,2070756116,f,1186/-;A1
	4,7870,2070756118,f,1186/-;A2
	4,7871,2070756119,-,1186/-;A3
	4,7872,2070756120,f,1185/-;A2
	4,7873,2070756122,-,1185/-;A3

1st line indicates fragmented line, PID=1185, and no interrupt context. 2nd line indicates fragmented line, PID=1186, and no interrupt context. So, 1st line will connect to 6th line and 7th line by fragment flags and PID. On the other hand, 2nd line will connect to 3rd line and 4th line. A message merging tool can convert these messages as follows:

	6,7868,2070756113,-,1185/-;A1A2A3	/* thread1 */
	6,7869,2070756116,-,1186/-;A1A2A3	/* thread2 */

Thanks!

---

Yoshihiro YUNOMAE (2):
printk: Add context information to the header of /dev/kmsg
printk: Simplify fragmented line information of the header of /dev/kmsg

 Documentation/ABI/testing/dev-kmsg |   34 ++++++++----
 kernel/printk/printk.c             |  104 +++++++++++++++++++++++++-----------
 2 files changed, 95 insertions(+), 43 deletions(-)

Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: [email protected]

Add context information to the header of /dev/kmsg.

Two printk messages connected with KERN_CONT can be divided in multiple lines by a different process context message. If the different context message seems like the 1st divided message, it is difficult to understand which the 2nd divided message belongs to. This problem can also occur for the situation where multiple message lines without KERN_CONT are broken into by similar messages. For example, SCSI disk error messages can be show as follows:

	[110781.736171] sd 2:0:0:0: [sdb]
	[110781.736170] sd 3:0:0:0: [sdc] Unhandled sense code
	[110781.736172] sd 3:0:0:0: [sdc]
	[110781.736175] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
	[110781.736177] sd 3:0:0:0: [sdc]
	[110781.736178] Sense Key : Medium Error [current]
	[110781.736187] Sense Key : Recovered Error
	[110781.736189] [current]

This patch adds PID and interrupt context flag to the header of /dev/kmsg as the context information in order to understand relation of output messages. If PID values of two messages and the interrupt context flags are same, it means that those messages are same context, so those message have some relation. If not so, it means that those messages are different context, so users do not need to take care about the relation of the messages.

The header information is changed as follows:
<prefix>,<seq#>,<timestamp>,<fragmented>,<PID>/<interrupt context>;<msg>

                                            |                       |
                                            +-----------------------+

context info.
Interrupt context indicates as follows:
n: NMI context
h: Hard IRQ context
s: Soft IRQ context
-: No interrupt context

<Examples>
- Output same 3 printk messages in two kernel threads.
Run two kernel threads in same time in order to make the messages compete.

	pr_info("A1");
	printk("A2");
	printk("A3\n");

- Current implementation (without context information)

	6,3321,31629088,-;A1    <== Who output this message?
	6,3322,31629091,c;A1         |
	4,3323,31629094,+;A2    <----+
	4,3324,31629095,+;A3         | Which?
	4,3325,31629097,c;A2    <----+
	4,3326,31629099,+;A3

A1, A2, and A3 messages of two threads are clearly fragmented in this result, but we cannot understand who output the 1st line message and which messages were output by whom. So, the relation of divided messages is unclear from this test.

- Applying this patch (with context information)

	6,2308,36687114,-,622/-;A1    <== Output by PID=622
	6,2309,36687118,c,621/-;A1         |
	4,2310,36687121,+,621/-;A2         | Relate
	4,2311,36687123,+,621/-;A3         |
	4,2312,36687124,c,622/-;A2    <----+   (1)
	4,2313,36687126,+,622/-;A3    <----+   (2)

We can understand the relation of divided messages. For example, the 1st line indicates PID=622 and no interrupt context. The same context is the lines of (1) and (2). So, users can understand these three messages are output by the same thread.

Note:
According to Documentation/ABI/testing/dev-kmsg, we can add comma separated values before ';' as the header information of /dev/kmsg. So, this change does not affect ABI.

---
 Documentation/ABI/testing/dev-kmsg |   21 ++++++++--
 kernel/printk/printk.c             |   77 ++++++++++++++++++++++++++++--------
 2 files changed, 76 insertions(+), 22 deletions(-)

index bb820be..d8128ac 100644
@@ -77,11 +77,11 @@ Description:	The /dev/kmsg character device node provides userspace access
 		userspace.
 
 		Example:
-		7,160,424069,-;pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
+		7,160,424069,-,1/-;pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
 		 SUBSYSTEM=acpi
 		 DEVICE=+acpi:PNP0A03:00
-		6,339,5140900,-;NET: Registered protocol family 10
-		30,340,5690716,-;udevd[80]: starting version 181
+		6,339,5140900,-,1/-;NET: Registered protocol family 10
+		30,340,5690716,-,80/-;udevd[80]: starting version 181
 
 		The DEVICE= key uniquely identifies devices the following way:
 		  b12:8        - block dev_t

@@ -89,7 +89,7 @@ Description:	The /dev/kmsg character device node provides userspace access
 		  n8           - netdev ifindex
 		  +sound:card0 - subsystem:devname
 
-		The flags field carries '-' by default. A 'c' indicates a
+		The 4th flags field carries '-' by default. A 'c' indicates a
 		fragment of a line. All following fragments are flagged with
 		'+'. Note, that these hints about continuation lines are not
 		necessarily correct, and the stream could be interleaved with

@@ -98,4 +98,17 @@ Description:	The /dev/kmsg character device node provides userspace access
 		logic is used internally when messages are printed to the
 		console, /proc/kmsg or the syslog() syscall.
 
+		The 5th field is context information to separate mixed messages
+		from different contexts. The field indicates PID and interrupt
+		context information like '<PID>/<interrupt context info.>'. In
+		interrupt context information, 'n' indicates NMI context, 'h'
+		indicates hard IRQ context, 's' indicates soft IRQ context, and
+		'-' indicates no interrupt context. This 5th context field tells
+		users which messages are output in the same context. If PID
+		values of two messages and interrupt context are same, it means
+		that those messages are output by the same process, so those
+		message may have any relation. If not so, it means that those
+		messages are different context, so users do not need to care
+		about the relation of the messages.
+
 Users:		dmesg(1), userspace kernel log consumers

[...]

[...]

Hi Kay,

Thank you for your reply.

As we discussed about this issue in LinuxCon Japan, mixed messages will be fixed in each subsystem. In the SCSI layer, tracing feature will be used. (http://www.spinics.net/lists/linux-scsi/msg74428.html)
If we found the same issue in other subsystem, we would like to add new generic printk API to avoid mixed messages.

Thank you,
Yoshihiro YUNOMAE

Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: [email protected]

Has this been tested with popular userspace that reads /dev/kmsg, to make sure that it actually plays nice with a 5th field being added? Yes, I know that Documentation/ABI/dev-kmsg says that added fields should be gracefully ignored - but we all know how good userspace programmers are about that sort of thing. :)

Hi,

I checked it for systemd-journald and rsyslog on the source code level, those tools don't handle new flag and field before ';' in the header of /dev/kmsg. Those tools use only log level, sequence#, and timestamp. So, even if we add these new flag and field for each message, those tools will be able to work.

But, we'll fix this issue by other method if we found it in any subsystems except for the SCSI layer.
(In the SCSI layer, we'll tackle this issue by using tracing feature.)

Thank you,
Yoshihiro YUNOMAE

Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: [email protected]

Simplify fragmented line information of the 4th flag of the header of /dev/kmsg.

One of the hint of the printk() linebreak is the header information of /dev/kmsg. 4th flag in the header adds 'c' or '+' when a message is divided. Users can roughly understand where the printk message was divided, but they cannot understand exactly which messages are divided or how those messages should be connected.

According to a comment in printk.c, 'c' is marked for the first fragment of a line. However, 'c' is not always marked as the first fragment of the line in current kernel. The kernel outputs the 'c' flag when current message flags has LOG_CONT and previous message flag does not have LOG_CONT. So, LOG_CONT flag is needed to add 'c'. However, when the previous message A is being stored in cont buffer and the current message B is not added to cont buffer, LOG_CONT flag is added not to the message A but to the message B. In this situation, 'c' flag is added to the message B even though the message A is actually the first fragmented line. As the result, it seems that the message A is not divided because the message A is output with '-' (no fragment).

In addition, all following fragments are flagged with '+' according to Documentation/ABI/testing/dev-kmsg. In kernel, when current message and the previous message has LOG_CONT flag, '+' flag is added to the current message. However, if those messages are output in different context and those messages have LOG_CONT flag, '+' flag is added to the current message but it is sometimes meaningless. For example, when previous message with LOG_CONT is output by process C and current message (1st continuous message) with LOG_CONT is output by process D, adding '+' flag to the current message of process D is incorrect. This occurs when both return values of both messages without '\n' are false in cont_add().

This patch simplifies the fragmented line flag policy.
1) Add 'f' flag if the kernel flushes a fragment message
2) Delete 'c' and '+'
When fragmentation occurs, the current message flushes the previous message with LOG_CONT. When the kernel outputs the messages to /dev/kmsg, it just checks whether messages have LOG_CONT flag or not. If the messages have LOG_CONT flag, it adds 'f' flag in the header of /dev/kmsg. Then, users can understand which message was divided by 'f' flag and how these messages should be connected by checking the fragmented flag and the context information.

<Example>
- Environment
Execute 3 kernel threads A, B, and C. Each thread outputs following
messages:

	/* for {A, B, C} */
	pr_info("{A, B, C}1");
	printk("{A, B, C}2");
	printk("{A, B, C}3\n");

- Current result of /dev/kmsg

	6,225186,93838029,-,2288/-;B1    <== No fragment?
	6,225187,93838091,c,2289/-;C1
	4,225188,93838092,+,2289/-;C2
	4,225189,93838092,+,2289/-;C3
	6,225190,93842059,c,2289/-;C1
	4,225191,93842409,+,2289/-;C2C3
	4,225192,93842713,-,2288/-;B2    <== No fragment?
	6,225193,93842944,c,2287/-;A1
	4,225194,93842944,+,2287/-;A2
	4,225195,93842945,+,2287/-;A3
	4,225196,93846199,-,2288/-;B3    <== No fragment?

In this example, fragmented flags of the B thread are incorrect because B1, B2, and B3 are actually divided, but there are no flags. So, users cannot understand which messages are divided or how those messages should be connected in current implementation.

- Apply this patch
This patch introduces 'f' flag policy and deletes 'c' and '+' flags. If a message is forcibly flushed in the middle, just add 'f'. Moreover, if a message includes '\n' meaning the end of the messages, add no fragment flag ('-'). So, if users find 'f' flag for a message, they can connect the message to next 'f' flag (forcibly flushed) or '-' (the end of the messages) in same context.

	6,8219,543073110,f,538/-;B1    <== This message is fragmented.
	6,8220,543073113,f,539/-;C1
	4,8221,543073115,f,539/-;C2
	4,8222,543073116,-,539/-;C3
	4,8223,543073117,f,538/-;B2    <== Stil fragmented
	6,8224,543073120,f,537/-;A1
	4,8225,543073120,-,538/-;B3    <== This is the end of the messages.
	4,8226,543073123,-,537/-;A2A3

A message merging tool can convert these messages as follows:

	6,8219,543073110,-,538/-;B1B2B3
	6,8220,543073113,-,539/-;C1C2C3
	6,8224,543073120,-,537/-;A1A2A3

---
 Documentation/ABI/testing/dev-kmsg |   15 +++++++--------
 kernel/printk/printk.c             |   31 +++++++++++++++----------------
 2 files changed, 22 insertions(+), 24 deletions(-)

index d8128ac..ccb7cf3 100644
@@ -89,14 +89,13 @@ Description:	The /dev/kmsg character device node provides userspace access
 		  n8           - netdev ifindex
 		  +sound:card0 - subsystem:devname
 
-		The 4th flags field carries '-' by default. A 'c' indicates a
-		fragment of a line. All following fragments are flagged with
-		'+'. Note, that these hints about continuation lines are not
-		necessarily correct, and the stream could be interleaved with
-		unrelated messages, but merging the lines in the output
-		usually produces better human readable results. A similar
-		logic is used internally when messages are printed to the
-		console, /proc/kmsg or the syslog() syscall.
+		The 4th flags field carries '-' by default. A 'f' indicates a
+		fragment of a line. If a message is forcibly flushed in the
+		middle, just add 'f'. Moreover, if a message includes '\n'
+		meaning the end of the messages, no add flag ('-'). So, if
+		users find 'f' flag for a message, they can connect the message
+		to next 'f' flag (forcibly flushed) or '-' (the end of the
+		messages) in same context information output in the 5th field.
 
 		The 5th field is context information to separate mixed messages
 		from different contexts. The field indicates PID and interrupt

index 8105431..d8c3716 100644
@@ -414,7 +414,6 @@ static int check_syslog_permissions(int type, bool from_file)
 struct devkmsg_user {
 	u64 seq;
 	u32 idx;
-	enum log_flags prev;
 	struct mutex lock;
 	char buf[8192];
 };

@@ -535,23 +534,16 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 
 	/*
 	 * 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.
+	 * export the stored flags 'f' to allow an optional external merge of
+	 * the records.
 	 */
-	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 = '+';
+	if (msg->flags & LOG_CONT)
+		cont = 'f';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c,%d/%c;",
 		      (msg->facility << 3) | msg->level,
 		      user->seq, ts_usec, cont, msg->pid,
 		      show_irq_count_flag(msg->irq_count));
-	user->prev = msg->flags;
 
 	/* escape non-printable characters */
 	for (i = 0; i < msg->text_len; i++) {

@@ -1620,9 +1612,13 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * Flush the conflicting buffer. An earlier newline was missing,
 		 * or another task also prints continuation lines.
 		 */
-		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current
-				 || cont.irq_count != irq_count()))
-			cont_flush(LOG_NEWLINE);
+		if (cont.len) {
+			if (cont.owner != current ||
+			    cont.irq_count != irq_count())
+				cont_flush(LOG_CONT);
+			else if (lflags & LOG_PREFIX)
+				cont_flush(LOG_NEWLINE);
+		}
 
 		/* buffer line if possible, otherwise store it right away */
 		if (!cont_add(facility, level, text, text_len))

@@ -1645,7 +1641,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    && !(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text,
 						  text_len);
-			cont_flush(LOG_NEWLINE);
+			if (!stored)
+				cont_flush(LOG_CONT);
+			else
+				cont_flush(LOG_NEWLINE);
 		}
 
 		if (!stored)