Bug 54601

Summary: PPP regression on 3.2.39 stop work need restart server on version 3.0.X not found this problem.
Product: Networking Reporter: Martin Zaharinov (micron10)
Component: IPV4Assignee: Stephen Hemminger (stephen)
Status: NEW ---    
Severity: high CC: szg00000
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.2.39 Subsystem:
Regression: Yes Bisected commit-id:

Description Martin Zaharinov 2013-03-01 09:23:30 UTC 
Hi
watch a problem with PPP after upgrade to version 3.2.39 ppp service stop work 2 hours after start with this crash :

[79619.180026] unregister_netdevice: waiting for ppp618 to become free. Usage count = 562
[79629.320074] unregister_netdevice: waiting for ppp618 to become free. Usage count = 529
[79639.460103] unregister_netdevice: waiting for ppp618 to become free. Usage count = 506
[79649.600071] unregister_netdevice: waiting for ppp618 to become free. Usage count = 486
[79659.740092] unregister_netdevice: waiting for ppp618 to become free. Usage count = 465
[79669.880014] unregister_netdevice: waiting for ppp618 to become free. Usage count = 444
[79680.020065] unregister_netdevice: waiting for ppp618 to become free. Usage count = 422
[79690.160111] unregister_netdevice: waiting for ppp618 to become free. Usage count = 402
[79700.300077] unregister_netdevice: waiting for ppp618 to become free. Usage count = 379
[79710.440018] unregister_netdevice: waiting for ppp618 to become free. Usage count = 355
[79720.580031] unregister_netdevice: waiting for ppp618 to become free. Usage count = 334
[79730.720082] unregister_netdevice: waiting for ppp618 to become free. Usage count = 313
[79740.860050] unregister_netdevice: waiting for ppp618 to become free. Usage count = 291
[79751.000030] unregister_netdevice: waiting for ppp618 to become free. Usage count = 268
[79761.140024] unregister_netdevice: waiting for ppp618 to become free. Usage count = 247
[79771.280201] unregister_netdevice: waiting for ppp618 to become free. Usage count = 223
[79781.420028] unregister_netdevice: waiting for ppp618 to become free. Usage count = 202
[79791.560098] unregister_netdevice: waiting for ppp618 to become free. Usage count = 180
[79801.700042] unregister_netdevice: waiting for ppp618 to become free. Usage count = 159
[79804.410096] INFO: task pppd:31852 blocked for more than 120 seconds.
[79804.410098] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410101] pppd            D ffff88015fd0cd00     0 31852  31800 0x00000004
[79804.410111]  ffff88010b69d600 0000000000000086 ffff88010b69d600 ffffffff8166e800
[79804.410114]  ffff880159120ac0 0000000000004000 ffff88010ba75fd8 ffff88010ba75fd8
[79804.410117]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410119] Call Trace:
[79804.410128]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410150]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410155]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410167]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410170]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410172]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410176]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410178]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410181]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410190]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410193]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410195]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410198] INFO: task pppd:31869 blocked for more than 120 seconds.
[79804.410199] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410201] pppd            D ffff88015fc0cd00     0 31869  31800 0x00000004
[79804.410203]  ffff88014b1deb80 0000000000000082 ffff88014b1deb80 ffffffff8166e800
[79804.410206]  ffff8801591250a0 0000000000004000 ffff88015829ffd8 ffff88015829ffd8
[79804.410209]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410212] Call Trace:
[79804.410214]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410216]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410218]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410221]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410223]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410226]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410228]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410249]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410251]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410253]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410256]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410258]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410260] INFO: task pppd:31889 blocked for more than 120 seconds.
[79804.410261] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410262] pppd            D ffff88015fc0cd00     0 31889  31800 0x00000000
[79804.410275]  ffff880159868ac0 0000000000000086 ffff880159868ac0 ffffffff8166e800
[79804.410277]  ffff8801599ab060 0000000000004000 ffff88014ba51fd8 ffff88014ba51fd8
[79804.410280]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410290] Call Trace:
[79804.410292]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410295]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410297]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410300]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410302]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410305]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410318]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410321]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410322]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410325]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410327]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410330]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410334] INFO: task pppd:31890 blocked for more than 120 seconds.
[79804.410335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410337] pppd            D ffff88015fd0cd00     0 31890  31800 0x00000000
[79804.410339]  ffff88015986cb40 0000000000000082 ffff88015986cb40 ffffffff8166e800
[79804.410342]  ffff8801599adb60 0000000000004000 ffff8801079d7fd8 ffff8801079d7fd8
[79804.410345]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410347] Call Trace:
[79804.410349]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410352]  [<ffffffff810b94a7>] ? link_path_walk+0x67/0x850
[79804.410354]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410368]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410390]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410392]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410394]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410397]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410399]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410401]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410403]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410407]  [<ffffffff81009f94>] ? fpu_finit+0x14/0x30
[79804.410409]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410411]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410413] INFO: task pppd:31897 blocked for more than 120 seconds.
[79804.410414] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410419] pppd            D ffff88015fd0cd00     0 31897  31800 0x00000004
[79804.410421]  ffff88014b1deb80 0000000000000082 ffff88014b1deb80 ffffffff8166e800
[79804.410424]  ffff88015901cb40 0000000000004000 ffff8801106dffd8 ffff8801106dffd8
[79804.410427]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410430] Call Trace:
[79804.410432]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410435]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410437]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410440]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410442]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410444]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410447]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410453]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410455]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410457]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410459]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410461]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410474] INFO: task pppd:31929 blocked for more than 120 seconds.
[79804.410476] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410477] pppd            D ffff88015fc0cd00     0 31929  31800 0x00000004
[79804.410480]  ffff88014b1deb80 0000000000000086 ffff88014b1deb80 ffffffff8166e800
[79804.410483]  ffff88014b192b00 0000000000004000 ffff88010d6fdfd8 ffff88010d6fdfd8
[79804.410486]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410488] Call Trace:
[79804.410490]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410493]  [<ffffffff810b94a7>] ? link_path_walk+0x67/0x850
[79804.410495]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410498]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410500]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410502]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410505]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410507]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410509]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410511]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410513]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410515]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410517] INFO: task pppd:31964 blocked for more than 120 seconds.
[79804.410519] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410520] pppd            D 0000000000000000     0 31964  31800 0x00000004
[79804.410522]  ffffffff8160b020 0000000000000086 ffffffff8107e2a9 ffffffff8166e800
[79804.410525]  ffff8801591260c0 0000000000004000 ffff88010b605fd8 ffff88010b605fd8
[79804.410528]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410530] Call Trace:
[79804.410533]  [<ffffffff8107e2a9>] ? __alloc_pages_nodemask+0x109/0x7c0
[79804.410540]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410542]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410544]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410547]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410549]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410551]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410554]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410556]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410558]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410560]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410562]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410564]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410566] INFO: task pppd:31993 blocked for more than 120 seconds.
[79804.410568] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410579] pppd            D 0000000000000000     0 31993  31800 0x00000004
[79804.410582]  ffffffff8160b020 0000000000000082 ffffffff8107e2a9 ffffffff8166e800
[79804.410585]  ffff8801590eb5c0 0000000000004000 ffff880107981fd8 ffff880107981fd8
[79804.410588]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410590] Call Trace:
[79804.410593]  [<ffffffff8107e2a9>] ? __alloc_pages_nodemask+0x109/0x7c0
[79804.410595]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410597]  [<ffffffff810b94a7>] ? link_path_walk+0x67/0x850
[79804.410599]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410601]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410604]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410606]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410608]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410611]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410613]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410615]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410617]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410619]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410624]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410626] INFO: task pppd:31994 blocked for more than 120 seconds.
[79804.410627] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410628] pppd            D ffff88015fd0cd00     0 31994  31800 0x00000000
[79804.410631]  ffff88015986cb40 0000000000000082 ffff88015986cb40 ffffffff8166e800
[79804.410634]  ffff8801590eab00 0000000000004000 ffff880156d41fd8 ffff880156d41fd8
[79804.410637]  0000000000000246 ffffffff8166e800 000280da8107f173 0000000000000000
[79804.410639] Call Trace:
[79804.410641]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410643]  [<ffffffff8107a0de>] ? find_get_pages+0x2e/0x120
[79804.410648]  [<ffffffff811802b3>] ? cpumask_any_but+0x23/0x40
[79804.410651]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410653]  [<ffffffff810218c5>] ? ptep_set_access_flags+0x25/0x30
[79804.410655]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410658]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[79804.410661]  [<ffffffff8101e2b8>] ? do_page_fault+0x198/0x460
[79804.410663]  [<ffffffff810c28be>] ? dput+0x1e/0x190
[79804.410678]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410680]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410683]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79804.410684] INFO: task pppd:31999 blocked for more than 120 seconds.
[79804.410686] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[79804.410687] pppd            D 0000000000000001     0 31999  31800 0x00000000
[79804.410690]  ffff88015986bb20 0000000000000082 0000000000002000 0000000000000000
[79804.410692]  ffff8801590ec080 0000000000004000 ffff88010b9e9fd8 ffff88010b9e9fd8
[79804.410695]  ffff88008c190500 ffff88010b9e9e88 00000010000000bb ffff88008c190500
[79804.410698] Call Trace:
[79804.410701]  [<ffffffff81375e48>] ? sock_recvmsg+0xf8/0x140
[79804.410703]  [<ffffffff81375fd5>] ? sock_sendmsg+0xe5/0x120
[79804.410708]  [<ffffffff81082108>] ? release_pages+0x1d8/0x200
[79804.410711]  [<ffffffff81090cbe>] ? unmap_vmas+0x3fe/0x750
[79804.410714]  [<ffffffff814831b8>] ? __mutex_lock_slowpath+0xc8/0x140
[79804.410717]  [<ffffffff81482d3a>] ? mutex_lock+0x1a/0x40
[79804.410719]  [<ffffffffa00083bb>] ? ppp_ioctl+0x8b/0xf20 [ppp_generic]
[79804.410722]  [<ffffffff81484139>] ? _raw_spin_lock_bh+0x9/0x30
[79804.410725]  [<ffffffff81045fb4>] ? bit_waitqueue+0x14/0xa0
[79804.410728]  [<ffffffff810e3d30>] ? fsnotify_clear_marks_by_inode+0x20/0xd0
[79804.410730]  [<ffffffff810be1bf>] ? do_vfs_ioctl+0x8f/0x530
[79804.410732]  [<ffffffff810c296a>] ? dput+0xca/0x190
[79804.410735]  [<ffffffff810af57e>] ? fput+0x15e/0x220
[79804.410737]  [<ffffffff810be6a9>] ? sys_ioctl+0x49/0x80
[79804.410739]  [<ffffffff814848bb>] ? system_call_fastpath+0x16/0x1b
[79811.840094] unregister_netdevice: waiting for ppp618 to become free. Usage count = 138
[79821.980036] unregister_netdevice: waiting for ppp618 to become free. Usage count = 117
[79832.120019] unregister_netdevice: waiting for ppp618 to become free. Usage count = 96
[79842.260020] unregister_netdevice: waiting for ppp618 to become free. Usage count = 74
[79852.400168] unregister_netdevice: waiting for ppp618 to become free. Usage count = 52
[79862.540040] unregister_netdevice: waiting for ppp618 to become free. Usage count = 30
[79872.680037] unregister_netdevice: waiting for ppp618 to become free. Usage count = 9

After this crash from dmesg i kill alll pppd services but users can not hang need to restart server to back in work state.

After rebuild and back to old kernel 3.2.21 it has no problema
I run 1000 pppoe connection to one PPP server.


Best regards,
m.
Comment 1 Martin Zaharinov 2013-03-01 12:25:47 UTC 
This is from kernel 3.2.21 dmesg: 

[39606.720089] unregister_netdevice: waiting for ppp539 to become free. Usage count = 259
[39616.860035] unregister_netdevice: waiting for ppp539 to become free. Usage count = 239
[39627.000047] unregister_netdevice: waiting for ppp539 to become free. Usage count = 218
[39637.150018] unregister_netdevice: waiting for ppp539 to become free. Usage count = 207
[39647.290016] unregister_netdevice: waiting for ppp539 to become free. Usage count = 196
[39657.430037] unregister_netdevice: waiting for ppp539 to become free. Usage count = 171
[39667.570022] unregister_netdevice: waiting for ppp539 to become free. Usage count = 169
[39677.710026] unregister_netdevice: waiting for ppp539 to become free. Usage count = 167
[39687.850030] unregister_netdevice: waiting for ppp539 to become free. Usage count = 149
[39697.990028] unregister_netdevice: waiting for ppp539 to become free. Usage count = 126
[39708.130024] unregister_netdevice: waiting for ppp539 to become free. Usage count = 103
[39718.270028] unregister_netdevice: waiting for ppp539 to become free. Usage count = 88
[39725.510107] INFO: task pppd:27260 blocked for more than 120 seconds.
[39725.510110] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510112] pppd            D 0000000000000000     0 27260   1452 0x00000004
[39725.510115]  ffffffff8159f020 0000000000000082 0000001400000000 0000000000000000
[39725.510119]  ffff8801598ebf00 0000000000004000 ffff8800b6cb1fd8 ffff8800b6cb1fd8
[39725.510122]  ffff8800b6cb1ec0 00007fff9bc324a8 ffffffff813d0b18 ffff8800b6cb1cf4
[39725.510125] Call Trace:
[39725.510132]  [<ffffffff813d0b18>] ? inet_recvmsg+0x48/0x80
[39725.510143]  [<ffffffff81361761>] ? sock_recvmsg+0xc1/0xf0
[39725.510147]  [<ffffffff8107bcb8>] ? release_pages+0x1d8/0x200
[39725.510158]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510161]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510165]  [<ffffffffa00083bb>] ? ppp_ioctl+0x8b/0xf20 [ppp_generic]
[39725.510167]  [<ffffffff81429bf9>] ? _raw_spin_lock_bh+0x9/0x30
[39725.510178]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510180]  [<ffffffff810bc1fa>] ? dput+0xca/0x190
[39725.510189]  [<ffffffff810a8e9e>] ? fput+0x15e/0x220
[39725.510196]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510199]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510202] INFO: task pppd:31171 blocked for more than 120 seconds.
[39725.510203] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510205] pppd            D ffff88015fd8cd00     0 31171   1455 0x00000000
[39725.510208]  ffff88015928d400 0000000000000082 ffff88015928d400 00000000000280da
[39725.510211]  ffff88010ec0b480 0000000000004000 ffff8800b23fffd8 ffff8800b23fffd8
[39725.510213]  0000000000000246 ffffffff815f3480 ffffffff81078d23 000280da00000000
[39725.510216] Call Trace:
[39725.510218]  [<ffffffff81078d23>] ? __pagevec_free+0x23/0x30
[39725.510220]  [<ffffffff8107bcb8>] ? release_pages+0x1d8/0x200
[39725.510222]  [<ffffffff81073b6e>] ? find_get_pages+0x2e/0x120
[39725.510226]  [<ffffffff81178083>] ? cpumask_any_but+0x23/0x40
[39725.510229]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510231]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510234]  [<ffffffffa0008624>] ? ppp_ioctl+0x2f4/0xf20 [ppp_generic]
[39725.510241]  [<ffffffff8101e278>] ? do_page_fault+0x198/0x460
[39725.510243]  [<ffffffff810bc14e>] ? dput+0x1e/0x190
[39725.510245]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510247]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510249]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510251] INFO: task pppd:31263 blocked for more than 120 seconds.
[39725.510252] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510254] pppd            D 0000000000000000     0 31263   1455 0x00000004
[39725.510256]  ffffffff8159f020 0000000000000082 ffff88015588c880 0000000000000000
[39725.510259]  ffff880117fc5940 0000000000004000 ffff8800b4853fd8 ffff8800b4853fd8
[39725.510262]  0000000000000000 ffff880154886000 0000000000000048 ffff88015588c880
[39725.510264] Call Trace:
[39725.510266]  [<ffffffff813618aa>] ? sock_sendmsg+0xba/0xf0
[39725.510270]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510272]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510275]  [<ffffffffa00083bb>] ? ppp_ioctl+0x8b/0xf20 [ppp_generic]
[39725.510278]  [<ffffffff81361952>] ? sockfd_lookup_light+0x22/0x80
[39725.510279]  [<ffffffff813637c4>] ? sys_sendto+0x114/0x180
[39725.510282]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510284]  [<ffffffff810a7690>] ? vfs_write+0x120/0x170
[39725.510287]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510289]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510291] INFO: task pppd:31287 blocked for more than 120 seconds.
[39725.510292] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510294] pppd            D 0000000000000001     0 31287   1452 0x00000004
[39725.510296]  ffff88015986b9c0 0000000000000082 ffff88015993e001 ffff8800b456de68
[39725.510299]  ffff88012dbe63c0 0000000000004000 ffff8800b456dfd8 ffff8800b456dfd8
[39725.510302]  ffffffff81179b22 ffffffffa0009fa0 0000000081034e99 0000041800000407
[39725.510304] Call Trace:
[39725.510306]  [<ffffffff81179b22>] ? kobject_get+0x12/0x20
[39725.510310]  [<ffffffff810869e6>] ? pcpu_next_pop+0x46/0x70
[39725.510313]  [<ffffffff8137bd8b>] ? __hw_addr_add_ex+0x9b/0x140
[39725.510316]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510318]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510321]  [<ffffffffa0008e31>] ? ppp_ioctl+0xb01/0xf20 [ppp_generic]
[39725.510323]  [<ffffffff810b5c44>] ? do_filp_open+0x44/0xb0
[39725.510325]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510327]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510330]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510331] INFO: task pppd:31302 blocked for more than 120 seconds.
[39725.510333] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510334] pppd            D 0000000000000003     0 31302   1455 0x00000004
[39725.510336]  ffff8801598e9f80 0000000000000086 ffff880155ff1001 ffff8800af451e68
[39725.510339]  ffff88012dbe39c0 0000000000004000 ffff8800af451fd8 ffff8800af451fd8
[39725.510347]  ffffffff81179b22 ffffffffa0009fa0 ffffffff81034e99 0000000000000000
[39725.510349] Call Trace:
[39725.510351]  [<ffffffff81179b22>] ? kobject_get+0x12/0x20
[39725.510354]  [<ffffffff81034e99>] ? ns_capable+0x29/0x50
[39725.510357]  [<ffffffffa00053ae>] ? ppp_open+0xe/0x20 [ppp_generic]
[39725.510359]  [<ffffffff810ab417>] ? chrdev_open+0xa7/0x1b0
[39725.510361]  [<ffffffff810b1f3d>] ? do_lookup+0x4d/0x3a0
[39725.510363]  [<ffffffff810a5b9b>] ? __dentry_open.isra.16+0x20b/0x2e0
[39725.510376]  [<ffffffff810bc14e>] ? dput+0x1e/0x190
[39725.510379]  [<ffffffff810c2d2d>] ? mntput_no_expire+0x1d/0x110
[39725.510383]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510385]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510388]  [<ffffffffa0008a00>] ? ppp_ioctl+0x6d0/0xf20 [ppp_generic]
[39725.510390]  [<ffffffff810b5c44>] ? do_filp_open+0x44/0xb0
[39725.510392]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510394]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510397]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510399] INFO: task pppd:31311 blocked for more than 120 seconds.
[39725.510400] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510401] pppd            D 0000000000000002     0 31311   1455 0x00000004
[39725.510404]  ffff88015986cec0 0000000000000086 ffff8800bbbdd001 ffff8800aa085e68
[39725.510407]  ffff880157cc0fc0 0000000000004000 ffff8800aa085fd8 ffff8800aa085fd8
[39725.510409]  ffffffff81179b22 ffffffffa0009fa0 ffffffff81034e99 0000000000000000
[39725.510412] Call Trace:
[39725.510413]  [<ffffffff81179b22>] ? kobject_get+0x12/0x20
[39725.510416]  [<ffffffff81034e99>] ? ns_capable+0x29/0x50
[39725.510418]  [<ffffffffa00053ae>] ? ppp_open+0xe/0x20 [ppp_generic]
[39725.510421]  [<ffffffff810ab417>] ? chrdev_open+0xa7/0x1b0
[39725.510422]  [<ffffffff810b1f3d>] ? do_lookup+0x4d/0x3a0
[39725.510424]  [<ffffffff810a5b9b>] ? __dentry_open.isra.16+0x20b/0x2e0
[39725.510426]  [<ffffffff810bc14e>] ? dput+0x1e/0x190
[39725.510428]  [<ffffffff810c2d2d>] ? mntput_no_expire+0x1d/0x110
[39725.510432]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510434]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510437]  [<ffffffffa0008a00>] ? ppp_ioctl+0x6d0/0xf20 [ppp_generic]
[39725.510439]  [<ffffffff810b5c44>] ? do_filp_open+0x44/0xb0
[39725.510441]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510443]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510445]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510453] INFO: task pppd:31323 blocked for more than 120 seconds.
[39725.510454] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510455] pppd            D 0000000000000002     0 31323   1455 0x00000004
[39725.510458]  ffff88015986cec0 0000000000000086 ffff8800bbbdd001 ffff8800b20b3e68
[39725.510461]  ffff880157cc24c0 0000000000004000 ffff8800b20b3fd8 ffff8800b20b3fd8
[39725.510463]  ffffffff81179b22 ffffffffa0009fa0 ffffffff81034e99 0000000000000000
[39725.510466] Call Trace:
[39725.510468]  [<ffffffff81179b22>] ? kobject_get+0x12/0x20
[39725.510470]  [<ffffffff81034e99>] ? ns_capable+0x29/0x50
[39725.510473]  [<ffffffffa00053ae>] ? ppp_open+0xe/0x20 [ppp_generic]
[39725.510475]  [<ffffffff810ab417>] ? chrdev_open+0xa7/0x1b0
[39725.510477]  [<ffffffff810b1f3d>] ? do_lookup+0x4d/0x3a0
[39725.510479]  [<ffffffff810a5b9b>] ? __dentry_open.isra.16+0x20b/0x2e0
[39725.510481]  [<ffffffff810bc14e>] ? dput+0x1e/0x190
[39725.510483]  [<ffffffff810c2d2d>] ? mntput_no_expire+0x1d/0x110
[39725.510486]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510488]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510491]  [<ffffffffa0008a00>] ? ppp_ioctl+0x6d0/0xf20 [ppp_generic]
[39725.510493]  [<ffffffff810b5c44>] ? do_filp_open+0x44/0xb0
[39725.510495]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510497]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510500]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39725.510502] INFO: task pppd:31334 blocked for more than 120 seconds.
[39725.510503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[39725.510504] pppd            D 0000000000000002     0 31334   1455 0x00000004
[39725.510507]  ffff88015986cec0 0000000000000082 ffff8800bbbdd001 ffff8800af425e68
[39725.510509]  ffff880157cc39c0 0000000000004000 ffff8800af425fd8 ffff8800af425fd8
[39725.510512]  ffffffff81179b22 ffffffffa0009fa0 ffffffff81034e99 0000000000000000
[39725.510515] Call Trace:
[39725.510516]  [<ffffffff81179b22>] ? kobject_get+0x12/0x20
[39725.510518]  [<ffffffff81034e99>] ? ns_capable+0x29/0x50
[39725.510521]  [<ffffffffa00053ae>] ? ppp_open+0xe/0x20 [ppp_generic]
[39725.510523]  [<ffffffff810ab417>] ? chrdev_open+0xa7/0x1b0
[39725.510525]  [<ffffffff810b1f3d>] ? do_lookup+0x4d/0x3a0
[39725.510527]  [<ffffffff810a5b9b>] ? __dentry_open.isra.16+0x20b/0x2e0
[39725.510529]  [<ffffffff810bc14e>] ? dput+0x1e/0x190
[39725.510531]  [<ffffffff810c2d2d>] ? mntput_no_expire+0x1d/0x110
[39725.510534]  [<ffffffff81428c78>] ? __mutex_lock_slowpath+0xc8/0x140
[39725.510537]  [<ffffffff814287fa>] ? mutex_lock+0x1a/0x40
[39725.510540]  [<ffffffffa0008a00>] ? ppp_ioctl+0x6d0/0xf20 [ppp_generic]
[39725.510559]  [<ffffffff810b5c44>] ? do_filp_open+0x44/0xb0
[39725.510562]  [<ffffffff810b7a5f>] ? do_vfs_ioctl+0x8f/0x530
[39725.510564]  [<ffffffff810b7f49>] ? sys_ioctl+0x49/0x80
[39725.510566]  [<ffffffff8142a37b>] ? system_call_fastpath+0x16/0x1b
[39728.410021] unregister_netdevice: waiting for ppp539 to become free. Usage count = 70
[39738.550022] unregister_netdevice: waiting for ppp539 to become free. Usage count = 66
[39748.690059] unregister_netdevice: waiting for ppp539 to become free. Usage count = 37
[39758.830023] unregister_netdevice: waiting for ppp539 to become free. Usage count = 17
[39768.970014] unregister_netdevice: waiting for ppp539 to become free. Usage count = 14
[39779.110044] unregister_netdevice: waiting for ppp539 to become free. Usage count = 13
[39789.250016] unregister_netdevice: waiting for ppp539 to become free. Usage count = 12
[39799.390018] unregister_netdevice: waiting for ppp539 to become free. Usage count = 12
[39809.530013] unregister_netdevice: waiting for ppp539 to become free. Usage count = 3
Comment 2 Martin Zaharinov 2013-03-05 12:35:16 UTC 
One test from my:
After connect 1000 pppoe users to server, 10 user with home soho routers and wrong password try to reconnect 10 times for 1 minute. After random time server crash with the above errors!
Next test reboot system and fix password and user from this 10 users the problem is going.
Maybe the problem is a end of open socket and kernel is going ot Hung task with this crash.

Best regards,
m.