Re: [vlan_device_event] BUG: unable to handle kernel paging request at 6b6b6ccf

On Thu, Nov 09, 2017 at 12:09:45PM +0800, Fengguang Wu wrote:

On Thu, Nov 09, 2017 at 11:12:06AM +0800, Fengguang Wu wrote:

quoted

Hi Alex,

quoted

So looking over the trace the panic seems to be happening after a
decnet interface is getting deleted. Is there any chance we could try
compiling the kernel without decnet support to see if that is the
source of these issues? I don't know if anyone on the Intel Wired Lan
team is testing with that enabled so if we can eliminate that as a
possible cause that would be useful.

Sure and thank you for the suggestion!

It looks disabling DECNET still triggers the vlan_device_event BUG.
However when looking at the dmesgs, I find another warning just before
the vlan_device_event BUG. Not sure if it's related one or independent
now-fixed issue.

Please press Enter to activate this console.
[ 1291.938326] Writes:  Total: 2  Max/Min: 0/0   Fail: 0
[ 1297.731690] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 1297.828227] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1300.506245] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1302.467460] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
LKP: HOSTNAME vm-lkp-wsx03-openwrt-i386-10, MAC , kernel 4.13.0 1, serial console /dev/ttyS0
[ 1304.161688] Kernel tests: Boot OK!
[ 1306.558532] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1308.507499] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 1310.526380] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1311.246017] LKP: waiting for network...
[ 1312.543432] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 1313.985807]
[ 1313.991541] =====================================
[ 1314.002398] WARNING: bad unlock balance detected!
[ 1314.013154] 4.13.0 #1 Not tainted
[ 1314.021549] -------------------------------------
[ 1314.032505] procd/1244 is trying to release lock (rcu_preempt_state) at:
[ 1314.047216] [<c10e5840>] rcu_read_unlock_special+0x580/0x5b0
[ 1314.059825] but there are no more locks to release!
[ 1314.070546]
[ 1314.070546] other info that might help us debug this:
[ 1314.085941] 2 locks held by procd/1244:
[ 1314.095139]  #0:  (&sig->cred_guard_mutex){......}, at: [<c12587b8>] prepare_bprm_creds+0x28/0xc0
[ 1314.114616]  #1:  (rcu_read_lock){......}, at: [<c1260140>] path_init+0x490/0x6f0
[ 1314.132155]
[ 1314.132155] stack backtrace:
[ 1314.144402] CPU: 0 PID: 1244 Comm: procd Not tainted 4.13.0 #1
[ 1314.160197] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 1314.179404] Call Trace:
[ 1314.186768]  dump_stack+0x16/0x1c
[ 1314.195387]  print_unlock_imbalance_bug+0xb9/0xd0
[ 1314.205753]  ? rcu_read_unlock_special+0x580/0x5b0
[ 1314.216381]  ? rcu_read_unlock_special+0x580/0x5b0
[ 1314.226982]  lock_release+0x1cc/0x490
[ 1314.235602]  ? rcu_gp_kthread_wake+0x34/0x50
[ 1314.245262]  ? rcu_read_unlock_special+0x580/0x5b0
[ 1314.255724]  rt_mutex_unlock+0x1e/0xb0
[ 1314.264610]  rcu_read_unlock_special+0x580/0x5b0
[ 1314.274814]  __rcu_read_unlock+0xa7/0xb0
[ 1314.283954]  unlazy_walk+0xcf/0x1f0
[ 1314.292409]  trailing_symlink+0x349/0x4e0
[ 1314.301583]  path_openat+0x333/0x1280
[ 1314.310197]  do_filp_open+0x67/0x140
[ 1314.318696]  ? getname_kernel+0x23/0x1e0
[ 1314.327766]  ? cache_alloc_debugcheck_after+0x13a/0x2a0
[ 1314.340076]  ? getname_kernel+0x23/0x1e0
[ 1314.349179]  do_open_execat+0xab/0x2a0
[ 1314.358063]  open_exec+0x57/0x80
[ 1314.366128]  load_script+0x33c/0x3d0
[ 1314.374556]  ? kvm_sched_clock_read+0x9/0x20
[ 1314.384219]  ? sched_clock+0x9/0x10
[ 1314.392611]  ? sched_clock_cpu+0x1a/0x1e0
[ 1314.401875]  ? _raw_read_unlock+0x55/0x90
[ 1314.411080]  search_binary_handler+0xd9/0x160
[ 1314.420799]  do_execveat_common+0x8f6/0xb10
[ 1314.430334]  SyS_execve+0x1f/0x30
[ 1314.438458]  do_int80_syscall_32+0x95/0x1b0
[ 1314.447956]  entry_INT80_32+0x2f/0x2f
[ 1314.456606] EIP: 0xb7e9ab07
[ 1314.464062] EFLAGS: 00000296 CPU: 0
[ 1314.472421] EAX: ffffffda EBX: 0807b584 ECX: bfb0fd70 EDX: 08061250
[ 1314.485257] ESI: 0807b584 EDI: 00000000 EBP: bfb0fd58 ESP: bfb0fd28
[ 1314.498024]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
[ 1314.613681] hotplug-call (1244) used greatest stack depth: 6384 bytes left
[ 1314.957636] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1316.955154] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 1318.197800] 8021q: adding VLAN 0 to HW filter on device eth0
[ 1320.222754] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 1321.409456] BUG: unable to handle kernel paging request at 6b6b6f4f
[ 1321.421942] IP: vlan_device_event+0x7f5/0xa40
[ 1321.431239] *pde = 00000000

Note that this call trace is different from the ones posted in earlier
emails.

[ 1321.431267]
[ 1321.443356] Oops: 0000 [#1] PREEMPT
[ 1321.451390] CPU: 0 PID: 798 Comm: netifd Not tainted 4.13.0 #1
[ 1321.462802] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 1321.479743] task: cf8ae5c0 task.stack: cf114000
[ 1321.489345] EIP: vlan_device_event+0x7f5/0xa40
[ 1321.498701] EFLAGS: 00010206 CPU: 0
[ 1321.506683] EAX: 000000f9 EBX: 00000002 ECX: 00000001 EDX: 6b6b6b6b
[ 1321.518893] ESI: 000014f9 EDI: cf3ec700 EBP: cf115dd8 ESP: cf115da4
[ 1321.531044]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[ 1321.541906] CR0: 80050033 CR2: 6b6b6f4f CR3: 10a02000 CR4: 00000690
[ 1321.554097] Call Trace:
[ 1321.560423]  ? __local_bh_enable_ip+0xf6/0x1a0
[ 1321.569987]  ? _raw_write_unlock_bh+0x2a/0x30
[ 1321.579393]  notifier_call_chain+0x4e/0xa0
[ 1321.588336]  raw_notifier_call_chain+0xc/0x10
[ 1321.597604]  call_netdevice_notifiers_info+0x59/0x90
[ 1321.607779]  __dev_notify_flags+0xea/0x130
[ 1321.616697]  dev_change_flags+0x60/0x70
[ 1321.625255]  dev_ifsioc+0x47b/0x5a0
[ 1321.633354]  ? mutex_lock_nested+0x14/0x20
[ 1321.642292]  dev_ioctl+0x36f/0xb20
[ 1321.650403]  sock_ioctl+0x1cd/0x350
[ 1321.658401]  ? sock_fasync+0xb0/0xb0
[ 1321.666573]  vfs_ioctl+0x33/0x70
[ 1321.674214]  do_vfs_ioctl+0x8d/0xc60
[ 1321.682384]  ? kmem_cache_free+0x186/0x290
[ 1321.691201]  ? putname+0x9f/0xe0
[ 1321.698876]  ? putname+0x9f/0xe0
[ 1321.706491]  ? do_sys_open+0x28d/0x420
[ 1321.714920]  ? __fget_light+0xb7/0xf0
[ 1321.723153]  SyS_ioctl+0x98/0xb0
[ 1321.730961]  do_int80_syscall_32+0x95/0x1b0
[ 1321.740064]  entry_INT80_32+0x2f/0x2f
[ 1321.748335] EIP: 0xb7eb9648
[ 1321.755299] EFLAGS: 00000246 CPU: 0
[ 1321.763209] EAX: ffffffda EBX: 00000005 ECX: 00008914 EDX: bfed0640
[ 1321.775289] ESI: bfed0640 EDI: bfed0660 EBP: bfed0678 ESP: bfed060c
[ 1321.787449]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
[ 1321.798394] Code: 8d f4 5d b3 c4 8d 56 01 89 14 8d f4 5d b3 c4 0f 85 03 02 00 00 89 7d d4 31 f6 8b 7d d8 e9 84 00 00 00 8d 74 26 00 25 ff 01 00 00 <8b> 1c 82 31 d2 85 db 0f 95 c2 8b 04 95 e0 5d b3 c4 83 c0 01 85
[ 1321.833755] EIP: vlan_device_event+0x7f5/0xa40 SS:ESP: 0068:cf115da4
[ 1321.846005] CR2: 000000006b6b6f4f

quoted

[ 1321.431267]

Attached is the full .config and dmesg. Please don't waste time on reproducing
-- it's not quite possible since it seems to only happen in one of our
host machine.

Here are the faddr2line parsed 4.11 call traces:

[  194.685204] wait for background monitors: 1164 oom-killer
[  196.712107] BUG: unable to handle kernel paging request at 6b6b6e73
[  196.725844] IP: vlan_device_event+0x725/0xa30:
vlan_device_event at net/8021q/vlan.h:59
[  196.735827] *pde = 00000000
[  196.735855]
[  196.749561] Oops: 0000 [#1] PREEMPT
[  196.769520] CPU: 0 PID: 797 Comm: netifd Not tainted 4.11.0 #1
[  196.792728] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  196.821634] task: cfcc9000 task.stack: cfc7e000
[  196.831969] EIP: vlan_device_event+0x725/0xa30:
vlan_device_event at net/8021q/vlan.h:59
[  196.842019] EFLAGS: 00010202 CPU: 0
[  196.850925] EAX: 000000c2 EBX: 00000002 ECX: 00000000 EDX: 6b6b6b6b
[  196.863985] ESI: 000008c2 EDI: d08c0f00 EBP: cfc7fdd4 ESP: cfc7fda0
[  196.876463]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[  196.887903] CR0: 80050033 CR2: 6b6b6e73 CR3: 10f0b000 CR4: 00000690
[  196.900970] Call Trace:
[  196.907905]  ? dn_dev_delete+0x18c/0x1b0:
dn_dev_delete at net/decnet/dn_dev.c:1219
[  196.917749]  ? dn_dev_down+0x69/0x80:
dn_dev_down at net/decnet/dn_dev.c:1235
[  196.926701]  notifier_call_chain+0x4e/0xa0:
notifier_call_chain at kernel/notifier.c:95 (discriminator 1)
--
[  197.042320]  do_vfs_ioctl+0x91/0xcc0:
do_vfs_ioctl at fs/ioctl.c:685
[  197.051621]  ? kmem_cache_free+0x124/0x270:
kmem_cache_free at include/linux/rcupdate.h:981
[  197.061767]  ? putname+0x9f/0xe0:
putname at fs/namei.c:258
[  197.080497]  ? putname+0x9f/0xe0:
putname at fs/namei.c:258
[  197.098679]  ? do_sys_open+0x271/0x3e0:
do_sys_open at fs/open.c:1062
[  197.108071]  ? __fget_light+0xb7/0xf0:
__fget_light at fs/file.c:752 (discriminator 2)
[  197.127385]  SyS_ioctl+0x96/0xb0:
SyS_ioctl at fs/ioctl.c:700
[  197.136262]  do_int80_syscall_32+0x95/0x1b0:
do_int80_syscall_32 at arch/x86/entry/common.c:323
[  197.146639]  entry_INT80_32+0x2f/0x2f:
restore_all at arch/x86/entry/entry_32.S:530
[  197.155513] EIP: 0xb7727648
[  197.162874] EFLAGS: 00000246 CPU: 0
[  197.171852] EAX: ffffffda EBX: 00000005 ECX: 00008914 EDX: bff1f5d0
[  197.184875] ESI: bff1f5d0 EDI: bff1f5f0 EBP: bff1f608 ESP: bff1f59c
[  197.198320]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
[  197.210120] Code: 8d fc a1 8d c4 8d 56 01 89 14 8d fc a1 8d c4 0f 85 b4 02 00 00 89 7d d8 31 f6 8b 7d e0 e9 84 00 00 00 8d 74 26 00 25 ff 01 00 00 <8b> 1c 82 31 d2 85 db 0f 95 c2 8b 04 95 e8 a1 8d c4 83 c0 01 85
[  197.249301] EIP: vlan_device_event+0x725/0xa30:
vlan_device_event at net/8021q/vlan.h:59 SS:ESP: 0068:cfc7fda0
[  197.262812] CR2: 000000006b6b6e73
[  199.290882] /bin/busybox wget -q http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/scheduled/vm-lkp-wsx03-openwrt-i386-11/trinity-300s-openwrt-i386-2016-03-16.cgz-a351e9b9fc24e982ec2f0e76379a49826036da12-20171109-13235-ab6tcc-wait_kernel-4.yaml&loadavg=5.12%202.92%201.17%204/93%201360&start_time=1510191311&end_time=1510191314&version=/lkp/lkp/.src-20171109-011142& -O /dev/null
[  199.356767] wget: socket(AF_INET,1,0): Address family not supported by protocol
[  199.474622] ---[ end trace a8f7db573cc5216e ]---
[  199.474631] Kernel panic - not syncing: Fatal exception
[  199.474660] Kernel Offset: disabled
[  199.534708] Rebooting in 3 seconds..

Here is yet another call trace, this time it's "NULL point dereference".

[  748.471023] procd: - init -
Please press Enter to activate this console.
[  753.540379] random: uci: uninitialized urandom read (6 bytes read)
[  754.030470] random: uci: uninitialized urandom read (6 bytes read)
[  754.245351] random: uci: uninitialized urandom read (6 bytes read)
[  757.258323] Writes:  Total: 2  Max/Min: 0/0   Fail: 0
[  760.340612] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[  760.448681] 8021q: adding VLAN 0 to HW filter on device eth0
[  762.403927] 8021q: adding VLAN 0 to HW filter on device eth0
[  764.380369] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
LKP: HOSTNAME vm-lkp-wsx03-openwrt-i386-18, MAC , kernel 4.11.0-08060-g8d5e72d 1, serial console /dev/ttyS0
[  765.018938] Kernel tests: Boot OK!
[  766.118342] BUG: unable to handle kernel NULL pointer dereference at 00000639
[  766.127471] IP: vlan_device_event+0x7f5/0xa40
[  766.133669] *pde = 00000000
[  766.133694]
[  766.141020] Oops: 0000 [#1] PREEMPT
[  766.146171] CPU: 0 PID: 832 Comm: netifd Not tainted 4.11.0-08060-g8d5e72d #1
[  766.154925] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  766.166422] task: d1ac3000 task.stack: d2952000
[  766.172581] EIP: vlan_device_event+0x7f5/0xa40
[  766.178581] EFLAGS: 00010206 CPU: 0
[  766.183537] EAX: 0000018e EBX: 00000002 ECX: 00000000 EDX: 00000001
[  766.191471] ESI: 0000038e EDI: d1f0ed80 EBP: d2953dd8 ESP: d2953da4
[  766.199453]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[  766.206997] CR0: 80050033 CR2: 00000639 CR3: 1199e000 CR4: 00000690
[  766.216394] Call Trace:
[  766.220644]  ? dn_dev_delete+0x138/0x1d0
[  766.226253]  ? dn_dev_down+0x69/0x80
[  766.231402]  notifier_call_chain+0x4e/0xa0
[  766.237335]  raw_notifier_call_chain+0xc/0x10
[  766.243331]  call_netdevice_notifiers_info+0x59/0x90
[  766.250689]  __dev_notify_flags+0xea/0x130
[  766.257746]  dev_change_flags+0x60/0x70
[  766.265073]  dev_ifsioc+0x44b/0x570
[  766.271028]  ? mutex_lock_nested+0x14/0x20
[  766.278162]  dev_ioctl+0x399/0xa70
[  766.284317]  ? slow_virt_to_phys+0x3e/0x110
[  766.291227]  sock_ioctl+0x1cd/0x350
[  766.297515]  ? sock_fasync+0xb0/0xb0
[  766.304019]  vfs_ioctl+0x33/0x70
[  766.309894]  do_vfs_ioctl+0x8d/0xc30
[  766.316242]  ? kmem_cache_free+0x186/0x290
[  766.323504]  ? putname+0x9f/0xe0
[  766.330082]  ? putname+0x9f/0xe0
[  766.335780]  ? do_sys_open+0x28d/0x420
[  766.342393]  ? __fget_light+0xb7/0xf0
[  766.348578]  SyS_ioctl+0x98/0xb0
[  766.353281]  do_int80_syscall_32+0x95/0x1b0
[  766.359117]  entry_INT80_32+0x2f/0x2f
[  766.364295] EIP: 0xb7766648
[  766.368512] EFLAGS: 00000246 CPU: 0
[  766.373497] EAX: ffffffda EBX: 00000005 ECX: 00008914 EDX: bfdae180
[  766.381443] ESI: bfdae180 EDI: bfdae1a0 EBP: bfdae1b8 ESP: bfdae14c
[  766.389775]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
[  766.396967] Code: 8d a4 80 9b c4 8d 56 01 89 14 8d a4 80 9b c4 0f 85 03 02 00 00 89 7d d4 31 f6 8b 7d d8 e9 84 00 00 00 8d 74 26 00 25 ff 01 00 00 <8b> 1c 82 31 d2 85 db 0f 95 c2 8b 04 95 90 80 9b c4 83 c0 01 85
[  766.420978] EIP: vlan_device_event+0x7f5/0xa40 SS:ESP: 0068:d2953da4
[  766.428984] CR2: 0000000000000639
[  768.045479] ---[ end trace 4eaaf76db348fd80 ]---
[  768.105484] Kernel panic - not syncing: Fatal exception
[  768.112938] Kernel Offset: disabled
[  768.118386] Rebooting in 3 seconds..

kernel NULL pointer