netdev - Re: [bonding] 86838ad7bd: BUG:sleeping_function_called_from_invalid_context_at

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Date:   Thu, 21 Feb 2019 21:54:52 +0800
From:   Kefeng Wang <wangkefeng.wang@...wei.com>
To:     kernel test robot <lkp@...el.com>
CC:     <netdev@...r.kernel.org>, Willem de Bruijn <willemb@...gle.com>,
        "David S . Miller" <davem@...emloft.net>,
        Jay Vosburgh <j.vosburgh@...il.com>,
        Veaceslav Falico <vfalico@...il.com>,
        Eric Dumazet <edumazet@...gle.com>, <weiyongjun1@...wei.com>,
        <lkp@...org>
Subject: Re: [bonding] 86838ad7bd:
 BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c

Please ignore this patch, this is unacceptable, thanks.

On 2019/2/21 21:32, kernel test robot wrote:
> FYI, we noticed the following commit (built with gcc-8):
>
> commit: 86838ad7bde0d7741b272670d94d535580173d95 ("[RFC PATCH] bonding: use mutex lock in bond_get_stats()")
> url: https://github.com/0day-ci/linux/commits/Kefeng-Wang/bonding-use-mutex-lock-in-bond_get_stats/20190216-030058
>
>
> in testcase: rcutorture
> with following parameters:
>
> 	runtime: 300s
> 	test: cpuhotplug
> 	torture_type: srcu
>
> test-description: rcutorture is rcutorture kernel module load/unload test.
> test-url: https://www.kernel.org/doc/Documentation/RCU/torture.txt
>
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 1G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +-----------------------------------------------------------------------------+------------+------------+
> |                                                                             | f9bcc9f3ee | 86838ad7bd |
> +-----------------------------------------------------------------------------+------------+------------+
> | boot_successes                                                              | 50         | 24         |
> | boot_failures                                                               | 10         | 41         |
> | invoked_oom-killer:gfp_mask=0x                                              | 1          |            |
> | Mem-Info                                                                    | 1          |            |
> | Out_of_memory:Kill_process                                                  | 1          |            |
> | BUG:kernel_in_stage                                                         | 6          | 8          |
> | BUG:kernel_reboot-without-warning_in_early-boot_stage                       | 2          |            |
> | BUG:kernel_hang_in_test_stage                                               | 1          | 1          |
> | BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c | 0          | 32         |
> +-----------------------------------------------------------------------------+------------+------------+
>
>
>
> [   17.153431] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:908
> [   17.157556] in_atomic(): 0, irqs_disabled(): 0, pid: 599, name: dropbearkey
> [   17.159141] 2 locks held by dropbearkey/599:
> [   17.159779]  #0: (____ptrval____) (&p->lock){+.+.}, at: seq_read+0x41/0x3f0
> [   17.160802]  #1: (____ptrval____) (rcu_read_lock){....}, at: dev_seq_start+0x5/0x110
> [   17.161928] Preemption disabled at:
> [   17.161935] [<ffffffff818eafe0>] __mutex_lock+0x50/0x980
> [   17.163150] CPU: 1 PID: 599 Comm: dropbearkey Not tainted 5.0.0-rc5-00320-g86838ad #1
> [   17.164213] Call Trace:
> [   17.164571]  dump_stack+0x67/0x90
> [   17.165051]  ___might_sleep.cold.14+0xf0/0x106
> [   17.165675]  ? bond_get_stats+0x3b/0x260
> [   17.166232]  __mutex_lock+0x46/0x980
> [   17.166743]  ? kvm_clock_read+0x14/0x30
> [   17.167288]  ? validate_chain+0xb5/0xad0
> [   17.167936]  ? number+0x2fc/0x340
> [   17.168416]  ? bond_get_stats+0x3b/0x260
> [   17.168966]  bond_get_stats+0x3b/0x260
> [   17.169500]  ? seq_vprintf+0x30/0x50
> [   17.170007]  ? seq_printf+0x43/0x50
> [   17.170498]  ? validate_chain+0xb5/0xad0
> [   17.171136]  ? dev_seq_printf_stats+0x9a/0xb0
> [   17.171736]  dev_get_stats+0x55/0xb0
> [   17.172221]  dev_seq_printf_stats+0x1f/0xb0
> [   17.172817]  dev_seq_show+0x10/0x30
> [   17.173289]  seq_read+0x2cd/0x3f0
> [   17.173777]  proc_reg_read+0x36/0x60
> [   17.174288]  __vfs_read+0x23/0x160
> [   17.174779]  ? _copy_to_user+0x5e/0x70
> [   17.175312]  ? entry_INT80_compat+0x7c/0x90
> [   17.175903]  vfs_read+0xa6/0x140
> [   17.176366]  ksys_read+0x42/0xa0
> [   17.176834]  do_int80_syscall_32+0x4f/0x150
> [   17.177418]  entry_INT80_compat+0x84/0x90
> LKP: HOSTNAME vm-snb-openwrt-ia32-524, MAC , kernel 5.0.0-rc5-00320-g86838ad 1, serial console /dev/ttyS0
> [   18.404764] Kernel tests: Boot OK!
> [   18.404764] LKP: waiting for network...
> [   19.256982] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
> [   19.271235] _warn_unseeded_randomness: 1329 callbacks suppressed
> [   19.271244] random: get_random_u64 called from arch_pick_mmap_layout+0x65/0x170 with crng_init=0
> [   19.273507] random: get_random_u64 called from arch_pick_mmap_layout+0x10e/0x170 with crng_init=0
> [   19.274790] random: get_random_u64 called from load_elf_binary+0x87d/0x1120 with crng_init=0
> [   20.407748] /lkp/lkp/src/bin/run-lkp
> [   20.407748] RESULT_ROOT=/result/rcutorture/300s-cpuhotplug-srcu/vm-snb-openwrt-ia32/openwrt-i386-2016-03-16.cgz/x86_64-randconfig-s4-02200400/gcc-8/86838ad7bde0d7741b272670d94d535580173d95/3
> [   20.407748] job=/lkp/jobs/scheduled/vm-snb-openwrt-ia32-524/rcutorture-300s-cpuhotplug-srcu-openwrt-i386-2016-03-16.cgz-20190220-89648-gjivxf-3.yaml
> [   20.407748] run-job /lkp/jobs/scheduled/vm-snb-openwrt-ia32-524/rcutorture-300s-cpuhotplug-srcu-openwrt-i386-2016-03-16.cgz-20190220-89648-gjivxf-3.yaml
> [   20.407748] /bin/busybox wget -q http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/scheduled/vm-snb-openwrt-ia32-524/rcutorture-300s-cpuhotplug-srcu-openwrt-i386-2016-03-16.cgz-20190220-89648-gjivxf-3.yaml&job_state=running -O /dev/null
> [   20.407748] target ucode: 
> [   20.416008] wget: can't connect to remote host (192.168.1.1): Network is unreachable
> [   20.416008] /lkp/lkp/src/monitors/heartbeat: line 9: vmstat: not found
> [   20.416008] /lkp/lkp/src/monitors/heartbeat: exec: line 23: vmstat: not found
> [   20.678602] _warn_unseeded_randomness: 431 callbacks suppressed
> [   20.678610] random: get_random_u64 called from arch_pick_mmap_layout+0x65/0x170 with crng_init=0
> [   20.681816] random: get_random_u64 called from arch_pick_mmap_layout+0x10e/0x170 with crng_init=0
> [   20.683622] random: get_random_u64 called from load_elf_binary+0x87d/0x1120 with crng_init=0
> [   21.418765] BusyBox v1.23.2 (2016-01-02 14:31:17 CET) multi-call binary.
> [   21.418765] 
> [   21.418765] Usage: time [-v] PROG ARGS
> [   21.418765] 
> [   21.418765] Run PROG, display resource usage when it exits
> [   21.418765] 
> [   21.418765] 	-v	Verbose
> [   21.418765] 
> [   21.418765] failed to load rcutorture module, try to enable CONFIG_RCU_TORTURE_TEST and build rcutorture.ko
> [   21.418765] wget: can't connect to remote host (192.168.1.1): Network is unreachable
> [   21.423344] 2019-02-20 06:29:25 modprobe rcutorture onoff_interval=3 onoff_holdoff=30 torture_type=srcu
> [   21.423344] /bin/busybox wget -q http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/scheduled/vm-snb-openwrt-ia32-524/rcutorture-300s-cpuhotplug-srcu-openwrt-i386-2016-03-16.cgz-20190220-89648-gjivxf-3.yaml&job_state=post_run -O /dev/null
> [   21.818029] _warn_unseeded_randomness: 210 callbacks suppressed
> [   21.818037] random: get_random_u64 called from arch_pick_mmap_layout+0x65/0x170 with crng_init=0
> [   21.821714] random: get_random_u64 called from arch_pick_mmap_layout+0x10e/0x170 with crng_init=0
> [   21.823918] random: get_random_u64 called from load_elf_binary+0x87d/0x1120 with crng_init=0
> [   22.190264] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
> [   22.444763] kill 804 cat /proc/kmsg 
> [   22.444763] wait for background processes: 812 810 oom-killer meminfo
>
> Elapsed time: 20
>
> qemu-img create -f qcow2 disk-vm-snb-openwrt-ia32-524-0 256G
> qemu-img create -f qcow2 disk-vm-snb-openwrt-ia32-524-1 256G
>
> kvm=(
> 	qemu-system-x86_64
> 	-enable-kvm
> 	-cpu SandyBridge
> 	-kernel $kernel
> 	-initrd initrd-vm-snb-openwrt-ia32-524
> 	-m 1024
> 	-smp 2
> 	-device e1000,netdev=net0
> 	-netdev user,id=net0
> 	-boot order=nc
> 	-no-reboot
> 	-watchdog i6300esb
> 	-watchdog-action debug
> 	-rtc base=localtime
> 	-drive file=disk-vm-snb-openwrt-ia32-524-0,media=disk,if=virtio
> 	-drive file=disk-vm-snb-openwrt-ia32-524-1,media=disk,if=virtio
> 	-serial stdio
> 	-display none
> 	-monitor null
> )
>
>
> To reproduce:
>
>         git clone https://github.com/intel/lkp-tests.git
>         cd lkp-tests
>         bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
>
>
>
> Thanks,
> Rong Chen