[PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[Yoshihiro YUNOMAE]

Hi,

This patch set fixes message continuation breakage involved with structured
printk. A SCSI driver may output two continuation error messages like
    scmd_printk("foo");
    printf("bar\n");
Here, scmd_printk() is structured printk with key/value dictionary information.
Structured printk became to forcibly start a new line from commit c313af14, so
those SCSI continuation error messages are divided as follows:
    [1234.567890] sd 2:0:0:0: [sdb] foo
    [1234.567893] bar                    <---- Divided
However, the SCSI driver may expect following continuation error messages:
    [1234.567893] sd 2:0:0:0: [sdb] foo bar
When user tools handle the error messages, that divided message will create
some inconveniences.

This patch set makes structured printk with dictionary information not start a
new line. Moreover, when multiple structured printk messages are continued,
this patch outputs those multiple dictionary information when we read /dev/kmsg.

Thanks!

---

Yoshihiro YUNOMAE (2):
      printk: Add dictionary information in structure cont
      printk: Delete LOG_NEWLINE flag for structured printk


 kernel/printk/printk.c |   70 +++++++++++++++++++++++++++++++-----------------
 1 file changed, 45 insertions(+), 25 deletions(-)

-- 
Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: yoshihiro.yunomae.ez@hitachi.com

[PATCH 1/2] printk: Add dictionary information in structure cont

[Yoshihiro YUNOMAE]

Add dictionary information in structure cont.
Dictionary information is added when a driver uses structured printk, and the
information is shown in /dev/kmsg. Current kernel directly stores the
information to log_buf. This patch stores the dict information in structure cont
first, then the information in cont is stored to log_buf.

Signed-off-by: Yoshihiro YUNOMAE <yoshihiro.yunomae.ez@hitachi.com>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Joe Perches <joe@perches.com>
Cc: Tejun Heo <tj@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: linux-kernel@vger.kernel.org
---
 kernel/printk/printk.c |   70 ++++++++++++++++++++++++++++++++----------------
 1 file changed, 47 insertions(+), 23 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index be7c86b..c3662e6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1391,8 +1391,10 @@ static inline void printk_delay(void)
  * reached the console in case of a kernel crash.
  */
 static struct cont {
-	char buf[LOG_LINE_MAX];
-	size_t len;			/* length == 0 means unused buffer */
+	char text[LOG_LINE_MAX];
+	size_t text_len;		/* length == 0 means unused buffer */
+	char dict[LOG_LINE_MAX];	/* stores dict */
+	size_t dict_len;		/* 0 means dict is unstored */
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
 	u64 ts_nsec;			/* time of first print */
@@ -1406,7 +1408,7 @@ static void cont_flush(enum log_flags flags)
 {
 	if (cont.flushed)
 		return;
-	if (cont.len == 0)
+	if (cont.text_len == 0)
 		return;
 
 	if (cont.cons) {
@@ -1416,7 +1418,7 @@ static void cont_flush(enum log_flags flags)
 		 * line. LOG_NOCONS suppresses a duplicated output.
 		 */
 		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
-			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+			  cont.ts_nsec, NULL, 0, cont.text, cont.text_len);
 		cont.flags = flags;
 		cont.flushed = true;
 	} else {
@@ -1425,23 +1427,32 @@ static void cont_flush(enum log_flags flags)
 		 * just submit it to the store and free the buffer.
 		 */
 		log_store(cont.facility, cont.level, flags, 0,
-			  NULL, 0, cont.buf, cont.len);
-		cont.len = 0;
+			  NULL, 0, cont.text, cont.text_len);
+		cont.text_len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static void cont_dict_add(const char *dict, size_t dict_len)
 {
-	if (cont.len && cont.flushed)
+	if (cont.dict_len + dict_len > sizeof(cont.dict))
+		return;
+
+	memcpy(cont.dict + cont.dict_len, dict, dict_len);
+	cont.dict_len += dict_len;
+}
+
+static bool cont_add(int facility, int level, const char *text, size_t text_len)
+{
+	if (cont.text_len && cont.flushed)
 		return false;
 
-	if (cont.len + len > sizeof(cont.buf)) {
+	if (cont.text_len + text_len > sizeof(cont.text)) {
 		/* the line gets too long, split it up in separate records */
 		cont_flush(LOG_CONT);
 		return false;
 	}
 
-	if (!cont.len) {
+	if (!cont.text_len) {
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
@@ -1451,10 +1462,10 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.flushed = false;
 	}
 
-	memcpy(cont.buf + cont.len, text, len);
-	cont.len += len;
+	memcpy(cont.text + cont.text_len, text, text_len);
+	cont.text_len += text_len;
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
+	if (cont.text_len > (sizeof(cont.text) * 80) / 100)
 		cont_flush(LOG_CONT);
 
 	return true;
@@ -1470,20 +1481,20 @@ static size_t cont_print_text(char *text, size_t size)
 		size -= textlen;
 	}
 
-	len = cont.len - cont.cons;
+	len = cont.text_len - cont.cons;
 	if (len > 0) {
 		if (len+1 > size)
 			len = size-1;
-		memcpy(text + textlen, cont.buf + cont.cons, len);
+		memcpy(text + textlen, cont.text + cont.cons, len);
 		textlen += len;
-		cont.cons = cont.len;
+		cont.cons = cont.text_len;
 	}
 
 	if (cont.flushed) {
 		if (cont.flags & LOG_NEWLINE)
 			text[textlen++] = '\n';
 		/* got everything, release buffer */
-		cont.len = 0;
+		cont.text_len = 0;
 	}
 	return textlen;
 }
@@ -1576,21 +1587,29 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (level == -1)
 		level = default_message_loglevel;
 
-	if (dict)
+	if (dict) {
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
+		/* Another task is trying to output a message */
+		if (cont.text_len && cont.owner != current)
+			cont_flush(LOG_NEWLINE);
+
+		cont_dict_add(dict, dictlen);
+	}
+
 	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))
+		if (cont.text_len &&
+		    (lflags & LOG_PREFIX || cont.owner != current))
 			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,
-				  dict, dictlen, text, text_len);
+				  NULL, 0, text, text_len);
 	} else {
 		bool stored = false;
 
@@ -1600,7 +1619,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * 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 (cont.text_len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text, text_len);
 			cont_flush(LOG_NEWLINE);
@@ -1608,7 +1627,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 		if (!stored)
 			log_store(facility, level, lflags, 0,
-				  dict, dictlen, text, text_len);
+				  cont.dict, cont.dict_len, text, text_len);
+		/*
+		 * Structured printk always starts a new line now, so clear
+		 * current dictionary information for next structured printk.
+		 */
+		cont.dict_len = 0;
 	}
 	printed_len += text_len;
 
@@ -1974,7 +1998,7 @@ static void console_cont_flush(char *text, size_t size)
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
-	if (!cont.len)
+	if (!cont.text_len)
 		goto out;
 
 	/*

Re: [PATCH 1/2] printk: Add dictionary information in structure cont

[Kay Sievers]

On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
<yoshihiro.yunomae.ez@hitachi.com> wrote:
> Add dictionary information in structure cont.
> Dictionary information is added when a driver uses structured printk, and the
> information is shown in /dev/kmsg. Current kernel directly stores the
> information to log_buf. This patch stores the dict information in structure cont
> first, then the information in cont is stored to log_buf.
>
> Signed-off-by: Yoshihiro YUNOMAE <yoshihiro.yunomae.ez@hitachi.com>
> Cc: Kay Sievers <kay@vrfy.org>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Joe Perches <joe@perches.com>
> Cc: Tejun Heo <tj@kernel.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: linux-kernel@vger.kernel.org

This is wrong. Please do not apply. Racy ontinuation lines and
strutured logging should not be mixed. Continuation lines are a nice
kernel hack for debugging, useful to have, but cannot be trusted by
userspace. The entire purpose of structured logging is to have
trustable atomic logging messages, the both facilities should not be
mixed.

Thanks,
Kay

[PATCH 2/2] printk: Delete LOG_NEWLINE flag for structured printk

[Yoshihiro YUNOMAE]

Delete LOG_NEWLINE flag for structured printk.
When structured printk is used, the next printk message is output in a new line
from patch c313af145b9bc4fb8e8e0c83b8cfc10e1b894a50. However, in a following
pseudo SCSI error test, the device information and the detail information are
divided:

-- Pseudo SCSI error test for current kernel
  # modprobe scsi_debug
  # cd /sys/bus/pseudo/drivers/scsi_debug
  # echo 2 > opts
  # dd if=/dev/sdb of=/dev/null 2> /dev/null

-- Result for current kernel
  # dmesg

[   17.842110] sd 2:0:0:0: [sdb] Attached SCSI disk
[   18.859098] sd 2:0:0:0: [sdb] Unhandled sense code
[   18.859103] sd 2:0:0:0: [sdb]
[   18.859106] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[   18.859108] sd 2:0:0:0: [sdb]
[   18.859110] Sense Key : Medium Error [current]
[   18.859114] Info fld=0x1234
[   18.859116] sd 2:0:0:0: [sdb]
[   18.859119] Add. Sense: Unrecovered read error
[   18.859122] sd 2:0:0:0: [sdb] CDB:
[   18.859124] Read(10): 28 00 00 00 11 e0 00 01 00 00

This is because the virtual scsi device outputs the error message as follows:
   scmd_printk(KERN_INFO, scmd, "DEVICE INFORMATION");
   printk("DETAIL INFORMATION");
   printk("\n");
Here, "DETAIL INFORMATION" expects scmd_printk() does not include "\n".
So, by applying this patch, the detail information is continued as follows:

  # dmesg

[   17.145085]  sdb: unknown partition table
[   17.149096] sd 2:0:0:0: [sdb] Attached SCSI disk
[   18.166090] sd 2:0:0:0: [sdb] Unhandled sense code
[   18.166095] sd 2:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[   18.166099] sd 2:0:0:0: [sdb]  Sense Key : Medium Error [current]
[   18.166104] Info fld=0x1234
[   18.166106] sd 2:0:0:0: [sdb]  Add. Sense: Unrecovered read error
[   18.166111] sd 2:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 11 e0 00 01 00 00

-- Multiple dictionary information

This patch combines multiple dictionary information.
We can read the combined dictionary information from /dev/kmsg.
<For example>
   printk("===========================================\n");
   printk("---- printk + printk_emit ----\n");
   printk("foo");
   printk_emit(0, -1, "dictdict",  8, "bar\n");

   printk("---- printk_emit + printk ----\n");
   printk_emit(0, -1, "DICTDICT",  8, "foo");
   printk("bar\n");

   printk("---- printk_emit + printk_emit ----\n");
   printk_emit(0, -1, "DICTDICT",  8, "foo");
   printk_emit(0, -1, "dictdict",  8, "bar\n");
   printk("===========================================\n");

<Result>
  4,248194,2045485319,-;===========================================
  4,248195,2045485321,-;---- printk + printk_emit ----
  4,248196,2045485322,-;foobar
   dictdict
  4,248197,2045485324,-;---- printk_emit + printk ----
  4,248198,2045485324,-;foobar
   DICTDICT
  4,248199,2045485325,-;---- printk_emit + printk_emit ----
  4,248200,2045485328,-;foobar
   DICTDICTdictdict
  4,248201,2045485329,-;===========================================

-- Dictionary information in a competition state

This patch does not delete or duplicate the dictionary information in a
competition state in SMP.
<For example>
 - Thread1
   printk("(AAAA");
   printk_emit(0, -1, "aaaaaaaa", 8, "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA");
   printk("AAAA)\n");

 - Thread2
   printk("(BBBB");
   printk_emit(0, -1, "bbbbbbbb", 8, "BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB");
   printk("BBBB)\n");

 - Thread3
   printk("(CCCC");
   printk_emit(0, -1, "cccccccc", 8, "CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC");
   printk("CCCC)");

<Result>
4,229312,1819040124,-;(BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB)
 bbbbbbbb
4,229313,1819042116,-;(AAAA
4,229314,1819042118,-;(BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
 bbbbbbbb
4,229315,1819042123,-;AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
 aaaaaaaa
4,229316,1819042126,-;BBBB)
4,229317,1819042129,-;(CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC)
 cccccccc
4,229318,1819044105,-;(AAAA
4,229319,1819044108,-;(CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC
 cccccccc
4,229320,1819044112,-;AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
 aaaaaaaa
4,229321,1819044115,-;CCCC)
4,229322,1819044118,-;(BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB)
 bbbbbbbb
4,229323,1819046113,-;(BBBB
4,229324,1819046117,-;(AAAA
4,229325,1819046118,-;BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB)
 bbbbbbbb

Signed-off-by: Yoshihiro YUNOMAE <yoshihiro.yunomae.ez@hitachi.com>
Cc: Kay Sievers <kay@vrfy.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Joe Perches <joe@perches.com>
Cc: Tejun Heo <tj@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: linux-kernel@vger.kernel.org
---
 kernel/printk/printk.c |   38 +++++++++++++++++---------------------
 1 file changed, 17 insertions(+), 21 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c3662e6..a28516b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1418,7 +1418,8 @@ static void cont_flush(enum log_flags flags)
 		 * line. LOG_NOCONS suppresses a duplicated output.
 		 */
 		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
-			  cont.ts_nsec, NULL, 0, cont.text, cont.text_len);
+			  cont.ts_nsec, cont.dict, cont.dict_len,
+			  cont.text, cont.text_len);
 		cont.flags = flags;
 		cont.flushed = true;
 	} else {
@@ -1427,9 +1428,10 @@ static void cont_flush(enum log_flags flags)
 		 * just submit it to the store and free the buffer.
 		 */
 		log_store(cont.facility, cont.level, flags, 0,
-			  NULL, 0, cont.text, cont.text_len);
-		cont.text_len = 0;
+			  cont.dict, cont.dict_len, cont.text, cont.text_len);
 	}
+	cont.text_len = 0;
+	cont.dict_len = 0;
 }
 
 static void cont_dict_add(const char *dict, size_t dict_len)
@@ -1441,7 +1443,8 @@ static void cont_dict_add(const char *dict, size_t dict_len)
 	cont.dict_len += dict_len;
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t text_len)
+static bool cont_add(int facility, int level, const char *dict, size_t dict_len,
+		     const char *text, size_t text_len)
 {
 	if (cont.text_len && cont.flushed)
 		return false;
@@ -1464,6 +1467,7 @@ static bool cont_add(int facility, int level, const char *text, size_t text_len)
 
 	memcpy(cont.text + cont.text_len, text, text_len);
 	cont.text_len += text_len;
+	cont_dict_add(dict, dict_len);
 
 	if (cont.text_len > (sizeof(cont.text) * 80) / 100)
 		cont_flush(LOG_CONT);
@@ -1587,14 +1591,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (level == -1)
 		level = default_message_loglevel;
 
-	if (dict) {
-		lflags |= LOG_PREFIX|LOG_NEWLINE;
-
-		/* Another task is trying to output a message */
-		if (cont.text_len && cont.owner != current)
-			cont_flush(LOG_NEWLINE);
-
-		cont_dict_add(dict, dictlen);
+	if (!dict) {
+		/* Discard dictionary information except for KERN_CONT */
+		if (lflags & LOG_PREFIX)
+			cont.dict_len = 0;
 	}
 
 	if (!(lflags & LOG_NEWLINE)) {
@@ -1607,9 +1607,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 			cont_flush(LOG_NEWLINE);
 
 		/* buffer line if possible, otherwise store it right away */
-		if (!cont_add(facility, level, text, text_len))
+		if (!cont_add(facility, level, dict, dictlen, text, text_len))
 			log_store(facility, level, lflags | LOG_CONT, 0,
-				  NULL, 0, text, text_len);
+				  cont.dict, cont.dict_len, text, text_len);
 	} else {
 		bool stored = false;
 
@@ -1621,18 +1621,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (cont.text_len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
+				stored = cont_add(facility, level, dict,
+						  dictlen, text, text_len);
 			cont_flush(LOG_NEWLINE);
 		}
 
 		if (!stored)
 			log_store(facility, level, lflags, 0,
-				  cont.dict, cont.dict_len, text, text_len);
-		/*
-		 * Structured printk always starts a new line now, so clear
-		 * current dictionary information for next structured printk.
-		 */
-		cont.dict_len = 0;
+				  dict, dictlen, text, text_len);
 	}
 	printed_len += text_len;
 

Re: [PATCH 2/2] printk: Delete LOG_NEWLINE flag for structured printk

[Kay Sievers]

On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
<yoshihiro.yunomae.ez@hitachi.com> wrote:
> Delete LOG_NEWLINE flag for structured printk.
> When structured printk is used, the next printk message is output in a new line
> from patch c313af145b9bc4fb8e8e0c83b8cfc10e1b894a50. However, in a following
> pseudo SCSI error test, the device information and the detail information are
> divided:

This is wrong. Please do not apply. Racy ontinuation lines and
strutured logging should not be mixed. Continuation lines are a nice
kernel hack for debugging, useful to have, but cannot be trusted by
userspace. The entire purpose of structured logging is to have
trustable atomic logging messages, the both facilities should not be
mixed.

Thanks,
Kay

Re: [PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[Kay Sievers]

On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
<yoshihiro.yunomae.ez@hitachi.com> wrote:

> This patch set fixes message continuation breakage involved with structured
> printk. A SCSI driver may output two continuation error messages like
>     scmd_printk("foo");
>     printf("bar\n");

Which is the absolutely wrong thing to do. Structured logging and racy
printk continuation must never be mixed. Userspace needs to be sure
that dictionary entries are not subject to racy continuation hackery,
and that these mwssages atomic, whole and intact.

Please do not mix the both and do not apply these patches.

Thanks,
Kay

Re: Re: [PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[Yoshihiro YUNOMAE]

Hi Kay,

Thank you for replying me.

(2013/12/20 20:29), Kay Sievers wrote:
> On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
> <yoshihiro.yunomae.ez@hitachi.com> wrote:
>
>> This patch set fixes message continuation breakage involved with structured
>> printk. A SCSI driver may output two continuation error messages like
>>      scmd_printk("foo");
>>      printf("bar\n");
>
> Which is the absolutely wrong thing to do. Structured logging and racy
> printk continuation must never be mixed. Userspace needs to be sure
> that dictionary entries are not subject to racy continuation hackery,
> and that these mwssages atomic, whole and intact.

I see.
As you say, user tools need to support messages output in multiple lines
for SMP environments even if this patch set is introduced.

> Please do not mix the both and do not apply these patches.

OK, I'll make important messages with KERN_CONT or no-prefix printk()
output those in single line.

Thanks,
Yoshihiro YUNOMAE

-- 
Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: yoshihiro.yunomae.ez@hitachi.com

Re: Re: [PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[Kay Sievers]

On Tue, Dec 24, 2013 at 3:50 AM, Yoshihiro YUNOMAE
<yoshihiro.yunomae.ez@hitachi.com> wrote:
> (2013/12/20 20:29), Kay Sievers wrote:
>>
>> On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
>> <yoshihiro.yunomae.ez@hitachi.com> wrote:
>>
>>> This patch set fixes message continuation breakage involved with
>>> structured
>>> printk. A SCSI driver may output two continuation error messages like
>>>      scmd_printk("foo");
>>>      printf("bar\n");
>>
>>
>> Which is the absolutely wrong thing to do. Structured logging and racy
>> printk continuation must never be mixed. Userspace needs to be sure
>> that dictionary entries are not subject to racy continuation hackery,
>> and that these mwssages atomic, whole and intact.
>
>
> I see.
> As you say, user tools need to support messages output in multiple lines
> for SMP environments even if this patch set is introduced.

They cannot really, they can try to re-construct, but Information and
context is sometimes lost with  the use of continuation lines.
Structured logging need to be reliable and trustable, and it it is not
"best effort", hence it cannot use continuation lines.

Continuation lines are a nice debugging tool for humans only.
Structured logging carries the human readable string but also
machine-readable context and that alwasy needs to be safely
machine-readable and recognizable.

>> Please do not mix the both and do not apply these patches.
>
> OK, I'll make important messages with KERN_CONT or no-prefix printk()
> output those in single line.

Yes, it should use the plain printk versions and not the one which add
structured data.

If structured logging is really wanted for more complex continuation
lines, it might be the simplest to buffer the line locally, instead of
the single printk-owned buffer, before the line is emitted to printk.
That way there will be no race with other print users but structured
data can still safely be added.

Kay

Re: Re: Re: [PATCH 0/2] [BUGFIX] printk: Fix message continuation breakage involved with structured printk

[Yoshihiro YUNOMAE]

(2013/12/24 12:00), Kay Sievers wrote:
> On Tue, Dec 24, 2013 at 3:50 AM, Yoshihiro YUNOMAE
> <yoshihiro.yunomae.ez@hitachi.com> wrote:
>> (2013/12/20 20:29), Kay Sievers wrote:
>>>
>>> On Fri, Dec 20, 2013 at 10:41 AM, Yoshihiro YUNOMAE
>>> <yoshihiro.yunomae.ez@hitachi.com> wrote:
>>>
>>>> This patch set fixes message continuation breakage involved with
>>>> structured
>>>> printk. A SCSI driver may output two continuation error messages like
>>>>       scmd_printk("foo");
>>>>       printf("bar\n");
>>>
>>>
>>> Which is the absolutely wrong thing to do. Structured logging and racy
>>> printk continuation must never be mixed. Userspace needs to be sure
>>> that dictionary entries are not subject to racy continuation hackery,
>>> and that these mwssages atomic, whole and intact.
>>
>>
>> I see.
>> As you say, user tools need to support messages output in multiple lines
>> for SMP environments even if this patch set is introduced.
>
> They cannot really, they can try to re-construct, but Information and
> context is sometimes lost with  the use of continuation lines.
> Structured logging need to be reliable and trustable, and it it is not
> "best effort", hence it cannot use continuation lines.
>
> Continuation lines are a nice debugging tool for humans only.
> Structured logging carries the human readable string but also
> machine-readable context and that alwasy needs to be safely
> machine-readable and recognizable.

I understand. I think if we make machine(user tools) handle important
messages, those messages need to be output in single line even if those
are not structured printk.

>>> Please do not mix the both and do not apply these patches.
>>
>> OK, I'll make important messages with KERN_CONT or no-prefix printk()
>> output those in single line.
>
> Yes, it should use the plain printk versions and not the one which add
> structured data.
>
> If structured logging is really wanted for more complex continuation
> lines, it might be the simplest to buffer the line locally, instead of
> the single printk-owned buffer, before the line is emitted to printk.

Yes, I'll do that.

Thanks,
Yoshihiro YUNOMAE

-- 
Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: yoshihiro.yunomae.ez@hitachi.com