Re: [PATCH][PPPOL2TP]: Fix SMP oops in pppol2tp driver

James Chapman
2008-02-12T10:58:29Z

David Miller wrote:
> From: James Chapman <jchapman@katalix.com>
> Date: Mon, 11 Feb 2008 23:41:18 +0000
>
>> Jarek Poplawski wrote:
>>> On Mon, Feb 11, 2008 at 10:19:35PM +0000, James Chapman wrote:
>>> ...
>>>> Below is example output from lockdep. The oops is reproducible when
>>>> creating/deleting lots of sessions while passing data. The lock is being
>>>> acquired for read and write in softirq contexts.
>>>>
>>>> Is there a better way to fix this?
>>>>
>>>> =================================
>>>> [ INFO: inconsistent lock state ]
>>>> 2.6.24-core2 #1
>>>> ---------------------------------
>>>> inconsistent {in-softirq-R} -> {softirq-on-W} usage.
>>>> openl2tpd/3215 [HC0[0]:SC0[0]:HE1:SE1] takes:
>>>> (&tunnel->hlist_lock){---?}, at: [<f8eea157>]
>>>> pppol2tp_connect+0x517/0x6d0 [pppol2tp]
>>>> {in-softirq-R} state was registered at:
>>> IMHO, according to this, disabling bh should be enough. And if it's
>>> like in this report: only read_lock is taken from softirqs, then this
>>> should be necessary to change only all write_locks to write_lock_bh
>>> (of course unless somewhere bhs are disabled already). Unless I miss
>>> something?!
>> I thought so too. I tried _bh locks first and the problem still
>> occurred. Maybe I'll try it again in case I messed something up.
>
> I agree with Jarek here, I look at all the code paths that take
> ->hlist_lock and all of them are in user context or software
> interrupts.
>
> Please get a lockdep trace with the change to _bh intead of
> hw interrupt protection so we can find out what that doesn't
> work.
>
> Thanks!

Here is a trace from when we had _bh locks.

Feb 5 16:26:32 ======================================================
Feb 5 16:26:32 [ INFO: soft-safe -> soft-unsafe lock order detected ]
Feb 5 16:26:32 2.6.24-core2 #1
Feb 5 16:26:32 ------------------------------------------------------
Feb 5 16:26:32 pppd/3224 [HC0[0]:SC0[2]:HE1:SE0] is trying to acquire:
Feb 5 16:26:32 (&sk->sk_dst_lock){----}, at: [<f8efacac>]
pppol2tp_xmit+0x23c/0x460 [pppol2tp]
Feb 5 16:26:32
Feb 5 16:26:32 and this task is already holding:
Feb 5 16:26:32 (&pch->downl){-...}, at: [<f8eb828e>]
ppp_push+0x44e/0x620 [ppp_generic]
Feb 5 16:26:32 which would create a new lock dependency:
Feb 5 16:26:32 (&pch->downl){-...} -> (&sk->sk_dst_lock){----}
Feb 5 16:26:32
Feb 5 16:26:32 but this new dependency connects a soft-irq-safe lock:
Feb 5 16:26:32 (&pch->upl){-.-+}
Feb 5 16:26:32 ... which became soft-irq-safe at:
Feb 5 16:26:32 [<c014d87f>] check_usage_backwards+0x1f/0x50
Feb 5 16:26:32 [<c014c479>] save_trace+0x39/0xa0
Feb 5 16:26:32 [<c014edaf>] __lock_acquire+0x6bf/0x10a0
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<c040425f>] _read_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<f8ef915a>] pppol2tp_recv_core+0x46a/0x960 [pppol2tp]
Feb 5 16:26:32 [<f8ef967e>] pppol2tp_udp_encap_recv+0x2e/0x70 [pppol2tp]
Feb 5 16:26:32 [<c0403fd4>] _read_unlock+0x14/0x20
Feb 5 16:26:32 [<c03dd6b6>] udp_queue_rcv_skb+0x106/0x2a0
Feb 5 16:26:32 [<c03ddc7a>] __udp4_lib_rcv+0x42a/0x7e0
Feb 5 16:26:32 [<f8d5c090>] ipt_hook+0x0/0x20 [iptable_filter]
Feb 5 16:26:32 [<c03bc2fa>] ip_local_deliver_finish+0xca/0x1c0
Feb 5 16:26:32 [<c03bc25e>] ip_local_deliver_finish+0x2e/0x1c0
Feb 5 16:26:32 [<c03bbfcf>] ip_rcv_finish+0xff/0x360
Feb 5 16:26:32 [<c03bc6fc>] ip_rcv+0x20c/0x2a0
Feb 5 16:26:32 [<c03bbed0>] ip_rcv_finish+0x0/0x360
Feb 5 16:26:32 [<c039ad87>] netif_receive_skb+0x317/0x4b0
Feb 5 16:26:32 [<c039ab70>] netif_receive_skb+0x100/0x4b0
Feb 5 16:26:32 [<f8d7e27a>] e1000_clean_rx_irq_ps+0x28a/0x560 [e1000]
Feb 5 16:26:32 [<f8d7dff0>] e1000_clean_rx_irq_ps+0x0/0x560 [e1000]
Feb 5 16:26:32 [<f8d7b84d>] e1000_clean+0x5d/0x290 [e1000]
Feb 5 16:26:32 [<c039d580>] net_rx_action+0x1a0/0x2a0
Feb 5 16:26:32 [<c039d43f>] net_rx_action+0x5f/0x2a0
Feb 5 16:26:32 [<c0131e72>] __do_softirq+0x92/0x120
Feb 5 16:26:32 [<c0131f78>] do_softirq+0x78/0x80
Feb 5 16:26:32 [<c010b15a>] do_IRQ+0x4a/0xa0
Feb 5 16:26:32 [<c0127af0>] finish_task_switch+0x0/0xc0
Feb 5 16:26:32 [<c0108dcc>] common_interrupt+0x24/0x34
Feb 5 16:26:32 [<c0108dd6>] common_interrupt+0x2e/0x34
Feb 5 16:26:32 [<c01062d6>] mwait_idle_with_hints+0x46/0x60
Feb 5 16:26:32 [<c0106550>] mwait_idle+0x0/0x20
Feb 5 16:26:32 [<c0106694>] cpu_idle+0x74/0xe0
Feb 5 16:26:32 [<c0536a9a>] start_kernel+0x30a/0x3a0
Feb 5 16:26:32 [<c0536150>] unknown_bootoption+0x0/0x1f0
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32
Feb 5 16:26:32 to a soft-irq-unsafe lock:
Feb 5 16:26:32 (&sk->sk_dst_lock){----}
Feb 5 16:26:32 ... which became soft-irq-unsafe at:
Feb 5 16:26:32 ... [<c014e02e>] mark_held_locks+0x5e/0x80
Feb 5 16:26:32 [<c014ed92>] __lock_acquire+0x6a2/0x10a0
Feb 5 16:26:32 [<c010f5b0>] save_stack_trace+0x20/0x40
Feb 5 16:26:32 [<c014c524>] add_lock_to_list+0x44/0xb0
Feb 5 16:26:32 [<c03dea29>] __udp_lib_get_port+0x19/0x200
Feb 5 16:26:32 [<c014f735>] __lock_acquire+0x1045/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<c03db0a3>] ip4_datagram_connect+0x53/0x380
Feb 5 16:26:32 [<c040418a>] _write_lock+0x2a/0x40
Feb 5 16:26:32 [<c03db0a3>] ip4_datagram_connect+0x53/0x380
Feb 5 16:26:32 [<c03db0a3>] ip4_datagram_connect+0x53/0x380
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c0132317>] local_bh_enable_ip+0xa7/0x120
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<c03e4d55>] inet_dgram_connect+0x35/0x80
Feb 5 16:26:32 [<c038ec52>] sys_connect+0x82/0xd0
Feb 5 16:26:32 [<c01455df>] down_read_trylock+0x4f/0x60
Feb 5 16:26:32 [<c011fe9c>] do_page_fault+0xfc/0x940
Feb 5 16:26:32 [<c0404024>] _spin_unlock+0x14/0x20
Feb 5 16:26:32 [<c03905f8>] sys_socketcall+0x98/0x280
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c02a86ba>] copy_to_user+0x3a/0x70
Feb 5 16:26:32 [<c0108417>] restore_nocheck+0x12/0x15
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32
Feb 5 16:26:32 other info that might help us debug this:
Feb 5 16:26:32
Feb 5 16:26:32 2 locks held by pppd/3224:
Feb 5 16:26:32 #0: (&ppp->wlock){-...}, at: [<f8eb8478>]
ppp_xmit_process+0x18/0x630 [ppp_generic]
Feb 5 16:26:32 #1: (&pch->downl){-...}, at: [<f8eb828e>]
ppp_push+0x44e/0x620 [ppp_generic]
Feb 5 16:26:32
Feb 5 16:26:32 the soft-irq-safe lock's dependencies:
Feb 5 16:26:32 -> (&pch->upl){-.-+} ops: 0 {
Feb 5 16:26:32 initial-use at:
Feb 5 16:26:32 [<c014e80d>] __lock_acquire+0x11d/0x10a0
Feb 5 16:26:32 [<f8efacf3>] pppol2tp_xmit+0x283/0x460 [pppol2tp]
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<c040425f>] _read_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<f8eb9ffd>] ppp_write+0xdd/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0181f86>] vfs_write+0xa6/0x140
Feb 5 16:26:32 [<c0108417>] restore_nocheck+0x12/0x15
Feb 5 16:26:32 [<f8eb9f20>] ppp_write+0x0/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0182651>] sys_write+0x41/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 hardirq-on-W at:
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014c524>] add_lock_to_list+0x44/0xb0
Feb 5 16:26:32 [<c014ed68>] __lock_acquire+0x678/0x10a0
Feb 5 16:26:32 [<c014e02e>] mark_held_locks+0x5e/0x80
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb7387>] ppp_ioctl+0x647/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c04041cf>] _write_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb7387>] ppp_ioctl+0x647/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb7387>] ppp_ioctl+0x647/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 in-softirq-R at:
Feb 5 16:26:32 [<c014d87f>] check_usage_backwards+0x1f/0x50
Feb 5 16:26:32 [<c014c479>] save_trace+0x39/0xa0
Feb 5 16:26:32 [<c014edaf>] __lock_acquire+0x6bf/0x10a0
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<c040425f>] _read_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<f8eba092>] ppp_input+0x62/0x140 [ppp_generic]
Feb 5 16:26:32 [<f8ef915a>] pppol2tp_recv_core+0x46a/0x960 [pppol2tp]
Feb 5 16:26:32 [<f8ef967e>] pppol2tp_udp_encap_recv+0x2e/0x70 [pppol2tp]
Feb 5 16:26:32 [<c0403fd4>] _read_unlock+0x14/0x20
Feb 5 16:26:32 [<c03dd6b6>] udp_queue_rcv_skb+0x106/0x2a0
Feb 5 16:26:32 [<c03ddc7a>] __udp4_lib_rcv+0x42a/0x7e0
Feb 5 16:26:32 [<f8d5c090>] ipt_hook+0x0/0x20 [iptable_filter]
Feb 5 16:26:32 [<c03bc2fa>] ip_local_deliver_finish+0xca/0x1c0
Feb 5 16:26:32 [<c03bc25e>] ip_local_deliver_finish+0x2e/0x1c0
Feb 5 16:26:32 [<c03bbfcf>] ip_rcv_finish+0xff/0x360
Feb 5 16:26:32 [<c03bc6fc>] ip_rcv+0x20c/0x2a0
Feb 5 16:26:32 [<c03bbed0>] ip_rcv_finish+0x0/0x360
Feb 5 16:26:32 [<c039ad87>] netif_receive_skb+0x317/0x4b0
Feb 5 16:26:32 [<c039ab70>] netif_receive_skb+0x100/0x4b0
Feb 5 16:26:32 [<f8d7e27a>] e1000_clean_rx_irq_ps+0x28a/0x560 [e1000]
Feb 5 16:26:32 [<f8d7dff0>] e1000_clean_rx_irq_ps+0x0/0x560 [e1000]
Feb 5 16:26:32 [<f8d7b84d>] e1000_clean+0x5d/0x290 [e1000]
Feb 5 16:26:32 [<c039d580>] net_rx_action+0x1a0/0x2a0
Feb 5 16:26:32 [<c039d43f>] net_rx_action+0x5f/0x2a0
Feb 5 16:26:32 [<c0131e72>] __do_softirq+0x92/0x120
Feb 5 16:26:32 [<c0131f78>] do_softirq+0x78/0x80
Feb 5 16:26:32 [<c010b15a>] do_IRQ+0x4a/0xa0
Feb 5 16:26:32 [<c0127af0>] finish_task_switch+0x0/0xc0
Feb 5 16:26:32 [<c0108dcc>] common_interrupt+0x24/0x34
Feb 5 16:26:32 [<c0108dd6>] common_interrupt+0x2e/0x34
Feb 5 16:26:32 [<c01062d6>] mwait_idle_with_hints+0x46/0x60
Feb 5 16:26:32 [<c0106550>] mwait_idle+0x0/0x20
Feb 5 16:26:32 [<c0106694>] cpu_idle+0x74/0xe0
Feb 5 16:26:32 [<c0536a9a>] start_kernel+0x30a/0x3a0
Feb 5 16:26:32 [<c0536150>] unknown_bootoption+0x0/0x1f0
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 hardirq-on-R at:
Feb 5 16:26:32 [<c014da27>] mark_lock+0x77/0x620
Feb 5 16:26:32 [<c014ec2f>] __lock_acquire+0x53f/0x10a0
Feb 5 16:26:32 [<f8efacf3>] pppol2tp_xmit+0x283/0x460 [pppol2tp]
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<c040425f>] _read_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<f8eb8af2>] ppp_channel_push+0x62/0x90 [ppp_generic]
Feb 5 16:26:32 [<f8eb9ffd>] ppp_write+0xdd/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0181f86>] vfs_write+0xa6/0x140
Feb 5 16:26:32 [<c0108417>] restore_nocheck+0x12/0x15
Feb 5 16:26:32 [<f8eb9f20>] ppp_write+0x0/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0182651>] sys_write+0x41/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 }
Feb 5 16:26:32 ... key at: [<f8ebdf20>]
__key.30415+0x0/0xffffc2e7 [ppp_generic]
Feb 5 16:26:32 -> (&ppp->wlock){-...} ops: 0 {
Feb 5 16:26:32 initial-use at:
Feb 5 16:26:32 [<c014e80d>] __lock_acquire+0x11d/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 hardirq-on-W at:
Feb 5 16:26:32 [<c014da27>] mark_lock+0x77/0x620
Feb 5 16:26:32 [<c014ed68>] __lock_acquire+0x678/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb7698>] ppp_ioctl+0x958/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 }
Feb 5 16:26:32 ... key at: [<f8ebdf08>]
__key.30659+0x0/0xffffc2ff [ppp_generic]
Feb 5 16:26:32 -> (&ppp->rlock){-...} ops: 0 {
Feb 5 16:26:32 initial-use at:
Feb 5 16:26:32 [<c014e80d>] __lock_acquire+0x11d/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 hardirq-on-W at:
Feb 5 16:26:32 [<c014da27>] mark_lock+0x77/0x620
Feb 5 16:26:32 [<c014ed68>] __lock_acquire+0x678/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb7661>] ppp_ioctl+0x921/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c014e1c5>] trace_hardirqs_on+0xc5/0x170
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 }
Feb 5 16:26:32 ... key at: [<f8ebdf10>]
__key.30658+0x0/0xffffc2f7 [ppp_generic]
Feb 5 16:26:32 ... acquired at:
Feb 5 16:26:32 [<c014f68f>] __lock_acquire+0xf9f/0x10a0
Feb 5 16:26:32 [<f8eb76a5>] ppp_ioctl+0x965/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<f8eb76a5>] ppp_ioctl+0x965/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c040414f>] _spin_lock_bh+0x2f/0x40
Feb 5 16:26:32 [<f8eb76a5>] ppp_ioctl+0x965/0xf40 [ppp_generic]
Feb 5 16:26:32 [<f8eb76a5>] ppp_ioctl+0x965/0xf40 [ppp_generic]
Feb 5 16:26:32 [<c0404665>] _spin_unlock_irqrestore+0x55/0x70
Feb 5 16:26:32 [<c0403e4e>] __down+0xde/0xed
Feb 5 16:26:32 [<c0124220>] default_wake_function+0x0/0x10
Feb 5 16:26:32 [<c0403bdb>] __down_failed+0x7/0xc
Feb 5 16:26:32 [<c018d8f8>] do_ioctl+0x78/0x90
Feb 5 16:26:32 [<c018d96c>] vfs_ioctl+0x5c/0x290
Feb 5 16:26:32 [<c018dbdd>] sys_ioctl+0x3d/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32
Feb 5 16:26:32 -> (&list->lock#4){.+..} ops: 0 {
Feb 5 16:26:32 initial-use at:
Feb 5 16:26:32 [<c014e80d>] __lock_acquire+0x11d/0x10a0
Feb 5 16:26:32 [<c0193ba2>] dput+0xa2/0x130
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<c040450c>] _spin_lock_irqsave+0x4c/0x70
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<f8eb9fd5>] ppp_write+0xb5/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0181f86>] vfs_write+0xa6/0x140
Feb 5 16:26:32 [<c0108417>] restore_nocheck+0x12/0x15
Feb 5 16:26:32 [<f8eb9f20>] ppp_write+0x0/0x110 [ppp_generic]
Feb 5 16:26:32 [<c0182651>] sys_write+0x41/0x70
Feb 5 16:26:32 [<c01083aa>] syscall_call+0x7/0xb
Feb 5 16:26:32 [<ffffffff>] 0xffffffff
Feb 5 16:26:32 in-softirq-W at:
Feb 5 16:26:32 [<c014c479>] save_trace+0x39/0xa0
Feb 5 16:26:32 [<c014db32>] mark_lock+0x182/0x620
Feb 5 16:26:32 [<c014ed36>] __lock_acquire+0x646/0x10a0
Feb 5 16:26:32 [<c014ef26>] __lock_acquire+0x836/0x10a0
Feb 5 16:26:32 [<c014ee8e>] __lock_acquire+0x79e/0x10a0
Feb 5 16:26:32 [<c014f804>] lock_acquire+0x74/0xa0
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<c040450c>] _spin_lock_irqsave+0x4c/0x70
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<c0394b9c>] skb_queue_tail+0x1c/0x50
Feb 5 16:26:32 [<f8eba0a8>] ppp_input+0x78/0x140 [ppp_generic]
Feb 5 16:26:32 [<f8ef915a>] pppol2tp_recv_core+0x46a/0x960 [pppol2tp]
Feb 5 16:26:32 [<f8ef967e>] pppol2tp_udp_encap_recv+0x2e/0x70 [pppol2tp]
Feb 5 16:26:32 [<c0403fd4>] _read_unlock+0x14/0x20
Feb 5 16:26:32 [<c03dd6b6>] udp_queue_rcv_skb+0x106/0x2a0
Feb 5 16:26:32 [<c03ddc7a>] __udp4_lib_rcv+0x42a/0x7e0
Feb 5 16:26:32 [<f8d5c090>] ipt_hook+0x0/0x20 [iptable_filter]
Feb 5 16:26:32 [<c03bc2fa>] ip_local_deliver_finish+0xca/0x1c0
Feb 5 16:26:32 [<c03bc25e>] ip_local_deliver_finish+0x2e/0x1c0
Feb 5 16:26:32 [<c03bbfcf>] ip_rcv_finish+0xff/0x360
Feb 5 16:26:32 [<c03bc6fc>] ip_rcv+0x20c/0x2a0
Feb 5 16:26:32 [<c03bbed0>] ip_rcv_finish+0x0/0x360
Feb 5 16:26:32 [<c039ad87>] netif_receive_skb+0x317/0x4b0
Feb 5 16:26:32 [<c039ab70>] netif_receive_skb+0x100/0x4b0
Feb 5 16:26:32 [<f8d7e27a>] e1000_clean_rx_irq_ps+0x28a/0x560 [e1000]
Feb 5 16:26:32 [<f8d7dff0>] e1000_clean_rx_irq_ps+0x0/0x560 [e1000]
Feb 5 16:26:32 [<f8d7b84d>] e1000_clean+0x5d/0x290 [e1000]
Feb 5 16:26:32 [<c039d580>] net_rx_action+0x1a0/0x2a0
Feb 5 16:26:32 [<c039d43f>] net_rx_action+0x5f/0x2a0
Feb 5 16:26:32 [<c0131e72>] __do_softirq+0x92/0x120
Feb 5 16:26:32 [<c0131f78>] do_softirq+0x78/0x80
Feb 5 16:26:32 [<c010b15a>] do_IRQ+0x4a/0xa0
Feb 5 16:26:32 [<c0127af0>] finish_task_switch+0x0/0xc0
Feb 5 16:26:32 [<c0108dcc>] common_interrupt+0x24/0x34
Feb 5 16:26:32 [<c0108dd6>] common_interrupt+0x2e/0x34
Feb 5 16:26:32 [<c01062d6>] mwait_idle_with_hints+0x46/0x60
Feb 5 16:26:32 [<c0106550>] mwait_idle+0x0/0x20
Feb 5 16:26:32 [<c0106694>] cpu_idle+0x74/0xe0
Feb 5 16:26:32 [<c0536a9a>] start_kernel+0x30a/0x3a0

--
James Chapman
Katalix Systems Ltd
http://www.katalix.com
Catalysts for your Embedded Linux software development