[PATCH] printk: drop ambiguous LOG_CONT flag

[PATCH] printk: drop ambiguous LOG_CONT flag

[Jan H. Schönherr]

From: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>

The meaning of LOG_CONT is unclear, i. e., whether a message is a starting,
ending, or middle fragment. Unfortunately, this cannot be inferred from
the LOG_PREFIX and LOG_NEWLINE flags, as they are not always kept.
Furthermore, in some cases LOG_CONT is set, although it is unknown if
there will be a continuation. This leads to wrongly concatenated output.

Fix this by dropping LOG_CONT and rely on LOG_PREFIX and LOG_NEWLINE to
distinguish the type of fragment. That is, if LOG_PREFIX is set, this
fragment does not continue the previous fragment. And if LOG_NEWLINE is
set, this fragment is not continued by the next fragment.

(Unfortunately, we still have to look at the previous fragment to catch the
case of an unset LOG_PREFIX on this fragment, but a set LOG_NEWLINE on
the previous fragment.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
Against v3.6-rc7, only lightly tested.
---
 kernel/printk.c | 57 +++++++++++++++++++++++++++++++++------------------------
 1 Datei geändert, 33 Zeilen hinzugefügt(+), 24 Zeilen entfernt(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 66a2ea3..302a08e 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -197,7 +197,6 @@ enum log_flags {
 	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
 	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 */
 };
 
 struct log {
@@ -481,10 +480,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	 * 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))
+	if (!(msg->flags & LOG_NEWLINE) && msg->flags & LOG_PREFIX)
 		cont = 'c';
-	else if ((msg->flags & LOG_CONT) ||
-		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
+	else if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		cont = '+';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
@@ -887,15 +885,17 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 	bool newline = true;
 	size_t len = 0;
 
-	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+	if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		prefix = false;
 
-	if (msg->flags & LOG_CONT) {
-		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
-			prefix = false;
+	if (!(msg->flags & LOG_NEWLINE))
+		newline = false;
 
-		if (!(msg->flags & LOG_NEWLINE))
-			newline = false;
+	if (!(prev & LOG_NEWLINE) && prefix) {
+		if (buf)
+			buf[len++] = '\n';
+		else
+			len++;
 	}
 
 	do {
@@ -1400,35 +1400,36 @@ static void cont_flush(enum log_flags flags)
 	if (cont.len == 0)
 		return;
 
+	cont.flags |= flags;
 	if (cont.cons) {
 		/*
 		 * 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.
 		 */
-		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+		log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
 			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-		cont.flags = flags;
 		cont.flushed = true;
 	} else {
 		/*
 		 * If no fragment of this line ever reached the console,
 		 * just submit it to the store and free the buffer.
 		 */
-		log_store(cont.facility, cont.level, flags, 0,
+		log_store(cont.facility, cont.level, cont.flags, 0,
 			  NULL, 0, cont.buf, cont.len);
 		cont.len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, enum log_flags flags,
+		     const char *text, size_t len)
 {
 	if (cont.len && cont.flushed)
 		return false;
 
 	if (cont.len + len > sizeof(cont.buf)) {
 		/* the line gets too long, split it up in separate records */
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 		return false;
 	}
 
@@ -1437,7 +1438,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.level = level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
-		cont.flags = 0;
+		cont.flags = flags;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
@@ -1446,7 +1447,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	cont.len += len;
 
 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 
 	return true;
 }
@@ -1456,8 +1457,11 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t textlen = 0;
 	size_t len;
 
-	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+	if (cont.cons == 0 && (console_prev & LOG_NEWLINE ||
+						cont.flags & LOG_PREFIX)) {
+		if (!(console_prev & LOG_NEWLINE))
+			text[textlen++] = '\n';
+		textlen += print_time(cont.ts_nsec, text + textlen);
 		size -= textlen;
 	}
 
@@ -1575,12 +1579,16 @@ 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_flush(LOG_NEWLINE);
+		if (cont.len) {
+			if (cont.owner != current)
+				lflags |= LOG_PREFIX;
+			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))
-			log_store(facility, level, lflags | LOG_CONT, 0,
+		if (!cont_add(facility, level, lflags, text, text_len))
+			log_store(facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	} else {
 		bool stored = false;
@@ -1593,7 +1601,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (cont.len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
+				stored = cont_add(facility, level, lflags,
+							text, text_len);
 			cont_flush(LOG_NEWLINE);
 		}
 
-- 
1.7.12

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Greg Kroah-Hartman]

On Wed, Sep 26, 2012 at 07:58:45PM +0200, Jan H. Schönherr wrote:
> From: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
> 
> The meaning of LOG_CONT is unclear, i. e., whether a message is a starting,
> ending, or middle fragment. Unfortunately, this cannot be inferred from
> the LOG_PREFIX and LOG_NEWLINE flags, as they are not always kept.
> Furthermore, in some cases LOG_CONT is set, although it is unknown if
> there will be a continuation. This leads to wrongly concatenated output.
> 
> Fix this by dropping LOG_CONT and rely on LOG_PREFIX and LOG_NEWLINE to
> distinguish the type of fragment. That is, if LOG_PREFIX is set, this
> fragment does not continue the previous fragment. And if LOG_NEWLINE is
> set, this fragment is not continued by the next fragment.
> 
> (Unfortunately, we still have to look at the previous fragment to catch the
> case of an unset LOG_PREFIX on this fragment, but a set LOG_NEWLINE on
> the previous fragment.)
> 
> Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
> ---
> Against v3.6-rc7, only lightly tested.

Well, against linux-next and highly tested would be best.  It's a bit
late to get this into linux-next for 3.7, how important is it really?

thanks,

greg k-h

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Am 26.09.2012 23:15, schrieb Greg Kroah-Hartman:
> On Wed, Sep 26, 2012 at 07:58:45PM +0200, Jan H. Schönherr wrote:
>> Against v3.6-rc7, only lightly tested.
> 
> Well, against linux-next and highly tested would be best.  It's a bit
> late to get this into linux-next for 3.7, how important is it really?

There are no conflicting commits in linux-next, so it should apply there
as well.

"Tested" as in: it fixes my use case: multiple printk()s shortly after each
other -- with KERN_prefix but without a newline at the end. Those were
sometimes concatenated since that printk-rewrite.

All other printk()s that I come across more often look as usual, before and
after the patch. (Mostly singular printk()s, but I also checked the output
from the oom-killer.)

There is no need to include this hastily -- at least not from my point of view
-- as it is already broken in 3.5 and nobody else seems to notice it
(... and I have now a fix for my development printk()s). Should I resend the
patch later?

I was also hoping that Kay might share his opinion, as the LOG_CONT
flag is rather young, and he might have some different plans for it.

(And of course, some more testing wouldn't hurt.)

Regards
Jan

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Thu, Sep 27, 2012 at 12:33 AM, "Jan H. Schönherr"
<schnhrr@cs.tu-berlin.de> wrote:
> Am 26.09.2012 23:15, schrieb Greg Kroah-Hartman:
>> On Wed, Sep 26, 2012 at 07:58:45PM +0200, Jan H. Schönherr wrote:
>>> Against v3.6-rc7, only lightly tested.
>>
>> Well, against linux-next and highly tested would be best.  It's a bit
>> late to get this into linux-next for 3.7, how important is it really?
>
> There are no conflicting commits in linux-next, so it should apply there
> as well.
>
> "Tested" as in: it fixes my use case: multiple printk()s shortly after each
> other -- with KERN_prefix but without a newline at the end. Those were
> sometimes concatenated since that printk-rewrite.

Please provide the output of /dev/kmsg so we can see what's going on here.

> All other printk()s that I come across more often look as usual, before and
> after the patch. (Mostly singular printk()s, but I also checked the output
> from the oom-killer.)
>
> There is no need to include this hastily -- at least not from my point of view
> -- as it is already broken in 3.5 and nobody else seems to notice it
> (... and I have now a fix for my development printk()s). Should I resend the
> patch later?
>
> I was also hoping that Kay might share his opinion, as the LOG_CONT
> flag is rather young, and he might have some different plans for it.

It is a flag that we have not been able to merge a continuation line
in the buffer, because we had a race with another thread, or the
console lock was taken for a long time and we couldn't use the merge
buffer.

LOG_CONT is used to merge (not intended to be) separate records at
time we read them from the record buffer, and print them, it is also
exported as a flag in /dev/kmsg.

I don't think we can just remove it, we can not get that information
from the prefix+newlines, they are not sufficient.

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

[-- Attachment #1: Type: text/plain, Size: 9626 bytes --]

Am 27.09.2012 15:39, schrieb Kay Sievers:
> On Thu, Sep 27, 2012 at 12:33 AM, "Jan H. Schönherr"
> <schnhrr@cs.tu-berlin.de> wrote:
>> "Tested" as in: it fixes my use case: multiple printk()s shortly after each
>> other -- with KERN_prefix but without a newline at the end. Those were
>> sometimes concatenated since that printk-rewrite.
> 
> Please provide the output of /dev/kmsg so we can see what's going on here.

Here we go. Test case attached. (Now I would say, the patch is
lightly to moderately tested.)

======= Results with v3.6-rc7 without patch =========

virtual-parasit ~ # insmod foo.ko; rmmod foo
[  122.965207] newline 1
[  122.965583] newline 2newline 3
[  122.965904] newline 4newline 5
[  122.966221] newline 6newline 7
[  122.966681] newline 8newline 9
[  122.966978] newline 10 continued 1 continued 2 continued 3
[  122.966980] newline 11 continued 4 continued 5 continued 6 continued 7
[  122.966980] newline 12
[  122.966981] newline 13
[  122.966981] newline 15
[  122.966983] newline 16a
[  122.966983] newline 16b
[  122.966983] newline 16c continued 8
[  122.966983] newline 17
[  122.966983] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # insmod foo.ko; rmmod foo

[  128.993048] newline 1newline 2
[  128.993414] newline 3newline 4
[  128.993776] newline 5newline 6
[  128.994009] newline 7
[  128.994010] newline 8
[  128.994010] newline 9
[  128.994011] newline 10 continued 1 continued 2 continued 3
[  128.994012] newline 11 continued 4 continued 5 continued 6 continued 7
[  128.994013] newline 12
[  128.994013] newline 13
[  128.994013] newline 15
[  128.994020] newline 16a
[  128.994020] newline 16b
[  128.994020] newline 16c continued 8
[  128.994020] newline 17
[  128.994020] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # cat /dev/kmsg
<snip>
7,397,122965207,-;newline 1
7,398,122965583,c;newline 2
7,399,122965820,+;newline 3
7,400,122965904,c;newline 4
7,401,122966136,+;newline 5
7,402,122966221,c;newline 6
6,403,122966532,+;newline 7
7,404,122966681,c;newline 8
6,405,122966977,+;newline 9
7,406,122966978,-;newline 10 continued 1 continued 2 continued 3
7,407,122966980,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,408,122966980,-;newline 12
4,409,122966981,-;newline 13
4,410,122966981,-;newline 15
7,411,122966983,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
7,412,122966983,-;newline 18a\x0anewline 18b\x0anewline 18c continued 9
7,413,128993048,c;newline 1
7,414,128993318,+;newline 2
7,415,128993414,c;newline 3
7,416,128993691,+;newline 4
7,417,128993776,c;newline 5
7,418,128994009,+;newline 6
6,419,128994009,-;newline 7
7,420,128994010,-;newline 8
6,421,128994010,-;newline 9
7,422,128994011,-;newline 10 continued 1 continued 2 continued 3
7,423,128994012,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,424,128994013,-;newline 12
4,425,128994013,-;newline 13
4,426,128994013,-;newline 15
7,427,128994020,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17

=====================================================

Without the patch results are pretty non-deterministic.
Sometimes also concatenating timestamps, e. g.:

virtual-parasit ~ # insmod foo.ko; rmmod foo
[   29.624176] newline 1newline 2
[   29.624589] newline 3newline 4
[   29.625155] newline 5newline 6
[   29.625572] newline 7newline 8newline 9newline 10 continued 1 continued 2 continued 3newline 11
continued 4 continued 5 continued 6 continued 7[   29.625575] newline 12
[   29.625576] newline 13
[   29.625576] newline 15
[   29.625576] newline 16a
[   29.625576] newline 16b
[   29.625576] newline 16c continued 8
[   29.625577] newline 17newline 18a
[   29.625577] newline 18b
[   29.625577] newline 18c continued 9

7,604,29624176,c;newline 1
7,605,29624449,+;newline 2
7,606,29624589,c;newline 3
7,607,29625051,+;newline 4
7,608,29625155,c;newline 5
7,609,29625479,+;newline 6
6,610,29625572,c;newline 7
7,611,29625572,+;newline 8
6,612,29625572,+;newline 9
7,613,29625573,+;newline 10
4,614,29625573,+; continued 1
4,615,29625573,+; continued 2
4,616,29625574,+; continued 3
7,617,29625574,+;newline 11
4,618,29625574,+; continued 4
4,619,29625574,+; continued 5
4,620,29625575,+; continued 6
4,621,29625575,+; continued 7
6,622,29625575,-;newline 12
4,623,29625576,-;newline 13
4,624,29625576,-;newline 15
7,625,29625576,c;newline 16a\x0anewline 16b\x0anewline 16c
4,626,29625577,+; continued 8\x0anewline 17
7,627,29625577,+;newline 18a\x0anewline 18b\x0anewline 18c
4,628,29625577,+; continued 9

dmesg for this one:

[   29.624176] newline 1newline 2
[   29.624589] newline 3newline 4
[   29.625155] newline 5newline 6
[   29.625572] newline 7newline 8newline 9newline 10 continued 1 continued 2 continued 3newline 11
continued 4 continued 5 continued 6 continued 7<6>[   29.625575] newline 12
[   29.625576] newline 13
[   29.625576] newline 15
[   29.625576] newline 16a
[   29.625576] newline 16b
[   29.625576] newline 16c continued 8
[   29.625577] newline 17newline 18a
[   29.625577] newline 18b
[   29.625577] newline 18c continued 9newline 1



======= Results with v3.6-rc7 with patch ============

virtual-parasit ~ # insmod foo.ko; rmmod foo
[   47.619453] newline 1
[   47.619719] newline 2
[   47.619974] newline 3
[   47.620182] newline 4
[   47.620474] newline 5
[   47.620763] newline 6
[   47.621007] newline 7
[   47.621008] newline 8
[   47.621008] newline 9
[   47.621009] newline 10 continued 1 continued 2 continued 3
[   47.621011] newline 11 continued 4 continued 5 continued 6 continued 7
[   47.621011] newline 12
[   47.621011] newline 13
[   47.621011] newline 15
[   47.621012] newline 16a
[   47.621012] newline 16b
[   47.621012] newline 16c continued 8
[   47.621012] newline 17
[   47.621012] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # insmod foo.ko; rmmod foo

[   49.979192] newline 1
[   49.979630] newline 2
[   49.979876] newline 3
[   49.979876] newline 4
[   49.979877] newline 5
[   49.979877] newline 6
[   49.979877] newline 7
[   49.979878] newline 8
[   49.979878] newline 9
[   49.979878] newline 10 continued 1 continued 2 continued 3
[   49.979879] newline 11 continued 4 continued 5 continued 6 continued 7
[   49.979885] newline 12
[   49.979895] newline 13
[   49.979896] newline 15
[   49.979896] newline 16a
[   49.979896] newline 16b
[   49.979896] newline 16c continued 8
[   49.979897] newline 17
[   49.979897] newline 18a
[   49.979897] newline 18b
[   49.979897] newline 18c continued 9virtual-parasit ~ # cat /dev/kmsg
<snip>
7,397,47619453,-;newline 1
7,398,47619719,c;newline 2
7,399,47619974,-;newline 3
7,400,47620182,c;newline 4
7,401,47620474,-;newline 5
7,402,47620763,c;newline 6
6,403,47621007,-;newline 7
7,404,47621008,-;newline 8
6,405,47621008,-;newline 9
7,406,47621009,-;newline 10 continued 1 continued 2 continued 3
7,407,47621011,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,408,47621011,-;newline 12
4,409,47621011,-;newline 13
4,410,47621011,-;newline 15
7,411,47621012,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
7,412,47621012,-;newline 18a\x0anewline 18b\x0anewline 18c continued 9
7,413,49979192,c;newline 1
7,414,49979630,-;newline 2
7,415,49979876,c;newline 3
7,416,49979876,c;newline 4
7,417,49979877,c;newline 5
7,418,49979877,c;newline 6
6,419,49979877,c;newline 7
7,420,49979878,c;newline 8
6,421,49979878,c;newline 9
7,422,49979878,c;newline 10
4,423,49979879,+; continued 1
4,424,49979879,+; continued 2
4,425,49979879,+; continued 3
7,426,49979879,c;newline 11
4,427,49979880,+; continued 4
4,428,49979880,+; continued 5
4,429,49979880,+; continued 6
4,430,49979880,+; continued 7
6,431,49979885,-;newline 12
4,432,49979895,-;newline 13
4,433,49979896,-;newline 15
7,434,49979896,c;newline 16a\x0anewline 16b\x0anewline 16c
4,435,49979897,+; continued 8\x0anewline 17
7,436,49979897,c;newline 18a\x0anewline 18b\x0anewline 18c
4,437,49979897,+; continued 9


>> I was also hoping that Kay might share his opinion, as the LOG_CONT
>> flag is rather young, and he might have some different plans for it.
> 
> It is a flag that we have not been able to merge a continuation line
> in the buffer, because we had a race with another thread, or the
> console lock was taken for a long time and we couldn't use the merge
> buffer.

But it is also set, if we don't know yet, whether there is going to
be a continuation (printk.c, line 1583):

	log_store(facility, level, lflags | LOG_CONT, 0,
		  dict, dictlen, text, text_len);

This confuses devkmsg_read() and msg_print_text() later on.


> LOG_CONT is used to merge (not intended to be) separate records at
> time we read them from the record buffer, and print them, it is also
> exported as a flag in /dev/kmsg.
> 
> I don't think we can just remove it, we can not get that information
> from the prefix+newlines, they are not sufficient.

Here I disagree. ;)

If we say "if LOG_CONT is set, next message might be a continuation",
then that is similar to saying "there is no newline at the end of this
message". And we would need an additional flag on messages indicating
that a message does not continue a previous message.

If we say "if LOG_CONT is set, this message continues the previous one",
we can also say "there is no prefix on this message". Then on the other
hand, we would need a "whatever comes next, it does not continue this
message"....

However, if you want to be able to fully sort out continuation line races
afterwards and be able to reconstruct a race free output, then I agree
that the current information is not sufficient.

Regards
Jan


[-- Attachment #2: foo.c --]
[-- Type: text/x-csrc, Size: 1171 bytes --]

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>

static int __init foo_init(void)
{
	printk(KERN_DEBUG "newline 1");
	printk(KERN_DEBUG "newline 2");
	printk(KERN_DEBUG "newline 3");
	printk(KERN_DEBUG "newline 4");
	printk(KERN_DEBUG "newline 5");

	printk(KERN_DEBUG "newline 6");
	printk(KERN_INFO  "newline 7");
	printk(KERN_DEBUG "newline 8");
	printk(KERN_INFO  "newline 9");

	printk(KERN_DEBUG "newline 10");
	printk(KERN_CONT  " continued 1");
	printk(KERN_CONT  " continued 2");
	printk(KERN_CONT  " continued 3");
	printk(KERN_DEBUG "newline 11");
	printk(KERN_CONT  " continued 4");
	printk(           " continued 5");
	printk(           " continued 6");
	printk(           " continued 7");
	printk(KERN_INFO  "newline 12\n");
	printk(KERN_CONT  "newline 13\n");
	printk(KERN_CONT  "newline 15\n");

	printk(KERN_DEBUG "newline 16a\nnewline 16b\nnewline 16c");
	printk(           " continued 8\nnewline 17");
	printk(KERN_DEBUG "newline 18a\nnewline 18b\nnewline 18c");
	printk(           " continued 9");

	return 0;
}

static void __exit foo_exit(void)
{
}

module_init(foo_init);
module_exit(foo_exit);

MODULE_LICENSE("GPL");

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Am 27.09.2012 17:46, schrieb "Jan H. Schönherr":
> If we say "if LOG_CONT is set, this message continues the previous one",
> we can also say "there is no prefix on this message". Then on the other
> hand, we would need a "whatever comes next, it does not continue this
> message"....

Thinking a bit longer about this one.

If really, really everything passes through vprintk_emit()
then we could keep all info about the previous message
there and definitely decide whether the current message continues
the previous one.

Then, we wouldn't need to track the previous flags everywhere.

Do I miss something?

Regards
Jan

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Thu, Sep 27, 2012 at 5:46 PM, "Jan H. Schönherr"
<schnhrr@cs.tu-berlin.de> wrote:
> Am 27.09.2012 15:39, schrieb Kay Sievers:

>> It is a flag that we have not been able to merge a continuation line
>> in the buffer, because we had a race with another thread, or the
>> console lock was taken for a long time and we couldn't use the merge
>> buffer.
>
> But it is also set, if we don't know yet, whether there is going to
> be a continuation (printk.c, line 1583):
>
>         log_store(facility, level, lflags | LOG_CONT, 0,
>                   dict, dictlen, text, text_len);
>
> This confuses devkmsg_read() and msg_print_text() later on.

Yeah, I can see that here too. Tested your patch and seems to behave
well with a bunch of other tests I still have available. Looks good
and worth to try:
  Tested-By: Kay Sievers <kay@vrfy.org>

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Jan H. Schönherr]

Am 27.09.2012 18:04, schrieb Jan H. Schönherr:
> Am 27.09.2012 17:46, schrieb Jan H. Schönherr:
>> If we say "if LOG_CONT is set, this message continues the previous one",
>> we can also say "there is no prefix on this message". Then on the other
>> hand, we would need a "whatever comes next, it does not continue this
>> message"....
>
> Thinking a bit longer about this one.
>
> If really, really everything passes through vprintk_emit()
> then we could keep all info about the previous message
> there and definitely decide whether the current message continues
> the previous one.
>
> Then, we wouldn't need to track the previous flags everywhere.

Here is a patch that does just that.

Seems to work. And it makes the code easier to understand.
A more detailed description is below.

Here is, what it now looks like:

virtual-parasit ~ # insmod foo.ko; rmmod foo
[   29.894348] newline 1
[   29.894686] newline 2
[   29.895067] newline 3
[   29.895469] newline 4
[   29.895859] newline 5
[   29.895860] newline 6
[   29.895860] newline 7
[   29.895860] newline 8
[   29.895861] newline 9
[   29.895861] newline 10 continued 1 continued 2 continued 3
[   29.895862] newline 11 continued 4 continued 5 continued 6 continued 7
[   29.895863] newline 12
[   29.895864] newline 13
[   29.895864] newline 15
[   29.895864] newline 16a
[   29.895864] newline 16b
[   29.895864] newline 16c continued 8
[   29.895864] newline 17
[   29.895865] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # insmod foo.ko; rmmod foo

[   32.291223] newline 1
[   32.291529] newline 2
[   32.291847] newline 3
[   32.291848] newline 4
[   32.291848] newline 5
[   32.291848] newline 6
[   32.291849] newline 7
[   32.291849] newline 8
[   32.291849] newline 9
[   32.291850] newline 10 continued 1 continued 2 continued 3
[   32.291851] newline 11 continued 4 continued 5 continued 6 continued 7
[   32.291853] newline 12
[   32.291858] newline 13
[   32.291859] newline 15
[   32.291859] newline 16a
[   32.291859] newline 16b
[   32.291859] newline 16c continued 8
[   32.291860] newline 17
[   32.291860] newline 18a
[   32.291860] newline 18b
[   32.291860] newline 18c continued 9virtual-parasit ~ # cat /dev/kmsg
<snip>
7,397,29894348,-;newline 1
7,398,29894686,c;newline 2
7,399,29895067,-;newline 3
7,400,29895469,c;newline 4
7,401,29895859,-;newline 5
7,402,29895860,-;newline 6
6,403,29895860,-;newline 7
7,404,29895860,-;newline 8
6,405,29895861,-;newline 9
7,406,29895861,-;newline 10 continued 1 continued 2 continued 3
7,407,29895862,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,408,29895863,-;newline 12
4,409,29895864,-;newline 13
4,410,29895864,-;newline 15
7,411,29895864,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
7,412,29895865,-;newline 18a\x0anewline 18b\x0anewline 18c continued 9
7,413,32291223,c;newline 1
7,414,32291529,-;newline 2
7,415,32291847,c;newline 3
7,416,32291848,c;newline 4
7,417,32291848,c;newline 5
7,418,32291848,c;newline 6
6,419,32291849,c;newline 7
7,420,32291849,c;newline 8
6,421,32291849,c;newline 9
7,422,32291850,c;newline 10
7,423,32291850,+; continued 1
7,424,32291851,+; continued 2
7,425,32291851,+; continued 3
7,426,32291851,c;newline 11
7,427,32291852,+; continued 4
7,428,32291852,+; continued 5
7,429,32291853,+; continued 6
7,430,32291853,+; continued 7
6,431,32291853,-;newline 12
4,432,32291858,-;newline 13
4,433,32291859,-;newline 15
7,434,32291859,c;newline 16a\x0anewline 16b\x0anewline 16c
7,435,32291860,+; continued 8\x0anewline 17
7,436,32291860,c;newline 18a\x0anewline 18b\x0anewline 18c
7,437,32291861,+; continued 9

What do you think?

Regards
Jan

---- 8< ----
From: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
Subject: printk: rework continuation record handling

Centrally track the previous record in vprintk_emit() itself instead of
doing it from formatting code. This enables us to setup the flags of the
current record, so that a later formatting is possible without knowledge
of the previous record.

This simplifies the code and also fixes an issue of too aggressive merging
of printk()s that have a prefix but no newline at the end by defining
the flags more clearly.

The flags have now the following meaning if set:

LOG_CONT:    This record continues the previous record.
LOG_NEWLINE: This record finishes the current message, i. e., ends
             with a newline.
LOG_PREFIX:  The previous record should have had LOG_NEWLINE set,
             but it was unknown at that time, i. e., this record
	     starts with a newline.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 243 ++++++++++++++++++++++++++++----------------------------
 1 Datei geändert, 120 Zeilen hinzugefügt(+), 123 Zeilen entfernt(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 66a2ea3..6bea6e7 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -195,9 +195,9 @@ static int console_may_schedule;
 
 enum log_flags {
 	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
-	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_NEWLINE	= 2,	/* end fragment with a newline */
+	LOG_PREFIX	= 4,	/* start fragment with a newline */
+	LOG_CONT	= 8,	/* fragment continues previous fragmet */
 };
 
 struct log {
@@ -220,7 +220,6 @@ static DEFINE_RAW_SPINLOCK(logbuf_lock);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
 static u32 syslog_idx;
-static enum log_flags syslog_prev;
 static size_t syslog_partial;
 
 /* index and sequence number of the first record stored in the buffer */
@@ -234,7 +233,6 @@ static u32 log_next_idx;
 /* the next printk record to write to the console */
 static u64 console_seq;
 static u32 console_idx;
-static enum log_flags console_prev;
 
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
@@ -366,7 +364,6 @@ static void log_store(int facility, int level,
 struct devkmsg_user {
 	u64 seq;
 	u32 idx;
-	enum log_flags prev;
 	struct mutex lock;
 	char buf[8192];
 };
@@ -481,16 +478,14 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	 * 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)))
+	if (msg->flags & LOG_CONT)
 		cont = '+';
+	else if (!(msg->flags & LOG_NEWLINE))
+		cont = 'c';
 
 	len = sprintf(user->buf, "%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++) {
@@ -878,24 +873,19 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 	return len;
 }
 
-static size_t msg_print_text(const struct log *msg, enum log_flags prev,
+static size_t msg_print_text(const struct log *msg,
 			     bool syslog, char *buf, size_t size)
 {
 	const char *text = log_text(msg);
 	size_t text_size = msg->text_len;
-	bool prefix = true;
-	bool newline = true;
+	bool prefix = !(msg->flags & LOG_CONT);
+	bool newline = msg->flags & LOG_NEWLINE;
 	size_t len = 0;
 
-	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
-		prefix = false;
-
-	if (msg->flags & LOG_CONT) {
-		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
-			prefix = false;
-
-		if (!(msg->flags & LOG_NEWLINE))
-			newline = false;
+	if (msg->flags & LOG_PREFIX) {
+		if (buf)
+			buf[len] = '\n';
+		len++;
 	}
 
 	do {
@@ -956,7 +946,6 @@ static int syslog_print(char __user *buf, int size)
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
-			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (syslog_seq == log_next_seq) {
@@ -966,13 +955,12 @@ static int syslog_print(char __user *buf, int size)
 
 		skip = syslog_partial;
 		msg = log_from_idx(syslog_idx);
-		n = msg_print_text(msg, syslog_prev, true, text,
+		n = msg_print_text(msg, true, text,
 				   LOG_LINE_MAX + PREFIX_MAX);
 		if (n - syslog_partial <= size) {
 			/* message fits into buffer, move forward */
 			syslog_idx = log_next(syslog_idx);
 			syslog_seq++;
-			syslog_prev = msg->flags;
 			n -= syslog_partial;
 			syslog_partial = 0;
 		} else if (!len){
@@ -1015,7 +1003,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		u64 next_seq;
 		u64 seq;
 		u32 idx;
-		enum log_flags prev;
 
 		if (clear_seq < log_first_seq) {
 			/* messages are gone, move to first available one */
@@ -1029,12 +1016,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		 */
 		seq = clear_seq;
 		idx = clear_idx;
-		prev = 0;
 		while (seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len += msg_print_text(msg, prev, true, NULL, 0);
-			prev = msg->flags;
+			len += msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -1042,12 +1027,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		/* move first record forward until length fits into the buffer */
 		seq = clear_seq;
 		idx = clear_idx;
-		prev = 0;
 		while (len > size && seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len -= msg_print_text(msg, prev, true, NULL, 0);
-			prev = msg->flags;
+			len -= msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -1056,12 +1039,11 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		next_seq = log_next_seq;
 
 		len = 0;
-		prev = 0;
 		while (len >= 0 && seq < next_seq) {
 			struct log *msg = log_from_idx(idx);
 			int textlen;
 
-			textlen = msg_print_text(msg, prev, true, text,
+			textlen = msg_print_text(msg, true, text,
 						 LOG_LINE_MAX + PREFIX_MAX);
 			if (textlen < 0) {
 				len = textlen;
@@ -1069,7 +1051,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 			}
 			idx = log_next(idx);
 			seq++;
-			prev = msg->flags;
 
 			raw_spin_unlock_irq(&logbuf_lock);
 			if (copy_to_user(buf + len, text, textlen))
@@ -1082,7 +1063,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 				/* messages are gone, move to next one */
 				seq = log_first_seq;
 				idx = log_first_idx;
-				prev = 0;
 			}
 		}
 	}
@@ -1187,7 +1167,6 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
-			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (from_file) {
@@ -1200,16 +1179,14 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 		} else {
 			u64 seq = syslog_seq;
 			u32 idx = syslog_idx;
-			enum log_flags prev = syslog_prev;
 
 			error = 0;
 			while (seq < log_next_seq) {
 				struct log *msg = log_from_idx(idx);
 
-				error += msg_print_text(msg, prev, true, NULL, 0);
+				error += msg_print_text(msg, true, NULL, 0);
 				idx = log_next(idx);
 				seq++;
-				prev = msg->flags;
 			}
 			error -= syslog_partial;
 		}
@@ -1391,9 +1368,10 @@ static struct cont {
 	u8 facility;			/* log level of first message */
 	enum log_flags flags;		/* prefix, newline flags */
 	bool flushed:1;			/* buffer sealed and committed */
-} cont;
+				const char *dict; u16 dict_len;
+} cont = { .flags = LOG_NEWLINE, };
 
-static void cont_flush(enum log_flags flags)
+static void cont_flush(void)
 {
 	if (cont.flushed)
 		return;
@@ -1403,52 +1381,110 @@ static void cont_flush(enum log_flags flags)
 	if (cont.cons) {
 		/*
 		 * If a fragment of this line was directly flushed to the
-		 * console; wait for the console to pick up the rest of the
+		 * console, wait for the console to pick up the rest of the
 		 * line. LOG_NOCONS suppresses a duplicated output.
 		 */
-		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+		log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
 			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-		cont.flags = flags;
+		if (cont.flags & LOG_NEWLINE)
+			cont.buf[cont.len++] = '\n';
 		cont.flushed = true;
 	} else {
 		/*
 		 * If no fragment of this line ever reached the console,
 		 * just submit it to the store and free the buffer.
 		 */
-		log_store(cont.facility, cont.level, flags, 0,
+		log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
 			  NULL, 0, cont.buf, cont.len);
 		cont.len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static void cont_add(int facility, int level, enum log_flags flags,
+				const char *dict, u16 dict_len,
+				const char *text, size_t text_len)
 {
-	if (cont.len && cont.flushed)
-		return false;
+	/* BUG_ON(flags & ~(LOG_NEWLINE | LOG_PREFIX)); */
 
-	if (cont.len + len > sizeof(cont.buf)) {
-		/* the line gets too long, split it up in separate records */
-		cont_flush(LOG_CONT);
-		return false;
+	if (cont.len && !cont.flushed) {
+		/*
+		 * previous fragment still buffered, let's have a look
+		 * at it
+		 */
+		/* BUG_ON(cont.flags & LOG_NEWLINE); */
+
+		if (cont.owner != current || cont.facility != facility ||
+		    flags & LOG_PREFIX) {
+			/*
+			 * current fragment does not continue previous
+			 * fragment
+			 */
+			cont.flags |= LOG_NEWLINE;
+			cont_flush();
+		} else if (cont.len + text_len + 1 > sizeof(cont.buf)) {
+			/*
+			 * current fragment continues previous fragment,
+			 * but we cannot merge them as the result would be
+			 * too long
+			 */
+			flags |= LOG_CONT;
+			cont_flush();
+		} else {
+			/*
+			 * current fragment continues previous fragment
+			 * and we are able to merge them
+			 */
+			memcpy(cont.buf + cont.len, text, text_len);
+			cont.len += text_len;
+			cont.flags |= flags;
+			if (cont.len > (sizeof(cont.buf) * 80) / 100 ||
+						cont.flags & LOG_NEWLINE)
+				cont_flush();
+			return;
+		}
 	}
 
-	if (!cont.len) {
-		cont.facility = facility;
-		cont.level = level;
-		cont.owner = current;
-		cont.ts_nsec = local_clock();
-		cont.flags = 0;
-		cont.cons = 0;
-		cont.flushed = false;
+	if (cont.owner == current && cont.facility == facility &&
+	    !(cont.flags & LOG_NEWLINE) && !(flags & LOG_PREFIX)) {
+		/* current fragment continues previous fragment */
+		flags |= LOG_CONT;
+		level = cont.level;
 	}
 
-	memcpy(cont.buf + cont.len, text, len);
-	cont.len += len;
+	flags &= ~LOG_PREFIX;
+	if (!(cont.flags & LOG_NEWLINE) && !(flags & LOG_CONT)) {
+		/* previous fragment missed a newline */
+		flags |= LOG_PREFIX;
+	}
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(LOG_CONT);
+	cont.flags = flags;
+	cont.owner = current;
+	cont.facility = facility;
+	cont.level = level;
 
-	return true;
+	if ((cont.len && cont.flushed) || (flags & LOG_NEWLINE) ||
+	    (text_len > (sizeof(cont.buf) * 80) / 100)) {
+		/*
+		 *    cont.buf + cont.cons + cont.len still occupied
+		 * OR current fragment is self-contained
+		 * OR current fragment is too long
+		 *
+		 * store fragment directly
+		 */
+		log_store(facility, level, flags, 0,
+				  dict, dict_len, text, text_len);
+		return;
+	}
+
+	/* BUG_ON(cont.len); */
+	/* BUG_ON(flags & LOG_NEWLINE); */
+
+	/* buffer is empty, buffer current fragment */
+	memcpy(cont.buf, text, text_len);
+	cont.len = text_len;
+	cont.ts_nsec = local_clock();
+	cont.cons = 0;
+	cont.flushed = false;
 }
 
 static size_t cont_print_text(char *text, size_t size)
@@ -1456,8 +1492,10 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t textlen = 0;
 	size_t len;
 
-	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+	if (cont.cons == 0 && !(cont.flags & LOG_CONT)) {
+		if (cont.flags & LOG_PREFIX)
+			text[textlen++] = '\n';
+		textlen += print_time(cont.ts_nsec, text + textlen);
 		size -= textlen;
 	}
 
@@ -1471,8 +1509,6 @@ static size_t cont_print_text(char *text, size_t size)
 	}
 
 	if (cont.flushed) {
-		if (cont.flags & LOG_NEWLINE)
-			text[textlen++] = '\n';
 		/* got everything, release buffer */
 		cont.len = 0;
 	}
@@ -1528,7 +1564,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		recursion_bug = 0;
 		printed_len += strlen(recursion_msg);
 		/* emit KERN_CRIT message */
-		log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
+		cont_add(0, 2, LOG_PREFIX | LOG_NEWLINE,
 			  NULL, 0, recursion_msg, printed_len);
 	}
 
@@ -1555,7 +1591,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 				if (level == -1)
 					level = kern_level - '0';
 			case 'd':	/* KERN_DEFAULT */
-				lflags |= LOG_PREFIX;
+				if (level == -1)
+					level = default_message_loglevel;
 			case 'c':	/* KERN_CONT */
 				break;
 			}
@@ -1566,41 +1603,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	if (level == -1)
 		level = default_message_loglevel;
+	else
+		lflags |= LOG_PREFIX;
 
 	if (dict)
-		lflags |= LOG_PREFIX|LOG_NEWLINE;
+		lflags |= LOG_PREFIX | LOG_NEWLINE;
 
-	if (!(lflags & LOG_NEWLINE)) {
-		/*
-		 * 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_flush(LOG_NEWLINE);
+	cont_add(facility, level, lflags, dict, dictlen, text, text_len);
 
-		/* buffer line if possible, otherwise store it right away */
-		if (!cont_add(facility, level, text, text_len))
-			log_store(facility, level, lflags | LOG_CONT, 0,
-				  dict, dictlen, text, text_len);
-	} else {
-		bool stored = false;
-
-		/*
-		 * If an earlier newline was missing and it was the same task,
-		 * either merge it with the current buffer and flush, or if
-		 * there was a race with interrupts (prefix == true) then just
-		 * flush it out and store this line separately.
-		 */
-		if (cont.len && cont.owner == current) {
-			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
-			cont_flush(LOG_NEWLINE);
-		}
-
-		if (!stored)
-			log_store(facility, level, lflags, 0,
-				  dict, dictlen, text, text_len);
-	}
 	printed_len += text_len;
 
 	/*
@@ -1694,11 +1704,9 @@ static u64 syslog_seq;
 static u32 syslog_idx;
 static u64 console_seq;
 static u32 console_idx;
-static enum log_flags syslog_prev;
 static u64 log_first_seq;
 static u32 log_first_idx;
 static u64 log_next_seq;
-static enum log_flags console_prev;
 static struct cont {
 	size_t len;
 	size_t cons;
@@ -1708,7 +1716,7 @@ static struct cont {
 static struct 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 size_t msg_print_text(const struct log *msg, enum log_flags prev,
+static size_t msg_print_text(const struct log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
 
@@ -2058,7 +2066,6 @@ again:
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
-			console_prev = 0;
 		}
 skip:
 		if (console_seq == log_next_seq)
@@ -2078,16 +2085,14 @@ skip:
 			 * will properly dump everything later.
 			 */
 			msg->flags &= ~LOG_NOCONS;
-			console_prev = msg->flags;
 			goto skip;
 		}
 
 		level = msg->level;
-		len = msg_print_text(msg, console_prev, false,
+		len = msg_print_text(msg, false,
 				     text, sizeof(text));
 		console_idx = log_next(console_idx);
 		console_seq++;
-		console_prev = msg->flags;
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
@@ -2350,7 +2355,6 @@ void register_console(struct console *newcon)
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
-		console_prev = syslog_prev;
 		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 		/*
 		 * We're about to replay the log buffer.  Only do this to the
@@ -2642,7 +2646,7 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
 		goto out;
 
 	msg = log_from_idx(dumper->cur_idx);
-	l = msg_print_text(msg, 0, syslog, line, size);
+	l = msg_print_text(msg, syslog, line, size);
 
 	dumper->cur_idx = log_next(dumper->cur_idx);
 	dumper->cur_seq++;
@@ -2711,7 +2715,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	u32 idx;
 	u64 next_seq;
 	u32 next_idx;
-	enum log_flags prev;
 	size_t l = 0;
 	bool ret = false;
 
@@ -2734,27 +2737,23 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	/* calculate length of entire buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
-	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, prev, true, NULL, 0);
+		l += msg_print_text(msg, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	/* move first record forward until length fits into the buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
-	prev = 0;
 	while (l > size && seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l -= msg_print_text(msg, prev, true, NULL, 0);
+		l -= msg_print_text(msg, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	/* last message in next interation */
@@ -2762,14 +2761,12 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	next_idx = idx;
 
 	l = 0;
-	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, prev, syslog, buf + l, size - l);
+		l += msg_print_text(msg, syslog, buf + l, size - l);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	dumper->next_seq = next_seq;
-- 
1.7.12

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Fri, Sep 28, 2012 at 10:25 AM, Jan H. Schönherr
<schnhrr@cs.tu-berlin.de> wrote:

>> If really, really everything passes through vprintk_emit()
>> then we could keep all info about the previous message
>> there and definitely decide whether the current message continues
>> the previous one.
>>
>> Then, we wouldn't need to track the previous flags everywhere.
>
> Here is a patch that does just that.
>
> Seems to work. And it makes the code easier to understand.
> A more detailed description is below.

> -       if (!(lflags & LOG_NEWLINE)) {
> -               /*
> -                * 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_flush(LOG_NEWLINE);
> +       cont_add(facility, level, lflags, dict, dictlen, text, text_len);

That fails the racing task test, and a cont user that was nicely
merged before is now all in separate records.

It seems, unconditionally using the cont buffer like in your patch,
for all incoming messages just makes the entire cont merge buffer
dance useless when it comes to races.

The current behaviour has the advantage, that non-cont users will not
race against a cont user (which is like 99.x% of the races I expect).
The cont buffer is currently only used when we expect a cont user,
non-cont users happening in the middle of a cont-print will not flush
the and disturb the cont buffer.

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Am 28.09.2012 16:34, schrieb Kay Sievers:
> On Fri, Sep 28, 2012 at 10:25 AM, Jan H. Schönherr
> That fails the racing task test, and a cont user that was nicely
> merged before is now all in separate records.

I guess, I need to extend my test cases. Do you have something
ready that I could use?

> It seems, unconditionally using the cont buffer like in your patch,
> for all incoming messages just makes the entire cont merge buffer
> dance useless when it comes to races.

I see. :(

> The current behaviour has the advantage, that non-cont users will not
> race against a cont user (which is like 99.x% of the races I expect).
> The cont buffer is currently only used when we expect a cont user,
> non-cont users happening in the middle of a cont-print will not flush
> the and disturb the cont buffer.

That should be fixable by using a second set of flags, owner, and so on
within vprintk... I still think, that getting rid of of remotely tracking
the flags is worth something.

(Ideally, we should also be able to correctly reassemble multiple
simultaneous cont users. But that it still a bit out of scope I think.)

Given that I'm able to fix the racing case, would you be in favor of
this approach, or should we stick to the earlier version?

Regards
Jan

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Fri, Sep 28, 2012 at 4:49 PM, "Jan H. Schönherr"
<schnhrr@cs.tu-berlin.de> wrote:
> Am 28.09.2012 16:34, schrieb Kay Sievers:
>> On Fri, Sep 28, 2012 at 10:25 AM, Jan H. Schönherr

>> The current behaviour has the advantage, that non-cont users will not
>> race against a cont user (which is like 99.x% of the races I expect).
>> The cont buffer is currently only used when we expect a cont user,
>> non-cont users happening in the middle of a cont-print will not flush
>> the and disturb the cont buffer.
>
> That should be fixable by using a second set of flags, owner, and so on
> within vprintk... I still think, that getting rid of of remotely tracking
> the flags is worth something.

Sure, sounds fine in theory.

> (Ideally, we should also be able to correctly reassemble multiple
> simultaneous cont users. But that it still a bit out of scope I think.)

Yeah, that's messy, and not really worth it, I guess. We enter per-cpu
data and in_interrupt() territory with that, which is not really worth
the complexity for cont printing. The one separated cont buffer works
pretty well already.

> Given that I'm able to fix the racing case, would you be in favor of
> this approach, or should we stick to the earlier version?

I'm open to everything that makes sense. Let's see how it looks and we
can decide when we have something that passes the tests.

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Fri, Sep 28, 2012 at 4:56 PM, Kay Sievers <kay@vrfy.org> wrote:
> On Fri, Sep 28, 2012 at 4:49 PM, "Jan H. Schönherr"

>> Given that I'm able to fix the racing case, would you be in favor of
>> this approach, or should we stick to the earlier version?
>
> I'm open to everything that makes sense. Let's see how it looks and we
> can decide when we have something that passes the tests.

Jan,
any updates, did you try something else?
Or should we merge the first version for now?

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Am 08.10.2012 21:24, schrieb Kay Sievers:
> On Fri, Sep 28, 2012 at 4:56 PM, Kay Sievers <kay@vrfy.org> wrote:
>> On Fri, Sep 28, 2012 at 4:49 PM, "Jan H. Schönherr"
> 
>>> Given that I'm able to fix the racing case, would you be in favor of
>>> this approach, or should we stick to the earlier version?
>>
>> I'm open to everything that makes sense. Let's see how it looks and we
>> can decide when we have something that passes the tests.
> 
> Jan,
> any updates, did you try something else?
> Or should we merge the first version for now?

I'm working on it, though I cannot spend as much time as I want. :)

My current version does mostly well for race-printk()s, now. But
there's still one issue to resolve and some polishing to do.

If we can afford to wait a little longer, we might get a nicer
solution (and avoid a possible mostly-revert later).

Regards
Jan

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Mon, Oct 8, 2012 at 9:54 PM, "Jan H. Schönherr"
<schnhrr@cs.tu-berlin.de> wrote:
> Am 08.10.2012 21:24, schrieb Kay Sievers:
>> On Fri, Sep 28, 2012 at 4:56 PM, Kay Sievers <kay@vrfy.org> wrote:
>>> On Fri, Sep 28, 2012 at 4:49 PM, "Jan H. Schönherr"
>>
>>>> Given that I'm able to fix the racing case, would you be in favor of
>>>> this approach, or should we stick to the earlier version?
>>>
>>> I'm open to everything that makes sense. Let's see how it looks and we
>>> can decide when we have something that passes the tests.
>>
>> Jan,
>> any updates, did you try something else?
>> Or should we merge the first version for now?
>
> I'm working on it, though I cannot spend as much time as I want. :)
>
> My current version does mostly well for race-printk()s, now. But
> there's still one issue to resolve and some polishing to do.
>
> If we can afford to wait a little longer, we might get a nicer
> solution (and avoid a possible mostly-revert later).

Sure, no hurry, I was just going through my TODO emails. :)

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Joe Perches]

On Mon, 2012-10-08 at 21:54 +0200, "Jan H. Schönherr" wrote:
> Am 08.10.2012 21:24, schrieb Kay Sievers:
> > On Fri, Sep 28, 2012 at 4:56 PM, Kay Sievers <kay@vrfy.org> wrote:
> >> On Fri, Sep 28, 2012 at 4:49 PM, "Jan H. Schönherr"
> >>> Given that I'm able to fix the racing case, would you be in favor of
> >>> this approach, or should we stick to the earlier version?
> >>
> >> I'm open to everything that makes sense. Let's see how it looks and we
> >> can decide when we have something that passes the tests.
[]
> > any updates, did you try something else?
> > Or should we merge the first version for now?
[]
> My current version does mostly well for race-printk()s, now. But
> there's still one issue to resolve and some polishing to do.
> 
> If we can afford to wait a little longer, we might get a nicer
> solution (and avoid a possible mostly-revert later).

I've also got a large refactoring patch series to printk.c
(move and declutter) I was going to submit post rc-1.

No doubt there'll be several conflicts there too.

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Kay Sievers]

On Mon, Oct 8, 2012 at 9:56 PM, Kay Sievers <kay@vrfy.org> wrote:
> On Mon, Oct 8, 2012 at 9:54 PM, "Jan H. Schönherr"

>>> Jan,
>>> any updates, did you try something else?
>>> Or should we merge the first version for now?
>>
>> I'm working on it, though I cannot spend as much time as I want. :)
>>
>> My current version does mostly well for race-printk()s, now. But
>> there's still one issue to resolve and some polishing to do.
>>
>> If we can afford to wait a little longer, we might get a nicer
>> solution (and avoid a possible mostly-revert later).
>
> Sure, no hurry, I was just going through my TODO emails. :)

My TODO is nagging me again. :)

Any updates? No problems if not, but we should merge the current
version then, I think.

Thanks,
Kay

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Am 02.11.2012 04:53, schrieb Kay Sievers:
> On Mon, Oct 8, 2012 at 9:56 PM, Kay Sievers <kay@vrfy.org> wrote:
>> On Mon, Oct 8, 2012 at 9:54 PM, "Jan H. Schönherr"
> 
>>>> Jan,
>>>> any updates, did you try something else?
>>>> Or should we merge the first version for now?
>>>
>>> I'm working on it, though I cannot spend as much time as I want. :)
>>>
>>> My current version does mostly well for race-printk()s, now. But
>>> there's still one issue to resolve and some polishing to do.
>>>
>>> If we can afford to wait a little longer, we might get a nicer
>>> solution (and avoid a possible mostly-revert later).
>>
>> Sure, no hurry, I was just going through my TODO emails. :)
> 
> My TODO is nagging me again. :)
> 
> Any updates? No problems if not, but we should merge the current
> version then, I think.
> 

Then let's take the first version. :)

Thanks
Jan

Re: [PATCH] printk: drop ambiguous LOG_CONT flag

[Greg Kroah-Hartman]

On Fri, Nov 02, 2012 at 11:37:10PM +0100, "Jan H. Schönherr" wrote:
> Am 02.11.2012 04:53, schrieb Kay Sievers:
> > On Mon, Oct 8, 2012 at 9:56 PM, Kay Sievers <kay@vrfy.org> wrote:
> >> On Mon, Oct 8, 2012 at 9:54 PM, "Jan H. Schönherr"
> > 
> >>>> Jan,
> >>>> any updates, did you try something else?
> >>>> Or should we merge the first version for now?
> >>>
> >>> I'm working on it, though I cannot spend as much time as I want. :)
> >>>
> >>> My current version does mostly well for race-printk()s, now. But
> >>> there's still one issue to resolve and some polishing to do.
> >>>
> >>> If we can afford to wait a little longer, we might get a nicer
> >>> solution (and avoid a possible mostly-revert later).
> >>
> >> Sure, no hurry, I was just going through my TODO emails. :)
> > 
> > My TODO is nagging me again. :)
> > 
> > Any updates? No problems if not, but we should merge the current
> > version then, I think.
> > 
> 
> Then let's take the first version. :)

Someone needs to resend it then, as it's lost to the archives of my
inbox, sorry.

greg k-h

[PATCH resend] printk: drop ambiguous LOG_CONT flag

[Jan H. Schönherr]

From: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>

The meaning of LOG_CONT is unclear, i. e., whether a message is a starting,
ending, or middle fragment. Unfortunately, this cannot be inferred from
the LOG_PREFIX and LOG_NEWLINE flags, as they are not always kept.
Furthermore, in some cases LOG_CONT is set, although it is unknown if
there will be a continuation. This leads to wrongly concatenated output.

Fix this by dropping LOG_CONT and rely on LOG_PREFIX and LOG_NEWLINE to
distinguish the type of fragment. That is, if LOG_PREFIX is set, this
fragment does not continue the previous fragment. And if LOG_NEWLINE is
set, this fragment is not continued by the next fragment.

(Unfortunately, we still have to look at the previous fragment to catch the
case of an unset LOG_PREFIX on this fragment, but a set LOG_NEWLINE on
the previous fragment.)

Tested-By: Kay Sievers <kay@vrfy.org>
Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
Against linux-next from 20121102, added Kay's tested-by.
---
 kernel/printk.c | 57 +++++++++++++++++++++++++++++++++------------------------
 1 file changed, 33 insertions(+), 24 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 22e070f..e8e4e67 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -203,7 +203,6 @@ enum log_flags {
 	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
 	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 */
 };
 
 struct log {
@@ -487,10 +486,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	 * 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))
+	if (!(msg->flags & LOG_NEWLINE) && msg->flags & LOG_PREFIX)
 		cont = 'c';
-	else if ((msg->flags & LOG_CONT) ||
-		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
+	else if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		cont = '+';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
@@ -893,15 +891,17 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 	bool newline = true;
 	size_t len = 0;
 
-	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+	if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		prefix = false;
 
-	if (msg->flags & LOG_CONT) {
-		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
-			prefix = false;
+	if (!(msg->flags & LOG_NEWLINE))
+		newline = false;
 
-		if (!(msg->flags & LOG_NEWLINE))
-			newline = false;
+	if (!(prev & LOG_NEWLINE) && prefix) {
+		if (buf)
+			buf[len++] = '\n';
+		else
+			len++;
 	}
 
 	do {
@@ -1406,35 +1406,36 @@ static void cont_flush(enum log_flags flags)
 	if (cont.len == 0)
 		return;
 
+	cont.flags |= flags;
 	if (cont.cons) {
 		/*
 		 * 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.
 		 */
-		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+		log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
 			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-		cont.flags = flags;
 		cont.flushed = true;
 	} else {
 		/*
 		 * If no fragment of this line ever reached the console,
 		 * just submit it to the store and free the buffer.
 		 */
-		log_store(cont.facility, cont.level, flags, 0,
+		log_store(cont.facility, cont.level, cont.flags, 0,
 			  NULL, 0, cont.buf, cont.len);
 		cont.len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, enum log_flags flags,
+		     const char *text, size_t len)
 {
 	if (cont.len && cont.flushed)
 		return false;
 
 	if (cont.len + len > sizeof(cont.buf)) {
 		/* the line gets too long, split it up in separate records */
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 		return false;
 	}
 
@@ -1443,7 +1444,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.level = level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
-		cont.flags = 0;
+		cont.flags = flags;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
@@ -1452,7 +1453,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	cont.len += len;
 
 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 
 	return true;
 }
@@ -1462,8 +1463,11 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t textlen = 0;
 	size_t len;
 
-	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+	if (cont.cons == 0 && (console_prev & LOG_NEWLINE ||
+						cont.flags & LOG_PREFIX)) {
+		if (!(console_prev & LOG_NEWLINE))
+			text[textlen++] = '\n';
+		textlen += print_time(cont.ts_nsec, text + textlen);
 		size -= textlen;
 	}
 
@@ -1581,12 +1585,16 @@ 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_flush(LOG_NEWLINE);
+		if (cont.len) {
+			if (cont.owner != current)
+				lflags |= LOG_PREFIX;
+			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))
-			log_store(facility, level, lflags | LOG_CONT, 0,
+		if (!cont_add(facility, level, lflags, text, text_len))
+			log_store(facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	} else {
 		bool stored = false;
@@ -1599,7 +1607,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (cont.len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
+				stored = cont_add(facility, level, lflags,
+							text, text_len);
 			cont_flush(LOG_NEWLINE);
 		}
 
-- 
1.8.0.316.g291341c.dirty

Re: [PATCH resend] printk: drop ambiguous LOG_CONT flag

["Jan H. Schönherr"]

Hi Greg.

This still needs a small fix, see below.

Am 03.11.2012 22:12, schrieb Jan H. Schönherr:
> From: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
> 
> The meaning of LOG_CONT is unclear, i. e., whether a message is a starting,
> ending, or middle fragment. Unfortunately, this cannot be inferred from
> the LOG_PREFIX and LOG_NEWLINE flags, as they are not always kept.
> Furthermore, in some cases LOG_CONT is set, although it is unknown if
> there will be a continuation. This leads to wrongly concatenated output.
> 
> Fix this by dropping LOG_CONT and rely on LOG_PREFIX and LOG_NEWLINE to
> distinguish the type of fragment. That is, if LOG_PREFIX is set, this
> fragment does not continue the previous fragment. And if LOG_NEWLINE is
> set, this fragment is not continued by the next fragment.
> 
> (Unfortunately, we still have to look at the previous fragment to catch the
> case of an unset LOG_PREFIX on this fragment, but a set LOG_NEWLINE on
> the previous fragment.)
> 
> Tested-By: Kay Sievers <kay@vrfy.org>
> Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
> ---
> Against linux-next from 20121102, added Kay's tested-by.
> ---
>  kernel/printk.c | 57 +++++++++++++++++++++++++++++++++------------------------
>  1 file changed, 33 insertions(+), 24 deletions(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 22e070f..e8e4e67 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c

[...]

> @@ -1581,12 +1585,16 @@ 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_flush(LOG_NEWLINE);
> +		if (cont.len) {

This line should have been:
+		if (cont.len && !cont.flushed) {

The effect of this is that we now avoid to add a superfluous newline
over and over (due to setting LOG_PREFIX), when the cont buffer has been
flushed but not yet printed.

> +			if (cont.owner != current)
> +				lflags |= LOG_PREFIX;
> +			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))
> -			log_store(facility, level, lflags | LOG_CONT, 0,
> +		if (!cont_add(facility, level, lflags, text, text_len))
> +			log_store(facility, level, lflags, 0,
>  				  dict, dictlen, text, text_len);
>  	} else {
>  		bool stored = false;
> @@ -1599,7 +1607,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		 */
>  		if (cont.len && cont.owner == current) {

For symmetry reasons, the "if" here could use the same change. But here it
does not really matter as currently cont_add() and cont_flush() are NOPs when
cont.flushed is set.

>  			if (!(lflags & LOG_PREFIX))
> -				stored = cont_add(facility, level, text, text_len);
> +				stored = cont_add(facility, level, lflags,
> +							text, text_len);
>  			cont_flush(LOG_NEWLINE);
>  		}

As I've not yet seen this patch turn up anywhere, I'm preparing a v2 of this
together with a couple of other patches that are now more or less ready.

Regards
Jan