[RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Luis Claudio R. Goncalves]

Avoid a possible circular locking dependency by taking the softirq_ctrl.lock
before taking raw_v6_hashinfo.lock in raw_seq_start(), keeping locking order
consistent.

Lockdep splat:

[  254.623863] ======================================================
[  254.623864] WARNING: possible circular locking dependency detected
[  254.623865] 5.10.65-rt53+ #1 Tainted: G S      W I      
[  254.623866] ------------------------------------------------------
[  254.623866] read_all/3963 is trying to acquire lock:
[  254.623867] ffffa05cde218220 ((softirq_ctrl.lock).lock){+.+.}-{2:2}, at: __local_bh_disable_ip+0x116/0x2f0
[  254.623876] 
               but task is already holding lock:
[  254.623877] ffffffffb68e93e0 (raw_v6_hashinfo.lock){++.+}-{0:0}, at: raw_seq_start+0x25/0x60
[  254.623883] 
               which lock already depends on the new lock.
...
[  254.623974]  Possible unsafe locking scenario:

[  254.623975]        CPU0                    CPU1
[  254.623975]        ----                    ----
[  254.623975]   lock(raw_v6_hashinfo.lock);
[  254.623976]                                lock((softirq_ctrl.lock).lock);
[  254.623977]                                lock(raw_v6_hashinfo.lock);
[  254.623978]   lock((softirq_ctrl.lock).lock);
[  254.623978] 
                *** DEADLOCK ***

[  254.623979] 3 locks held by read_all/3963:
[  254.623980]  #0: ffffa055d0c35990 (&p->lock){+.+.}-{0:0}, at: seq_read_iter+0x56/0x420
[  254.623983]  #1: ffffffffb68e93e0 (raw_v6_hashinfo.lock){++.+}-{0:0}, at: raw_seq_start+0x25/0x60
[  254.623986]  #2: ffffffffb64c8fa0 (rcu_read_lock){....}-{1:2}, at: rt_read_lock+0x7d/0x1e0


Reported-by: Chunyu Hu <chuhu@redhat.com>
Signed-off-by: Luis Claudio R. Goncalves <lgoncalv@redhat.com>
---
 net/ipv4/raw.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/net/ipv4/raw.c b/net/ipv4/raw.c
index a0188eb2689f..584d08679e3a 100644
--- a/net/ipv4/raw.c
+++ b/net/ipv4/raw.c
@@ -1051,7 +1051,7 @@ void *raw_seq_start(struct seq_file *seq, loff_t *pos)
 {
 	struct raw_hashinfo *h = PDE_DATA(file_inode(seq->file));
 
-	read_lock(&h->lock);
+	read_lock_bh(&h->lock);
 	return *pos ? raw_get_idx(seq, *pos - 1) : SEQ_START_TOKEN;
 }
 EXPORT_SYMBOL_GPL(raw_seq_start);
@@ -1073,7 +1073,7 @@ void raw_seq_stop(struct seq_file *seq, void *v)
 {
 	struct raw_hashinfo *h = PDE_DATA(file_inode(seq->file));
 
-	read_unlock(&h->lock);
+	read_unlock_bh(&h->lock);
 }
 EXPORT_SYMBOL_GPL(raw_seq_stop);
 

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Sebastian Andrzej Siewior]

On 2021-10-04 22:53:08 [-0300], Luis Claudio R. Goncalves wrote:
> Avoid a possible circular locking dependency by taking the softirq_ctrl.lock
> before taking raw_v6_hashinfo.lock in raw_seq_start(), keeping locking order
> consistent.

How do you reproduce this one? It does not trigger here. Maybe I'm doing
something wrong. The command
	hping3 -C 3 -K 1 -c 1 $ip

triggers raw_icmp_error() from within the softirq processing. And
	cat /proc/net/raw

does raw_seq_start(). No BH here. Additionally during boot raw_hash_sk()
is invoked from non-BH context here but it is a write-lock so it has to
disable BH since there is at least one reader in BH.

The ipv4 code looks close to the ipv6. The problem is that hping does
not support v6 :/ Maybe the ipv6 acquires a bh lock somewhere which
leads to this.

Sebastian

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Luis Goncalves]

On Mon, Oct 11, 2021 at 1:33 PM Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
>
> On 2021-10-04 22:53:08 [-0300], Luis Claudio R. Goncalves wrote:
> > Avoid a possible circular locking dependency by taking the softirq_ctrl.lock
> > before taking raw_v6_hashinfo.lock in raw_seq_start(), keeping locking order
> > consistent.
>
> How do you reproduce this one? It does not trigger here. Maybe I'm doing
> something wrong. The command
>         hping3 -C 3 -K 1 -c 1 $ip

In order to reproduce that lockdep splat I am running the following
tests from LTP lite:

   # Read every file in /proc. Not likely to crash, but does enough
   # to disturb the kernel. A good kernel latency killer too.
   # Was not sure why it should reside in runtest/crashme and won't
get tested ever

   read_all_dev read_all -d /dev -p -q -r 3
   read_all_proc read_all -d /proc -q -r 3
   read_all_sys read_all -d /sys -q -r 3

One thing I noticed though is that I can't reproduce the problem when
the tuned profile
in use is *realtime*. I can reproduce the problem with the
*throughput-performance* profile.

Again, the use of tuned in the tests is mostly to reproduce the
configuration in use at
the moment. I can isolate the specific configuration that makes it
possible to trigger the
lockdep splat.

>
> triggers raw_icmp_error() from within the softirq processing. And
>         cat /proc/net/raw
>
> does raw_seq_start(). No BH here. Additionally during boot raw_hash_sk()
> is invoked from non-BH context here but it is a write-lock so it has to
> disable BH since there is at least one reader in BH.
>
> The ipv4 code looks close to the ipv6. The problem is that hping does
> not support v6 :/ Maybe the ipv6 acquires a bh lock somewhere which
> leads to this.
>
> Sebastian
>

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Sebastian Andrzej Siewior]

On 2021-10-18 12:51:32 [-0300], Luis Goncalves wrote:
> Again, the use of tuned in the tests is mostly to reproduce the
> configuration in use at
> the moment. I can isolate the specific configuration that makes it
> possible to trigger the
> lockdep splat.

I can't reproduce any of those two issues. I tried both and iterated the
tuned profiles
	tuned-adm profile realtime
	tuned-adm profile throughput-performance

while running the test you mentioned.
Could you please try if this reproduces with latest v5.15-RT and post
complete lockdep backtrace?

Sebastian

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Luis Goncalves]

On Wed, Oct 27, 2021 at 6:06 AM Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
>
> On 2021-10-18 12:51:32 [-0300], Luis Goncalves wrote:
> > Again, the use of tuned in the tests is mostly to reproduce the
> > configuration in use at
> > the moment. I can isolate the specific configuration that makes it
> > possible to trigger the
> > lockdep splat.
>
> I can't reproduce any of those two issues. I tried both and iterated the
> tuned profiles
>         tuned-adm profile realtime
>         tuned-adm profile throughput-performance
>
> while running the test you mentioned.
> Could you please try if this reproduces with latest v5.15-RT and post
> complete lockdep backtrace?

Yes, sure!

Just as a reminder, I was able to reproduce that backtrace in v5.14-rt
up to v5.14-rc6-rt11. But starting from v5.14-rc7-rt12 I no longer
reproduced the problem.

> Sebastian
>

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Luis Goncalves]

On Wed, Oct 27, 2021 at 6:06 AM Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
>
> On 2021-10-18 12:51:32 [-0300], Luis Goncalves wrote:
> > Again, the use of tuned in the tests is mostly to reproduce the
> > configuration in use at
> > the moment. I can isolate the specific configuration that makes it
> > possible to trigger the
> > lockdep splat.
>
> I can't reproduce any of those two issues. I tried both and iterated the
> tuned profiles
>         tuned-adm profile realtime
>         tuned-adm profile throughput-performance
>
> while running the test you mentioned.
> Could you please try if this reproduces with latest v5.15-RT and post
> complete lockdep backtrace?

I couldn't reproduce that on v5.14-rt nor v5.15-rt. But I can easily
reproduce the lockdep splat on v5.10-rt, though.

This is the backtrace  for v5.10.73-rt54:

[  220.768268] run.sh (2905): /proc/2142/oom_adj is deprecated, please
use /proc/2142/oom_score_adj instead.
[  221.794958] LTP: starting read_all_proc (read_all -d /proc -q -r 3)
[  222.678607] ICMPv6: process `read_all' is using deprecated sysctl
(syscall) net.ipv6.neigh.default.base_reachable_time - use
net.ipv6.neigh.default.base_reachable_time_ms instead

[  222.897071] ======================================================
[  222.897071] WARNING: possible circular locking dependency detected
[  222.897072] 5.10.73-rt54.lockdep+ #2 Tainted: G S      W I
[  222.897073] ------------------------------------------------------
[  222.897074] read_all/3946 is trying to acquire lock:
[  222.897075] ffff9727dee18220
((softirq_ctrl.lock).lock){+.+.}-{2:2}, at:
__local_bh_disable_ip+0x116/0x2f0
[  222.897084]
               but task is already holding lock:
[  222.897085] ffffffffba2e9720 (raw_v6_hashinfo.lock){++.+}-{0:0},
at: raw_seq_start+0x25/0x60
[  222.897090]
               which lock already depends on the new lock.

[  222.897091]
               the existing dependency chain (in reverse order) is:
[  222.897092]
               -> #1 (raw_v6_hashinfo.lock){++.+}-{0:0}:
[  222.897093]        lock_acquire+0xde/0x380
[  222.897098]        rt_write_lock+0x3a/0x1b0
[  222.897101]        raw_hash_sk+0x3f/0xd0
[  222.897103]        inet6_create+0x2ef/0x690
[  222.897107]        __sock_create+0x1e2/0x430
[  222.897111]        inet_ctl_sock_create+0x33/0x90
[  222.897113]        icmpv6_sk_init+0x71/0x130
[  222.897118]        ops_init+0x3a/0x180
[  222.897123]        register_pernet_operations+0x126/0x220
[  222.897125]        register_pernet_subsys+0x24/0x40
[  222.897127]        icmpv6_init+0x11/0x4c
[  222.897132]        inet6_init+0x112/0x373
[  222.897133]        do_one_initcall+0x74/0x440
[  222.897137]        kernel_init_freeable+0x39d/0x408
[  222.897140]        kernel_init+0xb/0x12e
[  222.897142]        ret_from_fork+0x1f/0x30
[  222.897144]
               -> #0 ((softirq_ctrl.lock).lock){+.+.}-{2:2}:
[  222.897145]        check_prevs_add+0x1bb/0xe50
[  222.897147]        __lock_acquire+0x1187/0x1640
[  222.897149]        lock_acquire+0xde/0x380
[  222.897151]        rt_spin_lock+0x2b/0xd0
[  222.897152]        __local_bh_disable_ip+0x116/0x2f0
[  222.897155]        sock_i_ino+0x22/0x60
[  222.897157]        __ip6_dgram_sock_seq_show+0x3e/0xe0
[  222.897160]        raw6_seq_show+0x28/0x40
[  222.897162]        seq_read_iter+0x27e/0x420
[  222.897166]        seq_read+0x10f/0x160
[  222.897168]        proc_reg_read+0x3e/0x80
[  222.897171]        vfs_read+0xe7/0x1e0
[  222.897174]        ksys_read+0x5f/0xe0
[  222.897175]        do_syscall_64+0x33/0x40
[  222.897178]        entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  222.897179]
               other info that might help us debug this:

[  222.897179]  Possible unsafe locking scenario:

[  222.897180]        CPU0                    CPU1
[  222.897180]        ----                    ----
[  222.897180]   lock(raw_v6_hashinfo.lock);
[  222.897181]                                lock((softirq_ctrl.lock).lock);
[  222.897182]                                lock(raw_v6_hashinfo.lock);
[  222.897183]   lock((softirq_ctrl.lock).lock);
[  222.897183]
                *** DEADLOCK ***

[  222.897184] 3 locks held by read_all/3946:
[  222.897185]  #0: ffff9720939dfe10 (&p->lock){+.+.}-{0:0}, at:
seq_read_iter+0x56/0x420
[  222.897188]  #1: ffffffffba2e9720
(raw_v6_hashinfo.lock){++.+}-{0:0}, at: raw_seq_start+0x25/0x60
[  222.897191]  #2: ffffffffb9ec8fe0 (rcu_read_lock){....}-{1:2}, at:
rt_read_lock+0x7d/0x1e0
[  222.897194]
               stack backtrace:
[  222.897195] CPU: 28 PID: 3946 Comm: read_all Tainted: G S      W I
     5.10.73-rt54.lockdep+ #2
[  222.897196] Hardware name: Dell Inc. PowerEdge R740/07X9K0, BIOS
2.8.2 08/27/2020
[  222.897197] Call Trace:
[  222.897199]  dump_stack+0x77/0x97
[  222.897204]  check_noncircular+0xff/0x120
[  222.897208]  check_prevs_add+0x1bb/0xe50
[  222.897211]  __lock_acquire+0x1187/0x1640
[  222.897215]  lock_acquire+0xde/0x380
[  222.897217]  ? __local_bh_disable_ip+0x116/0x2f0
[  222.897221]  ? sock_i_ino+0x5/0x60
[  222.897223]  rt_spin_lock+0x2b/0xd0
[  222.897224]  ? __local_bh_disable_ip+0x116/0x2f0
[  222.897227]  __local_bh_disable_ip+0x116/0x2f0
[  222.897229]  sock_i_ino+0x22/0x60
[  222.897231]  __ip6_dgram_sock_seq_show+0x3e/0xe0
[  222.897234]  raw6_seq_show+0x28/0x40
[  222.897236]  seq_read_iter+0x27e/0x420
[  222.897239]  seq_read+0x10f/0x160
[  222.897243]  proc_reg_read+0x3e/0x80
[  222.897245]  vfs_read+0xe7/0x1e0
[  222.897247]  ksys_read+0x5f/0xe0
[  222.897249]  do_syscall_64+0x33/0x40
[  222.897251]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  222.897254] RIP: 0033:0x7f71817b99b2
[  222.897256] Code: 96 20 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb
b6 0f 1f 80 00 00 00 00 f3 0f 1e fa 8b 05 96 da 20 00 85 c0 75 12 31
c0 0f 05 <48> 3d 00 f0 ff ff 77 56 c3 0f 1f 44 00 00 41 54 49 89 d4 55
48 89
[  222.897258] RSP: 002b:00007ffed3549878 EFLAGS: 00000246 ORIG_RAX:
0000000000000000
[  222.897259] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f71817b99b2
[  222.897261] RDX: 00000000000003ff RSI: 00007ffed3549d20 RDI: 0000000000000003
[  222.897262] RBP: 00007f7181bec000 R08: 0000000000000020 R09: 0000000000000000
[  222.897262] R10: 0000000000000000 R11: 0000000000000246 R12: 000000002cab66e1
[  222.897263] R13: 00007ffed3549921 R14: 0000000000624730 R15: 0000000000000000
[  232.965010] LTP: starting read_all_sys (read_all -d /sys -q -r 3)
[  235.930281] rtc_cmos 00:00: Deprecated ABI, please use nvmem
[  237.200250] WARNING! power/level is deprecated; use power/control instead

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Sebastian Andrzej Siewior]

On 2021-11-04 15:48:46 [-0300], Luis Goncalves wrote:
> Yes, sure!
> 
> Just as a reminder, I was able to reproduce that backtrace in v5.14-rt
> up to v5.14-rc6-rt11. But starting from v5.14-rc7-rt12 I no longer
> reproduced the problem.

So I'm about to this but patch but this mail confused me. Can you bisect
which change is responsible for that? Based on the arguing, the same
callchain should exist in v5.15, too. And a diff
v5.14-rc6-rt11..v5.14-rc7-rt12 didn't show any change in that area.

Sebastian

Re: [RFC RT v5.10] [rt] repair usage of raw_v6_hashinfo.lock in raw_seq_start()

[Sebastian Andrzej Siewior]

On 2021-11-05 18:18:16 [+0100], To Luis Goncalves wrote:
> On 2021-11-04 15:48:46 [-0300], Luis Goncalves wrote:
> > Yes, sure!
> > 
> > Just as a reminder, I was able to reproduce that backtrace in v5.14-rt
> > up to v5.14-rc6-rt11. But starting from v5.14-rc7-rt12 I no longer
> > reproduced the problem.
> 
> So I'm about to this but patch but this mail confused me. Can you bisect
> which change is responsible for that? Based on the arguing, the same
> callchain should exist in v5.15, too. And a diff
> v5.14-rc6-rt11..v5.14-rc7-rt12 didn't show any change in that area.

Just to be clear:
- raw_seq_start() does read_lock(&h->lock) which is fine on its own.
- raw_seq_show() does local_bh_disable() via sock_i_ino() which nests
  into the former lock. So the problem as lockdep says is:
  
   Thread1                           Thread2
  raw_seq_start()
   -> read_lock(&h->lock)
                                     raw_hash_sk()
				     -> write_lock_bh(&h->lock)
				        -> local_bh_disable()
					-> write_lock(&h->lock) // blocks on T1
  raw_seq_show()
  -> sock_i_ino()
     -> local_bh_disable() // blocks on T2

and is valid on the same CPU.

Sebastian