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 changes how two global variables are initialized,
allowing the second patch to assume they always hold certain values.
The second patch simplifies some code based on the observation that
the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
The third and fourth patch 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.
The fifth patch inserts a newline in /dev/kmsg output in the
event a LOG_PREFIX record follows a LOG_CONT record.
One trivial final patch is included at the end of the series.
-Alex
History:
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-rc5, is available here:
http://git.linaro.org/landing-teams/working/broadcom/kernel.git
Branch review/printk-flags-v2
Alex Elder (6):
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: insert newline in devkmsg_read()
printk: correct some more typos
kernel/printk/printk.c | 63 +++++++++++++++++++++++++++-----------------------
1 file changed, 34 insertions(+), 29 deletions(-)
--
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 1ee1862..5d719bf 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
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]>
---
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 5d719bf..e5ee1cb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1006,11 +1006,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;
- }
do {
const char *next = memchr(text, '\n', text_size);
--
1.9.1
This patch corrects a few more typographical errors in "printk.c".
Signed-off-by: Alex Elder <[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 3174ba9..eff68a4 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.
@@ -2890,7 +2890,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;
@@ -2916,7 +2916,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
@@ -2934,7 +2934,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
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
some flag values, considerably 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 cont_flush():
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.
- 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 <[email protected]>
---
kernel/printk/printk.c | 23 +++++++++++++----------
1 file changed, 13 insertions(+), 10 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ff1c7ad..1ee1862 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 {
@@ -1639,10 +1637,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 */
@@ -1672,7 +1676,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)) {
/*
@@ -1686,9 +1690,8 @@ 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,
- dict, dictlen, text, text_len);
+ printed_len += log_store(facility, level, lflags, 0,
+ NULL, 0, text, text_len);
} else {
bool stored = false;
--
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.
Reported-by: Petr Mládek <[email protected]>
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e5ee1cb..3174ba9 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;
@@ -626,7 +627,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
else
cont = '-';
- len = sprintf(user->buf, "%u,%llu,%llu,%c;",
+ /* Insert a newline if we're terminating the previous record early */
+ 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;
--
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.
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]>
---
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 13e839d..ff1c7ad 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;
@@ -1071,7 +1071,7 @@ static int syslog_print(char __user *buf, int size)
/* messages are gone, move to first one */
syslog_seq = log_first_seq;
syslog_idx = log_first_idx;
- syslog_prev = 0;
+ syslog_prev = LOG_NEWLINE;
syslog_partial = 0;
}
if (syslog_seq == log_next_seq) {
@@ -1301,7 +1301,7 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
/* messages are gone, move to first one */
syslog_seq = log_first_seq;
syslog_idx = log_first_idx;
- syslog_prev = 0;
+ syslog_prev = LOG_NEWLINE;
syslog_partial = 0;
}
if (from_file) {
@@ -2148,7 +2148,7 @@ again:
/* messages are gone, move to first one */
console_seq = log_first_seq;
console_idx = log_first_idx;
- console_prev = 0;
+ console_prev = LOG_NEWLINE;
} else {
len = 0;
}
--
1.9.1
Again adding Kay Sievers.
Kay wrote almost all of this originally and should
be able to review it.
Alex, if this series is resubmitted, do please cc Kay.
It does seem reasonable to me, thanks for doing it.
On Thu, 2014-07-17 at 09:09 -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 changes how two global variables are initialized,
> allowing the second patch to assume they always hold certain values.
>
> The second patch simplifies some code based on the observation that
> the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
>
> The third and fourth patch 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.
>
> The fifth patch inserts a newline in /dev/kmsg output in the
> event a LOG_PREFIX record follows a LOG_CONT record.
>
> One trivial final patch is included at the end of the series.
>
> -Alex
>
> History:
> 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-rc5, is available here:
> http://git.linaro.org/landing-teams/working/broadcom/kernel.git
> Branch review/printk-flags-v2
>
> Alex Elder (6):
> 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: insert newline in devkmsg_read()
> printk: correct some more typos
>
> kernel/printk/printk.c | 63 +++++++++++++++++++++++++++-----------------------
> 1 file changed, 34 insertions(+), 29 deletions(-)
>
On 07/17/2014 10:59 AM, Joe Perches wrote:
> Again adding Kay Sievers.
>
> Kay wrote almost all of this originally and should
> be able to review it.
>
> Alex, if this series is resubmitted, do please cc Kay.
Yes, sorry about that. I meant to but forgot. Thanks for
forwarding.
-Alex
> It does seem reasonable to me, thanks for doing it.
>
> On Thu, 2014-07-17 at 09:09 -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 changes how two global variables are initialized,
>> allowing the second patch to assume they always hold certain values.
>>
>> The second patch simplifies some code based on the observation that
>> the LOG_CONT and LOG_NEWLINE flags are mutually exclusive.
>>
>> The third and fourth patch 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.
>>
>> The fifth patch inserts a newline in /dev/kmsg output in the
>> event a LOG_PREFIX record follows a LOG_CONT record.
>>
>> One trivial final patch is included at the end of the series.
>>
>> -Alex
>>
>> History:
>> 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-rc5, is available here:
>> http://git.linaro.org/landing-teams/working/broadcom/kernel.git
>> Branch review/printk-flags-v2
>>
>> Alex Elder (6):
>> 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: insert newline in devkmsg_read()
>> printk: correct some more typos
>>
>> kernel/printk/printk.c | 63 +++++++++++++++++++++++++++-----------------------
>> 1 file changed, 34 insertions(+), 29 deletions(-)
>>
>
>
>
On Thu 2014-07-17 09:09:06, 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.
>
> 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]>
> ---
> 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 13e839d..ff1c7ad 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 above makes sense.
> /* the next printk record to read after the last 'clear' command */
> static u64 clear_seq;
> @@ -1071,7 +1071,7 @@ static int syslog_print(char __user *buf, int size)
> /* messages are gone, move to first one */
> syslog_seq = log_first_seq;
> syslog_idx = log_first_idx;
> - syslog_prev = 0;
> + syslog_prev = LOG_NEWLINE;
> syslog_partial = 0;
> }
> if (syslog_seq == log_next_seq) {
> @@ -1301,7 +1301,7 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
> /* messages are gone, move to first one */
> syslog_seq = log_first_seq;
> syslog_idx = log_first_idx;
> - syslog_prev = 0;
> + syslog_prev = LOG_NEWLINE;
> syslog_partial = 0;
> }
> if (from_file) {
> @@ -2148,7 +2148,7 @@ again:
> /* messages are gone, move to first one */
> console_seq = log_first_seq;
> console_idx = log_first_idx;
> - console_prev = 0;
> + console_prev = LOG_NEWLINE;
> } else {
> len = 0;
> }
It would make sense to add '\n' if we skip something and the previous
copied line was continuous. This would change the behavior, so we
should do this in separate patch.
Anyway, it makes sense to reset the flag to LOG_NEWLINE.
Reviewed-by: Petr Mladek <[email protected]>
> --
> 1.9.1
>
On Thu 2014-07-17 09:09:07, Alex Elder wrote:
> 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
> some flag values, considerably 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 cont_flush():
> 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.
> - 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 <[email protected]>
> ---
> kernel/printk/printk.c | 23 +++++++++++++----------
> 1 file changed, 13 insertions(+), 10 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ff1c7ad..1ee1862 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 {
> @@ -1639,10 +1637,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 */
> @@ -1672,7 +1676,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)) {
> /*
All the above changes make sense and I support them after all.
> @@ -1686,9 +1690,8 @@ 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,
> - dict, dictlen, text, text_len);
> + printed_len += log_store(facility, level, lflags, 0,
> + NULL, 0, text, text_len);
> } else {
> bool stored = false;
>
I do not see real benefit in this change. I think that it would cause
more confusion than help. I would suggest to remove it. Then I will
agree with this patch :-)
Best Regards,
Petr
On Thu 2014-07-17 09:09:09, 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.
>
> 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]>
> ---
> 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 5d719bf..e5ee1cb 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1006,11 +1006,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;
> - }
I agree. It does not make sense to remove prefix just because someone
forgot to finish the previous continuous line. Instead, we should add
'\n" and you will do this in the next patch.
Reviewed-by: Petr Mladek <[email protected]>
Best Regards,
Petr
On Thu 2014-07-17 09:09:10, 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.
>
> Reported-by: Petr Ml?dek <[email protected]>
> Signed-off-by: Alex Elder <[email protected]>
> ---
> kernel/printk/printk.c | 6 +++++-
> 1 file changed, 5 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e5ee1cb..3174ba9 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;
> @@ -626,7 +627,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
> else
> cont = '-';
>
> - len = sprintf(user->buf, "%u,%llu,%llu,%c;",
> + /* Insert a newline if we're terminating the previous record
> early */
More correct description would be:
/* 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;
Please, do similar change also in msg_print_text() that would fix also
syslog(). Note that syslog is the place where we stopped to disable
prefix when there was continuous line before.
Best Regards.
Petr
On Thu 2014-07-17 09:09:11, Alex Elder wrote:
> This patch corrects a few more typographical errors in "printk.c".
>
> Signed-off-by: Alex Elder <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
Best Regards,
Petr
> ---
> 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 3174ba9..eff68a4 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.
> @@ -2890,7 +2890,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;
>
> @@ -2916,7 +2916,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
> @@ -2934,7 +2934,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
>
On 07/18/2014 05:43 AM, Petr Ml?dek wrote:
> On Thu 2014-07-17 09:09:06, 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.
. . .
>> @@ -2148,7 +2148,7 @@ again:
>> /* messages are gone, move to first one */
>> console_seq = log_first_seq;
>> console_idx = log_first_idx;
>> - console_prev = 0;
>> + console_prev = LOG_NEWLINE;
>> } else {
>> len = 0;
>> }
>
> It would make sense to add '\n' if we skip something and the previous
> copied line was continuous. This would change the behavior, so we
> should do this in separate patch.
I'm working up a v3 of this series and have inserted a patch
that implements this at the beginning.
> Anyway, it makes sense to reset the flag to LOG_NEWLINE.
>
> Reviewed-by: Petr Mladek <[email protected]>
Thanks a lot.
-Alex
On 07/18/2014 05:53 AM, Petr Ml?dek wrote:
>> @@ -1686,9 +1690,8 @@ 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,
>> > - dict, dictlen, text, text_len);
>> > + printed_len += log_store(facility, level, lflags, 0,
>> > + NULL, 0, text, text_len);
>> > } else {
>> > bool stored = false;
>> >
> I do not see real benefit in this change. I think that it would cause
> more confusion than help. I would suggest to remove it. Then I will
> agree with this patch :-)
Done. I'm going to add your Reviewed-by based on this. Please correct
me if that's not what you want.
-Alex
On 07/18/2014 06:45 AM, Petr Ml?dek wrote:
> On Thu 2014-07-17 09:09:10, 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.
>>
>> Reported-by: Petr Ml?dek <[email protected]>
>> Signed-off-by: Alex Elder <[email protected]>
>> ---
>> kernel/printk/printk.c | 6 +++++-
>> 1 file changed, 5 insertions(+), 1 deletion(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index e5ee1cb..3174ba9 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;
>> @@ -626,7 +627,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
>> else
>> cont = '-';
>>
>> - len = sprintf(user->buf, "%u,%llu,%llu,%c;",
>> + /* Insert a newline if we're terminating the previous record
>> early */
>
> More correct description would be:
>
> /* Insert a newline if the previous line was not terminated properly */
I will change it as you suggest.
>
>> + 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;
>
> Please, do similar change also in msg_print_text() that would fix also
> syslog(). Note that syslog is the place where we stopped to disable
> prefix when there was continuous line before.
I will do this, as you will see in v3 which I plan to post in a
few hours. (Note that this touches a spot where I have yet another
minor bug fix that I have not yet posted... Oh well.)
-Alex
> Best Regards.
> Petr
>