WARNING in schedule_bh

WARNING in schedule_bh

[Hao Sun]

Hello,

When using Healer to fuzz the latest Linux kernel, the following crash
was triggered.

HEAD commit: 4b93c544e90e-thunderbolt: test: split up test cases
git tree: upstream
console output:
https://drive.google.com/file/d/1hPcef9aADlFdNS6_ujlRpU-HoebC2uXF/view?usp=sharing
kernel config: https://drive.google.com/file/d/1c0u2EeRDhRO-ZCxr9MP2VvAtJd6kfg-p/view?usp=sharing
Syzlang reproducer:
https://drive.google.com/file/d/1zvo1s72quEdpM5xQ7zQxU8oOLiZpoFTN/view?usp=sharing
Similar report:
[1] https://groups.google.com/g/syzkaller-bugs/c/B8I1zHVqoxk/m/8PlQrZRbAwAJ
[2] https://groups.google.com/g/syzkaller-bugs/c/NLim2pbuazk/m/xd3MD-Q-BQAJ

Sorry, I don't have a C reproducer for this crash but have a Syzlang
reproducer. Also, hope the symbolized report can help.
Here are the instructions on how to execute Syzlang prog:
https://github.com/google/syzkaller/blob/master/docs/executing_syzkaller_programs.md

If you fix this issue, please add the following tag to the commit:
Reported-by: Hao Sun <sunhao.th@gmail.com>

------------[ cut here ]------------
WARNING: CPU: 3 PID: 8715 at drivers/block/floppy.c:999
schedule_bh+0x5f/0x70 drivers/block/floppy.c:999
Modules linked in:
CPU: 3 PID: 8715 Comm: kworker/u8:2 Not tainted 5.14.0+ #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
Workqueue: floppy floppy_work_workfn
RIP: 0010:schedule_bh+0x5f/0x70 drivers/block/floppy.c:999
Code: 27 67 ff fc 48 89 2d 40 d9 db 0b 5b 48 c7 c2 40 69 48 8c 48 8b
35 11 de db 0b bf 08 00 00 00 5d e9 56 d5 d4 fc e8 01 67 ff fc <0f> 0b
eb d1 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 e8 eb 66 ff fc
RSP: 0018:ffffc900008a0dc8 EFLAGS: 00010046
RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffff88801badd580
RDX: 0000000000000000 RSI: ffff88801badd580 RDI: 0000000000000002
RBP: ffffffff8476e0d0 R08: ffffffff8476b93f R09: 0000000000000000
R10: 0000000000000007 R11: fffffbfff1890d28 R12: 0000000000000001
R13: ffffffff8476e0d0 R14: 0000000000000000 R15: ffff888010c75000
FS:  0000000000000000(0000) GS:ffff888135d00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000000048b8e0 CR3: 000000002ee93000 CR4: 0000000000350ee0
Call Trace:
 <IRQ>
 floppy_interrupt+0x228/0x340 drivers/block/floppy.c:1765
 floppy_hardint+0x256/0x320 arch/x86/include/asm/floppy.h:66
 __handle_irq_event_percpu+0xfd/0x900 kernel/irq/handle.c:156
 handle_irq_event_percpu+0x76/0x160 kernel/irq/handle.c:196
 handle_irq_event+0xa1/0x130 kernel/irq/handle.c:213
 handle_edge_irq+0x24a/0x8a0 kernel/irq/chip.c:822
 generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
 handle_irq arch/x86/kernel/irq.c:231 [inline]
 __common_interrupt+0x9d/0x210 arch/x86/kernel/irq.c:250
 common_interrupt+0x9f/0xd0 arch/x86/kernel/irq.c:240
 </IRQ>
 asm_common_interrupt+0x1e/0x40 arch/x86/include/asm/idtentry.h:629
RIP: 0010:slow_down_io arch/x86/include/asm/paravirt.h:55 [inline]
RIP: 0010:outb_p arch/x86/include/asm/io.h:334 [inline]
RIP: 0010:fdc_outb drivers/block/floppy.c:602 [inline]
RIP: 0010:reset_fdc+0x328/0x8a0 drivers/block/floppy.c:1817
Code: ba 00 00 00 00 00 fc ff df 48 89 f9 48 c1 e9 03 80 3c 11 00 0f
85 e8 04 00 00 48 8d 14 9b 48 8b 14 d5 d0 97 52 90 83 c2 04 ee <48> c7
c3 e0 47 7f 8b 48 b8 00 00 00 00 00 fc ff df 48 89 da 48 c1
RSP: 0018:ffffc90001d0fcf8 EFLAGS: 00000202
RAX: 00000000ffffff83 RBX: 0000000000000000 RCX: 1ffffffff20a52fa
RDX: 00000000000003f4 RSI: ffff88801badd580 RDI: ffffffff905297d0
RBP: 0000000000000062 R08: ffffffff8476f60f R09: 0000000000000044
R10: 0000000000000001 R11: fffffbfff1fa0127 R12: 0000000000000001
R13: 0000000000000000 R14: dffffc0000000000 R15: 000000000000fffd
 process_one_work+0x9df/0x16d0 kernel/workqueue.c:2297
 worker_thread+0x90/0xed0 kernel/workqueue.c:2444
 kthread+0x3e5/0x4d0 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
----------------
Code disassembly (best guess):
   0: ba 00 00 00 00        mov    $0x0,%edx
   5: 00 fc                add    %bh,%ah
   7: ff                    (bad)
   8: df 48 89              fisttps -0x77(%rax)
   b: f9                    stc
   c: 48 c1 e9 03          shr    $0x3,%rcx
  10: 80 3c 11 00          cmpb   $0x0,(%rcx,%rdx,1)
  14: 0f 85 e8 04 00 00    jne    0x502
  1a: 48 8d 14 9b          lea    (%rbx,%rbx,4),%rdx
  1e: 48 8b 14 d5 d0 97 52 mov    -0x6fad6830(,%rdx,8),%rdx
  25: 90
  26: 83 c2 04              add    $0x4,%edx
  29: ee                    out    %al,(%dx)
* 2a: 48 c7 c3 e0 47 7f 8b mov    $0xffffffff8b7f47e0,%rbx <--
trapping instruction
  31: 48 b8 00 00 00 00 00 movabs $0xdffffc0000000000,%rax
  38: fc ff df
  3b: 48 89 da              mov    %rbx,%rdx
  3e: 48                    rex.W
  3f: c1                    .byte 0xc1

Re: WARNING in schedule_bh

[Denis Efremov]

Hi,

> 
> So, for me, concurrent execution of floppy_shutdown() and
> fd_locked_ioctl() is suspicious. Could you please check the above
> scenario is reasonable?
> 

Thank you for the analysis. You are right and concurrent execution
of floppy_shutdown() and fd_locked_ioctl() looks suspicious. I know about
this warning more than 2 years already since I wrote syzkaller descriptions
for the floppy. I can only wonder why did it take so long for the syzbot
to find it.
However, this bug is not reproducible on real hardware. I would prefer not
to touch the code significantly unless there is a security reason for it.
The pros here are that bugs should be fixed. The cons here are that changing
the code more-or-less significantly is hard to test on real hardware
(there was a regression in UAPI of floppy not so long ago, it took almost
half of a year before it was reported and it took another couple of months
before distros released kernels with a fix); floppy driver contains
undocumented/poorly-documented hacks (e.g. O_ACCMODE
https://github.com/google/syzkaller/commit/3ea5a3451b2bfa90a3b73397273560f17d587efc#diff-07b38a9cc5b8b1eed725414265f033c41abffbbe537567799ed678dfe9c49d7a);
/dev/fd0 is accessible only by root/disk user on most of the distros nowadays;
races are highly likely not reproducible on real hardware because floppy
devices are slow; from the functional point of view the driver worked with
this bug almost 10 years (maybe more) and I doubt it's possible to
face this bug during normal workflow (without direct intention to trigger it);
I think that usage of floppies inside VMs is limited to some specific
workflows and I doubt it's really broad.
If you see an easy way to fix this issue, please send a patch.

Thanks,
Denis

WARNING in schedule_bh

[Dae R. Jeong]

Hello,

During fuzzing, I observed a few warnings in the floppy driver, which
seems similar with the one found by Syzkaller.
(https://syzkaller.appspot.com/bug?id=7c17d936536dc3864e5df2d79ea11cdd946f81bf).

One of the warning reports is as follow:
------------[ cut here ]------------
WARNING: CPU: 2 PID: 11682 at drivers/block/floppy.c:1000 schedule_bh drivers/block/floppy.c:1000 [inline]
WARNING: CPU: 2 PID: 11682 at drivers/block/floppy.c:1000 process_fd_request drivers/block/floppy.c:2851 [inline]
WARNING: CPU: 2 PID: 11682 at drivers/block/floppy.c:1000 fd_locked_ioctl drivers/block/floppy.c:3506 [inline]
WARNING: CPU: 2 PID: 11682 at drivers/block/floppy.c:1000 fd_ioctl+0x4825/0x4e90 drivers/block/floppy.c:3555
Modules linked in:
...
(skipped)
...
Call Trace:
 <TASK>
 blkdev_ioctl+0x45f/0xb20 block/ioctl.c:609
 vfs_ioctl fs/ioctl.c:51 [inline]
 __do_sys_ioctl fs/ioctl.c:874 [inline]
 __se_sys_ioctl+0x12c/0x1e0 fs/ioctl.c:860
 __x64_sys_ioctl+0x9e/0xe0 fs/ioctl.c:860
 do_syscall_x64 arch/x86/entry/common.c:51 [inline]
 do_syscall_64+0x6f/0x110 arch/x86/entry/common.c:82
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x478b29
...
(skipped)
...
 </TASK>
------------------------------------

A similar warning seems to occur in places where schedule_bh() is
called (e.g., floppy_queue_rq, floppy_interrupt, ...).

I am trying to understand why this happens. The below execution
scenario is my best guess (but different with the above call
trace). Since I don't fully understand the semantic of the floppy
driver, please execuse me if this is wrong.


fd_locked_ioctl(FDRESET)      kworkerd                                  floppy_interrupt
  user_reset_fdc()
    cont = &reset_cont;
    wait_til_done(reset_fdc)
      schedule_bh(reset_fdc)
	  wait_event(command_done)
                              reset_fdc()
                                do_floppy = reset_interrupt
                                /* triggering an interrupt
                                   as stated in the comment */
                                                                        handler = do_floppy // reset_interrupt
                                                                        schedule_bh(handler)
                              reset_interrupt()
                                success_and_wakeup // reset_cont.redo
								  genric_success()
                                    generic_done(1)  // reset_cont.done
                                      cont = &wakeup_cont
                                  do_wakeup()      // wakeup_cont.redo
                                    reschedule_timeout()
                                    cont = NULL
                                    wake_up(command_done) // fd_locked_ioctl() can now resume

                              floppy_shutdown() // invoked by the above reschedule_timeout()
                                process_fd_request() // cont is NULL by reset_interrupt()
                                  schedule_bh(redo_fd_request)
    process_fd_request()
      schedule_bh(redo_fd_request) <- WARNING


So, for me, concurrent execution of floppy_shutdown() and
fd_locked_ioctl() is suspicious. Could you please check the above
scenario is reasonable?


Best regards,
Dae R. Jeong.

WARNING in schedule_bh

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    95e20af9 Merge tag 'nfs-for-5.5-2' of git://git.linux-nfs...
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=17648c21e00000
kernel config:  https://syzkaller.appspot.com/x/.config?x=d9290aeb7e6cf1c4
dashboard link: https://syzkaller.appspot.com/bug?extid=bfc0855888f853dca7ad
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
userspace arch: i386

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+bfc0855888f853dca7ad@syzkaller.appspotmail.com

------------[ cut here ]------------
WARNING: CPU: 3 PID: 12339 at drivers/block/floppy.c:985  
schedule_bh+0x67/0x70 drivers/block/floppy.c:985
Kernel panic - not syncing: panic_on_warn set ...
CPU: 3 PID: 12339 Comm: syz-executor.1 Not tainted 5.5.0-rc6-syzkaller #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS  
rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
Call Trace:
  __dump_stack lib/dump_stack.c:77 [inline]
  dump_stack+0x197/0x210 lib/dump_stack.c:118
  panic+0x2e3/0x75c kernel/panic.c:221
  __warn.cold+0x2f/0x3e kernel/panic.c:582
  report_bug+0x289/0x300 lib/bug.c:195
  fixup_bug arch/x86/kernel/traps.c:174 [inline]
  fixup_bug arch/x86/kernel/traps.c:169 [inline]
  do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:267
  do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:286
  invalid_op+0x23/0x30 arch/x86/entry/entry_64.S:1027
RIP: 0010:schedule_bh+0x67/0x70 drivers/block/floppy.c:985
Code: fd 48 8b 35 8b 82 ab 07 48 c7 c2 c0 80 00 8a bf 40 00 00 00 4c 89 25  
98 7d ab 07 e8 93 51 e3 fc 5b 41 5c 5d c3 e8 09 4a 0b fd <0f> 0b eb ce 0f  
1f 44 00 00 55 48 89 e5 e8 f7 49 0b fd 48 c7 c7 10
RSP: 0018:ffffc900075774b0 EFLAGS: 00010212
RAX: 0000000000040000 RBX: 0000000000000001 RCX: ffffc900039f0000
RDX: 00000000000086ed RSI: ffffffff8469ab77 RDI: 0000000000000007
RBP: ffffc900075774c0 R08: ffff888028b50d40 R09: fffffbfff1401019
R10: fffffbfff1401018 R11: ffffffff8a0080c7 R12: ffffffff846a94a0
R13: ffffffff846a94a0 R14: 0000000000000001 R15: 0000000000000001
  wait_til_done+0x88/0x370 drivers/block/floppy.c:1977
  poll_drive+0xd5/0xf0 drivers/block/floppy.c:2939
  floppy_check_events+0x39f/0x440 drivers/block/floppy.c:4107
  disk_check_events+0x13b/0x5c0 block/genhd.c:1859
  disk_clear_events+0x143/0x318 block/genhd.c:1819
  check_disk_change+0x79/0x140 fs/block_dev.c:1488
  floppy_open+0x6ba/0xae0 drivers/block/floppy.c:4067
  __blkdev_get+0x34f/0x1650 fs/block_dev.c:1604
  blkdev_get+0x47/0x2c0 fs/block_dev.c:1736
  blkdev_open+0x205/0x290 fs/block_dev.c:1875
  do_dentry_open+0x4e6/0x1380 fs/open.c:797
  vfs_open+0xa0/0xd0 fs/open.c:914
  do_last fs/namei.c:3420 [inline]
  path_openat+0x10df/0x4500 fs/namei.c:3537
  do_filp_open+0x1a1/0x280 fs/namei.c:3567
  do_sys_open+0x3fe/0x5d0 fs/open.c:1097
  __do_compat_sys_open fs/open.c:1134 [inline]
  __se_compat_sys_open fs/open.c:1132 [inline]
  __ia32_compat_sys_open+0x79/0xb0 fs/open.c:1132
  do_syscall_32_irqs_on arch/x86/entry/common.c:337 [inline]
  do_fast_syscall_32+0x27b/0xe16 arch/x86/entry/common.c:408
  entry_SYSENTER_compat+0x70/0x7f arch/x86/entry/entry_64_compat.S:139
RIP: 0023:0xf7fa9a39
Code: 00 00 00 89 d3 5b 5e 5f 5d c3 b8 80 96 98 00 eb c4 8b 04 24 c3 8b 1c  
24 c3 8b 34 24 c3 8b 3c 24 c3 51 52 55 89 e5 0f 34 cd 80 <5d> 5a 59 c3 90  
90 90 90 eb 0d 90 90 90 90 90 90 90 90 90 90 90 90
RSP: 002b:00000000f5da4c04 EFLAGS: 00000293 ORIG_RAX: 0000000000000005
RAX: ffffffffffffffda RBX: 00000000f5da4cc0 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000066666667 RDI: 00000000f5da4cc0
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Kernel Offset: disabled


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

WARNING in schedule_bh

[Dae R. Jeong]

Reporting the crash: WARNING in schedule_bh

This crash has been found in v4.18-rc4 using a modified version of
Syzkaller, which focus on exploring hard-to-reach coverages.

C repro code:
https://kiwi.cs.purdue.edu/static/alexkkid-fuzzer/repro-98b14a.c
Kernel config:
https://kiwi.cs.purdue.edu/static/alexkkid-fuzzer/config-98b14a

Crash log:
WARNING: CPU: 0 PID: 6107 at drivers/block/floppy.c:984 schedule_bh+0x4d/0x60 drivers/block/floppy.c:984
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 6107 Comm: kworker/u4:6 Not tainted 4.18.0-rc4 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Workqueue: floppy floppy_work_workfn
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x122/0x198 lib/dump_stack.c:113
 panic+0x27d/0x489 kernel/panic.c:184
 __warn+0x291/0x2d0 kernel/panic.c:536
 report_bug+0x243/0x300 lib/bug.c:186
 fixup_bug.part.9+0x42/0x1a0 arch/x86/kernel/traps.c:178
 fixup_bug arch/x86/kernel/traps.c:248 [inline]
 do_error_trap+0x278/0x2c0 arch/x86/kernel/traps.c:296
 do_invalid_op+0x20/0x30 arch/x86/kernel/traps.c:316
 invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:992
RIP: 0010:schedule_bh+0x4d/0x60 drivers/block/floppy.c:984
Code: c2 29 fe 48 8b 35 43 ee 88 07 48 c7 c2 40 f4 ac 88 bf 40 00 00 00 48 89 1d 50 e9 88 07 e8 cb 77 03 fe 5b 5d c3 e8 63 c2 29 fe <0f> 0b eb d0 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 
RSP: 0018:ffff88011a607d38 EFLAGS: 00010006
RAX: 0000000000010000 RBX: ffffffff83350970 RCX: ffffffff8333e1bd
RDX: ffff880110404440 RSI: ffffffff8abcd070 RDI: ffffffff83350970
RBP: ffff88011a607d40 R08: fffffbfff10e6995 R09: fffffbfff10e6995
R10: ffffffff88734ca3 R11: fffffbfff10e6994 R12: ffffffff83350970
R13: ffffffff8abcd070 R14: 0000000000000000 R15: ffffffff8abce960
 floppy_interrupt+0x1f6/0x390 drivers/block/floppy.c:1734
 floppy_hardint+0x25c/0x330 arch/x86/include/asm/floppy.h:66
 __handle_irq_event_percpu+0x10e/0xa30 kernel/irq/handle.c:149
 handle_irq_event_percpu+0x71/0x160 kernel/irq/handle.c:189
 handle_irq_event+0xca/0x170 kernel/irq/handle.c:206
 handle_edge_irq+0x2b0/0x960 kernel/irq/chip.c:791
 generic_handle_irq_desc include/linux/irqdesc.h:154 [inline]
 handle_irq+0x2dc/0x480 arch/x86/kernel/irq_64.c:77
 do_IRQ+0x15b/0x3c0 arch/x86/kernel/irq.c:245
 common_interrupt+0xf/0xf arch/x86/entry/entry_64.S:642
 </IRQ>
RIP: 0010:outb arch/x86/include/asm/io.h:333 [inline]
RIP: 0010:outb_p arch/x86/include/asm/io.h:333 [inline]
RIP: 0010:output_byte+0x133/0x3d0 drivers/block/floppy.c:1128
Code: 03 48 01 d0 80 38 00 0f 85 ab 02 00 00 4a 8d 14 b5 00 00 00 00 44 89 e8 49 01 d6 49 c1 e6 03 49 8b 96 70 d0 bc 8a 83 c2 05 ee <49> c7 c4 30 e1 6b 88 48 ba 00 00 00 00 00 fc ff df 4c 89 e0 48 c1 
RSP: 0018:ffff8800b998fcb8 EFLAGS: 00000206 ORIG_RAX: ffffffffffffffdc
RAX: 00000000ffffff8f RBX: 0000000000000090 RCX: ffffffff833438e3
RDX: 00000000000003f5 RSI: ffffffff8abcd070 RDI: ffffffff8abcd070
RBP: ffff8800b998fce0 R08: ffffffff8abcd070 R09: ffffffff8abcd060
R10: 0000000000000000 R11: ffffffff8abcd070 R12: 0000000000000000
R13: 00000000ffffff8f R14: 0000000000000000 R15: 0000000000000000
 seek_floppy drivers/block/floppy.c:1616 [inline]
 floppy_ready+0xac4/0x18f0 drivers/block/floppy.c:1920
 seek_interrupt+0x2c2/0x540 drivers/block/floppy.c:1540
 floppy_work_workfn+0x1a/0x20 drivers/block/floppy.c:977
 process_one_work+0x98d/0x1a30 kernel/workqueue.c:2153
 worker_thread+0x8f/0xcf0 kernel/workqueue.c:2296
 kthread+0x3d5/0x4b0 kernel/kthread.c:246
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
Dumping ftrace buffer:
   (ftrace buffer empty)
Kernel Offset: disabled
Rebooting in 86400 seconds..