>From 14cc1a7592e46a8b57081f90d7d54ab274ab7610 Mon Sep 17 00:00:00 2001
From: Arjan van de Ven <[email protected]>
Date: Mon, 15 Jun 2009 00:05:39 -0700
Subject: [PATCH] WARN(): add a \n to the message printk
many (most) users of WARN() don't have a \n at the end of their string;
as is understandable from the API usage point of view. But this means
that the backend needs to add this \n or the warning message
gets corrupted (as is seen by kerneloops.org).
Signed-off-by: Arjan van de Ven <[email protected]>
---
kernel/panic.c | 4 +++-
1 files changed, 3 insertions(+), 1 deletions(-)
diff --git a/kernel/panic.c b/kernel/panic.c
index 984b3ec..08ce451 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -355,8 +355,10 @@ static void warn_slowpath_common(const char *file, int line, void *caller, struc
if (board)
printk(KERN_WARNING "Hardware name: %s\n", board);
- if (args)
+ if (args) {
vprintk(args->fmt, args->args);
+ printk("\n");
+ }
print_modules();
dump_stack();
--
1.6.0.6
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
> + if (args) {
> vprintk(args->fmt, args->args);
> + printk("\n");
What stops another printk occuring between those two ?
Alan
On Mon, 15 Jun 2009 10:09:51 +0100
Alan Cox <[email protected]> wrote:
> > + if (args) {
> > vprintk(args->fmt, args->args);
> > + printk("\n");
>
> What stops another printk occuring between those two ?
>
absolutely nothing... and in that case you get what you get in a
million other places in the kernel; a bit of a mix.
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Mon, 15 Jun 2009, Arjan van de Ven wrote:
>
> - if (args)
> + if (args) {
> vprintk(args->fmt, args->args);
> + printk("\n");
> + }
I really don't like this. What if the format already does have a '\n'? And
what if some other CPU is printing at the same time?
I'd almost be open to adding a "flags" field to vprintk, and allow setting
things like "finish line with \n" there. Or perhaps even better, have a
"vprintk_line()" function that does it with no dynamic flags. Maybe make
it static, and move all these panic helper funtions into kernel/printk.c
(since this really is a special case).
I dunno. I'm just throwing out suggestions. I just don't think the above
patch is very nice.
Linus
On Mon, 15 Jun 2009, Linus Torvalds wrote:
>
> On Mon, 15 Jun 2009, Arjan van de Ven wrote:
> >
> > - if (args)
> > + if (args) {
> > vprintk(args->fmt, args->args);
> > + printk("\n");
> > + }
>
> I really don't like this. What if the format already does have a '\n'? And
> what if some other CPU is printing at the same time?
>
> I'd almost be open to adding a "flags" field to vprintk, and allow setting
> things like "finish line with \n" there. Or perhaps even better, have a
> "vprintk_line()" function that does it with no dynamic flags. Maybe make
> it static, and move all these panic helper funtions into kernel/printk.c
> (since this really is a special case).
>
> I dunno. I'm just throwing out suggestions. I just don't think the above
> patch is very nice.
Oh, I actually think I have a preference.
I think we should _always_ cause a line break at the beginning of a new
line, unless the new printk() starts with a KERN_CONT thing.
Right now KERN_CONT is "", but we could easily make it an explicit
"loglevel" thing. Like this.
NOTE! This is, of course, totally untested. And we're bound to have
continuation printk's that don't have the KERN_CONT at front, and need
them added, but I think this is generally a saner model than what we have
now, or your suggested explicit addition of '\n'.
Basically, it tries to guarantee that new messages always get a newline,
unless they _explicitly_ say that they don't want one. Doesn't that make
sense?
Linus
---
include/linux/kernel.h | 2 +-
kernel/printk.c | 16 +++++++++++++++-
2 files changed, 16 insertions(+), 2 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 883cd44..066bb1e 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -102,7 +102,7 @@ extern const char linux_proc_banner[];
* line that had no enclosing \n). Only to be used by core/arch code
* during early bootup (a continued line is not SMP-safe otherwise).
*/
-#define KERN_CONT ""
+#define KERN_CONT "<c>"
extern int console_printk[];
diff --git a/kernel/printk.c b/kernel/printk.c
index 5052b54..6f416fd 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -691,7 +691,21 @@ asmlinkage int vprintk(const char *fmt, va_list args)
* Copy the output into log_buf. If the caller didn't provide
* appropriate log level tags, we insert them here
*/
- for (p = printk_buf; *p; p++) {
+ p = printk_buf;
+
+ /* Are we continuing a previous printk? */
+ if (!new_text_line) {
+ if (!memcmp(p, KERN_CONT, 3)) {
+ /* We intended to do that continued printk! */
+ p += 3;
+ } else {
+ /* Force a line break */
+ emit_log_char('\n');
+ new_text_line = 1;
+ }
+ }
+
+ for ( ; *p; p++) {
if (new_text_line) {
/* If a token, set current_log_level and skip over */
if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
* Linus Torvalds <[email protected]> wrote:
> On Mon, 15 Jun 2009, Linus Torvalds wrote:
> >
> > On Mon, 15 Jun 2009, Arjan van de Ven wrote:
> > >
> > > - if (args)
> > > + if (args) {
> > > vprintk(args->fmt, args->args);
> > > + printk("\n");
> > > + }
> >
> > I really don't like this. What if the format already does have a '\n'? And
> > what if some other CPU is printing at the same time?
> >
> > I'd almost be open to adding a "flags" field to vprintk, and allow setting
> > things like "finish line with \n" there. Or perhaps even better, have a
> > "vprintk_line()" function that does it with no dynamic flags. Maybe make
> > it static, and move all these panic helper funtions into kernel/printk.c
> > (since this really is a special case).
> >
> > I dunno. I'm just throwing out suggestions. I just don't think the above
> > patch is very nice.
>
> Oh, I actually think I have a preference.
>
> I think we should _always_ cause a line break at the beginning of a new
> line, unless the new printk() starts with a KERN_CONT thing.
>
> Right now KERN_CONT is "", but we could easily make it an explicit
> "loglevel" thing. Like this.
>
> NOTE! This is, of course, totally untested. And we're bound to have
> continuation printk's that don't have the KERN_CONT at front, and need
> them added, but I think this is generally a saner model than what we have
> now, or your suggested explicit addition of '\n'.
>
> Basically, it tries to guarantee that new messages always get a newline,
> unless they _explicitly_ say that they don't want one. Doesn't that make
> sense?
>
> Linus
>
> ---
> include/linux/kernel.h | 2 +-
> kernel/printk.c | 16 +++++++++++++++-
> 2 files changed, 16 insertions(+), 2 deletions(-)
>
> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> index 883cd44..066bb1e 100644
> --- a/include/linux/kernel.h
> +++ b/include/linux/kernel.h
> @@ -102,7 +102,7 @@ extern const char linux_proc_banner[];
> * line that had no enclosing \n). Only to be used by core/arch code
> * during early bootup (a continued line is not SMP-safe otherwise).
> */
> -#define KERN_CONT ""
> +#define KERN_CONT "<c>"
>
> extern int console_printk[];
>
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 5052b54..6f416fd 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -691,7 +691,21 @@ asmlinkage int vprintk(const char *fmt, va_list args)
> * Copy the output into log_buf. If the caller didn't provide
> * appropriate log level tags, we insert them here
> */
> - for (p = printk_buf; *p; p++) {
> + p = printk_buf;
> +
> + /* Are we continuing a previous printk? */
> + if (!new_text_line) {
> + if (!memcmp(p, KERN_CONT, 3)) {
> + /* We intended to do that continued printk! */
> + p += 3;
> + } else {
> + /* Force a line break */
> + emit_log_char('\n');
> + new_text_line = 1;
> + }
> + }
> +
Nice idea ...
Puts some pressure on current intentionally 'naked' printks (there's
still a few of them) - but that's OK, it's not like KERN_CONT (or
pr_cont()) is that hard to add.
( Plus many of our boot printks (where most of the 'naked' printks
are currently occuring) are development leftovers and should
really be removed, so it's good to shake them up a bit. )
Ingo
On Mon, 15 Jun 2009, Linus Torvalds wrote:
>
> NOTE! This is, of course, totally untested. And we're bound to have
> continuation printk's that don't have the KERN_CONT at front, and need
> them added, but I think this is generally a saner model than what we have
> now, or your suggested explicit addition of '\n'.
Ok, it's tested now.
It works, and yes, it does show cases of insanity: both missing KERN_CONT
(common), and _extra_ KERN_CONT (odd).
For example, the ACPI printk's seem to have pointless KERN_CONT's in them,
an I get printouts like:
[ 0.000000] <c>ACPI: RSDP 00000000000fe020 00024 (v02 INTEL )
[ 0.000000] <c>ACPI: XSDT 00000000bf7fe120 0006C (v01 INTEL DX58SO 0000084F 01000013)
[ 0.000000] <c>ACPI: FACP 00000000bf7fd000 000F4 (v03 INTEL DX58SO 0000084F MSFT 0100000D)
...
where that "<c>" is just because ACPI does something odd and pointless.
The lack of KERN_CONT shows up in printouts like
[ 26.626492] CPU: L1 I cache: 32K
[ 26.626492] , L1 D cache: 32K
...
[ 26.826201] ACPI: (supports S0
[ 26.826243] S5
[ 26.826326] )
...
[ 26.839617] ACPI: PCI Interrupt Link [LNKA] (IRQs
[ 26.839660] 3
[ 26.839741] 4
[ 26.839823] 5
[ 26.839904] 6
[ 26.839985] 7
[ 26.840067] 9
[ 26.840148] 10
[ 26.840230] *11
[ 26.840313] 12
[ 26.840395] 14
[ 26.840476] 15
[ 26.840558] )
...
[ 26.964999] ACPI: CPU0 (power states:
[ 26.965040] C1[C1]
[ 26.965123] C2[C3]
[ 26.965205] )
...
[ 27.231268] ata_piix 0000:00:1f.5: MAP [
[ 27.231309] P0
[ 27.231390] --
[ 27.231472] P1
[ 27.231553] --
[ 27.231635] ]
...
[ 28.092534] sda:
[ 28.092820] sda1
[ 28.092910] sda2
...
where the kernel now added a newline because they were separate printk's
and didn't have KERN_CONT on the continuation.
But despite seeing these kinds of things, I do think the patch is the
right thing to do. It just shows that since KERN_CONT didn't use to _do_
anything, people obviously mis-used it. It's the old "if it wasn't tested,
it's buggy" thing, but none of these look in the least like serious
problems to the approach.
Comments? We could make it remove the unnecessary '<c>' things (so that
you can always add KERN_CONT if you _want_ to), but the patch as-is will
show them because I think it's useful to see them.
Linus
* Linus Torvalds <[email protected]> wrote:
> On Mon, 15 Jun 2009, Linus Torvalds wrote:
> >
> > NOTE! This is, of course, totally untested. And we're bound to have
> > continuation printk's that don't have the KERN_CONT at front, and need
> > them added, but I think this is generally a saner model than what we have
> > now, or your suggested explicit addition of '\n'.
>
> Ok, it's tested now.
>
> It works, and yes, it does show cases of insanity: both missing KERN_CONT
> (common), and _extra_ KERN_CONT (odd).
>
> For example, the ACPI printk's seem to have pointless KERN_CONT's in them,
> an I get printouts like:
>
> [ 0.000000] <c>ACPI: RSDP 00000000000fe020 00024 (v02 INTEL )
> [ 0.000000] <c>ACPI: XSDT 00000000bf7fe120 0006C (v01 INTEL DX58SO 0000084F 01000013)
> [ 0.000000] <c>ACPI: FACP 00000000bf7fd000 000F4 (v03 INTEL DX58SO 0000084F MSFT 0100000D)
> ...
>
> where that "<c>" is just because ACPI does something odd and pointless.
>
> The lack of KERN_CONT shows up in printouts like
>
> [ 26.626492] CPU: L1 I cache: 32K
> [ 26.626492] , L1 D cache: 32K
> ...
> [ 26.826201] ACPI: (supports S0
> [ 26.826243] S5
> [ 26.826326] )
> ...
> [ 26.839617] ACPI: PCI Interrupt Link [LNKA] (IRQs
> [ 26.839660] 3
> [ 26.839741] 4
> [ 26.839823] 5
> [ 26.839904] 6
> [ 26.839985] 7
> [ 26.840067] 9
> [ 26.840148] 10
> [ 26.840230] *11
> [ 26.840313] 12
> [ 26.840395] 14
> [ 26.840476] 15
> [ 26.840558] )
> ...
> [ 26.964999] ACPI: CPU0 (power states:
> [ 26.965040] C1[C1]
> [ 26.965123] C2[C3]
> [ 26.965205] )
> ...
> [ 27.231268] ata_piix 0000:00:1f.5: MAP [
> [ 27.231309] P0
> [ 27.231390] --
> [ 27.231472] P1
> [ 27.231553] --
> [ 27.231635] ]
> ...
> [ 28.092534] sda:
> [ 28.092820] sda1
> [ 28.092910] sda2
> ...
>
> where the kernel now added a newline because they were separate
> printk's and didn't have KERN_CONT on the continuation.
>
> But despite seeing these kinds of things, I do think the patch is
> the right thing to do. It just shows that since KERN_CONT didn't
> use to _do_ anything, people obviously mis-used it. It's the old
> "if it wasn't tested, it's buggy" thing, but none of these look in
> the least like serious problems to the approach.
>
> Comments? We could make it remove the unnecessary '<c>' things (so
> that you can always add KERN_CONT if you _want_ to), but the patch
> as-is will show them because I think it's useful to see them.
I like this - it makes KERN_CONT truly functional. (Should have
thought of that myself when i added KERN_CONT in 474925277.)
Acked-by: Ingo Molnar <[email protected]>
Ingo
On Mon, Jun 15, 2009 at 10:57:15AM -0700, Linus Torvalds wrote:
>
>
> On Mon, 15 Jun 2009, Linus Torvalds wrote:
> >
> > NOTE! This is, of course, totally untested. And we're bound to have
> > continuation printk's that don't have the KERN_CONT at front, and need
> > them added, but I think this is generally a saner model than what we have
> > now, or your suggested explicit addition of '\n'.
>
> Ok, it's tested now.
>
> It works, and yes, it does show cases of insanity: both missing KERN_CONT
> (common), and _extra_ KERN_CONT (odd).
>
> For example, the ACPI printk's seem to have pointless KERN_CONT's in them,
> an I get printouts like:
>
> [ 0.000000] <c>ACPI: RSDP 00000000000fe020 00024 (v02 INTEL )
> [ 0.000000] <c>ACPI: XSDT 00000000bf7fe120 0006C (v01 INTEL DX58SO 0000084F 01000013)
> [ 0.000000] <c>ACPI: FACP 00000000bf7fd000 000F4 (v03 INTEL DX58SO 0000084F MSFT 0100000D)
> ...
>
> where that "<c>" is just because ACPI does something odd and pointless.
>
> The lack of KERN_CONT shows up in printouts like
>
> [ 26.626492] CPU: L1 I cache: 32K
> [ 26.626492] , L1 D cache: 32K
> ...
> [ 26.826201] ACPI: (supports S0
> [ 26.826243] S5
> [ 26.826326] )
> ...
> [ 26.839617] ACPI: PCI Interrupt Link [LNKA] (IRQs
> [ 26.839660] 3
> [ 26.839741] 4
> [ 26.839823] 5
> [ 26.839904] 6
> [ 26.839985] 7
> [ 26.840067] 9
> [ 26.840148] 10
> [ 26.840230] *11
> [ 26.840313] 12
> [ 26.840395] 14
> [ 26.840476] 15
> [ 26.840558] )
> ...
> [ 26.964999] ACPI: CPU0 (power states:
> [ 26.965040] C1[C1]
> [ 26.965123] C2[C3]
> [ 26.965205] )
> ...
> [ 27.231268] ata_piix 0000:00:1f.5: MAP [
> [ 27.231309] P0
> [ 27.231390] --
> [ 27.231472] P1
> [ 27.231553] --
> [ 27.231635] ]
> ...
> [ 28.092534] sda:
> [ 28.092820] sda1
> [ 28.092910] sda2
> ...
>
> where the kernel now added a newline because they were separate printk's
> and didn't have KERN_CONT on the continuation.
>
> But despite seeing these kinds of things, I do think the patch is the
> right thing to do. It just shows that since KERN_CONT didn't use to _do_
> anything, people obviously mis-used it. It's the old "if it wasn't tested,
> it's buggy" thing, but none of these look in the least like serious
> problems to the approach.
>
> Comments? We could make it remove the unnecessary '<c>' things (so that
> you can always add KERN_CONT if you _want_ to), but the patch as-is will
> show them because I think it's useful to see them.
>
> Linus
Nice, eventually KERN_CONT have now a real sense.
IMHO it's good to keep <c> in the beginning of the line for misuses like
ACPI does. It provides easy and quick checks to find them.
Frederic.
On Mon, 15 Jun 2009, Ingo Molnar wrote:
>
> Nice idea ...
>
> Puts some pressure on current intentionally 'naked' printks (there's
> still a few of them) - but that's OK, it's not like KERN_CONT (or
> pr_cont()) is that hard to add.
I looked some more, and there's a _ton_ of these naked printk's in the
partition handling code.
So while I think the patch was a good idea, I don't feel like exposing
quite that many old printk's and forcing people to use KERN_CONT. Here's
an alternate patch that has a somewhat similar approach, but tries much
harder to leave naked printk's as-is.
So instead of always adding a '\n' if it doesn't say KERN_CONT, it just
adds '\n' if it has a KERN_xyz level. It also modifies the code to _only_
look at the beginning of the printk - if you have a multi-line printk,
it will take the log-level from the beginning of the printk, and nowhere
else.
And it will take the log-level from the beginning of the printk
*regardless* of whether it thinks you're at the beginning of a line or
not.
So with this, KERN_CONT is not as important, but it_is_ meaningful: if you
want to print out something like "<%d>", then you _have_ to have a
KERN_xyz header, and if you don't want to force a new line, you have to do
printk(KERN_CONT "<%d>", n);
because otherwise the printk code will think that what you want to print
out is the loglevel.
But for all the traditional printk()'s that don't have KERN_CONT (or other
loglevel info), and print out strings that are not of that "<.>" form,
they'll still work as they used to.
And no, this does not necessarily fix Arjan's problem: it only adds the
newline before printk's that _do_ have a KERN_<lvl> format. So now, in
order to get the extra '\n' after the WARN_ON() line, somebody needs to
make sure that the printk's in the warning printing have loglevels.
Arjan?
Linus
---
include/linux/kernel.h | 2 +-
kernel/printk.c | 31 ++++++++++++++++++++++---------
2 files changed, 23 insertions(+), 10 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 883cd44..066bb1e 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -102,7 +102,7 @@ extern const char linux_proc_banner[];
* line that had no enclosing \n). Only to be used by core/arch code
* during early bootup (a continued line is not SMP-safe otherwise).
*/
-#define KERN_CONT ""
+#define KERN_CONT "<c>"
extern int console_printk[];
diff --git a/kernel/printk.c b/kernel/printk.c
index 5052b54..a87770c 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -687,20 +687,33 @@ asmlinkage int vprintk(const char *fmt, va_list args)
sizeof(printk_buf) - printed_len, fmt, args);
+ p = printk_buf;
+
+ /* Do we have a loglevel in the string? */
+ if (p[0] == '<') {
+ unsigned char c = p[1];
+ if (c && p[2] == '>') {
+ switch (c) {
+ case '0' ... '7': /* loglevel */
+ current_log_level = c - '0';
+ if (!new_text_line) {
+ emit_log_char('\n');
+ new_text_line = 1;
+ }
+ /* Fallthrough - skip the loglevel */
+ case 'c': /* KERN_CONT */
+ p += 3;
+ break;
+ }
+ }
+ }
+
/*
* Copy the output into log_buf. If the caller didn't provide
* appropriate log level tags, we insert them here
*/
- for (p = printk_buf; *p; p++) {
+ for ( ; *p; p++) {
if (new_text_line) {
- /* If a token, set current_log_level and skip over */
- if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
- p[2] == '>') {
- current_log_level = p[1] - '0';
- p += 3;
- printed_len -= 3;
- }
-
/* Always output the token */
emit_log_char('<');
emit_log_char(current_log_level + '0');
On Mon, 15 Jun 2009, Linus Torvalds wrote:
>
> And no, this does not necessarily fix Arjan's problem: it only adds the
> newline before printk's that _do_ have a KERN_<lvl> format. So now, in
> order to get the extra '\n' after the WARN_ON() line, somebody needs to
> make sure that the printk's in the warning printing have loglevels.
>
> Arjan?
The "print_modules()" function needs a KERN_WARNING in front of it.
Or something like this (on top of the patch I just sent out), which allows
you to specify loglevel that is just the default one, whatever that
happens to be. Using KERN_DEFAULT, of course.
Hmm?
Linus
---
include/linux/kernel.h | 2 ++
kernel/module.c | 2 +-
kernel/printk.c | 2 ++
3 files changed, 5 insertions(+), 1 deletions(-)
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 066bb1e..1b2e174 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -97,6 +97,8 @@ extern const char linux_proc_banner[];
#define KERN_INFO "<6>" /* informational */
#define KERN_DEBUG "<7>" /* debug-level messages */
+/* Use the default kernel loglevel */
+#define KERN_DEFAULT "<d>"
/*
* Annotation for a "continued" line of log printout (only done after a
* line that had no enclosing \n). Only to be used by core/arch code
diff --git a/kernel/module.c b/kernel/module.c
index e4ab36c..215aaab 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -2899,7 +2899,7 @@ void print_modules(void)
struct module *mod;
char buf[8];
- printk("Modules linked in:");
+ printk(KERN_DEFAULT "Modules linked in:");
/* Most callers should already have preempt disabled, but make sure */
preempt_disable();
list_for_each_entry_rcu(mod, &modules, list)
diff --git a/kernel/printk.c b/kernel/printk.c
index a87770c..b4d97b5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -696,6 +696,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
switch (c) {
case '0' ... '7': /* loglevel */
current_log_level = c - '0';
+ /* Fallthrough - make sure we're on a new line */
+ case 'd': /* KERN_DEFAULT */
if (!new_text_line) {
emit_log_char('\n');
new_text_line = 1;
On Mon, 15 Jun 2009 21:04:25 -0700 (PDT)
Linus Torvalds <[email protected]> wrote:
>
> And no, this does not necessarily fix Arjan's problem: it only adds
> the newline before printk's that _do_ have a KERN_<lvl> format. So
> now, in order to get the extra '\n' after the WARN_ON() line,
> somebody needs to make sure that the printk's in the warning printing
> have loglevels.
>
> Arjan?
>
I liked the first patch more :-) ... but practical considerations make
this one more useful I suppose. I'll make the warnings work.
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org