kmsg_dump() sleeping while atomic

kmsg_dump() sleeping while atomic

[Scott Wood]

I got an oops on v5.0.7-rt5 (due to kexec code not properly checking for
disabled EFI, patch coming) and after the primary oops, I got this:

[  111.575331] 055: BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:2004
[  111.584457] 055: in_atomic(): 0, irqs_disabled(): 1, pid: 13289, name: kexec
[  111.591502] 055: INFO: lockdep is turned off.
[  111.595862] 055: irq event stamp: 481304
[  111.599786] 055: hardirqs last  enabled at (481303): [<ffffffff811853b0>] ktime_get_coarse_real_ts64+0x60/0xc0
[  111.609779] 055: hardirqs last disabled at (481304): [<ffffffff81001ea1>] trace_hardirqs_off_thunk+0x1a/0x1c
[  111.619599] 055: softirqs last  enabled at (0): [<ffffffff810d13e3>] copy_process.part.30+0x833/0x2680
[  111.628900] 055: softirqs last disabled at (0): [<0000000000000000>]           (null)
[  111.636723] 055: CPU: 55 PID: 13289 Comm: kexec Tainted: G      D     E     5.0.7-rt5+ #3
[  111.644896] 055: Hardware name: Intel Corporation S2600BT/S2600BT, BIOS SE5C620.86B.01.00.0763.022420181017 02/24/2018
[  111.655582] 055: Call Trace:
[  111.658468] 055:  dump_stack+0x5e/0x8b
[  111.662223] 055:  ___might_sleep+0x177/0x1e0
[  111.666494] 055:  __rt_mutex_lock_state+0x1f/0x80
[  111.671202] 055:  kmsg_dump+0x88/0x160
[  111.674951] 055:  ? kmsg_dump+0x1f/0x160
[  111.678880] 055:  oops_end+0x59/0xd0
[  111.682459] 055:  no_context+0x185/0x540
[  111.686383] 055:  ? __do_page_fault+0x1da/0x530
[  111.690918] 055:  do_page_fault+0x2d/0x290
[  111.695017] 055:  page_fault+0x1e/0x30
[  111.698769] 055: RIP: 0010:          (null)
[  111.702956] 055: Code: Bad RIP value.
[  111.706618] 055: RSP: 0018:ffffc900754d3ea8 EFLAGS: 00010246
[  111.712278] 055: 
[  111.714213] 055: RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffffc900754d3eb8
[  111.721777] 055: RDX: 0000000000000000 RSI: ffffc900754d3ec0 RDI: ffffc900754d3ed2
[  111.729342] 055: RBP: ffffc900754d3ef8 R08: ffffc900754d3eb7 R09: 0000000000000000
[  111.736910] 055: R10: 0000000000000000 R11: 0000000000000005 R12: 0000000000e84950
[  111.744476] 055: R13: 0000000037f54730 R14: 0000000000000000 R15: 0000000000000000
[  111.752045] 055:  ? arch_ima_get_secureboot+0x11e/0x190
[  111.757269] 055:  ? selinux_kernel_read_file+0x20/0x20
[  111.762406] 055:  ? ima_load_data+0x46/0xa0
[  111.766593] 055:  ? __x64_sys_kexec_load+0x44/0xd0
[  111.771384] 055:  ? do_syscall_64+0x5a/0x260
[  111.775657] 055:  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  111.791742] 055: RIP: 0010:          (null)
[  111.795930] 055: Code: Bad RIP value.
[  111.799595] 055: RSP: 0018:ffffc900754d3ea8 EFLAGS: 00010246
[  111.805254] 055: 
[  111.807185] 055: RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffffc900754d3eb8
[  111.814750] 055: RDX: 0000000000000000 RSI: ffffc900754d3ec0 RDI: ffffc900754d3ed2
[  111.822309] 055: RBP: ffffc900754d3ef8 R08: ffffc900754d3eb7 R09: 0000000000000000
[  111.829873] 055: R10: 0000000000000000 R11: 0000000000000005 R12: 0000000000e84950
[  111.837440] 055: R13: 0000000037f54730 R14: 0000000000000000 R15: 0000000000000000
[  111.845008] 055: FS:  00007fe31bffa740(0000) GS:ffff8897de200000(0000) knlGS:0000000000000000
[  111.853525] 055: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  111.859704] 055: CR2: ffffffffffffffd6 CR3: 00000017d47da004 CR4: 00000000007606e0
[  111.867272] 055: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  111.874837] 055: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  111.882401] 055: PKRU: 55555554
[  111.885540] 055: Kernel panic - not syncing: Fatal exception
[  111.891314] 055: Kernel Offset: disabled

...plus a bunch of "unexpected reschedule of offline CPU" messages.

kmsg_dump() calls kmsg_dump_rewind(), which calls mutex_lock().  This would
be broken even on non-RT.

It's not clear what kmsg_dump_lock is even supposed to be protecting --
kmsg_dump_get_buffer() does not take the lock, and the only caller to the
locked version of kmsg_dump_get_line() is in arch/um/kernel/kmsg_dump.c.

-Scott

[PATCH] printk: kmsg_dump: remove mutex usage

[John Ogness]

The kmsg dumper can be called from any context, but the dumping
helpers were using a mutex to synchronize the iterator against
concurrent dumps.

Rather than trying to synchronize the iterator, use a local copy
of the iterator during the dump. Then no synchronization is
required.

Reported-by: Scott Wood <swood@redhat.com>
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 I tested this patch by creating a custom dumper and triggering
 it from NMI context.

 kernel/printk/printk.c | 23 ++++++++++-------------
 1 file changed, 10 insertions(+), 13 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 997d07b6bf97..7d3522e0bcec 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -359,8 +359,6 @@ static u64 syslog_seq;
 static size_t syslog_partial;
 static bool syslog_time;
 
-static DEFINE_MUTEX(kmsg_dump_lock);
-
 /* the last printk record at the last 'clear' command */
 static u64 clear_seq;
 
@@ -2820,6 +2818,7 @@ module_param_named(always_kmsg_dump, always_kmsg_dump, bool, S_IRUGO | S_IWUSR);
  */
 void kmsg_dump(enum kmsg_dump_reason reason)
 {
+	struct kmsg_dumper dumper_local;
 	struct kmsg_dumper *dumper;
 
 	if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
@@ -2830,16 +2829,18 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		if (dumper->max_reason && reason > dumper->max_reason)
 			continue;
 
-		/* initialize iterator with data about the stored records */
-		dumper->active = true;
+		/*
+		 * use a local copy to avoid modifying the
+		 * iterator used by any other cpus/contexts
+		 */
+		memcpy(&dumper_local, dumper, sizeof(dumper_local));
 
-		kmsg_dump_rewind(dumper);
+		/* initialize iterator with data about the stored records */
+		dumper_local.active = true;
+		kmsg_dump_rewind(&dumper_local);
 
 		/* invoke dumper which will iterate over records */
-		dumper->dump(dumper, reason);
-
-		/* reset iterator */
-		dumper->active = false;
+		dumper_local.dump(&dumper_local, reason);
 	}
 	rcu_read_unlock();
 }
@@ -2951,9 +2952,7 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
 {
 	bool ret;
 
-	mutex_lock(&kmsg_dump_lock);
 	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
-	mutex_unlock(&kmsg_dump_lock);
 
 	return ret;
 }
@@ -3105,9 +3104,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
  */
 void kmsg_dump_rewind(struct kmsg_dumper *dumper)
 {
-	mutex_lock(&kmsg_dump_lock);
 	kmsg_dump_rewind_nolock(dumper);
-	mutex_unlock(&kmsg_dump_lock);
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
-- 
2.11.0

Re: [PATCH] printk: kmsg_dump: remove mutex usage

[Scott Wood]

On Wed, 2019-04-24 at 16:36 +0200, John Ogness wrote:
> @@ -2830,16 +2829,18 @@ void kmsg_dump(enum kmsg_dump_reason reason)
>  		if (dumper->max_reason && reason > dumper->max_reason)
>  			continue;
>  
> -		/* initialize iterator with data about the stored records */
> -		dumper->active = true;
> +		/*
> +		 * use a local copy to avoid modifying the
> +		 * iterator used by any other cpus/contexts
> +		 */
> +		memcpy(&dumper_local, dumper, sizeof(dumper_local));
>  
> -		kmsg_dump_rewind(dumper);
> +		/* initialize iterator with data about the stored records */
> +		dumper_local.active = true;
> +		kmsg_dump_rewind(&dumper_local);
>  
>  		/* invoke dumper which will iterate over records */
> -		dumper->dump(dumper, reason);
> -
> -		/* reset iterator */
> -		dumper->active = false;
> +		dumper_local.dump(&dumper_local, reason);
>  	}

When would a dumper (or anything else that checks it) ever see active be
false?

>  	rcu_read_unlock();
>  }
> @@ -2951,9 +2952,7 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper,
> bool syslog,
>  {
>  	bool ret;
>  
> -	mutex_lock(&kmsg_dump_lock);
>  	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
> -	mutex_unlock(&kmsg_dump_lock);
>  
>  	return ret;
>  }
> @@ -3105,9 +3104,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper
> *dumper)
>   */
>  void kmsg_dump_rewind(struct kmsg_dumper *dumper)
>  {
> -	mutex_lock(&kmsg_dump_lock);
>  	kmsg_dump_rewind_nolock(dumper);
> -	mutex_unlock(&kmsg_dump_lock);
>  }
>  EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
>  

Any reason not to get rid of the wrappers now that the lock's gone?

-Scott

Re: [PATCH] printk: kmsg_dump: remove mutex usage

[John Ogness]

On 2019-04-24, Scott Wood <swood@redhat.com> wrote:
> On Wed, 2019-04-24 at 16:36 +0200, John Ogness wrote:
>> @@ -2830,16 +2829,18 @@ void kmsg_dump(enum kmsg_dump_reason reason)
>>  		if (dumper->max_reason && reason > dumper->max_reason)
>>  			continue;
>>  
>> -		/* initialize iterator with data about the stored records */
>> -		dumper->active = true;
>> +		/*
>> +		 * use a local copy to avoid modifying the
>> +		 * iterator used by any other cpus/contexts
>> +		 */
>> +		memcpy(&dumper_local, dumper, sizeof(dumper_local));
>>  
>> -		kmsg_dump_rewind(dumper);
>> +		/* initialize iterator with data about the stored records */
>> +		dumper_local.active = true;
>> +		kmsg_dump_rewind(&dumper_local);
>>  
>>  		/* invoke dumper which will iterate over records */
>> -		dumper->dump(dumper, reason);
>> -
>> -		/* reset iterator */
>> -		dumper->active = false;
>> +		dumper_local.dump(&dumper_local, reason);
>>  	}
>
> When would a dumper (or anything else that checks it) ever see active be
> false?

A valid question. Originally I wanted to completely remove the active
flag. But really the rt patchset is not the place for these kinds of
changes. I am currently reworking printk (for mainline) and I will
evaluate the purpose/usefulness of the active flag for that work.

>>  	rcu_read_unlock();
>>  }
>> @@ -2951,9 +2952,7 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper,
>> bool syslog,
>>  {
>>  	bool ret;
>>  
>> -	mutex_lock(&kmsg_dump_lock);
>>  	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
>> -	mutex_unlock(&kmsg_dump_lock);
>>  
>>  	return ret;
>>  }
>> @@ -3105,9 +3104,7 @@ void kmsg_dump_rewind_nolock(struct kmsg_dumper
>> *dumper)
>>   */
>>  void kmsg_dump_rewind(struct kmsg_dumper *dumper)
>>  {
>> -	mutex_lock(&kmsg_dump_lock);
>>  	kmsg_dump_rewind_nolock(dumper);
>> -	mutex_unlock(&kmsg_dump_lock);
>>  }
>>  EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
>>  
>
> Any reason not to get rid of the wrappers now that the lock's gone?

I wanted my patch to be as less intrusive as possible. For my mainline
work I will look into eliminating the wrappers.

John Ogness

Re: [PATCH] printk: kmsg_dump: remove mutex usage

[Sebastian Andrzej Siewior]

On 2019-04-24 16:36:04 [+0200], John Ogness wrote:
> The kmsg dumper can be called from any context, but the dumping
> helpers were using a mutex to synchronize the iterator against
> concurrent dumps.
> 
> Rather than trying to synchronize the iterator, use a local copy
> of the iterator during the dump. Then no synchronization is
> required.
> 
> Reported-by: Scott Wood <swood@redhat.com>
> Signed-off-by: John Ogness <john.ogness@linutronix.de>

Applied.

Sebastian