Re: [PATCH 0/7] ROSE: Misc fixes

[f6bvp <f6bvp@free.fr>]

[-- Attachment #1: Type: text/plain, Size: 1708 bytes --]

Hello Ralf,

Running kernel 3.0.3 with rose patches.
Looking at the following code it seems that first spin_unlock is misplaced
just before memcpy().

I tried to move spin_unlock just after the call to memcpy without change.
The DEADLOCK is still there.


static void rose_get_neigh_callsign(ax25_address *rose_call,
         struct rose_neigh *neigh)
{
         spin_lock(&rose_callsign_lock);
         if (ax25cmp(&rose_callsign, &null_ax25_address) == 0) {
                 spin_unlock(&rose_callsign_lock);
                 memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));

                 return;
         }

When examining the inconsistent lock state report I may understand the 
reason.
The sequence is :

rose_route_frame()
rose_link_rx_start()
rose_send_frame()
rose_get_neigh_callsign()

However, rose_route_frame() is locking rose_route_list and 
rose_route_neigh_list with spin_lock_bh and if lci==0 there is a call in 
the function to rose_link_rx_restart before unlocking the lists.
If (neigh->restarted) rose_send_frame() is called and in turn will call 
rose_get_neigh_callsign() that tries to spin_lock rose_callsign_lock and 
here comes the conflicting situation.

Thus I modified rose_route_frame() in order to spin_unlock both lists 
before calling rose_link_rx_start().

Here are my patches.

However, another inconsistent lock state remains as you will see in the 
following attached file.


73 de Bernard


Le 08/08/2011 17:33, f6bvp a écrit :
> Hello Ralf,
>
> Booting 3.0.1 kernel with ROSE patches in SMP mode gives systematically
> the following Inconsistent Lock State.
> See attached file.
>
> Bernard
>
>


[-- Attachment #2: ROSE_8.patch --]
[-- Type: text/x-patch, Size: 845 bytes --]

--- a/net/rose/rose_link.c	2011-07-20 21:51:35.397778246 +0200
+++ a/net/rose/rose_link.new.c	2011-08-19 14:40:33.223383885 +0200
@@ -99,8 +99,8 @@ static void rose_get_neigh_callsign(ax25
 {
 	spin_lock(&rose_callsign_lock);
 	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0) {
-		spin_unlock(&rose_callsign_lock);
 		memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));
+		spin_unlock(&rose_callsign_lock);
 
 		return;
 	}
--- a/net/rose/rose_route.c	2011-07-20 22:00:57.104846408 +0200
+++ a/net/rose/rose_route.new.c	2011-08-19 15:01:07.498780039 +0200
@@ -910,8 +910,10 @@ int rose_route_frame(struct sk_buff *skb
 	 * 	frame.
 	 */
 	if (lci == 0) {
+		spin_unlock_bh(&rose_neigh_list_lock);
+		spin_unlock_bh(&rose_route_list_lock);
 		rose_link_rx_restart(skb, rose_neigh, frametype);
-		goto out;
+		return res;
 	}
 
 	/*

[-- Attachment #3: raw_spinlock_3.0.3 --]
[-- Type: text/plain, Size: 4355 bytes --]

=================================
[ INFO: inconsistent lock state ]
3.0.3 #2
---------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
kworker/1:1/20 [HC0[0]:SC1[1]:HE1:SE0] takes:
 (rose_callsign_lock){+.?...}, at: [<ffffffffa0583128>] rose_get_neigh_callsign+0x28/0x80 [rose]
{SOFTIRQ-ON-W} state was registered at:
  [<ffffffff81096ef4>] __lock_acquire+0x5f4/0x1620
  [<ffffffff81098512>] lock_acquire+0xa2/0x120
  [<ffffffff813fec21>] _raw_spin_lock+0x31/0x40
  [<ffffffffa02ab068>] 0xffffffffa02ab068
  [<ffffffff81002043>] do_one_initcall+0x43/0x190
  [<ffffffff810a4730>] sys_init_module+0x90/0x1f0
  [<ffffffff81407592>] system_call_fastpath+0x16/0x1b
irq event stamp: 24814
hardirqs last  enabled at (24814): [<ffffffff813ff420>] _raw_spin_unlock_irqrestore+0x40/0x70
hardirqs last disabled at (24813): [<ffffffff813fed1e>] _raw_spin_lock_irqsave+0x2e/0x70
softirqs last  enabled at (24772): [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
softirqs last disabled at (24773): [<ffffffff8140881c>] call_softirq+0x1c/0x30

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(rose_callsign_lock);
  <Interrupt>
    lock(rose_callsign_lock);

 *** DEADLOCK ***

3 locks held by kworker/1:1/20:
 #0:  (events){.+.+.+}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #1:  ((&tty->buf.work)){+.+...}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #2:  (rcu_read_lock){.+.+..}, at: [<ffffffff81340a4b>] __netif_receive_skb+0xeb/0x6a0

stack backtrace:
Pid: 20, comm: kworker/1:1 Not tainted 3.0.3 #2
Call Trace:
 <IRQ>  [<ffffffff810953d5>] print_usage_bug+0x225/0x270
 [<ffffffff810961c3>] mark_lock+0x323/0x3f0
 [<ffffffff81096e7e>] __lock_acquire+0x57e/0x1620
 [<ffffffff81097413>] ? __lock_acquire+0xb13/0x1620
 [<ffffffff81018fbf>] ? save_stack_trace+0x2f/0x50
 [<ffffffff81098512>] lock_acquire+0xa2/0x120
 [<ffffffffa0583128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff813fec21>] _raw_spin_lock+0x31/0x40
 [<ffffffffa0583128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff81096525>] ? trace_hardirqs_on_caller+0x65/0x180
 [<ffffffffa0583128>] rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffffa05832d3>] rose_send_frame+0x33/0xb0 [rose]
 [<ffffffff81333446>] ? skb_dequeue+0x66/0x90
 [<ffffffffa058366b>] rose_link_rx_restart+0x6b/0x170 [rose]
 [<ffffffffa0584dc7>] rose_route_frame+0x187/0x6f0 [rose]
 [<ffffffff8106ab6c>] ? lock_timer_base+0x3c/0x70
 [<ffffffffa056a96c>] ? ax25_protocol_function+0x1c/0x70 [ax25]
 [<ffffffff813ff420>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffffa0584c40>] ? rose_link_failed+0x90/0x90 [rose]
 [<ffffffffa056b8f7>] ax25_rx_iframe+0x77/0x350 [ax25]
 [<ffffffffa056df6e>] ax25_std_frame_in+0x8be/0x920 [ax25]
 [<ffffffffa057141c>] ? ax25_find_cb+0xcc/0x120 [ax25]
 [<ffffffffa056b1da>] ax25_rcv+0x3aa/0x9a0 [ax25]
 [<ffffffff810962fb>] ? mark_held_locks+0x6b/0xa0
 [<ffffffff813ff420>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffff8132f18a>] ? sock_def_readable+0x8a/0xb0
 [<ffffffff8132f100>] ? sock_get_timestamp+0xc0/0xc0
 [<ffffffffa056b86f>] ax25_kiss_rcv+0x9f/0xb0 [ax25]
 [<ffffffff81340b6d>] __netif_receive_skb+0x20d/0x6a0
 [<ffffffff81340a4b>] ? __netif_receive_skb+0xeb/0x6a0
 [<ffffffff813410d4>] process_backlog+0xd4/0x1e0
 [<ffffffff81342c75>] net_rx_action+0x125/0x280
 [<ffffffff81062196>] __do_softirq+0xc6/0x210
 [<ffffffff8140881c>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff8100d43d>] ? do_softirq+0x9d/0xd0
 [<ffffffffa0184532>] ? mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff81062efb>] local_bh_enable_ip+0xeb/0xf0
 [<ffffffff813ff394>] _raw_spin_unlock_bh+0x34/0x40
 [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff812a602a>] flush_to_ldisc+0x18a/0x1a0
 [<ffffffff81077336>] process_one_work+0x1a6/0x520
 [<ffffffff810772c7>] ? process_one_work+0x137/0x520
 [<ffffffff812a5ea0>] ? tty_schedule_flip+0x60/0x60
 [<ffffffff81079ca3>] worker_thread+0x173/0x400
 [<ffffffff81079b30>] ? manage_workers+0x210/0x210
 [<ffffffff8107e8a6>] kthread+0xb6/0xc0
 [<ffffffff810965fd>] ? trace_hardirqs_on_caller+0x13d/0x180
 [<ffffffff81408724>] kernel_thread_helper+0x4/0x10
 [<ffffffff813ff7d4>] ? retint_restore_args+0x13/0x13
 [<ffffffff8107e7f0>] ? __init_kthread_worker+0x70/0x70
 [<ffffffff81408720>] ? gs_change+0x13/0x13