[PATCH 0/4] printk: start simplifying some flags

[PATCH 0/4] printk: start simplifying some flags

[Alex Elder]

Each log record has a "flags" field.  The flags keep track of, for
instance, whether the record was saved in its entirety (as opposed
to being one of multiple records that should be merged as a single
unit).  A log record's flags field alone is not currently sufficient
to know how the record should be formatted; you need to know the
previous record's flags field as well.  I found understanding the
real effect of various combinations of these flags to be very
difficult, and was moved to try to do something about that.

This series includes three patches that begin the process of
simplifying how these flags are used and interpreted.  They include
very long, detailed explanations (as small patches often do) because
I want my reasoning to be very clear and examined very closely.  I
really don't want to break printk()...

The first patch simplifies some code based on the observation that
certain flag combinations never occur.

The second and third patch fix what I assert is a bug in two places.
The bug is that a LOG_PREFIX in a message should implicitly
terminate its predecessor, even if the predecessor was marked
LOG_CONT.  I would really like to have someone else confirm
they agree my assertion here.

One trivial extra patch is included at the end of the series.

					-Alex

This series, based on v3.16-rc4, is available here:
    http://git.linaro.org/landing-teams/working/broadcom/kernel.git
    Branch review/printk-flags

Alex Elder (4):
  printk: LOG_CONT and LOG_NEWLINE are separate
  printk: honor LOG_PREFIX in devkmsg_read()
  printk: honor LOG_PREFIX in msg_print_text()
  printk: correct some more typos

 kernel/printk/printk.c | 40 ++++++++++++++++++----------------------
 1 file changed, 18 insertions(+), 22 deletions(-)

-- 
1.9.1

[PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Alex Elder]

Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
at the same time in a log record flags field.  What follows is a
great deal of explanation that aims to prove this assertion.

Having that knowledge allows us to simplify a bit of logic though,
and with a little more work (in follow-on patches) it allows us to
do without some flag values, considerably simplifying things.

So this patch leverages the one-or-the-other nature of these two
flags to simplify a small bit of logic.  It makes a some other small
changes to make it obvious that a few things in surrounding (and
related) code are invariant.

Log record flags are held in the "cont" continuation buffer, as well
as in "syslog_prev" and "console_prev".  Those are discussed later.
Other than that, log record flags are only set in log_store():
        msg->flags = flags & 0x1f;
There are 5 places log_store() is called:  twice from cont_flush();
and three times from vprintk_emit().

Only two single-flag values are ever passed to cont_flush():
LOG_CONT; and LOG_NEWLINE.  That passed-in value is provided by
cont_flush() to log_store() either as-is, or modified to include
LOG_NOCONS.  There are thus four possible flag combinations supplied
to log_store() by cont_flush():  LOG_CONT; LOG_NEWLINE;
LOG_CONT|LOG_NOCONS; or LOG_NEWLINE|LOG_NOCONS.

The first call vprintk_emit() makes to log_store() passes a flags
value of LOG_PREFIX|LOG_NEWLINE.  The second and third calls pass a
computed "lflags" value, possibly with LOG_CONT added.  The only
possible flag combinations held in "lflags" are:  0; LOG_NEWLINE;
LOG_PREFIX; or LOG_NEWLINE|LOG_PREFIX.  And the LOG_CONT flag is
added only when LOG_NEWLINE is not set.  So there are six possible
flag combinations supplied by cont_flush():  0; LOG_NEWLINE;
LOG_PREFIX; LOG_CONT; LOG_PREFIX|LOG_CONT; or LOG_PREFIX|LOG_NEWLINE.

Therefore log_store() is never provided (so never records) a flag
value that contains both LOG_CONT and LOG_NEWLINE.

Meanwhile, the "cont" flags field is only ever assigned value 0, or
a value passed to cont_flush().  As mentioned above, cont_flush() is
never provided more than one flag value.  The only values assigned
to "syslog_prev" and "console_prev" are 0 or the flags value from
a log record.  So none of these ever hold LOG_CONT and LOG_NEWLINE
at the same time.

This proves that at most one of LOG_CONT and LOG_NEWLINE will ever
be set in a log record flags field.  And as a result, we know that
LOG_CONT being set implies LOG_NEWLINE is not set (and vice versa).

This patch makes the following changes:
    - Changes two spots in msg_print_txt() so they no longer bother
      checking for LOG_NEWLINE once its known that LOG_CONT is set.
    - Changes two |= assignments in vprintk_emit() to be simple
      assignments instead, because the result is known to be the
      same and it makes it obvious no other flags are involved.
    - Explicitly pass NULL rather than "dict" (and 0 as its length)
      to log_store() in one spot in vprintk_emit(), because we know
      the value of dict at that point is always NULL.

Signed-off-by: Alex Elder <elder@linaro.org>
---
 kernel/printk/printk.c | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 13e839d..301ade3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1006,11 +1006,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 		prefix = false;
 
 	if (msg->flags & LOG_CONT) {
-		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
+		if (prev & LOG_CONT)
 			prefix = false;
-
-		if (!(msg->flags & LOG_NEWLINE))
-			newline = false;
+		newline = false;
 	}
 
 	do {
@@ -1642,7 +1640,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
 		text_len--;
-		lflags |= LOG_NEWLINE;
+		lflags = LOG_NEWLINE;
 	}
 
 	/* strip kernel syslog prefix and extract log level or control flags */
@@ -1672,7 +1670,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		level = default_message_loglevel;
 
 	if (dict)
-		lflags |= LOG_PREFIX|LOG_NEWLINE;
+		lflags = LOG_PREFIX|LOG_NEWLINE;
 
 	if (!(lflags & LOG_NEWLINE)) {
 		/*
@@ -1688,7 +1686,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		else
 			printed_len += log_store(facility, level,
 						 lflags | LOG_CONT, 0,
-						 dict, dictlen, text, text_len);
+						 NULL, 0, text, text_len);
 	} else {
 		bool stored = false;
 
-- 
1.9.1

[PATCH 2/4] printk: honor LOG_PREFIX in devkmsg_read()

[Alex Elder]

In devkmsg_read(), a variable "cont" holds a character that's used
to indicate whether a given log line is a "continuation", that is,
whether a log record should be merged with the one before or after
it.  If a record should be merged with its successor (but not its
predecessor) that character is 'c'.  And the line following such a
'c' log record is normally marked with a '+' to show it is continues
its predecessor.  Any other cases are marked '-', indicating the
log record stands on its own.

There is an exception.  If a log record is marked LOG_PREFIX, it
indicates that this record represents a new log entry, implicitly
terminating the predecessor--even if the predecessor would otherwise
have been continued.  So a record marked LOG_PREFIX (that is not
also marked LOG_CONT) should have '-' for its "cont" variable.

The logic that determines this "continuation" character has a bug
that gets that exceptional case wrong.

The specific case that produces the wrong result is when all of
these conditions are non-zero:
    user->prev & LOG_CONT
    msg->flags & LOG_PREFIX
    msg->flags & LOG_CONT
The bug is that despite the message's LOG_PREFIX flag, the
"cont" character is getting set to '+' rather than 'c'.

The problem is that the message's LOG_PREFIX flag is getting
ignored if its LOG_CONT flag is also set.  Rearrange the logic
here to produce the correct result.

The following table concisely defines the problem:

     prev | msg  | msg  ||"cont"
     CONT |PREFIX| CONT || char
    ------+------+------++------
     clear| clear| clear||  '-'
     clear| clear|  set ||  'c'
     clear|  set | clear||  '-'
     clear|  set |  set ||  'c'
      set | clear| clear||  '+'
      set |  set |  set ||  '+'
      set |  set | clear||  '-'
      set |  set |  set ||  '+'      <-- should be 'c'

Signed-off-by: Alex Elder <elder@linaro.org>
---
 kernel/printk/printk.c | 11 ++++++-----
 1 file changed, 6 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 301ade3..9e9cf93 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -572,7 +572,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	struct printk_log *msg;
 	u64 ts_usec;
 	size_t i;
-	char cont = '-';
+	char cont;
 	size_t len;
 	ssize_t ret;
 
@@ -619,11 +619,12 @@ 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 (user->prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
 		cont = '+';
+	else if (msg->flags & LOG_CONT)
+		cont = 'c';
+	else
+		cont = '-';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
 		      (msg->facility << 3) | msg->level,
-- 
1.9.1

[PATCH 3/4] printk: honor LOG_PREFIX in msg_print_text()

[Alex Elder]

This patch fixes a problem similar to what was addressed in the
previous patch.

All paths that read and format log records (for consoles, and for
reading via syslog and /dev/kmsg) go through msg_print_text().  That
function starts with some logic to determine whether the given log
record when formatted should begin with a "prefix" string, and
whether it should end with a newline.  That logic has a bug.

The LOG_PREFIX flag in a log record indicates that when it's
formatted, a log record should include a prefix.  This is used to
force a record to begin a new line--even if its preceding log record
contained LOG_CONT (indicating its content should be combined with
the next record).

Like the previous patch, the problem occurs when these flags are
all set:
    prev & LOG_CONT
    msg->flags & LOG_PREFIX
    msg->flags & LOG_CONT
In that case, "prefix" should be true but it is not.

The fix involves checking LOG_PREFIX when a message has its LOG_CONT
flag set, and in that case allowing "prefix" to become false only
if LOG_PREFIX is not set.  I.e., the logic for "prefix" would become:

    if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
        prefix = false;
    if (msg->flags & LOG_CONT)
        if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
            prefix = false;

However, note that this makes the (msg->flags & LOG_CONT) block
redunant--it's handled by the test just above it.  The result
becomes quite a bit simpler than before.

The following table concisely defines the problem:

     prev | msg  | msg  ||
     CONT |PREFIX| CONT ||prefix
    ------+------+------++------
     clear| clear| clear|| true
     clear| clear|  set || true
     clear|  set | clear|| true
     clear|  set |  set || true
      set | clear| clear||false
      set |  set |  set ||false
      set |  set | clear|| true
      set |  set |  set ||false      <-- should be true

Signed-off-by: Alex Elder <elder@linaro.org>
---
 kernel/printk/printk.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9e9cf93..3f15d95 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1003,14 +1003,11 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 	bool newline = true;
 	size_t len = 0;
 
-	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+	if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
 		prefix = false;
 
-	if (msg->flags & LOG_CONT) {
-		if (prev & LOG_CONT)
-			prefix = false;
+	if (msg->flags & LOG_CONT)
 		newline = false;
-	}
 
 	do {
 		const char *next = memchr(text, '\n', text_size);
-- 
1.9.1

[PATCH 4/4] printk: correct some more typos

[Alex Elder]

This patch corrects a few more typographical errors in "printk.c".

Signed-off-by: Alex Elder <elder@linaro.org>
---
 kernel/printk/printk.c | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 3f15d95..0cbd060 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -201,7 +201,7 @@ static int console_may_schedule;
  *
  * The optional key/value pairs are attached as continuation lines starting
  * with a space character and terminated by a newline. All possible
- * non-prinatable characters are escaped in the "\xff" notation.
+ * non-printable characters are escaped in the "\xff" notation.
  *
  * Users of the export format should ignore possible additional values
  * separated by ',', and find the message after the ';' character.
@@ -411,7 +411,7 @@ static int log_store(int facility, int level,
 		/* truncate the message if it is too long for empty buffer */
 		size = truncate_msg(&text_len, &trunc_msg_len,
 				    &dict_len, &pad_len);
-		/* survive when the log buffer is too small for trunc_msg */
+		/* survive when the log buffer is too small for truncate_msg */
 		if (log_make_free_space(size))
 			return 0;
 	}
@@ -614,7 +614,7 @@ 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
+	 * records. Merging the records isn't always necessarily 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.
@@ -2881,7 +2881,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 		prev = msg->flags;
 	}
 
-	/* last message in next interation */
+	/* last message in next iteration */
 	next_seq = seq;
 	next_idx = idx;
 
@@ -2907,7 +2907,7 @@ out:
 EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
 
 /**
- * kmsg_dump_rewind_nolock - reset the interator (unlocked version)
+ * kmsg_dump_rewind_nolock - reset the iterator (unlocked version)
  * @dumper: registered kmsg dumper
  *
  * Reset the dumper's iterator so that kmsg_dump_get_line() and
@@ -2925,7 +2925,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
 }
 
 /**
- * kmsg_dump_rewind - reset the interator
+ * kmsg_dump_rewind - reset the iterator
  * @dumper: registered kmsg dumper
  *
  * Reset the dumper's iterator so that kmsg_dump_get_line() and
-- 
1.9.1

Re: [PATCH 0/4] printk: start simplifying some flags

[Joe Perches]

(adding Kay Sievers)

On Wed, 2014-07-16 at 12:26 -0500, Alex Elder wrote:
> Each log record has a "flags" field.  The flags keep track of, for
> instance, whether the record was saved in its entirety (as opposed
> to being one of multiple records that should be merged as a single
> unit).  A log record's flags field alone is not currently sufficient
> to know how the record should be formatted; you need to know the
> previous record's flags field as well.  I found understanding the
> real effect of various combinations of these flags to be very
> difficult, and was moved to try to do something about that.
> 
> This series includes three patches that begin the process of
> simplifying how these flags are used and interpreted.  They include
> very long, detailed explanations (as small patches often do) because
> I want my reasoning to be very clear and examined very closely.  I
> really don't want to break printk()...
> 
> The first patch simplifies some code based on the observation that
> certain flag combinations never occur.
> 
> The second and third patch fix what I assert is a bug in two places.
> The bug is that a LOG_PREFIX in a message should implicitly
> terminate its predecessor, even if the predecessor was marked
> LOG_CONT.  I would really like to have someone else confirm
> they agree my assertion here.
> 
> One trivial extra patch is included at the end of the series.
> 
> 					-Alex
> 
> This series, based on v3.16-rc4, is available here:
>     http://git.linaro.org/landing-teams/working/broadcom/kernel.git
>     Branch review/printk-flags
> 
> Alex Elder (4):
>   printk: LOG_CONT and LOG_NEWLINE are separate
>   printk: honor LOG_PREFIX in devkmsg_read()
>   printk: honor LOG_PREFIX in msg_print_text()
>   printk: correct some more typos
> 
>  kernel/printk/printk.c | 40 ++++++++++++++++++----------------------
>  1 file changed, 18 insertions(+), 22 deletions(-)
> 

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Petr Mládek]

On Wed 2014-07-16 12:26:57, Alex Elder wrote:
> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
> at the same time in a log record flags field.  What follows is a
> great deal of explanation that aims to prove this assertion.

It makes perfect sense. If you found a situation where both flags were
set together, it would mean a bug. If a record ends with new line, it
is not continuous and vice versa.

[...]

> Signed-off-by: Alex Elder <elder@linaro.org>
> ---
>  kernel/printk/printk.c | 12 +++++-------
>  1 file changed, 5 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 13e839d..301ade3 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1006,11 +1006,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
>  		prefix = false;
>  
>  	if (msg->flags & LOG_CONT) {
> -		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
> +		if (prev & LOG_CONT)
>  			prefix = false;
> -
> -		if (!(msg->flags & LOG_NEWLINE))
> -			newline = false;
> +		newline = false;
>  	}

Makes sense. I like it.

>  	do {
> @@ -1642,7 +1640,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	/* mark and strip a trailing newline */
>  	if (text_len && text[text_len-1] == '\n') {
>  		text_len--;
> -		lflags |= LOG_NEWLINE;
> +		lflags = LOG_NEWLINE;
>  	}
>  
>  	/* strip kernel syslog prefix and extract log level or control flags */
> @@ -1672,7 +1670,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		level = default_message_loglevel;
>  
>  	if (dict)
> -		lflags |= LOG_PREFIX|LOG_NEWLINE;
> +		lflags = LOG_PREFIX|LOG_NEWLINE;
>  
>  	if (!(lflags & LOG_NEWLINE)) {
>  		/*
> @@ -1688,7 +1686,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		else
>  			printed_len += log_store(facility, level,
>  						 lflags | LOG_CONT, 0,
> -						 dict, dictlen, text, text_len);
> +						 NULL, 0, text, text_len);
>  	} else {
>  		bool stored = false;
>  

I am not sure that I like the last three changes. The logic is
correct. But I think that these micro-optimizations makes the code less
readable and prone to errors with reordering and other changes.

The original code does not harm. The new code is less obvious and will
force many people to think why it is correct. Even you might be in
doubts if you see it after few months :-)

Well, I do not have strong opinion here. Other people might see it
different. Forcing people to think is not a bad idea after all :-)

Best Regards,
Petr

Re: [PATCH 3/4] printk: honor LOG_PREFIX in msg_print_text()

[Petr Mládek]

On Wed 2014-07-16 12:26:59, Alex Elder wrote:
> This patch fixes a problem similar to what was addressed in the
> previous patch.
> 
> All paths that read and format log records (for consoles, and for
> reading via syslog and /dev/kmsg) go through msg_print_text().  That
> function starts with some logic to determine whether the given log
> record when formatted should begin with a "prefix" string, and
> whether it should end with a newline.  That logic has a bug.
> 
> The LOG_PREFIX flag in a log record indicates that when it's
> formatted, a log record should include a prefix.  This is used to
> force a record to begin a new line--even if its preceding log record
> contained LOG_CONT (indicating its content should be combined with
> the next record).
> 
> Like the previous patch, the problem occurs when these flags are
> all set:
>     prev & LOG_CONT
>     msg->flags & LOG_PREFIX
>     msg->flags & LOG_CONT
> In that case, "prefix" should be true but it is not.

You are right.

> The fix involves checking LOG_PREFIX when a message has its LOG_CONT
> flag set, and in that case allowing "prefix" to become false only
> if LOG_PREFIX is not set.  I.e., the logic for "prefix" would become:
> 
>     if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>         prefix = false;
>     if (msg->flags & LOG_CONT)
>         if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>             prefix = false;
> 
> However, note that this makes the (msg->flags & LOG_CONT) block
> redunant--it's handled by the test just above it.  The result
> becomes quite a bit simpler than before.
> 
> The following table concisely defines the problem:
> 
>      prev | msg  | msg  ||
>      CONT |PREFIX| CONT ||prefix
>     ------+------+------++------
>      clear| clear| clear|| true
>      clear| clear|  set || true
>      clear|  set | clear|| true
>      clear|  set |  set || true
>       set | clear| clear||false
>       set |  set |  set ||false
>       set |  set | clear|| true
>       set |  set |  set ||false      <-- should be true
> 
> Signed-off-by: Alex Elder <elder@linaro.org>
> ---
>  kernel/printk/printk.c | 7 ++-----
>  1 file changed, 2 insertions(+), 5 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 9e9cf93..3f15d95 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1003,14 +1003,11 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
>  	bool newline = true;
>  	size_t len = 0;
>  
> -	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
> +	if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>  		prefix = false;

I would personaly keep the brackets there. For me.

  ( & ) && !( & )

is easier to parse than

  & && !( & )

> -	if (msg->flags & LOG_CONT) {
> -		if (prev & LOG_CONT)
> -			prefix = false;
> +	if (msg->flags & LOG_CONT)
>  		newline = false;
> -	}

You are right. The check before "prefix = false" did not make much
sense. We should not remove prefix just because the previous line was
continuous. Also it does not make sense to do this only when the new line
is continuous.

But I think that the fix is not complete. IMHO, we should finish the
previous continuous line with '\n' before we print the prefix. I mean something
like:

if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && (len < size)) {
	/* finish the incomplete continuous line */
	if (buf) {
		buf[len++] = '\n';
	} else {
		len++;
	}
}

Best Regards,
Petr


>  
>  	do {
>  		const char *next = memchr(text, '\n', text_size);
> -- 
> 1.9.1
> 

Re: [PATCH 2/4] printk: honor LOG_PREFIX in devkmsg_read()

[Petr Mládek]

On Wed 2014-07-16 12:26:58, Alex Elder wrote:
> In devkmsg_read(), a variable "cont" holds a character that's used
> to indicate whether a given log line is a "continuation", that is,
> whether a log record should be merged with the one before or after
> it.  If a record should be merged with its successor (but not its
> predecessor) that character is 'c'.  And the line following such a
> 'c' log record is normally marked with a '+' to show it is continues
> its predecessor.  Any other cases are marked '-', indicating the
> log record stands on its own.
> 
> There is an exception.  If a log record is marked LOG_PREFIX, it
> indicates that this record represents a new log entry, implicitly
> terminating the predecessor--even if the predecessor would otherwise
> have been continued.  So a record marked LOG_PREFIX (that is not
> also marked LOG_CONT) should have '-' for its "cont" variable.
> 
> The logic that determines this "continuation" character has a bug
> that gets that exceptional case wrong.
> 
> The specific case that produces the wrong result is when all of
> these conditions are non-zero:
>     user->prev & LOG_CONT
>     msg->flags & LOG_PREFIX
>     msg->flags & LOG_CONT
> The bug is that despite the message's LOG_PREFIX flag, the
> "cont" character is getting set to '+' rather than 'c'.
> 
> The problem is that the message's LOG_PREFIX flag is getting
> ignored if its LOG_CONT flag is also set.  Rearrange the logic
> here to produce the correct result.
> 
> The following table concisely defines the problem:
> 
>      prev | msg  | msg  ||"cont"
>      CONT |PREFIX| CONT || char
>     ------+------+------++------
>      clear| clear| clear||  '-'
>      clear| clear|  set ||  'c'
>      clear|  set | clear||  '-'
>      clear|  set |  set ||  'c'
>       set | clear| clear||  '+'
>       set |  set |  set ||  '+'
	       ^^^ typo, it should be:

       set |  clear |  set ||  '+'

>       set |  set | clear||  '-'
>       set |  set |  set ||  '+'      <-- should be 'c'
> 
> Signed-off-by: Alex Elder <elder@linaro.org>
> ---
>  kernel/printk/printk.c | 11 ++++++-----
>  1 file changed, 6 insertions(+), 5 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 301ade3..9e9cf93 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -572,7 +572,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
>  	struct printk_log *msg;
>  	u64 ts_usec;
>  	size_t i;
> -	char cont = '-';
> +	char cont;
>  	size_t len;
>  	ssize_t ret;
>  
> @@ -619,11 +619,12 @@ 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 (user->prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>  		cont = '+';
> +	else if (msg->flags & LOG_CONT)
> +		cont = 'c';
> +	else
> +		cont = '-';

Makes sense. Prefix should be always on a new line.

Reviewed-by: Petr Mladek <pmladek@suse.cz>

Best Regards,
Petr

>  	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
>  		      (msg->facility << 3) | msg->level,
> -- 
> 1.9.1
> 

Re: [PATCH 4/4] printk: correct some more typos

[Petr Mládek]

On Wed 2014-07-16 12:27:00, Alex Elder wrote:
> This patch corrects a few more typographical errors in "printk.c".
> 
> Signed-off-by: Alex Elder <elder@linaro.org>
> ---
>  kernel/printk/printk.c | 12 ++++++------
>  1 file changed, 6 insertions(+), 6 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 3f15d95..0cbd060 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -201,7 +201,7 @@ static int console_may_schedule;
>   *
>   * The optional key/value pairs are attached as continuation lines starting
>   * with a space character and terminated by a newline. All possible
> - * non-prinatable characters are escaped in the "\xff" notation.
> + * non-printable characters are escaped in the "\xff" notation.
>   *
>   * Users of the export format should ignore possible additional values
>   * separated by ',', and find the message after the ';' character.
> @@ -411,7 +411,7 @@ static int log_store(int facility, int level,
>  		/* truncate the message if it is too long for empty buffer */
>  		size = truncate_msg(&text_len, &trunc_msg_len,
>  				    &dict_len, &pad_len);
> -		/* survive when the log buffer is too small for trunc_msg */
> +		/* survive when the log buffer is too small for truncate_msg */

It meant the trunc_msg = "<truncated>" string. So, the original text
was more precise. I agree that it is a bit confusing :-)

The other changes look correct.

Best Regards,
Petr

>  		if (log_make_free_space(size))
>  			return 0;
>  	}
> @@ -614,7 +614,7 @@ 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
> +	 * records. Merging the records isn't always necessarily 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.
> @@ -2881,7 +2881,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
>  		prev = msg->flags;
>  	}
>  
> -	/* last message in next interation */
> +	/* last message in next iteration */
>  	next_seq = seq;
>  	next_idx = idx;
>  
> @@ -2907,7 +2907,7 @@ out:
>  EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
>  
>  /**
> - * kmsg_dump_rewind_nolock - reset the interator (unlocked version)
> + * kmsg_dump_rewind_nolock - reset the iterator (unlocked version)
>   * @dumper: registered kmsg dumper
>   *
>   * Reset the dumper's iterator so that kmsg_dump_get_line() and
> @@ -2925,7 +2925,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
>  }
>  
>  /**
> - * kmsg_dump_rewind - reset the interator
> + * kmsg_dump_rewind - reset the iterator
>   * @dumper: registered kmsg dumper
>   *
>   * Reset the dumper's iterator so that kmsg_dump_get_line() and
> -- 
> 1.9.1
> 

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Alex Elder]

On 07/17/2014 03:39 AM, Petr Mládek wrote:
> On Wed 2014-07-16 12:26:57, Alex Elder wrote:
>> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
>> at the same time in a log record flags field.  What follows is a
>> great deal of explanation that aims to prove this assertion.

Thank you so much for reviewing these patches.

Your confirmation of the fact that LOG_CONT and LOG_NEWLINE
should not go together is very valuable to me.  I have a set
of follow-on patches that rely on this, and I didn't want to
go ahead with proposing them until I knew this was right.

I have some responses to your feedback below.

> It makes perfect sense. If you found a situation where both flags were
> set together, it would mean a bug. If a record ends with new line, it
> is not continuous and vice versa.

At an abstract level this makes sense to me too, but the code
is written to handle many combinations of flags that simply will
never happen.  It obscures what's going on, or is supposed to be
going on.  So to the reader, this appears much more complicated than
it really is.

> [...]
> 
>> Signed-off-by: Alex Elder <elder@linaro.org>
>> ---
>>  kernel/printk/printk.c | 12 +++++-------
>>  1 file changed, 5 insertions(+), 7 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 13e839d..301ade3 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1006,11 +1006,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
>>  		prefix = false;
>>  
>>  	if (msg->flags & LOG_CONT) {
>> -		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
>> +		if (prev & LOG_CONT)
>>  			prefix = false;
>> -
>> -		if (!(msg->flags & LOG_NEWLINE))
>> -			newline = false;
>> +		newline = false;
>>  	}
> 
> Makes sense. I like it.
> 
>>  	do {
>> @@ -1642,7 +1640,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>  	/* mark and strip a trailing newline */
>>  	if (text_len && text[text_len-1] == '\n') {
>>  		text_len--;
>> -		lflags |= LOG_NEWLINE;
>> +		lflags = LOG_NEWLINE;
>>  	}
>>  
>>  	/* strip kernel syslog prefix and extract log level or control flags */
>> @@ -1672,7 +1670,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>  		level = default_message_loglevel;
>>  
>>  	if (dict)
>> -		lflags |= LOG_PREFIX|LOG_NEWLINE;
>> +		lflags = LOG_PREFIX|LOG_NEWLINE;
>>  
>>  	if (!(lflags & LOG_NEWLINE)) {
>>  		/*
>> @@ -1688,7 +1686,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>  		else
>>  			printed_len += log_store(facility, level,
>>  						 lflags | LOG_CONT, 0,
>> -						 dict, dictlen, text, text_len);
>> +						 NULL, 0, text, text_len);
>>  	} else {
>>  		bool stored = false;
>>  
> 
> I am not sure that I like the last three changes. The logic is
> correct. But I think that these micro-optimizations makes the code less
> readable and prone to errors with reordering and other changes.

It is not an optimization.  I don't care about that.

It is replacing a variable with a constant, because I
know by static analysis that the variable will always
have constant value.  This makes it completely obvious
that "dict" will *never* be NULL in this case, and as
above, makes it more obvious what's happening.

(You'll see in my follow-on series that I rely on the
assignment rather than |= in order to do some refactoring.)

If someone chooses to reorder the code in a way that
makes |= necessary (for example) will put that back
again, because not doing so would introduce a bug.

> The original code does not harm. The new code is less obvious and will
> force many people to think why it is correct. Even you might be in
> doubts if you see it after few months :-)

Actually I think it's the opposite.

> Well, I do not have strong opinion here. Other people might see it
> different. Forcing people to think is not a bad idea after all :-)

I may be naive, but I think it's a requirement if you're going
to change code.

Thanks again for the review.  If you're willing after reading my
explanations, please offer an ACK or Reviewed-by (or further
questions and suggestions).  I'll have responses to your others
shortly.

					-Alex

> Best Regards,
> Petr
> 

Re: [PATCH 3/4] printk: honor LOG_PREFIX in msg_print_text()

[Alex Elder]

On 07/17/2014 04:40 AM, Petr Mládek wrote:
> On Wed 2014-07-16 12:26:59, Alex Elder wrote:
>> This patch fixes a problem similar to what was addressed in the
>> previous patch.
>>
>> All paths that read and format log records (for consoles, and for
>> reading via syslog and /dev/kmsg) go through msg_print_text().  That
>> function starts with some logic to determine whether the given log
>> record when formatted should begin with a "prefix" string, and
>> whether it should end with a newline.  That logic has a bug.
>>
>> The LOG_PREFIX flag in a log record indicates that when it's
>> formatted, a log record should include a prefix.  This is used to
>> force a record to begin a new line--even if its preceding log record
>> contained LOG_CONT (indicating its content should be combined with
>> the next record).
>>
>> Like the previous patch, the problem occurs when these flags are
>> all set:
>>     prev & LOG_CONT
>>     msg->flags & LOG_PREFIX
>>     msg->flags & LOG_CONT
>> In that case, "prefix" should be true but it is not.
> 
> You are right.

That's great news.

>> The fix involves checking LOG_PREFIX when a message has its LOG_CONT
>> flag set, and in that case allowing "prefix" to become false only
>> if LOG_PREFIX is not set.  I.e., the logic for "prefix" would become:
>>
>>     if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>>         prefix = false;
>>     if (msg->flags & LOG_CONT)
>>         if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>>             prefix = false;
>>
>> However, note that this makes the (msg->flags & LOG_CONT) block
>> redunant--it's handled by the test just above it.  The result
>> becomes quite a bit simpler than before.
>>
>> The following table concisely defines the problem:
>>
>>      prev | msg  | msg  ||
>>      CONT |PREFIX| CONT ||prefix
>>     ------+------+------++------
>>      clear| clear| clear|| true
>>      clear| clear|  set || true
>>      clear|  set | clear|| true
>>      clear|  set |  set || true
>>       set | clear| clear||false
>>       set |  set |  set ||false
               clear

(Same problem you pointed out in the next patch.)

>>       set |  set | clear|| true
>>       set |  set |  set ||false      <-- should be true
>>
>> Signed-off-by: Alex Elder <elder@linaro.org>
>> ---
>>  kernel/printk/printk.c | 7 ++-----
>>  1 file changed, 2 insertions(+), 5 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 9e9cf93..3f15d95 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1003,14 +1003,11 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
>>  	bool newline = true;
>>  	size_t len = 0;
>>  
>> -	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
>> +	if (prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>>  		prefix = false;
> 
> I would personaly keep the brackets there. For me.
> 
>   ( & ) && !( & )

That's fine.  I tend to be minimalist unless the compiler suggests
otherwise, but I'll keep the parentheses.

> is easier to parse than
> 
>   & && !( & )
> 
>> -	if (msg->flags & LOG_CONT) {
>> -		if (prev & LOG_CONT)
>> -			prefix = false;
>> +	if (msg->flags & LOG_CONT)
>>  		newline = false;
>> -	}
> 
> You are right. The check before "prefix = false" did not make much
> sense. We should not remove prefix just because the previous line was
> continuous. Also it does not make sense to do this only when the new line
> is continuous.

I came at this trying to understand what was intended by
reading the code.  And it is not easy.  These patches and
the set that I'll post soon simplify things enormously.

> But I think that the fix is not complete. IMHO, we should finish the
> previous continuous line with '\n' before we print the prefix. I mean something
> like:

I will re-post a new version of this patch.  When I do so
I will look at this and--unless I find I disagree--will
implement your suggestion.

Thanks.

					-Alex

> 
> if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && (len < size)) {
> 	/* finish the incomplete continuous line */
> 	if (buf) {
> 		buf[len++] = '\n';
> 	} else {
> 		len++;
> 	}
> }
> 
> Best Regards,
> Petr
> 
> 
>>  
>>  	do {
>>  		const char *next = memchr(text, '\n', text_size);
>> -- 
>> 1.9.1
>>

Re: [PATCH 2/4] printk: honor LOG_PREFIX in devkmsg_read()

[Alex Elder]

On 07/17/2014 05:14 AM, Petr Mládek wrote:
> On Wed 2014-07-16 12:26:58, Alex Elder wrote:
>> In devkmsg_read(), a variable "cont" holds a character that's used
>> to indicate whether a given log line is a "continuation", that is,
>> whether a log record should be merged with the one before or after
>> it.  If a record should be merged with its successor (but not its
>> predecessor) that character is 'c'.  And the line following such a
>> 'c' log record is normally marked with a '+' to show it is continues
>> its predecessor.  Any other cases are marked '-', indicating the
>> log record stands on its own.
>>
>> There is an exception.  If a log record is marked LOG_PREFIX, it
>> indicates that this record represents a new log entry, implicitly
>> terminating the predecessor--even if the predecessor would otherwise
>> have been continued.  So a record marked LOG_PREFIX (that is not
>> also marked LOG_CONT) should have '-' for its "cont" variable.
>>
>> The logic that determines this "continuation" character has a bug
>> that gets that exceptional case wrong.
>>
>> The specific case that produces the wrong result is when all of
>> these conditions are non-zero:
>>     user->prev & LOG_CONT
>>     msg->flags & LOG_PREFIX
>>     msg->flags & LOG_CONT
>> The bug is that despite the message's LOG_PREFIX flag, the
>> "cont" character is getting set to '+' rather than 'c'.
>>
>> The problem is that the message's LOG_PREFIX flag is getting
>> ignored if its LOG_CONT flag is also set.  Rearrange the logic
>> here to produce the correct result.
>>
>> The following table concisely defines the problem:
>>
>>      prev | msg  | msg  ||"cont"
>>      CONT |PREFIX| CONT || char
>>     ------+------+------++------
>>      clear| clear| clear||  '-'
>>      clear| clear|  set ||  'c'
>>      clear|  set | clear||  '-'
>>      clear|  set |  set ||  'c'
>>       set | clear| clear||  '+'
>>       set |  set |  set ||  '+'
> 	       ^^^ typo, it should be:

I will fix this, and it will show up when I re-post the series.

> 
>        set |  clear |  set ||  '+'
> 
>>       set |  set | clear||  '-'
>>       set |  set |  set ||  '+'      <-- should be 'c'
>>
>> Signed-off-by: Alex Elder <elder@linaro.org>
>> ---
>>  kernel/printk/printk.c | 11 ++++++-----
>>  1 file changed, 6 insertions(+), 5 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 301ade3..9e9cf93 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -572,7 +572,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
>>  	struct printk_log *msg;
>>  	u64 ts_usec;
>>  	size_t i;
>> -	char cont = '-';
>> +	char cont;
>>  	size_t len;
>>  	ssize_t ret;
>>  
>> @@ -619,11 +619,12 @@ 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 (user->prev & LOG_CONT && !(msg->flags & LOG_PREFIX))
>>  		cont = '+';
>> +	else if (msg->flags & LOG_CONT)
>> +		cont = 'c';
>> +	else
>> +		cont = '-';
> 
> Makes sense. Prefix should be always on a new line.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.cz>

Yay!!!  Thanks.

					-Alex

> 
> Best Regards,
> Petr
> 
>>  	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
>>  		      (msg->facility << 3) | msg->level,
>> -- 
>> 1.9.1
>>

Re: [PATCH 4/4] printk: correct some more typos

[Alex Elder]

On 07/17/2014 06:46 AM, Petr Mládek wrote:
> On Wed 2014-07-16 12:27:00, Alex Elder wrote:
>> This patch corrects a few more typographical errors in "printk.c".
>>
>> Signed-off-by: Alex Elder <elder@linaro.org>
>> ---
>>  kernel/printk/printk.c | 12 ++++++------
>>  1 file changed, 6 insertions(+), 6 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 3f15d95..0cbd060 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -201,7 +201,7 @@ static int console_may_schedule;
>>   *
>>   * The optional key/value pairs are attached as continuation lines starting
>>   * with a space character and terminated by a newline. All possible
>> - * non-prinatable characters are escaped in the "\xff" notation.
>> + * non-printable characters are escaped in the "\xff" notation.
>>   *
>>   * Users of the export format should ignore possible additional values
>>   * separated by ',', and find the message after the ';' character.
>> @@ -411,7 +411,7 @@ static int log_store(int facility, int level,
>>  		/* truncate the message if it is too long for empty buffer */
>>  		size = truncate_msg(&text_len, &trunc_msg_len,
>>  				    &dict_len, &pad_len);
>> -		/* survive when the log buffer is too small for trunc_msg */
>> +		/* survive when the log buffer is too small for truncate_msg */
> 
> It meant the trunc_msg = "<truncated>" string. So, the original text
> was more precise. I agree that it is a bit confusing :-)

Oh, I see now.  No it's not confusing, it's just that right here
trunc_msg[] is not mentioned--that's buried inside truncate_msg().

I don't feel strongly about this one, I'll drop this hunk.

					-Alex

> The other changes look correct.
> 
> Best Regards,
> Petr
> 
>>  		if (log_make_free_space(size))
>>  			return 0;
>>  	}
>> @@ -614,7 +614,7 @@ 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
>> +	 * records. Merging the records isn't always necessarily 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.
>> @@ -2881,7 +2881,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
>>  		prev = msg->flags;
>>  	}
>>  
>> -	/* last message in next interation */
>> +	/* last message in next iteration */
>>  	next_seq = seq;
>>  	next_idx = idx;
>>  
>> @@ -2907,7 +2907,7 @@ out:
>>  EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
>>  
>>  /**
>> - * kmsg_dump_rewind_nolock - reset the interator (unlocked version)
>> + * kmsg_dump_rewind_nolock - reset the iterator (unlocked version)
>>   * @dumper: registered kmsg dumper
>>   *
>>   * Reset the dumper's iterator so that kmsg_dump_get_line() and
>> @@ -2925,7 +2925,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
>>  }
>>  
>>  /**
>> - * kmsg_dump_rewind - reset the interator
>> + * kmsg_dump_rewind - reset the iterator
>>   * @dumper: registered kmsg dumper
>>   *
>>   * Reset the dumper's iterator so that kmsg_dump_get_line() and
>> -- 
>> 1.9.1
>>

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Alex Elder]

On 07/17/2014 03:39 AM, Petr Mládek wrote:
> On Wed 2014-07-16 12:26:57, Alex Elder wrote:
>> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
>> at the same time in a log record flags field.  What follows is a
>> great deal of explanation that aims to prove this assertion.
> 
> It makes perfect sense. If you found a situation where both flags were
> set together, it would mean a bug. If a record ends with new line, it
> is not continuous and vice versa.

. . .

My earlier response basically argued for keeping the patch
as I originally proposed it.

That is still my plan.  However there is one more thing
that I have verified since posting it--I can make the
stronger assertion that LOG_CONT and LOG_NEWLINE are
mutually exclusive.  That is, not only will they never
be both set at the time, but one of them will always
be set.

Rather than add that as a new patch I'm going to rework
the explanation, and make one more small code change
to make this a little easier to see.

					-Alex

Re: [PATCH 3/4] printk: honor LOG_PREFIX in msg_print_text()

[Alex Elder]

On 07/17/2014 07:18 AM, Alex Elder wrote:
>> But I think that the fix is not complete. IMHO, we should finish the
>> > previous continuous line with '\n' before we print the prefix. I mean something
>> > like:
> I will re-post a new version of this patch.  When I do so
> I will look at this and--unless I find I disagree--will
> implement your suggestion.

I concur with this, but it's a different bug that changes
externally-visible behavior, so I'm going to add this as
a separate patch.

					-Alex

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Petr Mládek]

On Thu 2014-07-17 07:11:39, Alex Elder wrote:
> On 07/17/2014 03:39 AM, Petr Mládek wrote:
> > On Wed 2014-07-16 12:26:57, Alex Elder wrote:
> >> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
> >> at the same time in a log record flags field.  What follows is a
> >> great deal of explanation that aims to prove this assertion.
> 
> Thank you so much for reviewing these patches.
> 
> Your confirmation of the fact that LOG_CONT and LOG_NEWLINE
> should not go together is very valuable to me.  I have a set
> of follow-on patches that rely on this, and I didn't want to
> go ahead with proposing them until I knew this was right.

To be honest. My statement was based on a common sense. I simply
cannot imagine situatiuon when a text ends with "\n" and is continuous
at the same time. IMHO, it is against any logic.

IMHO, it would make sense to have only one flag, either LOG_NEWLINE or
LOG_CONT. Well, I am not sure if we could remove it easily. AFAIK, the
ring buffer is read also by external tools, e.g. crash.

Some more experienced kernel developer should answer this.

> I have some responses to your feedback below.
> 
> > It makes perfect sense. If you found a situation where both flags were
> > set together, it would mean a bug. If a record ends with new line, it
> > is not continuous and vice versa.
> 
> At an abstract level this makes sense to me too, but the code
> is written to handle many combinations of flags that simply will
> never happen.  It obscures what's going on, or is supposed to be
> going on.  So to the reader, this appears much more complicated than
> it really is.

Yes, the code is too complicated and deserve simplification.

> 
> > [...]
> > 
> >> Signed-off-by: Alex Elder <elder@linaro.org>
> >> ---
> >>  kernel/printk/printk.c | 12 +++++-------
> >>  1 file changed, 5 insertions(+), 7 deletions(-)
> >>
> >> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> >> index 13e839d..301ade3 100644
> >> --- a/kernel/printk/printk.c
> >> +++ b/kernel/printk/printk.c
> >> @@ -1006,11 +1006,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
> >>  		prefix = false;
> >>  
> >>  	if (msg->flags & LOG_CONT) {
> >> -		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
> >> +		if (prev & LOG_CONT)
> >>  			prefix = false;
> >> -
> >> -		if (!(msg->flags & LOG_NEWLINE))
> >> -			newline = false;
> >> +		newline = false;
> >>  	}
> > 
> > Makes sense. I like it.
> > 
> >>  	do {
> >> @@ -1642,7 +1640,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >>  	/* mark and strip a trailing newline */
> >>  	if (text_len && text[text_len-1] == '\n') {
> >>  		text_len--;
> >> -		lflags |= LOG_NEWLINE;
> >> +		lflags = LOG_NEWLINE;
> >>  	}
> >>  
> >>  	/* strip kernel syslog prefix and extract log level or control flags */
> >> @@ -1672,7 +1670,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >>  		level = default_message_loglevel;
> >>  
> >>  	if (dict)
> >> -		lflags |= LOG_PREFIX|LOG_NEWLINE;
> >> +		lflags = LOG_PREFIX|LOG_NEWLINE;
> >>  
> >>  	if (!(lflags & LOG_NEWLINE)) {
> >>  		/*
> >> @@ -1688,7 +1686,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >>  		else
> >>  			printed_len += log_store(facility, level,
> >>  						 lflags | LOG_CONT, 0,
> >> -						 dict, dictlen, text, text_len);
> >> +						 NULL, 0, text, text_len);
> >>  	} else {
> >>  		bool stored = false;
> >>  
> > 
> > I am not sure that I like the last three changes. The logic is
> > correct. But I think that these micro-optimizations makes the code less
> > readable and prone to errors with reordering and other changes.
> 
> It is not an optimization.  I don't care about that.
> 
> It is replacing a variable with a constant, because I
> know by static analysis that the variable will always
> have constant value.  This makes it completely obvious
> that "dict" will *never* be NULL in this case, and as
> above, makes it more obvious what's happening.
> 
> (You'll see in my follow-on series that I rely on the
> assignment rather than |= in order to do some refactoring.)

As I said, I do not have strong opinion here. It might be interesting
to see the whole serie to get better picture.

> If someone chooses to reorder the code in a way that
> makes |= necessary (for example) will put that back
> again, because not doing so would introduce a bug.
> 
> > The original code does not harm. The new code is less obvious and will
> > force many people to think why it is correct. Even you might be in
> > doubts if you see it after few months :-)
> 
> Actually I think it's the opposite.
> 
> > Well, I do not have strong opinion here. Other people might see it
> > different. Forcing people to think is not a bad idea after all :-)
> 
> I may be naive, but I think it's a requirement if you're going
> to change code.

But it is easier when the code is readable and there are as few
surprises as possible. Also you never could have everything in your
head. The less dependncy is there, the easier is to work with it.

Regarding the above changes. The origial code used the typical
pattern. It set default value and then modified different flags according
to various tests. It did not need to take care much of other flags that
were not related to the given test.

If you add lated another flag and more tests, the final forced
assignent could break things.

Also the hardcoded NULL is not obvious. If you would want to modify the
code, you would need to think harder why it is there. IMHO, it does
not bring any real benefit unless you want to use it for some furher
optimization. But this is not visible from the patchset.


Please, take this as my personal opinion. I am not maintainer of this
code and the final decisions will not not be mine. Also I am still
learning good code patterns.

> Thanks again for the review.  If you're willing after reading my
> explanations, please offer an ACK or Reviewed-by (or further
> questions and suggestions).  I'll have responses to your others
> shortly.

I would like to see the bigger picture before :-)

Best Regards,
Petr

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Alex Elder]

On 07/17/2014 09:46 AM, Petr Mládek wrote:
> On Thu 2014-07-17 07:11:39, Alex Elder wrote:
>> On 07/17/2014 03:39 AM, Petr Mládek wrote:
>>> On Wed 2014-07-16 12:26:57, Alex Elder wrote:
>>>> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
>>>> at the same time in a log record flags field.  What follows is a
>>>> great deal of explanation that aims to prove this assertion.
>>
>> Thank you so much for reviewing these patches.
>>
>> Your confirmation of the fact that LOG_CONT and LOG_NEWLINE
>> should not go together is very valuable to me.  I have a set
>> of follow-on patches that rely on this, and I didn't want to
>> go ahead with proposing them until I knew this was right.
> 
> To be honest. My statement was based on a common sense. I simply
> cannot imagine situatiuon when a text ends with "\n" and is continuous
> at the same time. IMHO, it is against any logic.

Well, I thought so too, but it was hard to see that by
just looking at the code.

> IMHO, it would make sense to have only one flag, either LOG_NEWLINE or
> LOG_CONT. Well, I am not sure if we could remove it easily. AFAIK, the
> ring buffer is read also by external tools, e.g. crash.

The single flag is coming.  I have that done, but I didn't want
to send that patch (and others) until I get past this little group.

I have been concerned about the effects on other things but the
comments insist the log structure is kernel private. :)

I took a very quick look at crash-7.0.7 and see dump_log_entry(),
which seems to dump the contents of a log record but does not
interpret any of the flags.

This is a really important point, so if anybody knows of other
utilities outside the kernel that interpret the log record flags
I'd like to know about it.

> Some more experienced kernel developer should answer this.

>> I have some responses to your feedback below.
>>
>>> It makes perfect sense. If you found a situation where both flags were
>>> set together, it would mean a bug. If a record ends with new line, it
>>> is not continuous and vice versa.
>>
>> At an abstract level this makes sense to me too, but the code
>> is written to handle many combinations of flags that simply will
>> never happen.  It obscures what's going on, or is supposed to be
>> going on.  So to the reader, this appears much more complicated than
>> it really is.
> 
> Yes, the code is too complicated and deserve simplification.
> 
>>
>>> [...]
>>>
>>>> Signed-off-by: Alex Elder <elder@linaro.org>
>>>> ---
>>>>  kernel/printk/printk.c | 12 +++++-------
>>>>  1 file changed, 5 insertions(+), 7 deletions(-)
>>>>
>>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>>> index 13e839d..301ade3 100644
>>>> --- a/kernel/printk/printk.c
>>>> +++ b/kernel/printk/printk.c
>>>> @@ -1006,11 +1006,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
>>>>  		prefix = false;
>>>>  
>>>>  	if (msg->flags & LOG_CONT) {
>>>> -		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
>>>> +		if (prev & LOG_CONT)
>>>>  			prefix = false;
>>>> -
>>>> -		if (!(msg->flags & LOG_NEWLINE))
>>>> -			newline = false;
>>>> +		newline = false;
>>>>  	}
>>>
>>> Makes sense. I like it.
>>>
>>>>  	do {
>>>> @@ -1642,7 +1640,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>>>  	/* mark and strip a trailing newline */
>>>>  	if (text_len && text[text_len-1] == '\n') {
>>>>  		text_len--;
>>>> -		lflags |= LOG_NEWLINE;
>>>> +		lflags = LOG_NEWLINE;
>>>>  	}
>>>>  
>>>>  	/* strip kernel syslog prefix and extract log level or control flags */
>>>> @@ -1672,7 +1670,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>>>  		level = default_message_loglevel;
>>>>  
>>>>  	if (dict)
>>>> -		lflags |= LOG_PREFIX|LOG_NEWLINE;
>>>> +		lflags = LOG_PREFIX|LOG_NEWLINE;
>>>>  
>>>>  	if (!(lflags & LOG_NEWLINE)) {
>>>>  		/*
>>>> @@ -1688,7 +1686,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>>>>  		else
>>>>  			printed_len += log_store(facility, level,
>>>>  						 lflags | LOG_CONT, 0,
>>>> -						 dict, dictlen, text, text_len);
>>>> +						 NULL, 0, text, text_len);
>>>>  	} else {
>>>>  		bool stored = false;
>>>>  
>>>
>>> I am not sure that I like the last three changes. The logic is
>>> correct. But I think that these micro-optimizations makes the code less
>>> readable and prone to errors with reordering and other changes.
>>
>> It is not an optimization.  I don't care about that.
>>
>> It is replacing a variable with a constant, because I
>> know by static analysis that the variable will always
>> have constant value.  This makes it completely obvious
>> that "dict" will *never* be NULL in this case, and as
>> above, makes it more obvious what's happening.
>>
>> (You'll see in my follow-on series that I rely on the
>> assignment rather than |= in order to do some refactoring.)
> 
> As I said, I do not have strong opinion here. It might be interesting
> to see the whole serie to get better picture.

You'll see it.  Once I feel like this initial series is
close to acceptable (or accepted) I'll be posting the
others soon afterward.  I'd love to get it out this week.

>> If someone chooses to reorder the code in a way that
>> makes |= necessary (for example) will put that back
>> again, because not doing so would introduce a bug.
>>
>>> The original code does not harm. The new code is less obvious and will
>>> force many people to think why it is correct. Even you might be in
>>> doubts if you see it after few months :-)
>>
>> Actually I think it's the opposite.
>>
>>> Well, I do not have strong opinion here. Other people might see it
>>> different. Forcing people to think is not a bad idea after all :-)
>>
>> I may be naive, but I think it's a requirement if you're going
>> to change code.
> 
> But it is easier when the code is readable and there are as few
> surprises as possible. Also you never could have everything in your
> head. The less dependncy is there, the easier is to work with it.
> 
> Regarding the above changes. The origial code used the typical
> pattern. It set default value and then modified different flags according
> to various tests. It did not need to take care much of other flags that
> were not related to the given test.
> 
> If you add lated another flag and more tests, the final forced
> assignent could break things.
> 
> Also the hardcoded NULL is not obvious. If you would want to modify the
> code, you would need to think harder why it is there. IMHO, it does
> not bring any real benefit unless you want to use it for some furher
> optimization. But this is not visible from the patchset.

OK.  I think we disagree but I don't mind putting that "dict"
pointer back.  I find it much easier to deal with constants
than variables--constants are just that, unchanging.  Variables
can take on any value, including, possibly, unexpected ones.

> Please, take this as my personal opinion. I am not maintainer of this
> code and the final decisions will not not be mine. Also I am still
> learning good code patterns.

Given that, I will plan to keep the patch as it is posted
unless someone else weighs in to request the change you
suggest.

>> Thanks again for the review.  If you're willing after reading my
>> explanations, please offer an ACK or Reviewed-by (or further
>> questions and suggestions).  I'll have responses to your others
>> shortly.
> 
> I would like to see the bigger picture before :-)

OK, the big picture for this is that I have a set of about
5 more patches, which have the end result of eliminating
LOG_CONT and LOG_PREFIX.  The only thing that matters is
LOG_NEWLINE, which indicates the log entry completes a
sequence of one or more.  Most records will have that set;
any that do not will be "continuation" records, which should
be taken along with one or more successor records to make
up a single logical log entry.  There is no need for
LOG_PREFIX, because that is implied by the presence of
LOG_NEWLINE in the previous log entry.  We're already tracking
the previous record state where that's needed.

It's all clear how to get from here to there in the patches.

					-Alex



> Best Regards,
> Petr
> 

Re: [PATCH 1/4] printk: LOG_CONT and LOG_NEWLINE are separate

[Petr Mládek]

On Thu 2014-07-17 11:19:15, Alex Elder wrote:
> On 07/17/2014 09:46 AM, Petr Mládek wrote:
> > On Thu 2014-07-17 07:11:39, Alex Elder wrote:
> >> On 07/17/2014 03:39 AM, Petr Mládek wrote:
> >>> On Wed 2014-07-16 12:26:57, Alex Elder wrote:
> >>>> Two log record flags--LOG_CONT and LOG_NEWLINE--are never both set
> >>>> at the same time in a log record flags field.  What follows is a
> >>>> great deal of explanation that aims to prove this assertion.
> >>
> >> Thank you so much for reviewing these patches.
> >>
> >> Your confirmation of the fact that LOG_CONT and LOG_NEWLINE
> >> should not go together is very valuable to me.  I have a set
> >> of follow-on patches that rely on this, and I didn't want to
> >> go ahead with proposing them until I knew this was right.
> > 
> > To be honest. My statement was based on a common sense. I simply
> > cannot imagine situatiuon when a text ends with "\n" and is continuous
> > at the same time. IMHO, it is against any logic.
> 
> Well, I thought so too, but it was hard to see that by
> just looking at the code.
> 
> > IMHO, it would make sense to have only one flag, either LOG_NEWLINE or
> > LOG_CONT. Well, I am not sure if we could remove it easily. AFAIK, the
> > ring buffer is read also by external tools, e.g. crash.
> 
> I took a very quick look at crash-7.0.7 and see dump_log_entry(),
> which seems to dump the contents of a log record but does not
> interpret any of the flags.

Good to know.

> This is a really important point, so if anybody knows of other
> utilities outside the kernel that interpret the log record flags
> I'd like to know about it.

AFAIK, also makedumpfile tool somehow access the private data.
See the comments for log_buf_kexec_setup()

[...]
 
> >> Thanks again for the review.  If you're willing after reading my
> >> explanations, please offer an ACK or Reviewed-by (or further
> >> questions and suggestions).  I'll have responses to your others
> >> shortly.
> > 
> > I would like to see the bigger picture before :-)
> 
> OK, the big picture for this is that I have a set of about
> 5 more patches, which have the end result of eliminating
> LOG_CONT and LOG_PREFIX.  The only thing that matters is
> LOG_NEWLINE, which indicates the log entry completes a
> sequence of one or more.  Most records will have that set;
> any that do not will be "continuation" records, which should
> be taken along with one or more successor records to make
> up a single logical log entry.  There is no need for
> LOG_PREFIX, because that is implied by the presence of
> LOG_NEWLINE in the previous log entry.  We're already tracking
> the previous record state where that's needed.

I wanted to think about this over night. And Kay actually confirmed my
doubts. There are various situations when the messages could get mixed
either when writing or when reading.

We do not care much about whole lines. Users are usually able to put
the right lines together by context.

Most of the hackery seems to be done for the continuous lines. The
following problematic situations come to my mind:


1. More tasks are printing at the same time. It is solved by flushing
   the cont buffer with newline when message from another task comes.

2. Someone prints continuous lines and forgets to put '\n' at the end.
   This is solved by flushing the cont buffer with newline when
   the same tasks prints new message with prefix.

3. Task is interrupted and the handler prints something. It is not
   currently detected. It is fine because it usually looks like
   the second scenario. The handler prints the first message with
   prefix...

4. There is a flood of messages. The readers, e.g. console, syslog,
   are not able to handle everything. They copy a continuous line and
   miss the rest. This is currently solved by resetting the flags
   for the previous message. I think that it is handled as if
   the previous line was newline.


The question is how many flags we need to handle the situations
reasonable way. We are discussing the three flags:

	   LOG_CONT
	   LOG_NEWLINE
	   LOG_PREFIX

Let's start with CONT and NEWLINE. The only situation when they
have the same value is when readers miss a message and reset the flag
for the previous message. It has the meaning: "we do not know".

IMHO, we do not need both CONT and NEWLINE flags. If we do not know
what was the last message, we need to decide somehow. It seems that we
currently do nothing special and expect that the last message ended
with newline. It means that the we could omit LOG_CONT flag and
simplify the code.


What about LOG_PREFIX? IMHO, we need it because the following
situations:

a) printk() could not modify flags of the previous messages. They
might be already proceed by readers, .e.g console, syslog. We could
not add LOG_NEWLINE flag to the previous message if suddenly new
message with prefix comes and the previous was already flushed
without newline.

b) Readers might miss messages. We might want to print '\n' if
the previous message was proceed without newline and the current
one has prefix.


What are the expectations from any changes?

The code is already too complex. IMHO, nobody wants to make it worse
just to fix the few remaining corner cases.

Any simplification is great if it keeps the output reasonable.

Best Regards,
Petr