[PATCH] x86: Avoid pr_cont() in show_opcodes()

[PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

From: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>

Since syzbot is confused by concurrent printk() messages [1],
this patch changes show_opcodes() to use snprintf().

When we start adding prefix to each line of printk() output,
we will be able to handle concurrent printk() messages.

[1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
Cc: Borislav Petkov <bp@suse.de>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Andy Lutomirski <luto@amacapital.net>
---
 arch/x86/kernel/dumpstack.c | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index 666a284..bb47426 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -97,22 +97,24 @@ void show_opcodes(u8 *rip, const char *loglvl)
 	u8 opcodes[OPCODE_BUFSIZE];
 	u8 *ip;
 	int i;
-
-	printk("%sCode: ", loglvl);
+	int pos = 0;
+	char buf[(3 * OPCODE_BUFSIZE + 2) + 1];
 
 	ip = (u8 *)rip - code_prologue;
 	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
-		pr_cont("Bad RIP value.\n");
+		printk("%sCode: Bad RIP value.\n", loglvl);
 		return;
 	}
 
 	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
 		if (ip == rip)
-			pr_cont("<%02x> ", opcodes[i]);
+			pos += snprintf(buf + pos, sizeof(buf) - pos,
+					"<%02x> ", opcodes[i]);
 		else
-			pr_cont("%02x ", opcodes[i]);
+			pos += snprintf(buf + pos, sizeof(buf) - pos,
+					"%02x ", opcodes[i]);
 	}
-	pr_cont("\n");
+	printk("%sCode: %s\n", loglvl, buf);
 }
 
 void show_ip(struct pt_regs *regs, const char *loglvl)
-- 
2.7.4

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Ingo Molnar]

* Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> wrote:

> From: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
> 
> Since syzbot is confused by concurrent printk() messages [1],
> this patch changes show_opcodes() to use snprintf().
> 
> When we start adding prefix to each line of printk() output,
> we will be able to handle concurrent printk() messages.
> 
> [1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
> Cc: Borislav Petkov <bp@suse.de>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Josh Poimboeuf <jpoimboe@redhat.com>
> Cc: Linus Torvalds <torvalds@linux-foundation.org>
> Cc: Andy Lutomirski <luto@amacapital.net>
> ---
>  arch/x86/kernel/dumpstack.c | 14 ++++++++------
>  1 file changed, 8 insertions(+), 6 deletions(-)
> 
> diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
> index 666a284..bb47426 100644
> --- a/arch/x86/kernel/dumpstack.c
> +++ b/arch/x86/kernel/dumpstack.c
> @@ -97,22 +97,24 @@ void show_opcodes(u8 *rip, const char *loglvl)
>  	u8 opcodes[OPCODE_BUFSIZE];
>  	u8 *ip;
>  	int i;
> -
> -	printk("%sCode: ", loglvl);
> +	int pos = 0;
> +	char buf[(3 * OPCODE_BUFSIZE + 2) + 1];
>  
>  	ip = (u8 *)rip - code_prologue;
>  	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
> -		pr_cont("Bad RIP value.\n");
> +		printk("%sCode: Bad RIP value.\n", loglvl);
>  		return;
>  	}
>  
>  	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
>  		if (ip == rip)
> -			pr_cont("<%02x> ", opcodes[i]);
> +			pos += snprintf(buf + pos, sizeof(buf) - pos,
> +					"<%02x> ", opcodes[i]);
>  		else
> -			pr_cont("%02x ", opcodes[i]);
> +			pos += snprintf(buf + pos, sizeof(buf) - pos,
> +					"%02x ", opcodes[i]);
>  	}
> -	pr_cont("\n");
> +	printk("%sCode: %s\n", loglvl, buf);

Does this change the output?

- If yes, could you show the before/after output in the changelog,

- If not (i.e. if only the number of printk calls is changed, the output is the 
  same), could you say so in the changelog?

Also, 3*OPCODE_BUFSIZE+2+1 is 195 bytes - isn't that a bit too much on-stack 
footprint?

Thanks,

	Ingo

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

On 2018/07/07 20:12, Ingo Molnar wrote:
> 
> * Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> wrote:
> 
>> From: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
>>
>> Since syzbot is confused by concurrent printk() messages [1],
>> this patch changes show_opcodes() to use snprintf().
>>
>> When we start adding prefix to each line of printk() output,
>> we will be able to handle concurrent printk() messages.
>>
>> [1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000
> 
> Does this change the output?
> 
> - If yes, could you show the before/after output in the changelog,
> 
> - If not (i.e. if only the number of printk calls is changed, the output is the 
>   same), could you say so in the changelog?

This patch will not change the output unless multiple threads concurrently
call printk(). The purpose of this patch is to help parsing kernel messages
when multiple threads are concurrently calling printk() for multiple times
(e.g. backtrace) by reducing pr_cont()/KERN_CONT usage.

> 
> Also, 3*OPCODE_BUFSIZE+2+1 is 195 bytes - isn't that a bit too much on-stack 
> footprint?

Then, we can reduce it by OPCODE_BUFSIZE bytes by unionizing opcodes[] and buf[].



From 61752cef56fad2a910f6bfd277e1b9b028aeab43 Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Sat, 7 Jul 2018 22:45:30 +0900
Subject: [PATCH v2] x86: Avoid pr_cont() in show_opcodes()

Since syzbot is confused by concurrent printk() messages [1], this patch
changes show_opcodes() to use snprintf(). By this change, the Code: line
will always be printed as one line even if multiple threads concurrently
called printk().

To save on-stack footprint, this patch shares opcodes[] and buf[] because
we sequentially reads from opcodes[] and sequentially writes to buf[].

When we start adding prefix to each line of printk() output,
we will be able to handle concurrent printk() messages.

[1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
Cc: Borislav Petkov <bp@suse.de>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Andy Lutomirski <luto@amacapital.net>
---
 arch/x86/kernel/dumpstack.c | 16 +++++++++-------
 1 file changed, 9 insertions(+), 7 deletions(-)

diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index 666a284..6408123 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -94,25 +94,27 @@ static void printk_stack_address(unsigned long address, int reliable,
 void show_opcodes(u8 *rip, const char *loglvl)
 {
 	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
-	u8 opcodes[OPCODE_BUFSIZE];
 	u8 *ip;
 	int i;
-
-	printk("%sCode: ", loglvl);
+	int pos = 0;
+	char buf[(3 * OPCODE_BUFSIZE + 2) + 1];
+	u8 *opcodes = (u8 *) buf + sizeof(buf) - OPCODE_BUFSIZE;
 
 	ip = (u8 *)rip - code_prologue;
 	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
-		pr_cont("Bad RIP value.\n");
+		printk("%sCode: Bad RIP value.\n", loglvl);
 		return;
 	}
 
 	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
 		if (ip == rip)
-			pr_cont("<%02x> ", opcodes[i]);
+			pos += snprintf(buf + pos, sizeof(buf) - pos,
+					"<%02x> ", opcodes[i]);
 		else
-			pr_cont("%02x ", opcodes[i]);
+			pos += snprintf(buf + pos, sizeof(buf) - pos,
+					"%02x ", opcodes[i]);
 	}
-	pr_cont("\n");
+	printk("%sCode: %s\n", loglvl, buf);
 }
 
 void show_ip(struct pt_regs *regs, const char *loglvl)
-- 
1.8.3.1

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Peter Zijlstra]

On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
> >> Since syzbot is confused by concurrent printk() messages [1],
> >> this patch changes show_opcodes() to use snprintf().

But how big of a problem is that really? We can't very well remove all
pr_cont stuff from the kernel.

RE: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[David Laight]

From: Peter Zijlstra
> Sent: 09 July 2018 09:50
> On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
> > >> Since syzbot is confused by concurrent printk() messages [1],
> > >> this patch changes show_opcodes() to use snprintf().

snprintf() is probably the wrong function.
You want the variant that always returns the number of characters
added to the buffer - not the number that would have been added
were the buffer infinite length.

> But how big of a problem is that really? We can't very well remove all
> pr_cont stuff from the kernel.

On my ubuntu 17.10 system with a 4.13 kernel some messages printed with
pr_cont end up split when displayed by dmesg.
(These are from one of our drivers, I've not looked very hard at it though.)

So maybe removing pr_cont isn't a bad idea.

	David

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Josh Poimboeuf]

On Mon, Jul 09, 2018 at 10:49:53AM +0200, Peter Zijlstra wrote:
> On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
> > >> Since syzbot is confused by concurrent printk() messages [1],
> > >> this patch changes show_opcodes() to use snprintf().
> 
> But how big of a problem is that really? We can't very well remove all
> pr_cont stuff from the kernel.

I'd say we should try to make oopses as legible as possible.

Also KERN_CONT is inherently broken, and we should avoid using it in
general, IMO.

-- 
Josh

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

On 2018/07/10 4:11, Josh Poimboeuf wrote:
> On Mon, Jul 09, 2018 at 10:49:53AM +0200, Peter Zijlstra wrote:
>> On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
>>>>> Since syzbot is confused by concurrent printk() messages [1],
>>>>> this patch changes show_opcodes() to use snprintf().
>>
>> But how big of a problem is that really? We can't very well remove all
>> pr_cont stuff from the kernel.
> 
> I'd say we should try to make oopses as legible as possible.
> 
> Also KERN_CONT is inherently broken, and we should avoid using it in
> general, IMO.
> 

We can't afford removing all pr_cont()/KERN_CONT.
But show_opcodes() is an example of function which is expected to be SMP-safe.

  /*
   * 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
   * during early bootup (a continued line is not SMP-safe otherwise).
   */
  #define KERN_CONT       KERN_SOH "c"

RE: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[David Laight]

From: Josh Poimboeuf
> Sent: 09 July 2018 20:12
> On Mon, Jul 09, 2018 at 10:49:53AM +0200, Peter Zijlstra wrote:
> > On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
> > > >> Since syzbot is confused by concurrent printk() messages [1],
> > > >> this patch changes show_opcodes() to use snprintf().
> >
> > But how big of a problem is that really? We can't very well remove all
> > pr_cont stuff from the kernel.
> 
> I'd say we should try to make oopses as legible as possible.

To make oopses legible you need to lock the output between output lines.
Which would require a 'KERN_CONTINUED' marker on the previous print.

> Also KERN_CONT is inherently broken, and we should avoid using it in
> general, IMO.

I'm sure something semi-automatic could be done to expect a further
print if the line doesn't end in '\n'.
A per-cpu line buffer is probably excessive, but some kind of
timing out lock might work (release expecting re-acquire).

	David

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

On 2018/07/11 1:51, David Laight wrote:
> From: Josh Poimboeuf
>> Sent: 09 July 2018 20:12
>> On Mon, Jul 09, 2018 at 10:49:53AM +0200, Peter Zijlstra wrote:
>>> On Sat, Jul 07, 2018 at 10:54:28PM +0900, Tetsuo Handa wrote:
>>>>>> Since syzbot is confused by concurrent printk() messages [1],
>>>>>> this patch changes show_opcodes() to use snprintf().
>>>
>>> But how big of a problem is that really? We can't very well remove all
>>> pr_cont stuff from the kernel.
>>
>> I'd say we should try to make oopses as legible as possible.
> 
> To make oopses legible you need to lock the output between output lines.
> Which would require a 'KERN_CONTINUED' marker on the previous print.

There is an attempt to prefix context identifier to each line of output
( https://groups.google.com/d/msg/syzkaller/ttZehjXiHTU/JR67pXz3BAAJ ).
Therefore, I expect oops messages can stop using pr_cont()/KERN_CONT.

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

Ingo, is this patch acceptable?

On 2018/07/07 22:54, Tetsuo Handa wrote:
>From 61752cef56fad2a910f6bfd277e1b9b028aeab43 Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Sat, 7 Jul 2018 22:45:30 +0900
> Subject: [PATCH v2] x86: Avoid pr_cont() in show_opcodes()
> 
> Since syzbot is confused by concurrent printk() messages [1], this patch
> changes show_opcodes() to use snprintf(). By this change, the Code: line
> will always be printed as one line even if multiple threads concurrently
> called printk().
> 
> To save on-stack footprint, this patch shares opcodes[] and buf[] because
> we sequentially reads from opcodes[] and sequentially writes to buf[].
> 
> When we start adding prefix to each line of printk() output,
> we will be able to handle concurrent printk() messages.
> 
> [1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
> Cc: Borislav Petkov <bp@suse.de>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Josh Poimboeuf <jpoimboe@redhat.com>
> Cc: Linus Torvalds <torvalds@linux-foundation.org>
> Cc: Andy Lutomirski <luto@amacapital.net>
> ---
>  arch/x86/kernel/dumpstack.c | 16 +++++++++-------
>  1 file changed, 9 insertions(+), 7 deletions(-)
> 
> diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
> index 666a284..6408123 100644
> --- a/arch/x86/kernel/dumpstack.c
> +++ b/arch/x86/kernel/dumpstack.c
> @@ -94,25 +94,27 @@ static void printk_stack_address(unsigned long address, int reliable,
>  void show_opcodes(u8 *rip, const char *loglvl)
>  {
>  	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
> -	u8 opcodes[OPCODE_BUFSIZE];
>  	u8 *ip;
>  	int i;
> -
> -	printk("%sCode: ", loglvl);
> +	int pos = 0;
> +	char buf[(3 * OPCODE_BUFSIZE + 2) + 1];
> +	u8 *opcodes = (u8 *) buf + sizeof(buf) - OPCODE_BUFSIZE;
>  
>  	ip = (u8 *)rip - code_prologue;
>  	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
> -		pr_cont("Bad RIP value.\n");
> +		printk("%sCode: Bad RIP value.\n", loglvl);
>  		return;
>  	}
>  
>  	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
>  		if (ip == rip)
> -			pr_cont("<%02x> ", opcodes[i]);
> +			pos += snprintf(buf + pos, sizeof(buf) - pos,
> +					"<%02x> ", opcodes[i]);
>  		else
> -			pr_cont("%02x ", opcodes[i]);
> +			pos += snprintf(buf + pos, sizeof(buf) - pos,
> +					"%02x ", opcodes[i]);
>  	}
> -	pr_cont("\n");
> +	printk("%sCode: %s\n", loglvl, buf);
>  }
>  
>  void show_ip(struct pt_regs *regs, const char *loglvl)
> 

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Rasmus Villemoes]

On 2018-07-07 15:54, Tetsuo Handa wrote:
> On 2018/07/07 20:12, Ingo Molnar wrote:
>>
>> * Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> wrote:
>>
>>> From: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
>>>
>>> Since syzbot is confused by concurrent printk() messages [1],
>>> this patch changes show_opcodes() to use snprintf().
>>>
>>> When we start adding prefix to each line of printk() output,
>>> we will be able to handle concurrent printk() messages.
>>>
>>> [1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000
>>
>> Does this change the output?
>>
>> - If yes, could you show the before/after output in the changelog,
>>
>> - If not (i.e. if only the number of printk calls is changed, the output is the 
>>   same), could you say so in the changelog?
> 
> This patch will not change the output unless multiple threads concurrently
> call printk(). The purpose of this patch is to help parsing kernel messages
> when multiple threads are concurrently calling printk() for multiple times
> (e.g. backtrace) by reducing pr_cont()/KERN_CONT usage.
> 
>>
>> Also, 3*OPCODE_BUFSIZE+2+1 is 195 bytes - isn't that a bit too much on-stack 
>> footprint?
> 
> Then, we can reduce it by OPCODE_BUFSIZE bytes by unionizing opcodes[] and buf[].

Why not this instead? Less stack use, less code, no intermediary
snprintfs, no pr_cont...

diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index 666a284116ac..c881e8a757d9 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -93,26 +93,16 @@ static void printk_stack_address(unsigned long
address, int reliable,
  */
 void show_opcodes(u8 *rip, const char *loglvl)
 {
-       unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
+       unsigned int prologue = OPCODE_BUFSIZE * 2 / 3;
        u8 opcodes[OPCODE_BUFSIZE];
-       u8 *ip;
-       int i;

-       printk("%sCode: ", loglvl);
-
-       ip = (u8 *)rip - code_prologue;
-       if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
-               pr_cont("Bad RIP value.\n");
+       if (probe_kernel_read(opcodes, rip - prologue, OPCODE_BUFSIZE)) {
+               printk("%sCode: Bad RIP value.\n", loglvl);
                return;
        }
-
-       for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
-               if (ip == rip)
-                       pr_cont("<%02x> ", opcodes[i]);
-               else
-                       pr_cont("%02x ", opcodes[i]);
-       }
-       pr_cont("\n");
+       printk("%sCode: %*ph <%02x> %*ph\n", loglvl,
+              prologue, &opcodes[0], opcodes[prologue],
+              OPCODE_BUFSIZE - prologue - 1, &opcodes[prologue + 1]);
 }

 void show_ip(struct pt_regs *regs, const char *loglvl)

Not compile-tested, probably whitespace-damaged, but you get the idea.

Rasmus

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

On 2018/07/17 18:01, Rasmus Villemoes wrote:
> Why not this instead? Less stack use, less code, no intermediary
> snprintfs, no pr_cont...

Excellent! I didn't notice %ph extension.

> Not compile-tested, probably whitespace-damaged, but you get the idea.

Yes, it works well.



From 96d9d4d135994a081e54d33d23f5007c53d9b5dd Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Tue, 17 Jul 2018 22:47:11 +0900
Subject: [PATCH v3] x86: Avoid pr_cont() in show_opcodes()

Since syzbot is confused by concurrent printk() messages [1],
this patch changes show_opcodes() to use %*ph format string.

When we start adding prefix to each line of printk() output,
we will be able to handle concurrent printk() messages.

[1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
Signed-off-by: Rasmus Villemoes <mail@rasmusvillemoes.dk>
Cc: Borislav Petkov <bp@suse.de>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Andy Lutomirski <luto@amacapital.net>
---
 arch/x86/kernel/dumpstack.c | 25 +++++++------------------
 1 file changed, 7 insertions(+), 18 deletions(-)

diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index 666a284..ffdd484 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -93,26 +93,15 @@ static void printk_stack_address(unsigned long address, int reliable,
  */
 void show_opcodes(u8 *rip, const char *loglvl)
 {
-	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
+	const unsigned int prologue = OPCODE_BUFSIZE * 2 / 3;
 	u8 opcodes[OPCODE_BUFSIZE];
-	u8 *ip;
-	int i;
 
-	printk("%sCode: ", loglvl);
-
-	ip = (u8 *)rip - code_prologue;
-	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
-		pr_cont("Bad RIP value.\n");
-		return;
-	}
-
-	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
-		if (ip == rip)
-			pr_cont("<%02x> ", opcodes[i]);
-		else
-			pr_cont("%02x ", opcodes[i]);
-	}
-	pr_cont("\n");
+	if (probe_kernel_read(opcodes, rip - prologue, OPCODE_BUFSIZE))
+		printk("%sCode: Bad RIP value.\n", loglvl);
+	else
+		printk("%sCode: %*ph <%02x> %*ph\n", loglvl, prologue, opcodes,
+		       opcodes[prologue], OPCODE_BUFSIZE - prologue - 1,
+		       &opcodes[prologue + 1]);
 }
 
 void show_ip(struct pt_regs *regs, const char *loglvl)
-- 
1.8.3.1

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Rasmus Villemoes]

On 2018-07-17 15:53, Tetsuo Handa wrote:
> On 2018/07/17 18:01, Rasmus Villemoes wrote:
>> Why not this instead? Less stack use, less code, no intermediary
>> snprintfs, no pr_cont...
> 
> Excellent! I didn't notice %ph extension.
> 
>> Not compile-tested, probably whitespace-damaged, but you get the idea.
> 
> Yes, it works well.
> 
> 
> 
> From 96d9d4d135994a081e54d33d23f5007c53d9b5dd Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Tue, 17 Jul 2018 22:47:11 +0900
> Subject: [PATCH v3] x86: Avoid pr_cont() in show_opcodes()
> 
> Since syzbot is confused by concurrent printk() messages [1],
> this patch changes show_opcodes() to use %*ph format string.
> 
> When we start adding prefix to each line of printk() output,
> we will be able to handle concurrent printk() messages.
> 
> [1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp>
> Signed-off-by: Rasmus Villemoes <mail@rasmusvillemoes.dk>

I'm not sure that SoB-chain is correct. Anyway, however which way, and
if at all, you want to credit me, please use the email address
linux@rasmusvillemoes.dk . I probably botched From header in the
previous mail, not used to using Thunderbird...

Rasmus

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Tetsuo Handa]

Corrected Signed-off-by: addresses.

From 96d9d4d135994a081e54d33d23f5007c53d9b5dd Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Tue, 17 Jul 2018 22:47:11 +0900
Subject: [PATCH v4] x86: Avoid pr_cont() in show_opcodes()

Since syzbot is confused by concurrent printk() messages [1],
this patch changes show_opcodes() to use %*ph format string.

When we start adding prefix to each line of printk() output,
we will be able to handle concurrent printk() messages.

[1] https://syzkaller.appspot.com/text?tag=CrashReport&x=139d342c400000

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Signed-off-by: Rasmus Villemoes <linux@rasmusvillemoes.dk>
Cc: Borislav Petkov <bp@suse.de>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Andy Lutomirski <luto@amacapital.net>
---
 arch/x86/kernel/dumpstack.c | 25 +++++++------------------
 1 file changed, 7 insertions(+), 18 deletions(-)

diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
index 666a284..ffdd484 100644
--- a/arch/x86/kernel/dumpstack.c
+++ b/arch/x86/kernel/dumpstack.c
@@ -93,26 +93,15 @@ static void printk_stack_address(unsigned long address, int reliable,
  */
 void show_opcodes(u8 *rip, const char *loglvl)
 {
-	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
+	const unsigned int prologue = OPCODE_BUFSIZE * 2 / 3;
 	u8 opcodes[OPCODE_BUFSIZE];
-	u8 *ip;
-	int i;
 
-	printk("%sCode: ", loglvl);
-
-	ip = (u8 *)rip - code_prologue;
-	if (probe_kernel_read(opcodes, ip, OPCODE_BUFSIZE)) {
-		pr_cont("Bad RIP value.\n");
-		return;
-	}
-
-	for (i = 0; i < OPCODE_BUFSIZE; i++, ip++) {
-		if (ip == rip)
-			pr_cont("<%02x> ", opcodes[i]);
-		else
-			pr_cont("%02x ", opcodes[i]);
-	}
-	pr_cont("\n");
+	if (probe_kernel_read(opcodes, rip - prologue, OPCODE_BUFSIZE))
+		printk("%sCode: Bad RIP value.\n", loglvl);
+	else
+		printk("%sCode: %*ph <%02x> %*ph\n", loglvl, prologue, opcodes,
+		       opcodes[prologue], OPCODE_BUFSIZE - prologue - 1,
+		       &opcodes[prologue + 1]);
 }
 
 void show_ip(struct pt_regs *regs, const char *loglvl)
-- 
1.8.3.1

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Joe Perches]

On Wed, 2018-07-18 at 05:54 +0900, Tetsuo Handa wrote:
> Corrected Signed-off-by: addresses.
> 
> From 96d9d4d135994a081e54d33d23f5007c53d9b5dd Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Tue, 17 Jul 2018 22:47:11 +0900
> Subject: [PATCH v4] x86: Avoid pr_cont() in show_opcodes()
> 
> Since syzbot is confused by concurrent printk() messages [1],
> this patch changes show_opcodes() to use %*ph format string.
> 
> When we start adding prefix to each line of printk() output,
> we will be able to handle concurrent printk() messages.

If this were applied via git am, the commit would include
all the content from "Corrected Signed-off-by:"

Perhaps it would be better to send this as a new patch without
the leading 7 lines after the email header

> diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
[]
> @@ -93,26 +93,15 @@ static void printk_stack_address(unsigned long address, int reliable,
>   */
>  void show_opcodes(u8 *rip, const char *loglvl)
>  {
> -	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
> +	const unsigned int prologue = OPCODE_BUFSIZE * 2 / 3;

And this might be better as a #define to avoid
a few more bytes of stack consumption.

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Joe Perches]

On Tue, 2018-07-17 at 14:19 -0700, Joe Perches wrote:
> diff --git a/arch/x86/kernel/dumpstack.c b/arch/x86/kernel/dumpstack.c
> []
> > @@ -93,26 +93,15 @@ static void printk_stack_address(unsigned long address, int reliable,
> >   */
> >  void show_opcodes(u8 *rip, const char *loglvl)
> >  {
> > -	unsigned int code_prologue = OPCODE_BUFSIZE * 2 / 3;
> > +	const unsigned int prologue = OPCODE_BUFSIZE * 2 / 3;
> 
> And this might be better as a #define to avoid
> a few more bytes of stack consumption.

Apologies for this silly suggestion.

automatics are not structs and gcc will eliminate
this declaration at all compiler optimization levels.

Re: [PATCH] x86: Avoid pr_cont() in show_opcodes()

[Andy Shevchenko]

On Tue, Jul 17, 2018 at 12:01 PM, Rasmus Villemoes
<mail@rasmusvillemoes.dk> wrote:

> +       printk("%sCode: %*ph <%02x> %*ph\n", loglvl,

Ah, I had looked at this code and thought about %ph, but didn't get
through how to split it correctly.

Thanks for the hint!

P.S. I see the result, pretty nice and doesn't use pr_cont() at all.

-- 
With Best Regards,
Andy Shevchenko