Currently when kdb traps printk messages then the log level prefix does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This results in annoying visual noise and problems with grepping for ^.
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
printk(), which is used as an I/O handler for logging purposes, is handled as a special case; if the caller provided a log level then this will be preserved.
Signed-off-by: Daniel Thompson daniel.thompson@linaro.org Cc: Jason Wessel jason.wessel@windriver.com Cc: Mike Travis travis@sgi.com Cc: Ingo Molnar mingo@redhat.com Cc: Andrew Morton akpm@linux-foundation.org --- kernel/debug/kdb/kdb_io.c | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-)
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c index 7c70812..381f297 100644 --- a/kernel/debug/kdb/kdb_io.c +++ b/kernel/debug/kdb/kdb_io.c @@ -691,19 +691,22 @@ kdb_printit: * Write to all consoles. */ retlen = strlen(kdb_buffer); + cp = kdb_buffer; + if (cp[0] == KERN_SOH_ASCII && cp[1] != '\0') + cp += 2; if (!dbg_kdb_mode && kgdb_connected) { - gdbstub_msg_write(kdb_buffer, retlen); + gdbstub_msg_write(cp, retlen - (cp - kdb_buffer)); } else { if (dbg_io_ops && !dbg_io_ops->is_console) { - len = retlen; - cp = kdb_buffer; + len = retlen - (cp - kdb_buffer); + cp2 = cp; while (len--) { - dbg_io_ops->write_char(*cp); - cp++; + dbg_io_ops->write_char(*cp2); + cp2++; } } while (c) { - c->write(c, kdb_buffer, retlen); + c->write(c, cp, retlen - (cp - kdb_buffer)); touch_nmi_watchdog(); c = c->next; } @@ -711,7 +714,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT; - printk(KERN_INFO "%s", kdb_buffer); + if (cp == kdb_buffer) + printk(KERN_INFO "%s", kdb_buffer); + else + printk("%s", kdb_buffer); }
if (KDB_STATE(PAGER)) { -- 1.9.3
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
printk(), which is used as an I/O handler for logging purposes, is handled as a special case; if the caller provided a log level then this will be preserved.
Signed-off-by: Daniel Thompson daniel.thompson@linaro.org Cc: Jason Wessel jason.wessel@windriver.com ---
Notes: This patch is tested both on arm (kgdboc=ttyAMA0) and x86_64 (kgdboc=kdb,ttyS0).
kernel/debug/kdb/kdb_io.c | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-)
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c index 7c70812..381f297 100644 --- a/kernel/debug/kdb/kdb_io.c +++ b/kernel/debug/kdb/kdb_io.c @@ -691,19 +691,22 @@ kdb_printit: * Write to all consoles. */ retlen = strlen(kdb_buffer); + cp = kdb_buffer; + if (cp[0] == KERN_SOH_ASCII && cp[1] != '\0') + cp += 2; if (!dbg_kdb_mode && kgdb_connected) { - gdbstub_msg_write(kdb_buffer, retlen); + gdbstub_msg_write(cp, retlen - (cp - kdb_buffer)); } else { if (dbg_io_ops && !dbg_io_ops->is_console) { - len = retlen; - cp = kdb_buffer; + len = retlen - (cp - kdb_buffer); + cp2 = cp; while (len--) { - dbg_io_ops->write_char(*cp); - cp++; + dbg_io_ops->write_char(*cp2); + cp2++; } } while (c) { - c->write(c, kdb_buffer, retlen); + c->write(c, cp, retlen - (cp - kdb_buffer)); touch_nmi_watchdog(); c = c->next; } @@ -711,7 +714,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT; - printk(KERN_INFO "%s", kdb_buffer); + if (cp == kdb_buffer) + printk(KERN_INFO "%s", kdb_buffer); + else + printk("%s", kdb_buffer); }
if (KDB_STATE(PAGER)) { -- 1.9.3
On Thu, 2014-11-06 at 15:27 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
Perhaps instead of stripping the logging level, maybe a KERN_SOH_ASCII 'char' sequence should be emitted as '<' 'char' '>' (see: printk:print_prefix)
Maybe this should be added to stable from v3.6 when KERN_SOH_ASCII was first added.
On 06/11/14 16:13, Joe Perches wrote:
On Thu, 2014-11-06 at 15:27 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
Perhaps instead of stripping the logging level, maybe a KERN_SOH_ASCII 'char' sequence should be emitted as '<' 'char' '>' (see: printk:print_prefix)
Maybe this should be added to stable from v3.6 when KERN_SOH_ASCII was first added.
You mean call the problem a regression and try to restore the original 3.5 behaviour?
Maybe.
However I have to confess that I don't really like the old behaviour. I'd view it as contradicting the normal behaviours of consoles (including the kgdbcon console). Why should printk() inside kdb show different text to printk() outside kdb? For me, having <5> and <c> scribbled all over the output of an "sr" command (which I think is probably the heaviest user of printk() inside kdb) never struck me as adding much value.
Is the above paragraph convincing?
To be honest I'd happy to make the change if this is critical for you since almost anything is better than dumping a non-printable character (which does all sorts of different things depending on the combination of terminal emuluator/screen/minicom I need to access the board or emulator).
On the other hand if you really mean "perhaps and maybe" then I'd prefer to leave it as it it.
Daniel.
On Thu, 2014-11-06 at 17:22 +0000, Daniel Thompson wrote:
On 06/11/14 16:13, Joe Perches wrote:
On Thu, 2014-11-06 at 15:27 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
Perhaps instead of stripping the logging level, maybe a KERN_SOH_ASCII 'char' sequence should be emitted as '<' 'char' '>' (see: printk:print_prefix)
Maybe this should be added to stable from v3.6 when KERN_SOH_ASCII was first added.
You mean call the problem a regression and try to restore the original 3.5 behaviour?
Yes.
I added KERN_SOH_ASCII so to me it's a regression.
However I have to confess that I don't really like the old behaviour. I'd view it as contradicting the normal behaviours of consoles (including the kgdbcon console). Why should printk() inside kdb show different text to printk() outside kdb? For me, having <5> and <c> scribbled all over the output of an "sr" command (which I think is probably the heaviest user of printk() inside kdb) never struck me as adding much value.
Is the above paragraph convincing?
I don't use it so I have a useful opinion.
I don't recall that anyone has reported it in the 2+ years since so it doesn't seem widely used.
But then again, this is a resend and I don't recall seeing it the first time either.
On the other hand if you really mean "perhaps and maybe" then I'd prefer to leave it as it it.
Your choice.
btw: in the patch I suggest using printk_skip_level instead of the direct test here:
+ cp = kdb_buffer; + if (cp[0] == KERN_SOH_ASCII && cp[1] != '\0') + cp += 2;
so this could be
cp = printk_skip_level(kdb_buffer);
On 06/11/14 17:43, Joe Perches wrote:
On Thu, 2014-11-06 at 17:22 +0000, Daniel Thompson wrote:
On 06/11/14 16:13, Joe Perches wrote:
On Thu, 2014-11-06 at 15:27 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers.
Perhaps instead of stripping the logging level, maybe a KERN_SOH_ASCII 'char' sequence should be emitted as '<' 'char' '>' (see: printk:print_prefix)
Maybe this should be added to stable from v3.6 when KERN_SOH_ASCII was first added.
You mean call the problem a regression and try to restore the original 3.5 behaviour?
Yes.
I added KERN_SOH_ASCII so to me it's a regression.
However I have to confess that I don't really like the old behaviour. I'd view it as contradicting the normal behaviours of consoles (including the kgdbcon console). Why should printk() inside kdb show different text to printk() outside kdb? For me, having <5> and <c> scribbled all over the output of an "sr" command (which I think is probably the heaviest user of printk() inside kdb) never struck me as adding much value.
Is the above paragraph convincing?
I don't use it so I have a useful opinion.
I don't recall that anyone has reported it in the 2+ years since so it doesn't seem widely used.
Does that arguing against Cc:ing stable@ or you think I should just put that on anyway and leave it for the stable committee?
But then again, this is a resend and I don't recall seeing it the first time either.
On the other hand if you really mean "perhaps and maybe" then I'd prefer to leave it as it it.
Your choice.
btw: in the patch I suggest using printk_skip_level instead of the direct test here:
cp = kdb_buffer;if (cp[0] == KERN_SOH_ASCII && cp[1] != '\0')cp += 2;so this could be
cp = printk_skip_level(kdb_buffer);
Excellent. I'll do that.
On Fri, 2014-11-07 at 09:57 +0000, Daniel Thompson wrote:
Does that arguing against Cc:ing stable@ or you think I should just put that on anyway and leave it for the stable committee?
It's a regression, I think you should send a fix for it to stable. It's up to the stable folks to figure out if they want to take it.
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then this will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
Signed-off-by: Daniel Thompson daniel.thompson@linaro.org Cc: Jason Wessel jason.wessel@windriver.com Cc: Joe Perches joe@perches.com Cc: stable@vger.kernel.org ---
Notes: This patch is tested both on arm (kgdboc=ttyAMA0) and x86_64 (kgdboc=kdb,ttyS0).
v2:
* Adopt printk_skip_level() to skip the header characters (Joe Perches).
* Update patch description to describe the addition of non-printable characters to kdb output as a regression and Cc: stable@ (Joe Perches).
kernel/debug/kdb/kdb_io.c | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-)
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c index 7c70812caea5..f3982adf8695 100644 --- a/kernel/debug/kdb/kdb_io.c +++ b/kernel/debug/kdb/kdb_io.c @@ -691,19 +691,20 @@ kdb_printit: * Write to all consoles. */ retlen = strlen(kdb_buffer); + cp = printk_skip_level(kdb_buffer); if (!dbg_kdb_mode && kgdb_connected) { - gdbstub_msg_write(kdb_buffer, retlen); + gdbstub_msg_write(cp, retlen - (cp - kdb_buffer)); } else { if (dbg_io_ops && !dbg_io_ops->is_console) { - len = retlen; - cp = kdb_buffer; + len = retlen - (cp - kdb_buffer); + cp2 = cp; while (len--) { - dbg_io_ops->write_char(*cp); - cp++; + dbg_io_ops->write_char(*cp2); + cp2++; } } while (c) { - c->write(c, kdb_buffer, retlen); + c->write(c, cp, retlen - (cp - kdb_buffer)); touch_nmi_watchdog(); c = c->next; } @@ -711,7 +712,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT; - printk(KERN_INFO "%s", kdb_buffer); + if (cp == kdb_buffer) + printk(KERN_INFO "%s", kdb_buffer); + else + printk("%s", kdb_buffer); }
if (KDB_STATE(PAGER)) { -- 1.9.3
On Fri, 2014-11-07 at 12:01 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then this will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
[]
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c
[]
@@ -711,7 +712,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT;
printk(KERN_INFO "%s", kdb_buffer);
if (cp == kdb_buffer)printk(KERN_INFO "%s", kdb_buffer);elseprintk("%s", kdb_buffer);
The first part of the patch seem fine, but I'm confused about this bit above.
Here, isn't the "if (cp == kdb_buffer)" unnecessary?
if "(cp != kdb_buffer)", the buffer does have a prefix and it's emitted.
If (cp == kdb_buffer), the buffer does _not_ have a prefix (meaning it's either a naked printk or a continuation line. (KERN_CONT is "")
So why insert KERN_INFO?
I believe the code should be:
- printk(KERN_INFO "%s", kdb_buffer); + printk("%s", kdb_buffer);
On 07/11/14 16:04, Joe Perches wrote:
On Fri, 2014-11-07 at 12:01 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then this will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
[]
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c
[]
@@ -711,7 +712,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT;
printk(KERN_INFO "%s", kdb_buffer);
if (cp == kdb_buffer)printk(KERN_INFO "%s", kdb_buffer);elseprintk("%s", kdb_buffer);The first part of the patch seem fine, but I'm confused about this bit above.
Here, isn't the "if (cp == kdb_buffer)" unnecessary?
if "(cp != kdb_buffer)", the buffer does have a prefix and it's emitted.
If (cp == kdb_buffer), the buffer does _not_ have a prefix (meaning it's either a naked printk or a continuation line. (KERN_CONT is "")
So why insert KERN_INFO?
vkdb_printf() and printk() can appear either way round in a stack trace. Each is capable of calling the other and a flag (kdb_trap_printk) is used to prevent mutual recursion.
Messages that originate from with kdb itself start life as direct call to (v)kdb_printf() and are not prefixed. If these messages are logged then they are supposed to be tagged KERN_INFO hence the little dance here.
Before my patch then printk() messages would receive a double log header if they were copied to the log (they would unconditionally have KERN_INFO tacked in front of them). My patch does better and preserves log levels where this is possible. However there are cases when logging printk() continuations that data could be tagged with an unexpected log level.
A complete solution would require a means to know whether vkdb_printf() were entered directly or from printk(). A flag passed to vkdb_printf() would achieve this. I'll take a look.
Daniel.
On Fri, 2014-11-07 at 16:50 +0000, Daniel Thompson wrote:
On 07/11/14 16:04, Joe Perches wrote:
why insert KERN_INFO?
vkdb_printf() and printk() can appear either way round in a stack trace. Each is capable of calling the other and a flag (kdb_trap_printk) is used to prevent mutual recursion.
I see.
A complete solution would require a means to know whether vkdb_printf() were entered directly or from printk(). A flag passed to vkdb_printf() would achieve this. I'll take a look.
That bit seems pretty simple and sensible.
I don't know this code at all but would it be better if the kdb_trap_printk accesses were converted to atomic_<foo>?
Might this bit in vkdb_printf:
saved_trap_printk = kdb_trap_printk; kdb_trap_printk = 0;
be better atomic_xchg?
and the kdb_trap_printk++ bits as atomic_inc, etc...
On 07/11/14 17:16, Joe Perches wrote:
On Fri, 2014-11-07 at 16:50 +0000, Daniel Thompson wrote:
On 07/11/14 16:04, Joe Perches wrote:
why insert KERN_INFO?
vkdb_printf() and printk() can appear either way round in a stack trace. Each is capable of calling the other and a flag (kdb_trap_printk) is used to prevent mutual recursion.
I see.
A complete solution would require a means to know whether vkdb_printf() were entered directly or from printk(). A flag passed to vkdb_printf() would achieve this. I'll take a look.
That bit seems pretty simple and sensible.
I don't know this code at all but would it be better if the kdb_trap_printk accesses were converted to atomic_<foo>?
Might this bit in vkdb_printf:
saved_trap_printk = kdb_trap_printk; kdb_trap_printk = 0;
be better atomic_xchg?
and the kdb_trap_printk++ bits as atomic_inc, etc...
At present I don't think it would make any difference. All of this code is single threaded; interrupts are masked and all other cores are quiesced and held in a loop as part of the debugger entry protocol.
If a full asynchronous mode were ever added to kdb, meaning the ability to run some some commands without halting all the other cores, then we'd have to review quite a lot of code, including this bit. However in that case I think that flags like kdb_trap_printk might actually end up as per_cpu variables rather than atomics.
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then the prefix will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
Signed-off-by: Daniel Thompson daniel.thompson@linaro.org Cc: Jason Wessel jason.wessel@windriver.com Cc: Joe Perches joe@perches.com Cc: stable@vger.kernel.org ---
Notes: This patch is tested both on arm (kgdboc=ttyAMA0) and x86_64 (kgdboc=kdb,ttyS0).
v3:
* Introduce enum kdb_msgsrc to further improve the fidelity of messages that hit the log (Joe Perches). The output of "sr h" benefits a lot from this change.
v2:
* Adopt printk_skip_level() to skip the header characters (Joe Perches).
* Update patch description to describe the addition of non-printable characters to kdb output as a regression and Cc: stable@ (Joe Perches).
include/linux/kdb.h | 8 +++++++- kernel/debug/kdb/kdb_io.c | 22 +++++++++++++--------- kernel/printk/printk.c | 2 +- 3 files changed, 21 insertions(+), 11 deletions(-)
diff --git a/include/linux/kdb.h b/include/linux/kdb.h index 290db1269c4c..204901ae003a 100644 --- a/include/linux/kdb.h +++ b/include/linux/kdb.h @@ -112,8 +112,14 @@ typedef enum { KDB_REASON_SYSTEM_NMI, /* In NMI due to SYSTEM cmd; regs valid */ } kdb_reason_t;
+enum kdb_msgsrc { + KDB_MSGSRC_INTERNAL, /* direct call to kdb_printf() */ + KDB_MSGSRC_PRINTK, /* trapped from printk() */ +}; + extern int kdb_trap_printk; -extern __printf(1, 0) int vkdb_printf(const char *fmt, va_list args); +extern __printf(2, 0) int vkdb_printf(enum kdb_msgsrc src, const char *fmt, + va_list args); extern __printf(1, 2) int kdb_printf(const char *, ...); typedef __printf(1, 2) int (*kdb_printf_t)(const char *, ...);
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c index 7c70812caea5..a550afb99ebe 100644 --- a/kernel/debug/kdb/kdb_io.c +++ b/kernel/debug/kdb/kdb_io.c @@ -548,7 +548,7 @@ static int kdb_search_string(char *searched, char *searchfor) return 0; }
-int vkdb_printf(const char *fmt, va_list ap) +int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap) { int diag; int linecount; @@ -691,19 +691,20 @@ kdb_printit: * Write to all consoles. */ retlen = strlen(kdb_buffer); + cp = (char *) printk_skip_level(kdb_buffer); if (!dbg_kdb_mode && kgdb_connected) { - gdbstub_msg_write(kdb_buffer, retlen); + gdbstub_msg_write(cp, retlen - (cp - kdb_buffer)); } else { if (dbg_io_ops && !dbg_io_ops->is_console) { - len = retlen; - cp = kdb_buffer; + len = retlen - (cp - kdb_buffer); + cp2 = cp; while (len--) { - dbg_io_ops->write_char(*cp); - cp++; + dbg_io_ops->write_char(*cp2); + cp2++; } } while (c) { - c->write(c, kdb_buffer, retlen); + c->write(c, cp, retlen - (cp - kdb_buffer)); touch_nmi_watchdog(); c = c->next; } @@ -711,7 +712,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT; - printk(KERN_INFO "%s", kdb_buffer); + if (printk_get_level(kdb_buffer) || src == KDB_MSGSRC_PRINTK) + printk("%s", kdb_buffer); + else + pr_info("%s", kdb_buffer); }
if (KDB_STATE(PAGER)) { @@ -844,7 +848,7 @@ int kdb_printf(const char *fmt, ...) int r;
va_start(ap, fmt); - r = vkdb_printf(fmt, ap); + r = vkdb_printf(KDB_MSGSRC_INTERNAL, fmt, ap); va_end(ap);
return r; diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index ced2b84b1cb7..3a884ab1b9cb 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1836,7 +1836,7 @@ asmlinkage __visible int printk(const char *fmt, ...) #ifdef CONFIG_KGDB_KDB if (unlikely(kdb_trap_printk)) { va_start(args, fmt); - r = vkdb_printf(fmt, args); + r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args); va_end(args); return r; } -- 1.9.3
On Fri, 2014-11-07 at 18:47 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then the prefix will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
This looks nicer. Thanks Daniel.
On Fri, 2014-11-07 at 18:47 +0000, Daniel Thompson wrote:
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then the prefix will be preserved when sent to printk().
Andrew?
Any thoughts on whether or not you are going to pick this up?
Currently when kdb traps printk messages then the raw log level prefix (consisting of '\001' followed by a numeral) does not get stripped off before the message is issued to the various I/O handlers supported by kdb. This causes annoying visual noise as well as causing problems grepping for ^. It is also a change of behaviour compared to normal usage of printk() usage. For example <SysRq>-h ends up with different output to that of kdb's "sr h".
This patch addresses the problem by stripping log levels from messages before they are issued to the I/O handlers. printk() which can also act as an i/o handler in some cases is special cased; if the caller provided a log level then the prefix will be preserved when sent to printk().
The addition of non-printable characters to the output of kdb commands is a regression, albeit and extremely elderly one, introduced by commit 04d2c8c83d0e ("printk: convert the format for KERN_<LEVEL> to a 2 byte pattern"). Note also that this patch does *not* restore the original behaviour from v3.5. Instead it makes printk() from within a kdb command display the message without any prefix (i.e. like printk() normally does).
Signed-off-by: Daniel Thompson daniel.thompson@linaro.org Cc: Jason Wessel jason.wessel@windriver.com Cc: Joe Perches joe@perches.com Cc: stable@vger.kernel.org ---
Notes: This patch is tested both on arm (kgdboc=ttyAMA0) and x86_64 (kgdboc=kdb,ttyS0).
v3:
* Introduce enum kdb_msgsrc to further improve the fidelity of messages that hit the log (Joe Perches). The output of "sr h" benefits a lot from this change.
v2:
* Adopt printk_skip_level() to skip the header characters (Joe Perches).
* Update patch description to describe the addition of non-printable characters to kdb output as a regression and Cc: stable@ (Joe Perches).
include/linux/kdb.h | 8 +++++++- kernel/debug/kdb/kdb_io.c | 22 +++++++++++++--------- kernel/printk/printk.c | 2 +- 3 files changed, 21 insertions(+), 11 deletions(-)
diff --git a/include/linux/kdb.h b/include/linux/kdb.h index 290db1269c4c..204901ae003a 100644 --- a/include/linux/kdb.h +++ b/include/linux/kdb.h @@ -112,8 +112,14 @@ typedef enum { KDB_REASON_SYSTEM_NMI, /* In NMI due to SYSTEM cmd; regs valid */ } kdb_reason_t;
+enum kdb_msgsrc { + KDB_MSGSRC_INTERNAL, /* direct call to kdb_printf() */ + KDB_MSGSRC_PRINTK, /* trapped from printk() */ +}; + extern int kdb_trap_printk; -extern __printf(1, 0) int vkdb_printf(const char *fmt, va_list args); +extern __printf(2, 0) int vkdb_printf(enum kdb_msgsrc src, const char *fmt, + va_list args); extern __printf(1, 2) int kdb_printf(const char *, ...); typedef __printf(1, 2) int (*kdb_printf_t)(const char *, ...);
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c index 7c70812caea5..a550afb99ebe 100644 --- a/kernel/debug/kdb/kdb_io.c +++ b/kernel/debug/kdb/kdb_io.c @@ -548,7 +548,7 @@ static int kdb_search_string(char *searched, char *searchfor) return 0; }
-int vkdb_printf(const char *fmt, va_list ap) +int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap) { int diag; int linecount; @@ -691,19 +691,20 @@ kdb_printit: * Write to all consoles. */ retlen = strlen(kdb_buffer); + cp = (char *) printk_skip_level(kdb_buffer); if (!dbg_kdb_mode && kgdb_connected) { - gdbstub_msg_write(kdb_buffer, retlen); + gdbstub_msg_write(cp, retlen - (cp - kdb_buffer)); } else { if (dbg_io_ops && !dbg_io_ops->is_console) { - len = retlen; - cp = kdb_buffer; + len = retlen - (cp - kdb_buffer); + cp2 = cp; while (len--) { - dbg_io_ops->write_char(*cp); - cp++; + dbg_io_ops->write_char(*cp2); + cp2++; } } while (c) { - c->write(c, kdb_buffer, retlen); + c->write(c, cp, retlen - (cp - kdb_buffer)); touch_nmi_watchdog(); c = c->next; } @@ -711,7 +712,10 @@ kdb_printit: if (logging) { saved_loglevel = console_loglevel; console_loglevel = CONSOLE_LOGLEVEL_SILENT; - printk(KERN_INFO "%s", kdb_buffer); + if (printk_get_level(kdb_buffer) || src == KDB_MSGSRC_PRINTK) + printk("%s", kdb_buffer); + else + pr_info("%s", kdb_buffer); }
if (KDB_STATE(PAGER)) { @@ -844,7 +848,7 @@ int kdb_printf(const char *fmt, ...) int r;
va_start(ap, fmt); - r = vkdb_printf(fmt, ap); + r = vkdb_printf(KDB_MSGSRC_INTERNAL, fmt, ap); va_end(ap);
return r; diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 02d6b6d28796..fae29e3ffbf0 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1811,7 +1811,7 @@ int vprintk_default(const char *fmt, va_list args)
#ifdef CONFIG_KGDB_KDB if (unlikely(kdb_trap_printk)) { - r = vkdb_printf(fmt, args); + r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args); return r; } #endif -- 1.9.3
linaro-kernel@lists.linaro.org
-
Daniel Thompson -
Joe Perches