2019-02-21 13:38:40

by kernel test robot

[permalink] [raw]
Subject: [bpf] 568f196756: BUG:assuming_atomic_context_at_kernel/seccomp.c


FYI, we noticed the following commit (built with gcc-7):

commit: 568f196756ad9fe2b49c46bbf6a9de1b190438b4 ("bpf: check that BPF programs run with preemption disabled")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master

in testcase: boot

on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+---------------------------------------------------------+------------+------------+
| | a5d9265e01 | 568f196756 |
+---------------------------------------------------------+------------+------------+
| boot_successes | 12 | 1 |
| boot_failures | 6 | 13 |
| BUG:kernel_in_stage | 2 | 1 |
| invoked_oom-killer:gfp_mask=0x | 4 | 2 |
| Mem-Info | 4 | 2 |
| Out_of_memory_and_no_killable_processes | 4 | 2 |
| Kernel_panic-not_syncing:System_is_deadlocked_on_memory | 4 | 2 |
| BUG:assuming_atomic_context_at_kernel/seccomp.c | 0 | 9 |
| BUG:kernel_hang_in_test_stage | 0 | 1 |
+---------------------------------------------------------+------------+------------+



[ 11.245441] BUG: assuming atomic context at kernel/seccomp.c:271
[ 11.247417] in_atomic(): 0, irqs_disabled(): 0, pid: 212, name: (journald)
[ 11.248632] CPU: 0 PID: 212 Comm: (journald) Not tainted 5.0.0-rc6-01569-g568f196 #1
[ 11.249957] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 11.251327] Call Trace:
[ 11.252457] dump_stack+0x5c/0x7b
[ 11.253095] __cant_sleep+0xb2/0xc0
[ 11.253717] __seccomp_filter+0x71/0x650
[ 11.254439] ? __mmdrop+0x58/0x100
[ 11.255076] ? finish_task_switch+0x229/0x2b0
[ 11.255831] syscall_trace_enter+0x145/0x2f0
[ 11.269622] do_syscall_64+0x11a/0x180
[ 11.269626] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 11.269629] RIP: 0033:0x7fad2ad08229
[ 11.269631] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 3f 4c 2b 00 f7 d8 64 89 01 48
[ 11.269632] RSP: 002b:00007ffe7ed36cf8 EFLAGS: 00000246 ORIG_RAX: 000000000000013d
[ 11.269634] RAX: ffffffffffffffda RBX: 000055b74891c510 RCX: 00007fad2ad08229
[ 11.269635] RDX: 000055b74891c510 RSI: 0000000000000000 RDI: 0000000000000001
[ 11.269636] RBP: 000055b748916e50 R08: 0000000013248000 R09: 00000000c000003e
[ 11.269636] R10: 000055b74891a250 R11: 0000000000000246 R12: 00007ffe7ed36d50
[ 11.269637] R13: 00007ffe7ed36d48 R14: 00007fad2c455c18 R15: 000000000000002a
Starting udev Kernel Device Manager...
Starting Load/Save Random Seed...
Starting udev Coldplug all Devices...
Starting Preprocess NFS configuration...
Starting Raise network interfaces...
Starting Flush Journal to Persistent Storage...
Starting Create Volatile Files and Directories...
Starting Network Time Synchronization...
Starting RPC bind portmap service...
Starting Update UTMP about System Boot/Shutdown...
Starting LSB: Start and stop bmc-watchdog...
Starting Permit User Sessions...
Starting LSB: Execute the kexec -e command to reboot system...
Starting System Logging Service...
Starting Login Service...
Starting LKP bootstrap...
Starting /etc/rc.local Compatibility...
Starting OpenBSD Secure Shell server...
[
[ 11.748987] random: fast init done
[ 11.554086] rc.local[287]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/lkp/lkp/src/bin
Starting LSB: Load kernel image with kexec...
[ 12.034052] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0
[ 12.035513] PCI Interrupt Link [LNKD] enabled at IRQ 10
[ 12.087300] parport_pc 00:04: reported by Plug and Play ACPI
LKP: HOSTNAME vm-snb-2G-658, MAC 52:54:00:12:34:56, kernel 5.0.0-rc6-01569-g568f196 1, serial console /dev/ttyS0
[ 12.100785] Floppy drive(s): fd0 is 2.88M AMI BIOS
[ 12.102716] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
[ 12.113388] FDC 0 is a S82078B
[ 12.120530] PCI Interrupt Link [LNKA] enabled at IRQ 10
[ 12.206747] PCI Interrupt Link [LNKB] enabled at IRQ 11
[ 12.246019] BUG: assuming atomic context at kernel/seccomp.c:271
[ 12.247435] in_atomic(): 0, irqs_disabled(): 0, pid: 254, name: systemd-udevd
[ 12.248526] CPU: 1 PID: 254 Comm: systemd-udevd Tainted: G W 5.0.0-rc6-01569-g568f196 #1
[ 12.249996] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 12.251340] Call Trace:
[ 12.251840] dump_stack+0x5c/0x7b
[ 12.252443] __cant_sleep+0xb2/0xc0
[ 12.253062] __seccomp_filter+0x71/0x650
[ 12.253733] syscall_trace_enter+0x145/0x2f0
[ 12.254450] do_syscall_64+0x11a/0x180
[ 12.268149] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 12.268978] RIP: 0033:0x7f053d851347
[ 12.269606] Code: e2 4c 89 e6 31 ff e8 88 4d 00 00 31 c0 48 83 ec 80 5b 5d 41 5c c3 0f 1f 44 00 00 b8 ff ff ff ff eb eb 90 b8 5f 00 00 00 0f 05 <c3> 0f 1f 84 00 00 00 00 00 b8 5a 00 00 00 0f 05 48 3d 01 f0 ff ff
[ 12.272325] RSP: 002b:00007fff12b543e8 EFLAGS: 00000202 ORIG_RAX: 000000000000005f
[ 12.273559] RAX: ffffffffffffffda RBX: 000055c460880800 RCX: 00007f053d851347
[ 12.274622] RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 0000000000000012
[ 12.275686] RBP: 0000000000000007 R08: 0000000000000220 R09: 0000000000000030
[ 12.276745] R10: 0000000000000000 R11: 0000000000000202 R12: 00007fff12b54480
[ 12.277807] R13: 00007fff12b54478 R14: 0000000000000012 R15: 000000000000000e
[ 12.389426] i6300ESB timer 0000:00:0b.0: initialized (0x(____ptrval____)). heartbeat=30 sec (nowayout=0)
[ 12.412221] [drm] Found bochs VGA, ID 0xb0c0.
[ 12.412971] [drm] Framebuffer size 16384 kB @ 0xfd000000, mmio @ 0xfebf0000.
[ 12.435573] [TTM] Zone kernel: Available graphics memory: 1019336 kiB
[ 12.436614] [TTM] Initializing pool allocator
[ 12.457635] input: PC Speaker as /devices/platform/pcspkr/input/input5
[ 12.488919] [TTM] Initializing DMA pool allocator
[ 12.490408] bochs-drm 0000:00:02.0: Virtual-1: EDID is invalid:
[ 12.491363] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.492360] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.493358] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.494347] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.508397] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.509436] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.510470] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.511515] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 12.664881] fbcon: bochsdrmfb (fb0) is primary device
[ 12.756640] Console: switching to colour frame buffer device 128x48
[ 12.799400] bochs-drm 0000:00:02.0: fb0: bochsdrmfb frame buffer device
[ 12.808113] [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:02.0 on minor 0
[ 12.878102] Error: Driver 'pcspkr' is already registered, aborting...
[ 13.237244] ppdev: user-space parallel port driver
[ 13.254323] BUG: assuming atomic context at kernel/seccomp.c:271
[ 13.255192] in_atomic(): 0, irqs_disabled(): 0, pid: 251, name: systemd-udevd
[ 13.256032] CPU: 1 PID: 251 Comm: systemd-udevd Tainted: G W 5.0.0-rc6-01569-g568f196 #1
[ 13.257051] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 13.257933] Call Trace:
[ 13.258229] dump_stack+0x5c/0x7b
[ 13.258599] __cant_sleep+0xb2/0xc0
[ 13.259010] __seccomp_filter+0x71/0x650
[ 13.259456] ? __switch_to_asm+0x40/0x70
[ 13.259905] ? __switch_to_asm+0x34/0x70
[ 13.260351] ? __switch_to_asm+0x40/0x70
[ 13.260791] ? __switch_to_asm+0x34/0x70
[ 13.261241] ? __switch_to_asm+0x40/0x70
[ 13.261681] ? __switch_to_asm+0x34/0x70
[ 13.262141] ? __switch_to_asm+0x40/0x70
[ 13.262591] ? __switch_to_asm+0x34/0x70
[ 13.263023] ? __switch_to+0x115/0x440
[ 13.263434] syscall_trace_enter+0x145/0x2f0
[ 13.264161] do_syscall_64+0x11a/0x180
[ 13.264825] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 13.278730] RIP: 0033:0x7f053d85a4a7
[ 13.279406] Code: c7 c0 ff ff ff ff eb 8d 48 8b 15 ec 49 2b 00 f7 d8 64 89 02 e9 5b ff ff ff 66 2e 0f 1f 84 00 00 00 00 00 b8 0b 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c1 49 2b 00 f7 d8 64 89 01 48
[ 13.281995] RSP: 002b:00007fff12b53c38 EFLAGS: 00000246 ORIG_RAX: 000000000000000b
[ 13.283132] RAX: ffffffffffffffda RBX: 000055c460880ea0 RCX: 00007f053d85a4a7
[ 13.284240] RDX: 00000000ffffffff RSI: 000000000001ee66 RDI: 00007f053be8b000
[ 13.285359] RBP: 000055c460880780 R08: 000055c460881510 R09: 00007fff12b54000
[ 13.286480] R10: 000000000000000f R11: 0000000000000246 R12: 00007fff12b540e0
[ 13.287611] R13: 00007fff12b540d0 R14: 00007fff12b53c70 R15: 000055c45f589cbc
Starting Preprocess NFS configuration...
Starting Notify NFS peers of a restart...
Starting NFS status monitor for NFSv2/3 locking....
[ 13.453715] virtio_blk virtio0: [vda] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.482007] virtio_blk virtio1: [vdb] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.503013] virtio_blk virtio2: [vdc] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.513350] virtio_blk virtio3: [vdd] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.582059] virtio_blk virtio4: [vde] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.588240] virtio_blk virtio5: [vdf] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 13.663961] virtio_blk virtio6: [vdg] 536870912 512-byte logical blocks (275 GB/256 GiB)
[ 16.968012] BUG: assuming atomic context at kernel/seccomp.c:271
[ 16.973115] in_atomic(): 0, irqs_disabled(): 0, pid: 212, name: systemd-journal
[ 16.973118] CPU: 1 PID: 212 Comm: systemd-journal Tainted: G W 5.0.0-rc6-01569-g568f196 #1
[ 16.973119] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 16.973122] Call Trace:
[ 16.976267] dump_stack+0x5c/0x7b
[ 16.976274] __cant_sleep+0xb2/0xc0
[ 16.981204] __seccomp_filter+0x71/0x650
[ 16.981207] ? ep_poll+0x2af/0x4b0
[ 16.981213] syscall_trace_enter+0x145/0x2f0
[ 16.982529] do_syscall_64+0x11a/0x180
[ 16.982534] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 16.982537] RIP: 0033:0x7ffebb5957ee
[ 16.983930] Code: 48 89 e5 77 1a b8 01 00 00 00 89 f9 d3 e0 a9 03 08 00 00 74 06 5d e9 31 fe ff ff a8 60 75 0c 48 63 ff b8 e4 00 00 00 5d 0f 05 <c3> 48 63 c7 48 8d 15 87 c8 ff ff 48 83 c0 02 48 c1 e0 04 48 01 d0
[ 16.983931] RSP: 002b:00007ffebb506198 EFLAGS: 00000246 ORIG_RAX: 00000000000000e4
[ 16.983933] RAX: ffffffffffffffda RBX: 0000000000000007 RCX: 00007ffebb5957ee
[ 16.983934] RDX: ffffffffffffffff RSI: 00007ffebb5061c0 RDI: 0000000000000007
[ 16.983936] RBP: 00007ffebb5061c0 R08: 00007ffebb5920b0 R09: 00007ffebb592080
[ 16.992337] R10: 00007ffebb5061a0 R11: 0000000000000246 R12: 00007ffebb506200
[ 16.992338] R13: 0000000000000001 R14: 0000000000000001 R15: 0005825da748ccf6
[ 21.982938] BUG: assuming atomic context at kernel/seccomp.c:271
[ 21.986706] in_atomic(): 0, irqs_disabled(): 0, pid: 275, name: systemd-timesyn
[ 21.996001] CPU: 0 PID: 275 Comm: systemd-timesyn Tainted: G W 5.0.0-rc6-01569-g568f196 #1
[ 21.997096] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 21.997983] Call Trace:
[ 21.998272] dump_stack+0x5c/0x7b
[ 21.998639] __cant_sleep+0xb2/0xc0
[ 21.999024] __seccomp_filter+0x71/0x650
[ 21.999448] ? ep_poll+0x2af/0x4b0
[ 21.999821] syscall_trace_enter+0x145/0x2f0
[ 22.000285] do_syscall_64+0x11a/0x180
[ 22.000692] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 22.005292] RIP: 0033:0x7ffc165aa7ee
[ 22.005680] Code: 48 89 e5 77 1a b8 01 00 00 00 89 f9 d3 e0 a9 03 08 00 00 74 06 5d e9 31 fe ff ff a8 60 75 0c 48 63 ff b8 e4 00 00 00 5d 0f 05 <c3> 48 63 c7 48 8d 15 87 c8 ff ff 48 83 c0 02 48 c1 e0 04 48 01 d0
[ 22.009716] RSP: 002b:00007ffc1643a2f8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e4
[ 22.011559] RAX: ffffffffffffffda RBX: 0000000000000007 RCX: 00007ffc165aa7ee
[ 22.013366] RDX: ffffffffffffffff RSI: 00007ffc1643a320 RDI: 0000000000000007
[ 22.015184] RBP: 00007ffc1643a320 R08: 00007ffc165a70b0 R09: 00007ffc165a7080
[ 22.015971] R10: 00007ffc1643a300 R11: 0000000000000246 R12: 00007ffc1643a360
[ 22.017806] R13: 0000000000000001 R14: 0000000000000001 R15: 0000000000000000

Elapsed time: 20

qemu-img create -f qcow2 disk-vm-snb-2G-658-0 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-1 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-2 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-3 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-4 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-5 256G
qemu-img create -f qcow2 disk-vm-snb-2G-658-6 256G

kvm=(
qemu-system-x86_64
-enable-kvm
-cpu SandyBridge
-kernel $kernel
-initrd initrd-vm-snb-2G-658
-m 2048
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0,hostfwd=tcp::23765-:22
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-drive file=disk-vm-snb-2G-658-0,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-1,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-2,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-3,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-4,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-5,media=disk,if=virtio
-drive file=disk-vm-snb-2G-658-6,media=disk,if=virtio
-serial stdio
-display none
-monitor null
)

append=(
ip=::::vm-snb-2G-658::dhcp
root=/dev/ram0
user=lkp
job=/job-script
ARCH=x86_64
kconfig=x86_64-fedora-25
branch=bpf-next/master
commit=568f196756ad9fe2b49c46bbf6a9de1b190438b4
BOOT_IMAGE=/pkg/linux/x86_64-fedora-25/gcc-7/568f196756ad9fe2b49c46bbf6a9de1b190438b4/vmlinuz-5.0.0-rc6-01569-g568f196
max_uptime=600
RESULT_ROOT=/result/boot/1/vm-snb-2G/debian-x86_64-2018-04-03.cgz/x86_64-fedora-25/gcc-7/568f196756ad9fe2b49c46bbf6a9de1b190438b4/8
result_service=tmpfs
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
drbd.minor_count=8
systemd.log_level=err
ignore_loglevel
console=tty0
earlyprintk=ttyS0,115200
console=ttyS0,115200
vga=normal
rw
rcuperf.shutdown=0
)

"${kvm[@]}" -append "${append[*]}"


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


Attachments:
(No filename) (15.21 kB)
config-5.0.0-rc6-01569-g568f196 (203.82 kB)
job-script (4.60 kB)
dmesg.xz (13.48 kB)
Download all attachments

2019-02-21 13:41:44

by Daniel Borkmann

[permalink] [raw]
Subject: Re: [bpf] 568f196756: BUG:assuming_atomic_context_at_kernel/seccomp.c

On 02/21/2019 02:35 PM, kernel test robot wrote:
>
> FYI, we noticed the following commit (built with gcc-7):
>
> commit: 568f196756ad9fe2b49c46bbf6a9de1b190438b4 ("bpf: check that BPF programs run with preemption disabled")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):

Fyi, false positive and already fixed in bpf-next.

(https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git/commit/?id=435b3ff5b08a99a15647be32735abf8db66cea9a)

2019-02-22 22:42:45

by Valdis Klētnieks

[permalink] [raw]
Subject: Re: [bpf] 568f196756: BUG:assuming_atomic_context_at_kernel/seccomp.c

On Thu, 21 Feb 2019 14:39:27 +0100, Daniel Borkmann said:
> Fyi, false positive and already fixed in bpf-next.
>
> (https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git/commit/?id=435b3ff5b08a99a15647be32735abf8db66cea9a)

Is there a reason this commit appeared in next-20190221 but did not seem to be
in next-20190222 (confirmed via 'git tag --contains')?

[/usr/src/linux-next] git tag -l next-20190222
next-20190222
[/usr/src/linux-next] git tag --contains 435b3ff5b08a99a15647be32735abf8db66cea9a
next-20190221

(I went ahead and 'git cherry-pick -n' it on top of 0222)

2019-02-22 23:18:00

by Jann Horn

[permalink] [raw]
Subject: Re: [bpf] 568f196756: BUG:assuming_atomic_context_at_kernel/seccomp.c

On Fri, Feb 22, 2019 at 11:42 PM <[email protected]> wrote:
>
> On Thu, 21 Feb 2019 14:39:27 +0100, Daniel Borkmann said:
> > Fyi, false positive and already fixed in bpf-next.
> >
> > (https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git/commit/?id=435b3ff5b08a99a15647be32735abf8db66cea9a)
>
> Is there a reason this commit appeared in next-20190221 but did not seem to be
> in next-20190222 (confirmed via 'git tag --contains')?
>
> [/usr/src/linux-next] git tag -l next-20190222
> next-20190222
> [/usr/src/linux-next] git tag --contains 435b3ff5b08a99a15647be32735abf8db66cea9a
> next-20190221
>
> (I went ahead and 'git cherry-pick -n' it on top of 0222)

It was reverted by ast@, he wanted to fix it in a different way:
https://lore.kernel.org/netdev/[email protected]/

2019-02-23 00:05:38

by Valdis Klētnieks

[permalink] [raw]
Subject: Re: [bpf] 568f196756: BUG:assuming_atomic_context_at_kernel/seccomp.c

On Sat, 23 Feb 2019 00:15:38 +0100, Jann Horn said:
> On Fri, Feb 22, 2019 at 11:42 PM <[email protected]> wrote:
> > Is there a reason this commit appeared in next-20190221 but did not seem to be
> > in next-20190222 (confirmed via 'git tag --contains')?y ast@, he wanted to fix it in a different way:
> https://lore.kernel.org/netdev/[email protected]/

Aha. That was cc:ed to netdev, but not to lkml. Explains why I missed that piece
of the story....