[syzbot] INFO: task hung in jbd2_journal_commit_transaction (3)

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 5472f14a3742 Merge tag 'for_linus' of git://git.kernel.org..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=11132113b00000
kernel config: https://syzkaller.appspot.com/x/.config?x=e3bdfd29b408d1b6
dashboard link: https://syzkaller.appspot.com/bug?extid=9c3fb12e9128b6e1d7eb
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14559113b00000

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

INFO: task jbd2/sda1-8:2937 blocked for more than 143 seconds.
Not tainted 5.16.0-rc5-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:jbd2/sda1-8 state:D stack:27112 pid: 2937 ppid: 2 flags:0x00004000
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4972 [inline]
__schedule+0xa9a/0x4940 kernel/sched/core.c:6253
schedule+0xd2/0x260 kernel/sched/core.c:6326
io_schedule+0xee/0x170 kernel/sched/core.c:8371
bit_wait_io+0x12/0xd0 kernel/sched/wait_bit.c:209
__wait_on_bit+0x60/0x190 kernel/sched/wait_bit.c:49
out_of_line_wait_on_bit+0xd5/0x110 kernel/sched/wait_bit.c:64
wait_on_bit_io include/linux/wait_bit.h:101 [inline]
__wait_on_buffer+0x7a/0x90 fs/buffer.c:122
wait_on_buffer include/linux/buffer_head.h:356 [inline]
journal_wait_on_commit_record fs/jbd2/commit.c:175 [inline]
jbd2_journal_commit_transaction+0x4e3c/0x6be0 fs/jbd2/commit.c:931
kjournald2+0x1d0/0x930 fs/jbd2/journal.c:213
kthread+0x405/0x4f0 kernel/kthread.c:327
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
</TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/27:
#0: ffffffff8bb812e0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6458
1 lock held by udevd/2974:
2 locks held by getty/3287:
#0: ffff88807ec56098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:252
#1: ffffc90002b8e2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xcf0/0x1230 drivers/tty/n_tty.c:2113
2 locks held by kworker/1:0/3663:
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1198 [inline]
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:635 [inline]
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:662 [inline]
#0: ffff888010c76538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: process_one_work+0x896/0x1690 kernel/workqueue.c:2269
#1: ffffc90001b27db0 ((work_completion)(&rew.rew_work)){+.+.}-{0:0}, at: process_one_work+0x8ca/0x1690 kernel/workqueue.c:2273
2 locks held by syz-executor.2/13278:
#0: ffffffff8bc4c6c8 (perf_sched_mutex){+.+.}-{3:3}, at: account_event kernel/events/core.c:11445 [inline]
#0: ffffffff8bc4c6c8 (perf_sched_mutex){+.+.}-{3:3}, at: perf_event_alloc.part.0+0x31f9/0x3b10 kernel/events/core.c:11678
#1: ffffffff8bb8a668 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:290 [inline]
#1: ffffffff8bb8a668 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x4fa/0x620 kernel/rcu/tree_exp.h:836

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 27 Comm: khungtaskd Not tainted 5.16.0-rc5-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0xcd/0x134 lib/dump_stack.c:106
nmi_cpu_backtrace.cold+0x47/0x144 lib/nmi_backtrace.c:111
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:210 [inline]
watchdog+0xc1d/0xf50 kernel/hung_task.c:295
kthread+0x405/0x4f0 kernel/kthread.c:327
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
</TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 10 Comm: kworker/u4:1 Not tainted 5.16.0-rc5-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:__kasan_check_read+0x4/0x10 mm/kasan/shadow.c:31
Code: 44 07 48 85 db 0f 85 d0 9f 45 07 48 83 c4 60 5b 5d 41 5c 41 5d c3 c3 e9 d0 a0 45 07 cc cc cc cc cc cc cc cc cc cc 48 8b 0c 24 <89> f6 31 d2 e9 f3 f9 ff ff 0f 1f 00 48 8b 0c 24 89 f6 ba 01 00 00
RSP: 0018:ffffc90000f0f630 EFLAGS: 00000002
RAX: 0000000000000002 RBX: 1ffff920001e1ece RCX: ffffffff815b774f
RDX: 0000000000000092 RSI: 0000000000000008 RDI: ffffffff8ff77a10
RBP: 0000000000000100 R08: 0000000000000000 R09: ffffffff8ff77a17
R10: 0000000000000001 R11: 000000000000003f R12: 0000000000000008
R13: ffff888011c7eda8 R14: 0000000000000092 R15: ffff888011c7edc8
FS: 0000000000000000(0000) GS:ffff8880b9d00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00005555557b2708 CR3: 000000000b88e000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
instrument_atomic_read include/linux/instrumented.h:71 [inline]
test_bit include/asm-generic/bitops/instrumented-non-atomic.h:134 [inline]
hlock_class kernel/locking/lockdep.c:199 [inline]
mark_lock+0xef/0x17b0 kernel/locking/lockdep.c:4583
mark_usage kernel/locking/lockdep.c:4526 [inline]
__lock_acquire+0x8a7/0x54a0 kernel/locking/lockdep.c:4981
lock_acquire kernel/locking/lockdep.c:5637 [inline]
lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5602
__raw_spin_lock include/linux/spinlock_api_smp.h:133 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:154
spin_lock include/linux/spinlock.h:349 [inline]
__get_locked_pte+0x2b6/0x4d0 mm/memory.c:1722
get_locked_pte include/linux/mm.h:2160 [inline]
__text_poke+0x1ae/0x8c0 arch/x86/kernel/alternative.c:1000
text_poke_bp_batch+0x3d7/0x560 arch/x86/kernel/alternative.c:1361
text_poke_flush arch/x86/kernel/alternative.c:1451 [inline]
text_poke_flush arch/x86/kernel/alternative.c:1448 [inline]
text_poke_finish+0x16/0x30 arch/x86/kernel/alternative.c:1458
arch_jump_label_transform_apply+0x13/0x20 arch/x86/kernel/jump_label.c:146
jump_label_update+0x1d5/0x430 kernel/jump_label.c:830
static_key_enable_cpuslocked+0x1b1/0x260 kernel/jump_label.c:177
static_key_enable+0x16/0x20 kernel/jump_label.c:190
toggle_allocation_gate mm/kfence/core.c:732 [inline]
toggle_allocation_gate+0x100/0x390 mm/kfence/core.c:724
process_one_work+0x9b2/0x1690 kernel/workqueue.c:2298
worker_thread+0x658/0x11f0 kernel/workqueue.c:2445
kthread+0x405/0x4f0 kernel/kthread.c:327
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
</TASK>
sd 0:0:1:0: tag#6693 FAILED Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK cmd_age=0s
sd 0:0:1:0: tag#6693 CDB: opcode=0xe5 (vendor)
sd 0:0:1:0: tag#6693 CDB[00]: e5 f4 32 73 2f 4e 09 6d 26 e2 c7 35 d1 35 12 1c
sd 0:0:1:0: tag#6693 CDB[10]: 92 1b da 40 b8 58 5b a8 d4 7d 34 f3 90 4c f1 2d
sd 0:0:1:0: tag#6693 CDB[20]: ba
----------------
Code disassembly (best guess):
0: 44 07 rex.R (bad)
2: 48 85 db test %rbx,%rbx
5: 0f 85 d0 9f 45 07 jne 0x7459fdb
b: 48 83 c4 60 add $0x60,%rsp
f: 5b pop %rbx
10: 5d pop %rbp
11: 41 5c pop %r12
13: 41 5d pop %r13
15: c3 retq
16: c3 retq
17: e9 d0 a0 45 07 jmpq 0x745a0ec
1c: cc int3
1d: cc int3
1e: cc int3
1f: cc int3
20: cc int3
21: cc int3
22: cc int3
23: cc int3
24: cc int3
25: cc int3
26: 48 8b 0c 24 mov (%rsp),%rcx
* 2a: 89 f6 mov %esi,%esi <-- trapping instruction
2c: 31 d2 xor %edx,%edx
2e: e9 f3 f9 ff ff jmpq 0xfffffa26
33: 0f 1f 00 nopl (%rax)
36: 48 8b 0c 24 mov (%rsp),%rcx
3a: 89 f6 mov %esi,%esi
3c: ba .byte 0xba
3d: 01 00 add %eax,(%rax)


---
This report 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 syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches

[Matthew Wilcox]

On Sat, Dec 18, 2021 at 11:50:20AM -0800, syzbot wrote:
> INFO: task jbd2/sda1-8:2937 blocked for more than 143 seconds.
> Not tainted 5.16.0-rc5-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

sched_setattr(0x0, &(0x7f0000000080)={0x38, 0x1, 0x0, 0x0, 0x1}, 0x0)

so you've set a SCHED_FIFO priority and then are surprised that some
tasks are getting starved?

[Hillf Danton]

On Sat, 18 Dec 2021 21:22:57 +0000 Matthew Wilcox wrote:
>On Sat, Dec 18, 2021 at 11:50:20AM -0800, syzbot wrote:
>> INFO: task jbd2/sda1-8:2937 blocked for more than 143 seconds.
>> Not tainted 5.16.0-rc5-syzkaller #0
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Hey Willy

>
>sched_setattr(0x0, &(0x7f0000000080)={0x38, 0x1, 0x0, 0x0, 0x1}, 0x0)
>
>so you've set a SCHED_FIFO priority and then are surprised that some
>tasks are getting starved?

Can you speficy a bit more on how fifo could block journald waiting for
IO completion more than 120 seconds?

Hillf

[Matthew Wilcox]

On Sun, Dec 19, 2021 at 10:35:40AM +0800, Hillf Danton wrote:
> On Sat, 18 Dec 2021 21:22:57 +0000 Matthew Wilcox wrote:
> >On Sat, Dec 18, 2021 at 11:50:20AM -0800, syzbot wrote:
> >> INFO: task jbd2/sda1-8:2937 blocked for more than 143 seconds.
> >> Not tainted 5.16.0-rc5-syzkaller #0
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>
> Hey Willy
> >
> >sched_setattr(0x0, &(0x7f0000000080)={0x38, 0x1, 0x0, 0x0, 0x1}, 0x0)
> >
> >so you've set a SCHED_FIFO priority and then are surprised that some
> >tasks are getting starved?
>
> Can you speficy a bit more on how fifo could block journald waiting for
> IO completion more than 120 seconds?

Sure! You can see from the trace below that jbd2/sda1-8 is in D state,
so we know nobody's called unlock_buffer() yet, which would have woken
it. That would happen in journal_end_buffer_io_sync(), which is
the b_end_io for the buffer.

Learning more detail than that would require knowing the I/O path
for this particular test system. I suspect that the I/O was submitted
and has even completed, but there's a kernel thread waiting to run which
will call the ->b_end_io that hasn't been scheduled yet, because it's
at a lower priority than all the threads which are running at
SCHED_FIFO.

I'm disinclined to look at this report much further because syzbot is
stumbling around trying things which are definitely in the category of
"if you do this and things break, you get to keep both pieces". You
can learn some interesting things by playing with the various RT
scheduling classes, but mostly what you can learn is that you need to
choose your priorities carefully to have a functioning system.

[Theodore Ts'o]

On Sun, Dec 19, 2021 at 04:20:57AM +0000, Matthew Wilcox wrote:
> > Hey Willy
> > >
> > >sched_setattr(0x0, &(0x7f0000000080)={0x38, 0x1, 0x0, 0x0, 0x1}, 0x0)
> > >
> > >so you've set a SCHED_FIFO priority and then are surprised that some
> > >tasks are getting starved?
> >
> > Can you speficy a bit more on how fifo could block journald waiting for
> > IO completion more than 120 seconds?
>
> Sure! You can see from the trace below that jbd2/sda1-8 is in D state,
> so we know nobody's called unlock_buffer() yet, which would have woken
> it. That would happen in journal_end_buffer_io_sync(), which is
> the b_end_io for the buffer.
>
> Learning more detail than that would require knowing the I/O path
> for this particular test system. I suspect that the I/O was submitted
> and has even completed, but there's a kernel thread waiting to run which
> will call the ->b_end_io that hasn't been scheduled yet, because it's
> at a lower priority than all the threads which are running at
> SCHED_FIFO.
>
> I'm disinclined to look at this report much further because syzbot is
> stumbling around trying things which are definitely in the category of
> "if you do this and things break, you get to keep both pieces". You
> can learn some interesting things by playing with the various RT
> scheduling classes, but mostly what you can learn is that you need to
> choose your priorities carefully to have a functioning system.

In general, real-time threads (anything scheduled with SCHED_FIFO or
SCHED_RT) should never, *ever* try to do any kind of I/O. After all,
I/O can block, and if a real-time thread blocks, so much for any kind
of real-time guarantee that you might have.

If you must use do I/O from soft real-time thread, one trick you *can*
do is to some number of CPU's which are reserved for real-time
threads, and a subset of threads which are reserved for non-real-time
threads, enforced using CPU pinning. It's still not prefect, since
there are still priority inheritance issues, and while this protects
against a non-real-time thread holding some lock which is needed by a
real-time (SCHED_FIFO) thread, if there are two SCHED_FIFO running at
different priorities it's still possible to deadlock the entire
kernel.

Can it be done? Sure; I was part of an effort to make it work for the
US Navy's DDG-1000 Zumwalt-class destroyer[1]. But it's tricky, and
it's why IBM got paid the big bucks. :-) Certainly it's going to be
problematic for syzkaller if it's just going to be randomly trying to
set some threads to be real-time without doing any kind of formal
planning.

[1] https://dl.acm.org/doi/10.1147/sj.472.0207

Cheers,

- Ted

[Hillf Danton]

Hey Ted

Thank you for sharing the good and interesting materials.

I am trying to find the cause of same jbd2 journal thread blocked for
more than 120 seconds on a customer's system of linux-4.18 with RT
turned on and 12 CPUs in total bootup. Without both access to it and
clue of what RT apps running in the system, what I proposed is to
launch one more FIFO task of priority MAX_RT_PRIO-1 in the system like

for (;;) {
unsigned long i;

for (;;) /* spin for 150 seconds */
i++;
sleep a second;
}

in bid to observe the changes in behavior of underlying hardware using
the diff below.

Is it a well-designed system in general if it would take more than
three seconds for the IO to complete with hardware glitch ruled out?

Thanks
Hillf

+++ x/drivers/usb/core/message.c
@@ -703,7 +703,11 @@ void usb_sg_wait(struct usb_sg_request *
* So could the submit loop above ... but it's easier to
* solve neither problem than to solve both!
*/
- wait_for_completion(&io->complete);
+ for (i = 0;;) {
+ if (wait_for_completion_timeout(&io->complete, HZ))
+ break;
+ pr_err("%s for %d seconds\n", __func__, ++i);
+ }

sg_clean(io);
}

[Theodore Ts'o]

On Tue, Dec 21, 2021 at 05:08:04PM +0800, Hillf Danton wrote:
>
> I am trying to find the cause of same jbd2 journal thread blocked for
> more than 120 seconds on a customer's system of linux-4.18 with RT
> turned on and 12 CPUs in total bootup.

So here's the tricky bit with trying to use ext4 (or any file system,
really; the details will be different but the fundamental issues will
remain the same). When a thread either calls fsync(2) or tries to
initiate a flie system mutation by creating a jbd2 handle and there
isn't enough space, the process will wake up the jbd2 thread and block
until a new transaction has been started.

In the jbd2 thread, the first thing it does is wait for all currently
open handles to close, since it can only commit the current
transaction when all handles attached to the current transaction have
been closed. If some non-real-time process happens to have an open
handle, but it can't make forward progress for some reason, then this
will prevent the commit from completing, and this in turn will cause
any other process which needs to make changes to the file system from
making forward progress, since they will be blocked by jbd2 commit
thread, which in turn is blocked waiting low-priority process to make
forward progress --- and if that process is blocked behind some high
priority process, then that's the classic definition of "priority
inversion".

> Without both access to it and
> clue of what RT apps running in the system, what I proposed is to
> launch one more FIFO task of priority MAX_RT_PRIO-1 in the system like
>
> for (;;) {
> unsigned long i;
>
> for (;;) /* spin for 150 seconds */
> i++;
> sleep a second;
> }
>
> in bid to observe the changes in behavior of underlying hardware using
> the diff below.

I'm not sure what you hope to learn by doing something like that.
That will certainly perturb the system, but every 150 seconds, the
task is going to let other tasks/threads run --- but it will be
whatever is the next highest priority thread.

What you want to do is to figure out which thread is still holding a
handle open, and why it can't run --- is it because there are
sufficient higher priority threads that are running that it can't get
a time slice to run, so it can complete its file system operation and
release its handle? Is it blocked behind a memory allocation (perhaps
because it is in a memory-constrained cgroup)? Is it blocked waiting
on some mutex perhaps because it's doing something crazy like
sendfile()? Or some kind of I/O Uring system call? Etc, Etc., Etc.

What would probably make sense is to use "ps -eLcl" before the system
hangs so you can see what processes and threads are running with which
real-time or non-real-time priorities. Or if the system has hung,
uses the magic sysrq key to find out what threads are running on each
CPU, and grab a stack trace from all of the running processes so you
can figure out where some task might be blocked, and figure out which
task might be blocked inside a codepath where it would be holding a
handle.

If that level of access means you have to get a government security
clearance, or get permission from a finance company's vice president
for that kind of access --- get that clearance ahead of time, even if
it takes months and involves background investigations and polygraph
tests. Because you *will* need that kind of access to debug these
sorts of real-time locking issues. There is an extremely high (99.9%)
probability that the bug is in the system configuration or application
logic, so you will need full source code access to the workload to
understand what might have gone wrong. It's almost never a kernel
bug, but rather a fundamental application design or system
configuration problem.

> Is it a well-designed system in general if it would take more than
> three seconds for the IO to complete with hardware glitch ruled out?

Well, it depends on your definition of "well-designed" and "the I/O",
doesn't it? If you are using a cost-optimized cheap-sh*t flash device
from Shenzhen, it can minutes for I/O to complete. Just try copying
DVD's worth of data using buffered writes to said slow USB device, and
run "sync" or "umount /mnt", and watch the process hang for a long,
long time.

Or if you are using a cloud environment, and you are using virtual
block device which is provisioned for a small number of IOPS, whose
fault is it? The cloud system, for throttling I/O the IOPS that was
provisioned for the device? The person who created the VM, for not
appropriately provisioning enough IOPS? Or the application
programmer? Or the kernel programmer? (And if you've ever worked at
a Linux distro or a cloud provider, you can be sure that at least one
platinum customer will try to blame the kernel programmer. :-)

Or if you are using a storage area network, and you have a real time
process which is logging to a file, and battle damage takes out part
of the storage area network, and now the real-time process (which
might be responsible for ship navigation or missle defense) hangs
because file write is hanging, is that a "well-designed system"? This
is why you never, never, *NEVER* write to a file from a mission or
life-critical real-time thread. Instead you log to a ring buffer
which is shared by non-real-time process, and that non-realtime
process will save the log information to a file. And if the
non-real-time process can't keep up with writing the log, which is
worse? Missing log information? Or a laggy or deadlocked missile
defense system?

The bottom line is especially if you are trying to use real-time
threads, the entire system configuration, including choice of
hardware, as well as the overall system architecture, all needs to be
part of a holistic design. You can't just be "the OS person" but
instead you need to be part of the overall system architecture team.

Cheers,

- Ted

[Hillf Danton]

On Tue, 21 Dec 2021 17:32:18 -0500 Theodore Ts'o wrote:
> On Tue, Dec 21, 2021 at 05:08:04PM +0800, Hillf Danton wrote:
> >
> > I am trying to find the cause of same jbd2 journal thread blocked for
> > more than 120 seconds on a customer's system of linux-4.18 with RT
> > turned on and 12 CPUs in total bootup.
>
> So here's the tricky bit with trying to use ext4 (or any file system,

It is ext4 involved.

Without reproducer, I am trying to reproduce the issue using a FIFO CPU hog
which is supposed to beat the watchdog to show me the victims like various
kthreads, workqueue workers and user apps, despite I know zero about how the
watchdog is configured except the report was down to watchdog bite.

I also want to see if the RT system in question could survive a simple CPU
hog test like this.

>
> What you want to do is to figure out which thread is still holding a
> handle open, and why it can't run --- is it because there are
> sufficient higher priority threads that are running that it can't get
> a time slice to run, so it can complete its file system operation and
> release its handle? Is it blocked behind a memory allocation (perhaps

Yes.

> because it is in a memory-constrained cgroup)? Is it blocked waiting
> on some mutex perhaps because it's doing something crazy like
> sendfile()? Or some kind of I/O Uring system call? Etc, Etc., Etc.
>
> What would probably make sense is to use "ps -eLcl" before the system
> hangs so you can see what processes and threads are running with which
> real-time or non-real-time priorities. Or if the system has hung,
> uses the magic sysrq key to find out what threads are running on each
> CPU, and grab a stack trace from all of the running processes so you
> can figure out where some task might be blocked, and figure out which
> task might be blocked inside a codepath where it would be holding a
> handle.

Good material.

Got it.

>
> Cheers,
>
> - Ted
>

Thanks
Hillf

[Theodore Ts'o]

On Wed, Dec 22, 2021 at 10:25:27AM +0800, Hillf Danton wrote:
> > I'm not sure what you hope to learn by doing something like that.
> > That will certainly perturb the system, but every 150 seconds, the
> > task is going to let other tasks/threads run --- but it will be
> > whatever is the next highest priority thread.
>
> Without reproducer, I am trying to reproduce the issue using a FIFO CPU hog
> which is supposed to beat the watchdog to show me the victims like various
> kthreads, workqueue workers and user apps, despite I know zero about how the
> watchdog is configured except the report was down to watchdog bite.

It's really trivial to reproduce an issue that has the same symptom as
what has been reported to you. Mount the file system using a
non-real-time (SCHED_OTHER) thread, such that the jbd2 and ext4 worker
threads are running SCHED_OTHER. Then run some file system workload
(fsstress or fsmark) as SCHED_FIFO. Then on an N CPU system, run N
processes as SCHED_FIFO at any priority (doesn't matter whether it's
MAX_PRI-1 or MIN_PRI; SCHED_FIFO will have priority over SCHED_OTHER
processes, so this will effectively starve the ext4 and jbd2 worker
threads from ever getting to run. Once the ext4 journal fills up, any
SCHED_FIFO process which tries to write to the file system will hang.

The problem is that's *one* potential stupid configuration of the
real-time system. It's not necessarily the *only* potentially stupid
way that you can get yourself into a system hang. It appears the
syzkaller "repro" is another such "stupid way". And the number of
ways you can screw up with a real-time system is practically
unbounded...

So getting back to syzkaller, Willy had the right approach, which is a
Syzcaller "repro" happens to use SCHED_FIFO or SCHED_RR, and the
symptom is a system hang, it's probably worth ignoring the report,
since it's going to be a waste of time to debug userspace bug. If you
have anything that uses kernel threads, and SCHED_FIFO or SCHED_RR is
in play, it's probably a userspace bug.

Cheers,

- Ted

[syzbot]

syzbot has found a reproducer for the following issue on:

HEAD commit: 3f066e882bf1 Merge tag 'for-5.16/parisc-7' of git://git.ke..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=13aeaedbb00000
kernel config: https://syzkaller.appspot.com/x/.config?x=6104739ac5f067ea
dashboard link: https://syzkaller.appspot.com/bug?extid=9c3fb12e9128b6e1d7eb
compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=130e8ea5b00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=15b3620db00000

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

INFO: task jbd2/sda1-8:2935 blocked for more than 143 seconds.
Not tainted 5.16.0-rc6-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:jbd2/sda1-8 state:D stack:24688 pid: 2935 ppid: 2 flags:0x00004000

Call Trace:
<TASK>
context_switch kernel/sched/core.c:4972 [inline]

__schedule+0xb72/0x1460 kernel/sched/core.c:6253
schedule+0x12b/0x1f0 kernel/sched/core.c:6326
jbd2_journal_commit_transaction+0xc24/0x5c00 fs/jbd2/commit.c:496
kjournald2+0x4b4/0x940 fs/jbd2/journal.c:213
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30

</TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/27:

#0: ffffffff8cb1de00 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
2 locks held by getty/3281:
#0: ffff88814b4a6098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x21/0x70 drivers/tty/tty_ldisc.c:252
#1: ffffc90002b962e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6c5/0x1c60 drivers/tty/n_tty.c:2113
2 locks held by syz-executor272/3690:
#0: ffff88806d05dda8 (&type->i_mutex_dir_key#4){++++}-{3:3}, at: iterate_dir+0x124/0x640 fs/readdir.c:55
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: file_accessed include/linux/fs.h:2505 [inline]
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: iterate_dir+0x552/0x640 fs/readdir.c:70
2 locks held by syz-executor272/3689:
#0: ffff88806d0349b8 (&type->i_mutex_dir_key#4){++++}-{3:3}, at: iterate_dir+0x124/0x640 fs/readdir.c:55
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: file_accessed include/linux/fs.h:2505 [inline]
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: iterate_dir+0x552/0x640 fs/readdir.c:70
3 locks held by syz-executor272/3691:
#0: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: mnt_want_write+0x3b/0x80 fs/namespace.c:376
#1: ffff888074dcf198 (&type->i_mutex_dir_key#4/1){+.+.}-{3:3}, at: inode_lock_nested include/linux/fs.h:818 [inline]
#1: ffff888074dcf198 (&type->i_mutex_dir_key#4/1){+.+.}-{3:3}, at: filename_create+0x1da/0x4e0 fs/namei.c:3654
#2: ffff88814b6d4990 (jbd2_handle){++++}-{0:0}, at: start_this_handle+0x136d/0x1630 fs/jbd2/transaction.c:466
2 locks held by syz-executor272/3693:
#0: ffff88806d0317e0 (&type->i_mutex_dir_key#4){++++}-{3:3}, at: iterate_dir+0x124/0x640 fs/readdir.c:55
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: file_accessed include/linux/fs.h:2505 [inline]
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: iterate_dir+0x552/0x640 fs/readdir.c:70
2 locks held by syz-executor272/3694:
#0: ffff88806d0617e0 (&type->i_mutex_dir_key#4){++++}-{3:3}, at: iterate_dir+0x124/0x640 fs/readdir.c:55
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: file_accessed include/linux/fs.h:2505 [inline]
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: iterate_dir+0x552/0x640 fs/readdir.c:70
2 locks held by syz-executor272/3695:
#0: ffff88806d035da8 (&type->i_mutex_dir_key#4){++++}-{3:3}, at: iterate_dir+0x124/0x640 fs/readdir.c:55
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: file_accessed include/linux/fs.h:2505 [inline]
#1: ffff88814b6d0460 (sb_writers#5){.+.+}-{0:0}, at: iterate_dir+0x552/0x640 fs/readdir.c:70
2 locks held by kworker/u4:1/3719:
4 locks held by kworker/u4:4/3847:
#0: ffff888013bf3938 ((wq_completion)writeback){+.+.}-{0:0}, at: process_one_work+0x7ca/0x1140
#1: ffffc90003167d20 ((work_completion)(&(&wb->dwork)->work)){+.+.}-{0:0}, at: process_one_work+0x808/0x1140 kernel/workqueue.c:2273
#2: ffff88814b6d00e0 (&type->s_umount_key#31){++++}-{3:3}, at: trylock_super+0x1b/0xf0 fs/super.c:418
#3: ffff88814b6d2bd8 (&sbi->s_writepages_rwsem){.+.+}-{0:0}, at: ext4_writepages+0x1dd/0x4080 fs/ext4/inode.c:2655

=============================================

NMI backtrace for cpu 0

CPU: 0 PID: 27 Comm: khungtaskd Not tainted 5.16.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]

dump_stack_lvl+0x1dc/0x2d8 lib/dump_stack.c:106
nmi_cpu_backtrace+0x45f/0x490 lib/nmi_backtrace.c:111
nmi_trigger_cpumask_backtrace+0x16a/0x280 lib/nmi_backtrace.c:62

trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:210 [inline]

watchdog+0xc82/0xcd0 kernel/hung_task.c:295
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30

</TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1

CPU: 1 PID: 3719 Comm: kworker/u4:1 Not tainted 5.16.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011

Workqueue: bat_events batadv_nc_worker
RIP: 0010:mark_lock+0x6/0x1e00 kernel/locking/lockdep.c:4566
Code: 07 80 c1 03 38 c1 0f 8c 6f ff ff ff 4c 89 ff e8 80 fb 69 00 e9 62 ff ff ff e8 26 e7 ac 08 66 0f 1f 44 00 00 55 48 89 e5 41 57 <41> 56 41 55 41 54 53 48 83 e4 e0 48 81 ec c0 01 00 00 65 48 8b 04
RSP: 0018:ffffc900029bf8e8 EFLAGS: 00000046
RAX: 0000000000000002 RBX: ffff8880217761d0 RCX: 00000000ffffffff
RDX: 0000000000000008 RSI: ffff8880217761b0 RDI: ffff888021775700
RBP: ffffc900029bf8f0 R08: dffffc0000000000 R09: fffffbfff1ff3ff8
R10: fffffbfff1ff3ff8 R11: 0000000000000000 R12: 000000000000000a
R13: ffff8880217761b0 R14: ffff888021775700 R15: ffff8880217761d0
FS: 0000000000000000(0000) GS:ffff8880b9b00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00005621d6c67680 CR3: 000000000c88e000 CR4: 00000000003506e0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>

mark_usage kernel/locking/lockdep.c:4526 [inline]
__lock_acquire+0xd38/0x2b00 kernel/locking/lockdep.c:4981
lock_acquire+0x19f/0x4d0 kernel/locking/lockdep.c:5637
rcu_lock_acquire+0x2a/0x30 include/linux/rcupdate.h:268
rcu_read_lock include/linux/rcupdate.h:688 [inline]
batadv_nc_purge_orig_hash net/batman-adv/network-coding.c:412 [inline]
batadv_nc_worker+0xc8/0x5b0 net/batman-adv/network-coding.c:723
process_one_work+0x853/0x1140 kernel/workqueue.c:2298
worker_thread+0xac1/0x1320 kernel/workqueue.c:2445
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30
</TASK>
----------------
Code disassembly (best guess), 1 bytes skipped:
0: 80 c1 03 add $0x3,%cl
3: 38 c1 cmp %al,%cl
5: 0f 8c 6f ff ff ff jl 0xffffff7a
b: 4c 89 ff mov %r15,%rdi
e: e8 80 fb 69 00 callq 0x69fb93
13: e9 62 ff ff ff jmpq 0xffffff7a
18: e8 26 e7 ac 08 callq 0x8ace743
1d: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
23: 55 push %rbp
24: 48 89 e5 mov %rsp,%rbp
27: 41 57 push %r15
* 29: 41 56 push %r14 <-- trapping instruction
2b: 41 55 push %r13
2d: 41 54 push %r12
2f: 53 push %rbx
30: 48 83 e4 e0 and $0xffffffffffffffe0,%rsp
34: 48 81 ec c0 01 00 00 sub $0x1c0,%rsp
3b: 65 gs
3c: 48 rex.W
3d: 8b .byte 0x8b
3e: 04 .byte 0x4

[Dmitry Vyukov]

Hi Ted,

Reviving this old thread re syzkaller using SCHED_FIFO.

It's a bit hard to restrict what the fuzzer can do if we give it
sched_setattr() and friends syscalls. We could remove them from the
fuzzer entirely, but it's probably suboptimal as well.

I see that setting up SCHED_FIFO is guarded by CAP_SYS_NICE:
https://elixir.bootlin.com/linux/v5.18-rc7/source/kernel/sched/core.c#L7264

And I see we drop CAP_SYS_NICE from the fuzzer process since 2019
(after a similar discussion):
https://github.com/google/syzkaller/commit/f3ad68446455a

The latest C reproducer contains:

static void drop_caps(void)
{
struct __user_cap_header_struct cap_hdr = {};
struct __user_cap_data_struct cap_data[2] = {};
cap_hdr.version = _LINUX_CAPABILITY_VERSION_3;
cap_hdr.pid = getpid();
if (syscall(SYS_capget, &cap_hdr, &cap_data))
exit(1);
const int drop = (1 << CAP_SYS_PTRACE) | (1 << CAP_SYS_NICE);
cap_data[0].effective &= ~drop;
cap_data[0].permitted &= ~drop;
cap_data[0].inheritable &= ~drop;
if (syscall(SYS_capset, &cap_hdr, &cap_data))
exit(1);
}

Are we holding it wrong? How can the process manage to set any bad
scheduling policies if it dropped CAP_SYS_NICE?...
The process still has CAP_SYS_ADMIN, but I assume it should not allow
it using something that requires dropped CAP_SYS_NICE.

[Theodore Ts'o]

On Fri, May 20, 2022 at 01:57:07PM +0200, Dmitry Vyukov wrote:
>
> Hi Ted,
>
> Reviving this old thread re syzkaller using SCHED_FIFO.
>
> It's a bit hard to restrict what the fuzzer can do if we give it
> sched_setattr() and friends syscalls. We could remove them from the
> fuzzer entirely, but it's probably suboptimal as well.
>
> I see that setting up SCHED_FIFO is guarded by CAP_SYS_NICE:
> https://elixir.bootlin.com/linux/v5.18-rc7/source/kernel/sched/core.c#L7264
>
> And I see we drop CAP_SYS_NICE from the fuzzer process since 2019
> (after a similar discussion):
> https://github.com/google/syzkaller/commit/f3ad68446455a
>

> The latest C reproducer contains: ....

For this particular report, there *was* no C reproducer. There was
only a syz reproducer:

> syzbot found the following issue on:
>
> HEAD commit: 5472f14a3742 Merge tag 'for_linus' of git://git.kernel.org..
> git tree: upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=11132113b00000
> kernel config: https://syzkaller.appspot.com/x/.config?x=e3bdfd29b408d1b6
> dashboard link: https://syzkaller.appspot.com/bug?extid=9c3fb12e9128b6e1d7eb
> compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14559113b00000

So let me ask a counter question. I thought syzbot tries to create a
minimal reproducer? So if the sched_setattr is a no-op, and is
returning EPERM, why wasn't the sched_setattr line removed from the
syz repro?

As a side note, since in many cases running a reproducer can be
painful, would it be possible for the syzkiller dashboard to provide
the output of running "strace -f" while the reproducer is running?

That would also especially help since even when there is a C
reproducer, trying to understand what it is doing from reading the
syzbot-generated C source code is often non-trivial, and strace does a
much better job decoding what the !@#?@ the reproducer. Another
advantage of using strace is that it will also show us the return code
from the system call, which would very quickly confirm whether the
sched_setattr() was actually returning EPERM or not --- and it will
decode the system call arguments in a way that I often wished would be
included as comments in the syzbot-generated reproducer.

Providing the strace output could significantly reduce the amount of
upstream developer toil, and might therefore improve upstream
developer engagement with syzkaller.

Cheers,

- Ted

[Dmitry Vyukov]

On Fri, 20 May 2022 at 23:45, Theodore Ts'o <ty...@mit.edu> wrote:
> > Hi Ted,
> >
> > Reviving this old thread re syzkaller using SCHED_FIFO.
> >
> > It's a bit hard to restrict what the fuzzer can do if we give it
> > sched_setattr() and friends syscalls. We could remove them from the
> > fuzzer entirely, but it's probably suboptimal as well.
> >
> > I see that setting up SCHED_FIFO is guarded by CAP_SYS_NICE:
> > https://elixir.bootlin.com/linux/v5.18-rc7/source/kernel/sched/core.c#L7264
> >
> > And I see we drop CAP_SYS_NICE from the fuzzer process since 2019
> > (after a similar discussion):
> > https://github.com/google/syzkaller/commit/f3ad68446455a
> >
> > The latest C reproducer contains: ....
>
> For this particular report, there *was* no C reproducer. There was
> only a syz reproducer:

Yes, but the same logic should have been used. I just showed the
excerpt from the C reproducer b/c maybe there is something wrong with
that CAP_SYS_NICE logic.

> > syzbot found the following issue on:
> >
> > HEAD commit: 5472f14a3742 Merge tag 'for_linus' of git://git.kernel.org..
> > git tree: upstream
> > console output: https://syzkaller.appspot.com/x/log.txt?x=11132113b00000
> > kernel config: https://syzkaller.appspot.com/x/.config?x=e3bdfd29b408d1b6
> > dashboard link: https://syzkaller.appspot.com/bug?extid=9c3fb12e9128b6e1d7eb
> > compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
> > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14559113b00000
>
> So let me ask a counter question. I thought syzbot tries to create a
> minimal reproducer? So if the sched_setattr is a no-op, and is
> returning EPERM, why wasn't the sched_setattr line removed from the
> syz repro?

Two most common reasons would be (1) flaky reproduction, then each
minimization step can falsely decide that something is needed to
reproduce the bug b/c when we remove it, the crash does not reproduce;
(2) previously order/number of syscalls affected what syscalls are
executed concurrently to provoke races, so removing one syscall could
affect how subsequent syscalls are collided (this is not the case
anymore, but was the case when this bug was reported).

> As a side note, since in many cases running a reproducer can be
> painful, would it be possible for the syzkiller dashboard to provide
> the output of running "strace -f" while the reproducer is running?
>
> That would also especially help since even when there is a C
> reproducer, trying to understand what it is doing from reading the
> syzbot-generated C source code is often non-trivial, and strace does a
> much better job decoding what the !@#?@ the reproducer. Another
> advantage of using strace is that it will also show us the return code
> from the system call, which would very quickly confirm whether the
> sched_setattr() was actually returning EPERM or not --- and it will
> decode the system call arguments in a way that I often wished would be
> included as comments in the syzbot-generated reproducer.
>
> Providing the strace output could significantly reduce the amount of
> upstream developer toil, and might therefore improve upstream
> developer engagement with syzkaller.

+Aleksandr added this feature recently.

Console output will contain strace output for reproducers (when the
run under strace reproduced the same kernel crash as w/o strace).

Here is a recently reported bug:
https://syzkaller.appspot.com/bug?id=53c9bd2ca0e16936e45ff1333a22b838d91da0a2

"log" link for the reproducer crash shows:
https://syzkaller.appspot.com/text?tag=CrashLog&x=14f791aef00000
...

[ 26.757008][ T3179] 8021q: adding VLAN 0 to HW filter on device bond0
[ 26.766878][ T3179] eql: remember to turn off Van-Jacobson
compression on your slave devices
Starting sshd: OK
Warning: Permanently added '10.128.0.110' (ECDSA) to the list of known hosts.
execve("./syz-executor1865045535", ["./syz-executor1865045535"],
0x7ffdc91edf40 /* 10 vars */) = 0
brk(NULL) = 0x555557248000
brk(0x555557248c40) = 0x555557248c40
arch_prctl(ARCH_SET_FS, 0x555557248300) = 0
uname({sysname="Linux", nodename="syzkaller", ...}) = 0
readlink("/proc/self/exe", "/root/syz-executor1865045535", 4096) = 28
brk(0x555557269c40) = 0x555557269c40
brk(0x55555726a000) = 0x55555726a000
mprotect(0x7f37f8ecc000, 16384, PROT_READ) = 0
mmap(0x1ffff000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS,
-1, 0) = 0x1ffff000
mmap(0x20000000, 16777216, PROT_READ|PROT_WRITE|PROT_EXEC,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x20000000
mmap(0x21000000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS,
-1, 0) = 0x21000000
socket(AF_NETLINK, SOCK_RAW, NETLINK_NETFILTER) = 3
syzkaller login: [ 58.834018][ T3600] ------------[ cut here ]------------
[ 58.839772][ T3600] WARNING: CPU: 0 PID: 3600 at
net/netfilter/nfnetlink.c:703 nfnetlink_unbind+0x357/0x3b0
[ 58.849856][ T3600] Modules linked in:
...


The same is available in the report emails, e.g.:
https://lore.kernel.org/all/000000000000ff...@google.com/
...
console+strace: https://syzkaller.appspot.com/x/log.txt?x=14f791aef00000
...

[Jan Kara]

Wow, cool! Thanks for adding that! This was often one of the first steps I
did when looking into what the problem could be so it saves me some manual
work :)

Honza
--
Jan Kara <ja...@suse.com>
SUSE Labs, CR

[syzbot]

Auto-closing this bug as obsolete.
No recent activity, existing reproducers are no longer triggering the issue.