[v2,3.18-rc3] kdb: Avoid printing KERN_ levels to consoles

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(-)

--
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);
> +		else
> +			printk("%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);
>> +		else
>> +			printk("%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.