Re: [2.5.69] rtnl-deadlock with usermodehelper and keventd

Jean Tourrilhes
2003-05-15T20:01:16Z

Greg,

This is a HotPlug problem, so would you mind forwarding this
to the relevant person and help Martin ?
Thanks in advance...

Jean

On Thu, May 15, 2003 at 03:14:36PM +0200, Martin Diehl wrote:
>
> Hi,
>
> seems we may run into mutual deadlock in the unregister_netdev() path with
> CONFIG_HOTPLUG=y. I managed to reproduce an irda-user report leading to
> the following description:
>
> * killing irattach (userland daemon comparable to pppd) starts closing the
> irda tty-ldisc
>
> * there we call unregister_netdev() on behalf of the (already closed)
> irda0 network device.
>
> * unregister_netdev() takes rtnl_lock
>
> * further down in unregister_netdevice() with CONFIG_HOTPLUG the network
> layers wants to call userland hotplug stuff
>
> * the request to fork the usermodehelper gets queued for the event/0
> workqueue (aka keventd) and we are blocking with rtnl still acquired for
> completion.
>
> * at this moment for some reason keventd has a linkwatch_event()
> apparently already scheduled before the usermode helper. So we run into
> linkwatch_event() with tries to get rtnl_lock.
>
> -> mutual deadlock: keventd waiting for rtnl_lock which is still hold by
> unregister_netdev blocking for completion of work scheduled for keventd.
>
> I can reproduce this with 2.5.69 with CONFIG_HOTPLUG enabled, no matter
> what /proc/sys/kernel/hotplug is, even /bin/true is sufficient. I've no
> idea why I get this with irda0 but not with eth0 for example.
> FWIW kernel is SMP running on UP without preempt.
>
> As I don't see how the irda stuff could cause unregister_netdev() to
> schedule the hotplug stuff with some linkwatch_event already scheduled
> I've no idea what the real problem and fix might be.
>
> Below a commented calltrace catched right when it hangs as described.
>
> Thanks
> Martin
>
> -----------------------------
>
> > May 14 13:14:17 laptop kernel: events/0 D C12FDF04 412092 3 1 4 2 (L-TLB)
> > May 14 13:14:17 laptop kernel: Call Trace:
> > May 14 13:14:17 laptop kernel: [__down+150/256] __down+0x96/0x100
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [__down_failed+8/12] __down_failed+0x8/0xc
> > May 14 13:14:17 laptop kernel: [.text.lock.rtnetlink+5/54] .text.lock.rtnetlink+0x5/0x36
> > May 14 13:14:17 laptop kernel: [linkwatch_event+29/48] linkwatch_event+0x1d/0x30
> > May 14 13:14:17 laptop kernel: [worker_thread+511/736] worker_thread+0x1ff/0x2e0
> > May 14 13:14:17 laptop kernel: [linkwatch_event+0/48] linkwatch_event+0x0/0x30
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [ret_from_fork+6/20] ret_from_fork+0x6/0x14
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [worker_thread+0/736] worker_thread+0x0/0x2e0
> > May 14 13:14:17 laptop kernel: [kernel_thread_helper+5/24] kernel_thread_helper+0x5/0x18
>
> This is the keventd-thread. It has some work scheduled for the network
> layer, namely linkwatch_event(). This is currently blocking to get the
> rtnl_lock semaphore.
>
>
> > May 14 13:14:17 laptop kernel: irattach D 00000000 4283667124 400 1 537 396 (NOTLB)
> > May 14 13:14:17 laptop kernel: Call Trace:
> > May 14 13:14:17 laptop kernel: [try_to_wake_up+296/464] try_to_wake_up+0x128/0x1d0
> > May 14 13:14:17 laptop kernel: [wait_for_completion+153/224] wait_for_completion+0x99/0xe0
>
> (5)
>
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [queue_work+132/160] queue_work+0x84/0xa0
>
> (4)
>
> > May 14 13:14:17 laptop kernel: [call_usermodehelper+257/272] call_usermodehelper+0x101/0x110
> > May 14 13:14:17 laptop kernel: [__call_usermodehelper+0/112] __call_usermodehelper+0x0/0x70
> > May 14 13:14:17 laptop kernel: [vsprintf+39/48] vsprintf+0x27/0x30
> > May 14 13:14:17 laptop kernel: [sprintf+31/48] sprintf+0x1f/0x30
> > May 14 13:14:17 laptop kernel: [net_run_sbin_hotplug+174/195] net_run_sbin_hotplug+0xae/0xc3
>
> (3)
>
> > May 14 13:14:17 laptop kernel: [try_to_wake_up+296/464] try_to_wake_up+0x128/0x1d0
> > May 14 13:14:17 laptop kernel: [pfifo_fast_reset+158/160] pfifo_fast_reset+0x9e/0xa0
> > May 14 13:14:17 laptop kernel: [qdisc_destroy+158/160] qdisc_destroy+0x9e/0xa0
> > May 14 13:14:17 laptop kernel: [unregister_netdevice+211/608] unregister_netdevice+0xd3/0x260
> > May 14 13:14:17 laptop kernel: [_end+282800068/1070304612] sirdev_dtor+0x0/0x20 [sir_dev]
>
> (2)
>
> > May 14 13:14:17 laptop kernel: [unregister_netdev+24/48] unregister_netdev+0x18/0x30
>
> (1)
>
> > May 14 13:14:17 laptop kernel: [_end+282800429/1070304612] sirdev_put_instance+0x149/0x1ad [sir_dev]
> > May 14 13:14:17 laptop kernel: [_end+282804705/1070304612] __func__.9+0x0/0x14 [sir_dev]
> > May 14 13:14:17 laptop kernel: [_end+282131315/1070304612] irtty_close+0x4f/0x120 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [tty_set_ldisc+1091/1200] tty_set_ldisc+0x443/0x4b0
> > May 14 13:14:17 laptop kernel: [uart_wait_until_sent+144/224] uart_wait_until_sent+0x90/0xe0
> > May 14 13:14:17 laptop kernel: [tty_wait_until_sent+243/272] tty_wait_until_sent+0xf3/0x110
> > May 14 13:14:17 laptop kernel: [default_wake_function+0/32] default_wake_function+0x0/0x20
> > May 14 13:14:17 laptop kernel: [sock_destroy_inode+27/32] sock_destroy_inode+0x1b/0x20
> > May 14 13:14:17 laptop kernel: [_end+282132178/1070304612] +0x15a/0x16c [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282130740/1070304612] irtty_open+0x0/0x1f0 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282131236/1070304612] irtty_close+0x0/0x120 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282130132/1070304612] irtty_ioctl+0x0/0x260 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282129076/1070304612] irtty_receive_buf+0x0/0xc0 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282129268/1070304612] irtty_receive_room+0x0/0x30 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282129316/1070304612] irtty_write_wakeup+0x0/0x40 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [_end+282134820/1070304612] +0x0/0xe0 [irtty_sir]
> > May 14 13:14:17 laptop kernel: [sys_ioctl+256/656] sys_ioctl+0x100/0x290
> > May 14 13:14:17 laptop kernel: [syscall_call+7/11] syscall_call+0x7/0xb
>
> Ok, nice trace btw: The last printk from sir_dev was at (1) before we
> called unregister_netdev() - which in turn acquired rtnl_lock (2). Due to
> the disappearing irda0 device (and CONFIG_HOTPLUG=y) the network layer
> decided to call the hotplug stuff (3). For this to fork the usermode
> helper, it scheduled some work for keventd (4). Finally we are blocking
> for completion until keventd finishes wait4 usermodehelper (5).
>
> Unfortunately we are blocking for completion with rtnl still locked and
> keventd apparently having the linkwatch_event() scheduled before the
> usermodehelper -> mutual deadlock between irattach and keventd!
>