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 surrounds a "*** XXX printk messages dropped ***"
message with newlines, to improve readability.
The second patch inserts a newline in /dev/kmsg output in the
event a LOG_PREFIX record follows a LOG_CONT record.
The third patch changes how two global variables are initialized,
allowing the second patch to assume they always hold certain values.
The fourth patch simplifies some code based on the observation that
the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
The fifth and sixth patches fix a bug in two places. The bug is
that a LOG_PREFIX in a record should implicitly terminate its
predecessor, even if the predecessor was marked LOG_CONT.
One trivial final patch is included at the end of the series.
-Alex
History:
v5: - Initialized "prev" variables to LOG_NEWLINE in two more
spots, as suggested.
- Preserve previous flags when re-initializing "prev"
variables when previous log messages have been reused.
- Insert newline in msg_print_text() outside loop.
- Moved "insert newline" patch earlier in series.
- Rebased on v3.16-rc6.
v4: - Fixed two things I messed up in v3:
- Fixed a sprintf() warning I mistakenly created.
- Re-added a hunk inadvertently dropped from patch 3.
v3: - Inserted a patch to report dropped message on a new line.
- Dropped a hunk from the (now) third patch, as requested.
- Now insert a newline in msg_print_text() in addition to
devkmsg_read().
- Added Reviewed-by tags where appropriate.
v2: - Added a patch to initialize two globals with LOG_NEWLINE.
- Changed the (now) second patch to argue that LOG_CONT and
LOG_NEWLINES are mutally exclusive.
- Added a patch to insert a newline in one case in devkmsg_read().
- Added some extra parentheses in some conditions, as requested.
- Fixed and updated some header commentary.
- Deleted a hunk in the typo patch, as requested.
This series, based on v3.16-rc6, is available here:
http://git.linaro.org/landing-teams/working/broadcom/kernel.git
Branch review/printk-flags-v5
Alex Elder (7):
printk: report dropped messages on separate line
printk: insert newline for truncated records
printk: initialize syslog_prev and console_prev
printk: LOG_CONT and LOG_NEWLINE are opposites
printk: honor LOG_PREFIX in devkmsg_read()
printk: honor LOG_PREFIX in msg_print_text()
printk: correct some more typos
kernel/printk/printk.c | 104 +++++++++++++++++++++++++++++++------------------
1 file changed, 66 insertions(+), 38 deletions(-)
--
1.9.1
It is possible for the log to be filled too quickly for the consoles
to be able to keep up. This is detected in console_unlock(), and when
it occurs, a message is inserted to note the event. When reviewing
some nearby code, Petr Mládek suggested it might be nicer if this
message were placed on a separate line. This patch implements that
suggestion.
Suggested-by: Petr Mládek <[email protected]>
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mládek <[email protected]>
---
kernel/printk/printk.c | 5 +++--
1 file changed, 3 insertions(+), 2 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 13e839d..ffc9928 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2142,9 +2142,10 @@ again:
}
if (console_seq < log_first_seq) {
- len = sprintf(text, "** %u printk messages dropped ** ",
+ len = sprintf(text,
+ "%s** %u printk messages dropped **\n",
+ (console_prev & LOG_CONT) ? "\n" : "",
(unsigned)(log_first_seq - console_seq));
-
/* messages are gone, move to first one */
console_seq = log_first_seq;
console_idx = log_first_idx;
--
1.9.1
Two global variables, "syslog_prev" and "console_prev", maintain a
copy of the flags value used in the log record most recently
formatted for syslog or the console, respectively.
Initially there is no previous formatted log record, and these
variables simply have an initial value 0. And occasionally log
records can get consumed at a rate such that syslog or the console
can't keep up, in which case those variables (along with their
corresponding position variables) must be reset. Here too, they're
reset to 0.
This patch changes it so the initial value used is LOG_NEWLINE.
That is, if we know nothing about the prevously-formatted log
record, we can assume it was complete, and ended with a newline.
One exception is that occasionally we reset our syslog or console
(etc.) position variables. In that case the previously-formatted
record flags value is still valid, so we preserve that information.
This is being done to support the next patch. Initializing
these variables this way makes LOG_NEWLINE and LOG_CONT be
mutually exclusive, and the next patch uses that fact to simplify
some logic.
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mládek <[email protected]>
---
kernel/printk/printk.c | 44 ++++++++++++++++++++++++++++++--------------
1 file changed, 30 insertions(+), 14 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9f11eab..2f43116 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -236,7 +236,7 @@ DECLARE_WAIT_QUEUE_HEAD(log_wait);
/* 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 enum log_flags syslog_prev = LOG_NEWLINE;
static size_t syslog_partial;
/* index and sequence number of the first record stored in the buffer */
@@ -250,7 +250,7 @@ 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;
+static enum log_flags console_prev = LOG_NEWLINE;
/* the next printk record to read after the last 'clear' command */
static u64 clear_seq;
@@ -1078,10 +1078,14 @@ static int syslog_print(char __user *buf, int size)
raw_spin_lock_irq(&logbuf_lock);
if (syslog_seq < log_first_seq) {
- /* messages are gone, move to first one */
+ /*
+ * Messages are gone, move to first one.
+ * Don't discard what we know about the
+ * previously-formatted record.
+ */
syslog_seq = log_first_seq;
syslog_idx = log_first_idx;
- syslog_prev = 0;
+ syslog_prev &= LOG_NEWLINE|LOG_CONT;
syslog_partial = 0;
}
if (syslog_seq == log_next_seq) {
@@ -1154,7 +1158,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
*/
seq = clear_seq;
idx = clear_idx;
- prev = 0;
+ prev = LOG_NEWLINE;
while (seq < log_next_seq) {
struct printk_log *msg = log_from_idx(idx);
@@ -1167,7 +1171,7 @@ 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;
+ prev = LOG_NEWLINE;
while (len > size && seq < log_next_seq) {
struct printk_log *msg = log_from_idx(idx);
@@ -1203,10 +1207,14 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
raw_spin_lock_irq(&logbuf_lock);
if (seq < log_first_seq) {
- /* messages are gone, move to next one */
+ /*
+ * Messages are gone, move to first one.
+ * Don't discard what we know about the
+ * previously-formatted record.
+ */
seq = log_first_seq;
idx = log_first_idx;
- prev = 0;
+ prev &= LOG_NEWLINE|LOG_CONT;
}
}
}
@@ -1308,10 +1316,14 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
case SYSLOG_ACTION_SIZE_UNREAD:
raw_spin_lock_irq(&logbuf_lock);
if (syslog_seq < log_first_seq) {
- /* messages are gone, move to first one */
+ /*
+ * Messages are gone, move to first one.
+ * Don't discard what we know about the
+ * previously-formatted record.
+ */
syslog_seq = log_first_seq;
syslog_idx = log_first_idx;
- syslog_prev = 0;
+ syslog_prev &= LOG_NEWLINE|LOG_CONT;
syslog_partial = 0;
}
if (from_file) {
@@ -2156,10 +2168,14 @@ again:
"%s** %u printk messages dropped **\n",
(console_prev & LOG_CONT) ? "\n" : "",
(unsigned)(log_first_seq - console_seq));
- /* messages are gone, move to first one */
+ /*
+ * Messages are gone, move to first one.
+ * Don't discard what we know about the
+ * previously-formatted record.
+ */
console_seq = log_first_seq;
console_idx = log_first_idx;
- console_prev = 0;
+ console_prev &= LOG_NEWLINE|LOG_CONT;
} else {
len = 0;
}
@@ -2873,7 +2889,7 @@ 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;
+ prev = LOG_NEWLINE;
while (seq < dumper->next_seq) {
struct printk_log *msg = log_from_idx(idx);
@@ -2886,7 +2902,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
/* move first record forward until length fits into the buffer */
seq = dumper->cur_seq;
idx = dumper->cur_idx;
- prev = 0;
+ prev = LOG_NEWLINE;
while (l > size && seq < dumper->next_seq) {
struct printk_log *msg = log_from_idx(idx);
--
1.9.1
Two log record flags--LOG_CONT and LOG_NEWLINE--are mutually
exclusive. That is, one or the other is always set, but they 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, and with
a little more work (in follow-on patches) it allows us to do without
a flag value, simplifying things.
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 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
locally-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. If LOG_NEWLINE
is not set, LOG_CONT flag is added in the call to log_store(). So
there are four possible flag combinations supplied by vprintk_emit():
LOG_CONT; LOG_NEWLINE; 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, and one of those
flags is always present.
Meanwhile, the "cont" flags field is only ever assigned value 0, or
a value passed to cont_flush(). The value of cont.flags is only
ever *used* if cont.flushed is true, and that only gets set after
the cont.flags field is assigned to the value passed to
cont_flush(). As mentioned above, cont_flush() is never provided
more than one flag value, and it's always either LOG_NEWLINE
or LOG_CONT. Therefore, for all intents and purposes, cont.flags
only ever holds LOG_NEWLINE or LOG_CONT.
The only values assigned to "syslog_prev" and "console_prev" are the
initial value LOG_NEWLINE 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 LOG_CONT and LOG_NEWLINE are in fact mutually
exclusive flags.
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.
- Assigns LOG_CONT to "lflags" in vprintk_emit() if it does not
contain LOG_NEWLINE (rather than just adding it at the time
of the call to log_store()).
- Adds a short explanatory comment.
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mládek <[email protected]>
---
kernel/printk/printk.c | 21 ++++++++++++---------
1 file changed, 12 insertions(+), 9 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f43116..217a02a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1010,11 +1010,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;
}
if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && len < size) {
@@ -1661,10 +1659,16 @@ asmlinkage int vprintk_emit(int facility, int level,
text_len += vscnprintf(text + text_len,
sizeof(textbuf) - text_len, fmt, args);
- /* mark and strip a trailing newline */
+ /*
+ * If there's a trailing newline, flag it and strip it off.
+ * Otherwise we assume this is a partial log message, to be
+ * continued with the next call.
+ */
if (text_len && text[text_len-1] == '\n') {
text_len--;
- lflags |= LOG_NEWLINE;
+ lflags = LOG_NEWLINE;
+ } else {
+ lflags = LOG_CONT;
}
/* strip kernel syslog prefix and extract log level or control flags */
@@ -1694,7 +1698,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)) {
/*
@@ -1708,8 +1712,7 @@ asmlinkage int vprintk_emit(int facility, int level,
if (cont_add(facility, level, text, text_len))
printed_len += text_len;
else
- printed_len += log_store(facility, level,
- lflags | LOG_CONT, 0,
+ printed_len += log_store(facility, level, lflags, 0,
dict, dictlen, text, text_len);
} else {
bool stored = false;
--
1.9.1
This patch corrects a few more typographical errors in "printk.c".
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mládek <[email protected]>
---
kernel/printk/printk.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cbcfb20..0c585d4 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.
@@ -615,7 +615,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.
@@ -2913,7 +2913,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;
@@ -2939,7 +2939,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
@@ -2957,7 +2957,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
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 | clear| set || false
set | set | clear|| true
set | set | set || false <-- should be true
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mládek <[email protected]>
---
kernel/printk/printk.c | 5 +----
1 file changed, 1 insertion(+), 4 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e9e5104..cbcfb20 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1010,11 +1010,8 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
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;
- }
if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && len < size) {
if (buf)
--
1.9.1
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 | clear| set || '+'
set | set | clear|| '-'
set | set | set || '+' <-- should be 'c'
Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
---
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 217a02a..e9e5104 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;
bool insert_newline;
@@ -620,11 +620,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 = '-';
/* Insert a newline if the previous line was not terminated properly */
insert_newline = (user->prev & LOG_CONT) && (msg->flags & LOG_PREFIX);
--
1.9.1
If a log record has LOG_PREFIX set, its predecessor record should be
terminated if it was marked LOG_CONT.
In devkmsg_read(), this condition was being ignored, which would
lead to such records showing up combined when reading /dev/kmsg.
Fix this oversight.
We should similarly insert a newline in msg_print_text() in this
case, to avoid formatted records getting merged.
Suggested-by: Petr Mládek <[email protected]>
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 12 +++++++++++-
1 file changed, 11 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ffc9928..9f11eab 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -575,6 +575,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
char cont = '-';
size_t len;
ssize_t ret;
+ bool insert_newline;
if (!user)
return -EBADF;
@@ -625,7 +626,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
cont = '+';
- len = sprintf(user->buf, "%u,%llu,%llu,%c;",
+ /* Insert a newline if the previous line was not terminated properly */
+ insert_newline = (user->prev & LOG_CONT) && (msg->flags & LOG_PREFIX);
+ len = sprintf(user->buf, "%s%u,%llu,%llu,%c;",
+ insert_newline ? "\n" : "",
(msg->facility << 3) | msg->level,
user->seq, ts_usec, cont);
user->prev = msg->flags;
@@ -1013,6 +1017,12 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
newline = false;
}
+ if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && len < size) {
+ if (buf)
+ buf[len++] = '\n';
+ else
+ len++;
+ }
do {
const char *next = memchr(text, '\n', text_size);
size_t text_len;
--
1.9.1
On Mon 2014-07-21 08:02:36, Alex Elder wrote:
> If a log record has LOG_PREFIX set, its predecessor record should be
> terminated if it was marked LOG_CONT.
>
> In devkmsg_read(), this condition was being ignored, which would
> lead to such records showing up combined when reading /dev/kmsg.
> Fix this oversight.
>
> We should similarly insert a newline in msg_print_text() in this
> case, to avoid formatted records getting merged.
>
> Suggested-by: Petr Ml?dek <[email protected]>
> Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
Best Regards,
Petr
> ---
> kernel/printk/printk.c | 12 +++++++++++-
> 1 file changed, 11 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ffc9928..9f11eab 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -575,6 +575,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
> char cont = '-';
> size_t len;
> ssize_t ret;
> + bool insert_newline;
>
> if (!user)
> return -EBADF;
> @@ -625,7 +626,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
> ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
> cont = '+';
>
> - len = sprintf(user->buf, "%u,%llu,%llu,%c;",
> + /* Insert a newline if the previous line was not terminated properly */
> + insert_newline = (user->prev & LOG_CONT) && (msg->flags & LOG_PREFIX);
> + len = sprintf(user->buf, "%s%u,%llu,%llu,%c;",
> + insert_newline ? "\n" : "",
> (msg->facility << 3) | msg->level,
> user->seq, ts_usec, cont);
> user->prev = msg->flags;
> @@ -1013,6 +1017,12 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
> newline = false;
> }
>
> + if ((prev & LOG_CONT) && (msg->flags & LOG_PREFIX) && len < size) {
> + if (buf)
> + buf[len++] = '\n';
> + else
> + len++;
> + }
> do {
> const char *next = memchr(text, '\n', text_size);
> size_t text_len;
> --
> 1.9.1
>
On Mon 2014-07-21 08:02:34, 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 surrounds a "*** XXX printk messages dropped ***"
> message with newlines, to improve readability.
>
> The second patch inserts a newline in /dev/kmsg output in the
> event a LOG_PREFIX record follows a LOG_CONT record.
>
> The third patch changes how two global variables are initialized,
> allowing the second patch to assume they always hold certain values.
>
> The fourth patch simplifies some code based on the observation that
> the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
>
> The fifth and sixth patches fix a bug in two places. The bug is
> that a LOG_PREFIX in a record should implicitly terminate its
> predecessor, even if the predecessor was marked LOG_CONT.
>
> One trivial final patch is included at the end of the series.
>
> -Alex
>
> History:
> v5: - Initialized "prev" variables to LOG_NEWLINE in two more
> spots, as suggested.
> - Preserve previous flags when re-initializing "prev"
> variables when previous log messages have been reused.
> - Insert newline in msg_print_text() outside loop.
> - Moved "insert newline" patch earlier in series.
> - Rebased on v3.16-rc6.
> v4: - Fixed two things I messed up in v3:
> - Fixed a sprintf() warning I mistakenly created.
> - Re-added a hunk inadvertently dropped from patch 3.
> v3: - Inserted a patch to report dropped message on a new line.
> - Dropped a hunk from the (now) third patch, as requested.
> - Now insert a newline in msg_print_text() in addition to
> devkmsg_read().
> - Added Reviewed-by tags where appropriate.
> v2: - Added a patch to initialize two globals with LOG_NEWLINE.
> - Changed the (now) second patch to argue that LOG_CONT and
> LOG_NEWLINES are mutally exclusive.
> - Added a patch to insert a newline in one case in devkmsg_read().
> - Added some extra parentheses in some conditions, as requested.
> - Fixed and updated some header commentary.
> - Deleted a hunk in the typo patch, as requested.
>
> This series, based on v3.16-rc6, is available here:
> http://git.linaro.org/landing-teams/working/broadcom/kernel.git
> Branch review/printk-flags-v5
>
> Alex Elder (7):
> printk: report dropped messages on separate line
> printk: insert newline for truncated records
> printk: initialize syslog_prev and console_prev
> printk: LOG_CONT and LOG_NEWLINE are opposites
> printk: honor LOG_PREFIX in devkmsg_read()
> printk: honor LOG_PREFIX in msg_print_text()
> printk: correct some more typos
>
> kernel/printk/printk.c | 104 +++++++++++++++++++++++++++++++------------------
> 1 file changed, 66 insertions(+), 38 deletions(-)
Sadly the clean up could not be as big as we hoped. But there are some
wins:
1. It cleans up LOG_CONT/LOG_NEWLINE handling. Some conditions are
easier. Also we are ready to remove LOG_CONT entirely.
2. IT fixes some bugs. It better handles unfinished continuous lines.
Prefix should not longer appear in the middle of line.
It looks fine from my point of view.
Best Regards,
Petr
On 07/22/2014 05:04 AM, Petr Ml?dek wrote:
> On Mon 2014-07-21 08:02:34, 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 surrounds a "*** XXX printk messages dropped ***"
>> message with newlines, to improve readability.
>>
>> The second patch inserts a newline in /dev/kmsg output in the
>> event a LOG_PREFIX record follows a LOG_CONT record.
>>
>> The third patch changes how two global variables are initialized,
>> allowing the second patch to assume they always hold certain values.
>>
>> The fourth patch simplifies some code based on the observation that
>> the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
>>
>> The fifth and sixth patches fix a bug in two places. The bug is
>> that a LOG_PREFIX in a record should implicitly terminate its
>> predecessor, even if the predecessor was marked LOG_CONT.
>>
>> One trivial final patch is included at the end of the series.
>>
>> -Alex
>>
>> History:
>> v5: - Initialized "prev" variables to LOG_NEWLINE in two more
>> spots, as suggested.
>> - Preserve previous flags when re-initializing "prev"
>> variables when previous log messages have been reused.
>> - Insert newline in msg_print_text() outside loop.
>> - Moved "insert newline" patch earlier in series.
>> - Rebased on v3.16-rc6.
>> v4: - Fixed two things I messed up in v3:
>> - Fixed a sprintf() warning I mistakenly created.
>> - Re-added a hunk inadvertently dropped from patch 3.
>> v3: - Inserted a patch to report dropped message on a new line.
>> - Dropped a hunk from the (now) third patch, as requested.
>> - Now insert a newline in msg_print_text() in addition to
>> devkmsg_read().
>> - Added Reviewed-by tags where appropriate.
>> v2: - Added a patch to initialize two globals with LOG_NEWLINE.
>> - Changed the (now) second patch to argue that LOG_CONT and
>> LOG_NEWLINES are mutally exclusive.
>> - Added a patch to insert a newline in one case in devkmsg_read().
>> - Added some extra parentheses in some conditions, as requested.
>> - Fixed and updated some header commentary.
>> - Deleted a hunk in the typo patch, as requested.
>>
>> This series, based on v3.16-rc6, is available here:
>> http://git.linaro.org/landing-teams/working/broadcom/kernel.git
>> Branch review/printk-flags-v5
>>
>> Alex Elder (7):
>> printk: report dropped messages on separate line
>> printk: insert newline for truncated records
>> printk: initialize syslog_prev and console_prev
>> printk: LOG_CONT and LOG_NEWLINE are opposites
>> printk: honor LOG_PREFIX in devkmsg_read()
>> printk: honor LOG_PREFIX in msg_print_text()
>> printk: correct some more typos
>>
>> kernel/printk/printk.c | 104 +++++++++++++++++++++++++++++++------------------
>> 1 file changed, 66 insertions(+), 38 deletions(-)
>
> Sadly the clean up could not be as big as we hoped. But there are some
> wins:
>
> 1. It cleans up LOG_CONT/LOG_NEWLINE handling. Some conditions are
> easier. Also we are ready to remove LOG_CONT entirely.
>
> 2. IT fixes some bugs. It better handles unfinished continuous lines.
> Prefix should not longer appear in the middle of line.
>
>
> It looks fine from my point of view.
Thank you very much Petr.
I found another problem or two in my own review after posting,
but didn't want to add more mail traffic to what I've already
produced, so I've waited to make any remarks. I will send out
my comments, and then one (hopefully!) final version 6 of this
series.
-Alex
> Best Regards,
> Petr
>
On 07/21/2014 08:02 AM, Alex Elder wrote:
> Two global variables, "syslog_prev" and "console_prev", maintain a
> copy of the flags value used in the log record most recently
> formatted for syslog or the console, respectively.
>
> Initially there is no previous formatted log record, and these
> variables simply have an initial value 0. And occasionally log
> records can get consumed at a rate such that syslog or the console
> can't keep up, in which case those variables (along with their
> corresponding position variables) must be reset. Here too, they're
> reset to 0.
>
> This patch changes it so the initial value used is LOG_NEWLINE.
> That is, if we know nothing about the prevously-formatted log
> record, we can assume it was complete, and ended with a newline.
> One exception is that occasionally we reset our syslog or console
> (etc.) position variables. In that case the previously-formatted
> record flags value is still valid, so we preserve that information.
>
> This is being done to support the next patch. Initializing
> these variables this way makes LOG_NEWLINE and LOG_CONT be
> mutually exclusive, and the next patch uses that fact to simplify
> some logic.
>
> Signed-off-by: Alex Elder <[email protected]>
> Reviewed-by: Petr Mládek <[email protected]>
I have one change I'd like to suggest on this one.
Petr, could you offer your opinion?
> ---
> kernel/printk/printk.c | 44 ++++++++++++++++++++++++++++++--------------
> 1 file changed, 30 insertions(+), 14 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 9f11eab..2f43116 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
. . .
> @@ -2156,10 +2168,14 @@ again:
> "%s** %u printk messages dropped **\n",
> (console_prev & LOG_CONT) ? "\n" : "",
> (unsigned)(log_first_seq - console_seq));
> - /* messages are gone, move to first one */
> + /*
> + * Messages are gone, move to first one.
> + * Don't discard what we know about the
> + * previously-formatted record.
> + */
> console_seq = log_first_seq;
> console_idx = log_first_idx;
> - console_prev = 0;
> + console_prev &= LOG_NEWLINE|LOG_CONT;
In this one spot, I think console_prev should simply be
initialized with LOG_NEWLINE.
The reason is that the "printk messages dropped" message will
be inserted into the formatted output, and is hence the last
formatted line. And that message is (now) terminated with
a newline.
-Alex
> } else {
> len = 0;
> }
. . .
On Tue 2014-07-22 06:48:22, Alex Elder wrote:
> On 07/21/2014 08:02 AM, Alex Elder wrote:
> > Two global variables, "syslog_prev" and "console_prev", maintain a
> > copy of the flags value used in the log record most recently
> > formatted for syslog or the console, respectively.
> >
> > Initially there is no previous formatted log record, and these
> > variables simply have an initial value 0. And occasionally log
> > records can get consumed at a rate such that syslog or the console
> > can't keep up, in which case those variables (along with their
> > corresponding position variables) must be reset. Here too, they're
> > reset to 0.
> >
> > This patch changes it so the initial value used is LOG_NEWLINE.
> > That is, if we know nothing about the prevously-formatted log
> > record, we can assume it was complete, and ended with a newline.
> > One exception is that occasionally we reset our syslog or console
> > (etc.) position variables. In that case the previously-formatted
> > record flags value is still valid, so we preserve that information.
> >
> > This is being done to support the next patch. Initializing
> > these variables this way makes LOG_NEWLINE and LOG_CONT be
> > mutually exclusive, and the next patch uses that fact to simplify
> > some logic.
> >
> > Signed-off-by: Alex Elder <[email protected]>
> > Reviewed-by: Petr Ml?dek <[email protected]>
>
> I have one change I'd like to suggest on this one.
>
> Petr, could you offer your opinion?
>
>
> > ---
> > kernel/printk/printk.c | 44 ++++++++++++++++++++++++++++++--------------
> > 1 file changed, 30 insertions(+), 14 deletions(-)
> >
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 9f11eab..2f43116 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
>
>
> . . .
>
> > @@ -2156,10 +2168,14 @@ again:
> > "%s** %u printk messages dropped **\n",
> > (console_prev & LOG_CONT) ? "\n" : "",
> > (unsigned)(log_first_seq - console_seq));
> > - /* messages are gone, move to first one */
> > + /*
> > + * Messages are gone, move to first one.
> > + * Don't discard what we know about the
> > + * previously-formatted record.
> > + */
> > console_seq = log_first_seq;
> > console_idx = log_first_idx;
> > - console_prev = 0;
> > + console_prev &= LOG_NEWLINE|LOG_CONT;
>
> In this one spot, I think console_prev should simply be
> initialized with LOG_NEWLINE.
>
> The reason is that the "printk messages dropped" message will
> be inserted into the formatted output, and is hence the last
> formatted line. And that message is (now) terminated with
> a newline.
Sure. Great catch! I actually mentioned it when commenting v4, see
https://lkml.org/lkml/2014/7/21/153 . But I forgot it today :-/
Best Regards,
Petr