./strace-static-x86_64 -e \!wait4,clock_nanosleep,nanosleep -s 100 -x -f ./syz-executor1310598091
<...>
Warning: Permanently added '10.128.0.76' (ED25519) to the list of known hosts.
execve("./syz-executor1310598091", ["./syz-executor1310598091"], 0x7fffb6b28560 /* 10 vars */) = 0
brk(NULL) = 0x5555884f8000
brk(0x5555884f8d00) = 0x5555884f8d00
arch_prctl(ARCH_SET_FS, 0x5555884f8380) = 0
set_tid_address(0x5555884f8650) = 5828
set_robust_list(0x5555884f8660, 24) = 0
rseq(0x5555884f8ca0, 0x20, 0, 0x53053053) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
readlink("/proc/self/exe", "/root/syz-executor1310598091", 4096) = 28
getrandom("\x23\xb0\x45\x6f\x2a\x2a\x5f\x8b", 8, GRND_NONBLOCK) = 8
brk(NULL) = 0x5555884f8d00
brk(0x555588519d00) = 0x555588519d00
brk(0x55558851a000) = 0x55558851a000
mprotect(0x7fe46dd8b000, 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
unshare(CLONE_NEWPID) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD./strace-static-x86_64: Process 5829 attached
<unfinished ...>
[pid 5829] set_robust_list(0x5555884f8660, 24 <unfinished ...>
[pid 5828] <... clone resumed>, child_tidptr=0x5555884f8650) = 5829
[pid 5829] <... set_robust_list resumed>) = 0
[pid 5829] prctl(PR_SET_PDEATHSIG, SIGKILL) = 0
[pid 5829] getppid() = 0
[pid 5829] prlimit64(0, RLIMIT_AS, {rlim_cur=204800*1024, rlim_max=204800*1024}, NULL) = 0
[pid 5829] prlimit64(0, RLIMIT_MEMLOCK, {rlim_cur=32768*1024, rlim_max=32768*1024}, NULL) = 0
[pid 5829] prlimit64(0, RLIMIT_FSIZE, {rlim_cur=139264*1024, rlim_max=139264*1024}, NULL) = 0
[pid 5829] prlimit64(0, RLIMIT_STACK, {rlim_cur=1024*1024, rlim_max=1024*1024}, NULL) = 0
[pid 5829] prlimit64(0, RLIMIT_CORE, {rlim_cur=131072*1024, rlim_max=131072*1024}, NULL) = 0
[pid 5829] prlimit64(0, RLIMIT_NOFILE, {rlim_cur=256, rlim_max=256}, NULL) = 0
[pid 5829] unshare(CLONE_NEWNS) = 0
[pid 5829] mount(NULL, "/", NULL, MS_REC|MS_PRIVATE, NULL) = 0
[pid 5829] unshare(CLONE_NEWIPC) = 0
[pid 5829] unshare(CLONE_NEWCGROUP) = 0
[pid 5829] unshare(CLONE_NEWUTS) = 0
[pid 5829] unshare(CLONE_SYSVSEM) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/shmmax", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "16777216", 8) = 8
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/shmall", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "536870912", 9) = 9
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/shmmni", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "1024", 4) = 4
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/msgmax", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "8192", 4) = 4
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/msgmni", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "1024", 4) = 4
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/msgmnb", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "1024", 4) = 4
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/kernel/sem", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "1024 1048576 500 1024", 21) = 21
[pid 5829] close(3) = 0
[pid 5829] getpid() = 1
[pid 5829] capget({version=_LINUX_CAPABILITY_VERSION_3, pid=1}, {effective=1<<CAP_CHOWN|1<<CAP_DAC_OVERRIDE|1<<CAP_DAC_READ_SEARCH|1<<CAP_FOWNER|1<<CAP_FSETID|1<<CAP_KILL|1<<CAP_SETGID|1<<CAP_SETUID|1<<CAP_SETPCAP|1<<CAP_LINUX_IMMUTABLE|1<<CAP_NET_BIND_SERVICE|1<<CAP_NET_BROADCAST|1<<CAP_NET_ADMIN|1<<CAP_NET_RAW|1<<CAP_IPC_LOCK|1<<CAP_IPC_OWNER|1<<CAP_SYS_MODULE|1<<CAP_SYS_RAWIO|1<<CAP_SYS_CHROOT|1<<CAP_SYS_PTRACE|1<<CAP_SYS_PACCT|1<<CAP_SYS_ADMIN|1<<CAP_SYS_BOOT|1<<CAP_SYS_NICE|1<<CAP_SYS_RESOURCE|1<<CAP_SYS_TIME|1<<CAP_SYS_TTY_CONFIG|1<<CAP_MKNOD|1<<CAP_LEASE|1<<CAP_AUDIT_WRITE|1<<CAP_AUDIT_CONTROL|1<<CAP_SETFCAP|1<<CAP_MAC_OVERRIDE|1<<CAP_MAC_ADMIN|1<<CAP_SYSLOG|1<<CAP_WAKE_ALARM|1<<CAP_BLOCK_SUSPEND|1<<CAP_AUDIT_READ|1<<CAP_PERFMON|1<<CAP_BPF|1<<CAP_CHECKPOINT_RESTORE, permitted=1<<CAP_CHOWN|1<<CAP_DAC_OVERRIDE|1<<CAP_DAC_READ_SEARCH|1<<CAP_FOWNER|1<<CAP_FSETID|1<<CAP_KILL|1<<CAP_SETGID|1<<CAP_SETUID|1<<CAP_SETPCAP|1<<CAP_LINUX_IMMUTABLE|1<<CAP_NET_BIND_SERVICE|1<<CAP_NET_BROADCAST|1<<CAP_NET_ADMIN|1<<CAP_NET_RAW|1<<CAP_IPC_LOCK|1<<CAP_IPC_OWNER|1<<CAP_SYS_MODULE|1<<CAP_SYS_RAWIO|1<<CAP_SYS_CHROOT|1<<CAP_SYS_PTRACE|1<<CAP_SYS_PACCT|1<<CAP_SYS_ADMIN|1<<CAP_SYS_BOOT|1<<CAP_SYS_NICE|1<<CAP_SYS_RESOURCE|1<<CAP_SYS_TIME|1<<CAP_SYS_TTY_CONFIG|1<<CAP_MKNOD|1<<CAP_LEASE|1<<CAP_AUDIT_WRITE|1<<CAP_AUDIT_CONTROL|1<<CAP_SETFCAP|1<<CAP_MAC_OVERRIDE|1<<CAP_MAC_ADMIN|1<<CAP_SYSLOG|1<<CAP_WAKE_ALARM|1<<CAP_BLOCK_SUSPEND|1<<CAP_AUDIT_READ|1<<CAP_PERFMON|1<<CAP_BPF|1<<CAP_CHECKPOINT_RESTORE, inheritable=0}) = 0
[pid 5829] capset({version=_LINUX_CAPABILITY_VERSION_3, pid=1}, {effective=1<<CAP_CHOWN|1<<CAP_DAC_OVERRIDE|1<<CAP_DAC_READ_SEARCH|1<<CAP_FOWNER|1<<CAP_FSETID|1<<CAP_KILL|1<<CAP_SETGID|1<<CAP_SETUID|1<<CAP_SETPCAP|1<<CAP_LINUX_IMMUTABLE|1<<CAP_NET_BIND_SERVICE|1<<CAP_NET_BROADCAST|1<<CAP_NET_ADMIN|1<<CAP_NET_RAW|1<<CAP_IPC_LOCK|1<<CAP_IPC_OWNER|1<<CAP_SYS_MODULE|1<<CAP_SYS_RAWIO|1<<CAP_SYS_CHROOT|1<<CAP_SYS_PACCT|1<<CAP_SYS_ADMIN|1<<CAP_SYS_BOOT|1<<CAP_SYS_RESOURCE|1<<CAP_SYS_TIME|1<<CAP_SYS_TTY_CONFIG|1<<CAP_MKNOD|1<<CAP_LEASE|1<<CAP_AUDIT_WRITE|1<<CAP_AUDIT_CONTROL|1<<CAP_SETFCAP|1<<CAP_MAC_OVERRIDE|1<<CAP_MAC_ADMIN|1<<CAP_SYSLOG|1<<CAP_WAKE_ALARM|1<<CAP_BLOCK_SUSPEND|1<<CAP_AUDIT_READ|1<<CAP_PERFMON|1<<CAP_BPF|1<<CAP_CHECKPOINT_RESTORE, permitted=1<<CAP_CHOWN|1<<CAP_DAC_OVERRIDE|1<<CAP_DAC_READ_SEARCH|1<<CAP_FOWNER|1<<CAP_FSETID|1<<CAP_KILL|1<<CAP_SETGID|1<<CAP_SETUID|1<<CAP_SETPCAP|1<<CAP_LINUX_IMMUTABLE|1<<CAP_NET_BIND_SERVICE|1<<CAP_NET_BROADCAST|1<<CAP_NET_ADMIN|1<<CAP_NET_RAW|1<<CAP_IPC_LOCK|1<<CAP_IPC_OWNER|1<<CAP_SYS_MODULE|1<<CAP_SYS_RAWIO|1<<CAP_SYS_CHROOT|1<<CAP_SYS_PACCT|1<<CAP_SYS_ADMIN|1<<CAP_SYS_BOOT|1<<CAP_SYS_RESOURCE|1<<CAP_SYS_TIME|1<<CAP_SYS_TTY_CONFIG|1<<CAP_MKNOD|1<<CAP_LEASE|1<<CAP_AUDIT_WRITE|1<<CAP_AUDIT_CONTROL|1<<CAP_SETFCAP|1<<CAP_MAC_OVERRIDE|1<<CAP_MAC_ADMIN|1<<CAP_SYSLOG|1<<CAP_WAKE_ALARM|1<<CAP_BLOCK_SUSPEND|1<<CAP_AUDIT_READ|1<<CAP_PERFMON|1<<CAP_BPF|1<<CAP_CHECKPOINT_RESTORE, inheritable=0}) = 0
[pid 5829] unshare(CLONE_NEWNET) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/net/ipv4/ping_group_range", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "0 65535", 7) = 7
[pid 5829] close(3) = 0
[pid 5829] openat(AT_FDCWD, "/proc/sys/fs/mount-max", O_WRONLY|O_CLOEXEC) = 3
[pid 5829] write(3, "100000", 6) = 6
[pid 5829] close(3) = 0
[pid 5829] mkdir("./syz-tmp", 0777) = 0
[pid 5829] mount("", "./syz-tmp", "tmpfs", 0, NULL) = 0
[pid 5829] mkdir("./syz-tmp/newroot", 0777) = 0
[pid 5829] mkdir("./syz-tmp/newroot/dev", 0700) = 0
[pid 5829] mount("/dev", "./syz-tmp/newroot/dev", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = 0
[pid 5829] mkdir("./syz-tmp/newroot/proc", 0700) = 0
[pid 5829] mount("syz-proc", "./syz-tmp/newroot/proc", "proc", 0, NULL) = 0
[pid 5829] mkdir("./syz-tmp/newroot/selinux", 0700) = 0
[pid 5829] mount("/selinux", "./syz-tmp/newroot/selinux", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = -1 ENOENT (No such file or directory)
[pid 5829] mount("/sys/fs/selinux", "./syz-tmp/newroot/selinux", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = -1 ENOENT (No such file or directory)
[pid 5829] mkdir("./syz-tmp/newroot/sys", 0700) = 0
[pid 5829] mount("/sys", "./syz-tmp/newroot/sys", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = 0
[pid 5829] mount("/sys/kernel/debug", "./syz-tmp/newroot/sys/kernel/debug", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = 0
[pid 5829] mount("/sys/fs/smackfs", "./syz-tmp/newroot/sys/fs/smackfs", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = -1 ENOENT (No such file or directory)
[pid 5829] mount("/proc/sys/fs/binfmt_misc", "./syz-tmp/newroot/proc/sys/fs/binfmt_misc", NULL, MS_BIND|MS_REC|MS_PRIVATE, NULL) = 0
[pid 5829] mkdir("./syz-tmp/pivot", 0777) = 0
[pid 5829] pivot_root("./syz-tmp", "./syz-tmp/pivot") = 0
[pid 5829] chdir("/") = 0
[pid 5829] umount2("./pivot", MNT_DETACH) = 0
[pid 5829] chroot("./newroot") = 0
[pid 5829] chdir("/") = 0
[pid 5829] mkdir("/dev/binderfs", 0777) = 0
[pid 5829] mount("binder", "/dev/binderfs", "binder", 0, NULL) = 0
[pid 5829] symlink("/dev/binderfs", "./binderfs") = 0
[pid 5829] mount(NULL, "/sys/fs/fuse/connections", "fusectl", 0, NULL) = -1 EBUSY (Device or resource busy)
[pid 5829] openat(AT_FDCWD, "/dev/loop0", O_RDWR) = 3
[pid 5829] ioctl(3, LOOP_CLR_FD) = -1 ENXIO (No such device or address)
[pid 5829] close(3) = 0
[pid 5829] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD./strace-static-x86_64: Process 5832 attached
, child_tidptr=0x5555884f8650) = 2
[pid 5832] set_robust_list(0x5555884f8660, 24) = 0
[pid 5832] prctl(PR_SET_PDEATHSIG, SIGKILL) = 0
[pid 5832] setpgid(0, 0) = 0
[pid 5832] openat(AT_FDCWD, "/proc/self/oom_score_adj", O_WRONLY|O_CLOEXEC) = 3
[pid 5832] write(3, "1000", 4) = 4
[pid 5832] close(3) = 0
executing program
[pid 5832] write(1, "executing program\n", 18) = 18
[pid 5832] memfd_create("syzkaller", 0) = 3
[pid 5832] mmap(NULL, 138412032, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe465800000
[pid 5832] write(3, "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"..., 16777216) = 16777216
[pid 5832] munmap(0x7fe465800000, 138412032) = 0
[pid 5832] openat(AT_FDCWD, "/dev/loop0", O_RDWR) = 4
[pid 5832] ioctl(4, LOOP_SET_FD, 3) = 0
[pid 5832] close(3) = 0
[pid 5832] close(4) = 0
[pid 5832] mkdir("./file0", 0777) = 0
[ 58.577555][ T5832] loop0: detected capacity change from 0 to 32768
[ 58.649898][ T5832] bcachefs (loop0): starting version 1.7: mi_btree_bitmap opts=metadata_checksum=none,data_checksum=none,compression=lz4,usrquota,grpquota,fsck,fix_errors=yes,nojournal_transaction_names,no_data_io
[ 58.670127][ T5832] invalid bkey u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq 28f61e078e70b95c written 16 min_key POS_MIN durability: 1 ptr: 0:28:0 gen 0
[ 58.670146][ T5832] nonzero snapshot: delete?, fixing
[ 58.690185][ T5832] bcachefs (loop0): recovering from clean shutdown, journal seq 10
[ 58.698274][ T5832] bcachefs (loop0): Version upgrade required:
[ 58.698274][ T5832] Version upgrade from 0.128: (unknown version) to 1.7: mi_btree_bitmap incomplete
[ 58.698274][ T5832] Doing incompatible version upgrade from 0.128: (unknown version) to 1.13: inode_has_child_snapshots
[ 58.698274][ T5832] running recovery passes: check_allocations,check_snapshots,check_subvols,check_inodes,check_dirents,set_fs_needs_rebalance
[ 58.743625][ T5832] invalid bkey u64s 17 type inode_v3 0:4097:U32_MAX len 0 ver 0: (unpack error)
[ 58.743652][ T5832] invalid variable length fields: delete?, fixing
[ 58.762262][ T5832] bcachefs (loop0): error validating btree node at btree alloc level 0/0
[ 58.762275][ T5832] u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq ac62141f8dc7e261 written 24 min_key POS_MIN durability: 1 ptr: 0:26:0 gen 0
[ 58.762283][ T5832] node offset 8/24 bset u64s 375 bset byte offset 184: keys out of order: u64s 11 type alloc_v4 0:32:0 len 0 ver 0 > u64s 11 type alloc_v4 0:2:0 len 0 ver 0, fixing
[ 58.801940][ T5832] invalid bkey u64s 12 type alloc_v4 0:28:0 len 0 ver 0:
[ 58.801952][ T5832] gen 0 oldest_gen 0 data_type btree
[ 58.801958][ T5832] journal_seq 6
[ 58.801963][ T5832] need_discard 1
[ 58.801968][ T5832] need_inc_gen 1
[ 58.801974][ T5832] dirty_sectors 0
[ 58.801979][ T5832] stripe_sectors 0
[ 58.801984][ T5832] cached_sectors 0
[ 58.801989][ T5832] stripe 0
[ 58.801994][ T5832] stripe_redundancy 0
[ 58.801999][ T5832] io_time[READ] 1
[ 58.802004][ T5832] io_time[WRITE] 768
[ 58.802009][ T5832] fragmentation 0
[ 58.802014][ T5832] bp_start 8
[ 58.802019][ T5832]
[ 58.802024][ T5832] invalid data type (got 3 should be 9): delete?, fixing
[ 58.874438][ T5832] bcachefs (loop0): btree_node_read_work: rewriting btree node at due to error
[ 58.874438][ T5832] btree=alloc level=0 u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq ac62141f8dc7e261 written 24 min_key POS_MIN durability: 1 ptr: 0:26:0 gen 0
[ 58.900210][ T5832] bcachefs (loop0): error validating btree node on loop0 at btree snapshots level 0/0
[ 58.900227][ T5832] u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq ebb8d5a9e3463bdb written 16 min_key POS_MIN durability: 1 ptr: 0:32:0 gen 0
[ 58.900235][ T5832] node offset 0/16: got wrong btree node: got
[ 58.900240][ T5832] btree=snapshots level=0 seq 50817571109851x
[ 58.900246][ T5832] min: POS_MIN
[ 58.900251][ T5832] max: SPOS_MAX
[ 58.943695][ T5832] bcachefs (loop0): flagging btree snapshots lost data
[ 58.950665][ T5832] bcachefs (loop0): running explicit recovery pass scan_for_btree_nodes (1), currently at recovery_pass_empty (0)
[ 58.965243][ T5832] error reading btree root btree=snapshots level=0: btree_node_read_error, fixing
[ 58.978698][ T5832] bcachefs (loop0): scan_for_btree_nodes...
[ 58.997943][ T5832] bch2_scan_for_btree_nodes: nodes found after overwrites:
[ 58.997962][ T5832] btree=extents level=0 seq=1 journal_seq=5 cookie=c6c25c03258c59c5 POS_MIN-SPOS_MAX ptr: 0:27:0 gen 0
[ 58.997970][ T5832] btree=inodes level=0 seq=1 journal_seq=5 cookie=7589ab5e0c11cc7a POS_MIN-SPOS_MAX ptr: 0:38:0 gen 0
[ 58.997976][ T5832] btree=dirents level=0 seq=1 journal_seq=4 cookie=9aa2895aefce4bdf POS_MIN-SPOS_MAX ptr: 0:41:0 gen 0
[ 58.997982][ T5832] btree=xattrs level=0 seq=1 journal_seq=4 cookie=2285c34bed0abe32 POS_MIN-SPOS_MAX ptr: 0:31:0 gen 0
[ 58.997989][ T5832] btree=subvolumes level=0 seq=1 journal_seq=1 cookie=c0bef60d07ceb940 POS_MIN-SPOS_MAX ptr: 0:35:0 gen 0
[ 58.997995][ T5832] btree=snapshots level=0 seq=1 journal_seq=0 cookie=2e37e3463bdb POS_MIN-SPOS_MAX ptr: 0:32:0 gen 0
[ 58.998002][ T5832] btree=deleted_inodes level=0 seq=1 journal_seq=0 cookie=1db8f60c84bb244c POS_MIN-SPOS_MAX ptr: 0:42:0 gen 0
[ 58.998008][ T5832]
[ 59.092724][ T5832] done
[ 59.096360][ T5832] bcachefs (loop0): check_topology...
[ 59.096573][ T5832] bcachefs (loop0): btree root extentsinodesdirentsxattrsallocquotasstripesreflinksubvolumessnapshots unreadable, must recover from scan
[ 59.116168][ T5832] bcachefs (loop0): bch2_get_scanned_nodes(): recovery btree=snapshots level=0 POS_MIN - SPOS_MAX
[ 59.126907][ T5832] bcachefs (loop0): bch2_get_scanned_nodes(): recovering u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq 2e37e3463bdb written 8 min_key POS_MIN durability: 1 ptr: 0:32:0 gen 0
[ 59.147552][ T5832] done
[ 59.151107][ T5832] bcachefs (loop0): accounting_read... done
[ 59.158118][ T5832] bcachefs (loop0): alloc_read... done
[ 59.163681][ T5832] bcachefs (loop0): stripes_read... done
[ 59.169351][ T5832] bcachefs (loop0): snapshots_read...
[ 59.170283][ T5832] bcachefs (loop0): running explicit recovery pass reconstruct_snapshots (21), currently at snapshots_read (7)
[ 59.187508][ T5832] done
[ 59.190279][ T5832] bcachefs (loop0): check_allocations...
[ 59.193803][ T5832] bucket 0:26 data type btree ptr gen 0 missing in alloc btree
[ 59.193820][ T5832] while marking u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq ac62141f8dc7e261 written 24 min_key POS_MIN durability: 1 ptr: 0:26:0 gen 0, fixing
[ 59.224242][ T5832] bucket 0:38 data type btree ptr gen 0 missing in alloc btree
[ 59.224256][ T5832] while marking u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq 7589ab5e0c11cc7a written 24 min_key POS_MIN durability: 1 ptr: 0:38:0 gen 0, fixing
[ 59.248418][ T5832] bucket 0:41 data type btree ptr gen 0 missing in alloc btree
[ 59.248431][ T5832] while marking u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq 9aa2895aefce4bdf written 24 min_key POS_MIN durability: 1 ptr: 0:41:0 gen 0, fixing
[ 59.272942][ T5832] bucket 0:35 data type btree ptr gen 0 missing in alloc btree
[ 59.272954][ T5832] while marking u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq c0bef60d07ceb940 written 16 min_key POS_MIN durability: 1 ptr: 0:35:0 gen 0, fixing
[ 59.298621][ T5832] bucket 0:29 data type btree ptr gen 0 missing in alloc btree
[ 59.298634][ T5832] while marking u64s 11 type btree_ptr_v2 SPOS_MAX len 0 ver 0: seq e81e1ed936acf3df written 32 min_key POS_MIN durability: 1 ptr: 0:29:0 gen 0, fixing
[ 59.322364][ T5832] bucket 0:1 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.330953][ T5832] bucket 0:1 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.341683][ T5832] bucket 0:2 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.350128][ T5832] bucket 0:2 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.359894][ T5832] bucket 0:3 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.368242][ T5832] bucket 0:3 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.378315][ T5832] bucket 0:4 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.386678][ T5832] bucket 0:4 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.396392][ T5832] bucket 0:5 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.404750][ T5832] bucket 0:5 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.414458][ T5832] bucket 0:6 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.422742][ T5832] bucket 0:6 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.432548][ T5832] bucket 0:7 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.440874][ T5832] bucket 0:7 gen 0 data type sb has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.450657][ T5832] bucket 0:8 gen 0 has wrong data_type: got free, should be sb, fixing
[ 59.458971][ T5832] bucket 0:8 gen 0 data type sb has wrong dirty_sectors: got 0, should be 8, fixing
[ 59.468573][ T5832] bucket 0:9 gen 0 has wrong data_type: got free, should be journal, fixing
[ 59.477324][ T5832] bucket 0:9 gen 0 data type journal has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.487556][ T5832] bucket 0:10 gen 0 has wrong data_type: got free, should be journal, fixing
[ 59.496425][ T5832] bucket 0:10 gen 0 data type journal has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.506755][ T5832] bucket 0:11 gen 0 has wrong data_type: got free, should be journal, fixing
[ 59.515585][ T5832] bcachefs (loop0): Ratelimiting new instances of previous error
[ 59.523407][ T5832] bucket 0:11 gen 0 data type journal has wrong dirty_sectors: got 0, should be 256, fixing
[ 59.533593][ T5832] bcachefs (loop0): Ratelimiting new instances of previous error
[ 59.547064][ T5832] done
[ 59.551408][ T5832] bcachefs (loop0): going read-write
[ 59.558452][ T5832] bcachefs (loop0): journal_replay...
[ 59.562978][ T5832] u64s 13 type alloc_v4 0:21:0 len 0 ver 0:
[ 59.562996][ T5832] gen 0 oldest_gen 0 data_type sb
[ 59.563002][ T5832] journal_seq 0
[ 59.563007][ T5832] need_discard 0
[ 59.563013][ T5832] need_inc_gen 0
[ 59.563018][ T5832] dirty_sectors 256
[ 59.563024][ T5832] stripe_sectors 0
[ 59.563029][ T5832] cached_sectors 0
[ 59.563035][ T5832] stripe 0
[ 59.563040][ T5832] stripe_redundancy 0
[ 59.563046][ T5832] io_time[READ] 0
[ 59.563051][ T5832] io_time[WRITE] 0
[ 59.563057][ T5832] fragmentation 0
[ 59.563062][ T5832] bp_start 8
[ 59.563067][ T5832]
[ 59.563073][ T5832] incorrectly set at freespace:0:21:0 (free 0, genbits 0 should be 0), fixing
[ 59.645527][ T5832]
[ 59.647863][ T5832] ============================================
[ 59.653990][ T5832] WARNING: possible recursive locking detected
[ 59.660125][ T5832] 6.12.0-next-20241120-syzkaller #0 Not tainted
[ 59.666338][ T5832] --------------------------------------------
[ 59.672465][ T5832] syz-executor131/5832 is trying to acquire lock:
[ 59.678854][ T5832] ffff888079f9dc38 (&wp->lock){+.+.}-{4:4}, at: bch2_alloc_sectors_start_trans+0x956/0x2030
[ 59.688924][ T5832]
[ 59.688924][ T5832] but task is already holding lock:
[ 59.696265][ T5832] ffff888079f9dc38 (&wp->lock){+.+.}-{4:4}, at: bch2_alloc_sectors_start_trans+0x2e8/0x2030
[ 59.706346][ T5832]
[ 59.706346][ T5832] other info that might help us debug this:
[ 59.714381][ T5832] Possible unsafe locking scenario:
[ 59.714381][ T5832]
[ 59.721819][ T5832] CPU0
[ 59.725080][ T5832] ----
[ 59.728340][ T5832] lock(&wp->lock);
[ 59.732228][ T5832] lock(&wp->lock);
[ 59.736115][ T5832]
[ 59.736115][ T5832] *** DEADLOCK ***
[ 59.736115][ T5832]
[ 59.744242][ T5832] May be due to missing lock nesting notation
[ 59.744242][ T5832]
[ 59.752544][ T5832] 5 locks held by syz-executor131/5832:
[ 59.758071][ T5832] #0: ffff888079f80278 (&c->state_lock){+.+.}-{4:4}, at: bch2_fs_start+0x45/0x610
[ 59.767381][ T5832] #1: ffff888079f843a8 (&c->btree_trans_barrier){.+.+}-{0:0}, at: bch2_trans_srcu_lock+0x9a/0x1a0
[ 59.778078][ T5832] #2: ffff888079fa6710 (&c->gc_lock){++++}-{4:4}, at: bch2_btree_update_start+0x682/0x14e0
[ 59.788160][ T5832] #3: ffff888079f9dc38 (&wp->lock){+.+.}-{4:4}, at: bch2_alloc_sectors_start_trans+0x2e8/0x2030
[ 59.798684][ T5832] #4: ffff888079fa6710 (&c->gc_lock){++++}-{4:4}, at: bch2_btree_update_start+0x682/0x14e0
[ 59.808766][ T5832]
[ 59.808766][ T5832] stack backtrace:
[ 59.814651][ T5832] CPU: 0 UID: 0 PID: 5832 Comm: syz-executor131 Not tainted 6.12.0-next-20241120-syzkaller #0
[ 59.824879][ T5832] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/30/2024
[ 59.834924][ T5832] Call Trace:
[ 59.838190][ T5832] <TASK>
[ 59.841116][ T5832] dump_stack_lvl+0x241/0x360
[ 59.845792][ T5832] ? __pfx_dump_stack_lvl+0x10/0x10
[ 59.850979][ T5832] ? __pfx__printk+0x10/0x10
[ 59.855556][ T5832] ? lockdep_unlock+0x16a/0x300
[ 59.860395][ T5832] print_deadlock_bug+0x483/0x620
[ 59.865420][ T5832] validate_chain+0x15e2/0x5920
[ 59.870259][ T5832] ? hlock_conflict+0x59/0x1e0
[ 59.875014][ T5832] ? __pfx___bfs+0x10/0x10
[ 59.879423][ T5832] ? __pfx_validate_chain+0x10/0x10
[ 59.884612][ T5832] ? check_path+0x21/0x40
[ 59.888948][ T5832] ? check_noncircular+0x259/0x4a0
[ 59.894059][ T5832] ? __pfx_validate_chain+0x10/0x10
[ 59.899260][ T5832] ? __pfx_check_noncircular+0x10/0x10
[ 59.904720][ T5832] ? lockdep_unlock+0x16a/0x300
[ 59.909561][ T5832] ? __pfx_lockdep_unlock+0x10/0x10
[ 59.914760][ T5832] ? validate_chain+0x15c0/0x5920
[ 59.919781][ T5832] ? mark_lock+0x9a/0x360
[ 59.924102][ T5832] __lock_acquire+0x1397/0x2100
[ 59.928946][ T5832] lock_acquire+0x1ed/0x550
[ 59.933466][ T5832] ? bch2_alloc_sectors_start_trans+0x956/0x2030
[ 59.939799][ T5832] ? __pfx_lock_acquire+0x10/0x10
[ 59.944819][ T5832] ? __pfx___might_resched+0x10/0x10
[ 59.950114][ T5832] ? __pfx_reacquire_held_locks+0x10/0x10
[ 59.955837][ T5832] ? lock_release+0xbf/0xa30
[ 59.960428][ T5832] __mutex_lock+0x1ac/0xee0
[ 59.964935][ T5832] ? bch2_alloc_sectors_start_trans+0x956/0x2030
[ 59.971268][ T5832] ? bch2_trans_unlock+0x346/0x470
[ 59.976369][ T5832] ? __pfx_lock_release+0x10/0x10
[ 59.981382][ T5832] ? bch2_alloc_sectors_start_trans+0x956/0x2030
[ 59.987708][ T5832] ? __pfx___mutex_lock+0x10/0x10
[ 59.992721][ T5832] ? bch2_trans_unlock+0x3a6/0x470
[ 59.997824][ T5832] bch2_alloc_sectors_start_trans+0x956/0x2030
[ 60.003995][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.009006][ T5832] ? trace_contention_end+0x3c/0x120
[ 60.014281][ T5832] ? __pfx_bch2_alloc_sectors_start_trans+0x10/0x10
[ 60.020863][ T5832] ? __mutex_unlock_slowpath+0x21e/0x790
[ 60.026488][ T5832] ? __pfx___mutex_lock+0x10/0x10
[ 60.031504][ T5832] bch2_btree_reserve_get+0x612/0x1890
[ 60.036964][ T5832] ? __pfx_bch2_btree_reserve_get+0x10/0x10
[ 60.042846][ T5832] ? percpu_up_read+0xdc/0x1b0
[ 60.047602][ T5832] ? __pfx___bch2_disk_reservation_add+0x10/0x10
[ 60.053919][ T5832] ? bch2_btree_update_start+0x682/0x14e0
[ 60.059630][ T5832] bch2_btree_update_start+0xe56/0x14e0
[ 60.065174][ T5832] ? bch2_btree_split_leaf+0x121/0x880
[ 60.070621][ T5832] ? __pfx_bch2_btree_update_start+0x10/0x10
[ 60.076594][ T5832] ? bch2_path_put+0x1d3/0x2290
[ 60.081437][ T5832] ? __build_rw_aux_tree+0x6ce/0x880
[ 60.086717][ T5832] bch2_btree_split_leaf+0x121/0x880
[ 60.091992][ T5832] bch2_trans_commit_error+0x212/0x1390
[ 60.097526][ T5832] ? bch2_check_discard_freespace_key+0xba7/0x1120
[ 60.104018][ T5832] ? six_unlock_ip+0x2ce/0x3e0
[ 60.108769][ T5832] ? bch2_trans_unlock_write+0x892/0xce0
[ 60.114391][ T5832] ? __pfx_bch2_trans_commit_error+0x10/0x10
[ 60.120360][ T5832] ? bch2_trans_unlock_write+0xc2d/0xce0
[ 60.125980][ T5832] ? bch2_btree_path_verify_locks+0x633/0x720
[ 60.132038][ T5832] ? bch2_trans_verify_locks+0x339/0x3c0
[ 60.137666][ T5832] __bch2_trans_commit+0x7f95/0x9520
[ 60.142944][ T5832] ? __pfx___bch2_fsck_err+0x10/0x10
[ 60.148223][ T5832] ? __pfx___bch2_trans_commit+0x10/0x10
[ 60.153844][ T5832] ? __asan_memcpy+0x40/0x70
[ 60.158425][ T5832] bch2_check_discard_freespace_key+0xba7/0x1120
[ 60.164750][ T5832] ? __pfx_bch2_check_discard_freespace_key+0x10/0x10
[ 60.171501][ T5832] ? bch2_path_get+0xf03/0x15d0
[ 60.176353][ T5832] ? bch2_check_discard_freespace_key+0x2b2/0x1120
[ 60.182842][ T5832] ? __bch2_path_free+0x6ef/0x820
[ 60.187877][ T5832] ? bch2_bucket_alloc_trans+0xefd/0x2fd0
[ 60.193590][ T5832] bch2_bucket_alloc_trans+0x1584/0x2fd0
[ 60.199213][ T5832] ? __pfx_validate_chain+0x10/0x10
[ 60.204416][ T5832] ? bch2_bucket_alloc_trans+0xc04/0x2fd0
[ 60.210150][ T5832] ? __pfx_bch2_bucket_alloc_trans+0x10/0x10
[ 60.216145][ T5832] ? bch2_bucket_alloc_trans+0xc04/0x2fd0
[ 60.221865][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.226889][ T5832] bch2_bucket_alloc_set_trans+0x517/0xd30
[ 60.232692][ T5832] ? bch2_bucket_alloc_set_trans+0x26f/0xd30
[ 60.238669][ T5832] ? __pfx___bfs+0x10/0x10
[ 60.243074][ T5832] ? __pfx_bch2_bucket_alloc_set_trans+0x10/0x10
[ 60.249394][ T5832] ? hlock_conflict+0x59/0x1e0
[ 60.254148][ T5832] ? __bfs+0x368/0x6f0
[ 60.258207][ T5832] ? mark_lock+0x9a/0x360
[ 60.262524][ T5832] ? __lock_acquire+0x1397/0x2100
[ 60.267547][ T5832] ? lockdep_unlock+0x16a/0x300
[ 60.272382][ T5832] ? __pfx_lockdep_unlock+0x10/0x10
[ 60.277574][ T5832] __open_bucket_add_buckets+0x13d0/0x1ec0
[ 60.283391][ T5832] ? __pfx_validate_chain+0x10/0x10
[ 60.288579][ T5832] ? __pfx___open_bucket_add_buckets+0x10/0x10
[ 60.294727][ T5832] ? __pfx_validate_chain+0x10/0x10
[ 60.299914][ T5832] ? mark_lock+0x9a/0x360
[ 60.304241][ T5832] ? __lock_acquire+0x1397/0x2100
[ 60.309256][ T5832] ? bch2_btree_path_verify_locks+0x279/0x720
[ 60.315324][ T5832] ? __bch2_trans_relock+0x44d/0x5f0
[ 60.320601][ T5832] open_bucket_add_buckets+0x33a/0x410
[ 60.326063][ T5832] bch2_alloc_sectors_start_trans+0xce9/0x2030
[ 60.332214][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.337229][ T5832] ? trace_contention_end+0x3c/0x120
[ 60.342506][ T5832] ? __pfx_bch2_alloc_sectors_start_trans+0x10/0x10
[ 60.349085][ T5832] ? __mutex_unlock_slowpath+0x21e/0x790
[ 60.354713][ T5832] ? __pfx___mutex_lock+0x10/0x10
[ 60.359726][ T5832] bch2_btree_reserve_get+0x612/0x1890
[ 60.365188][ T5832] ? __pfx_bch2_btree_reserve_get+0x10/0x10
[ 60.371078][ T5832] ? __pfx___closure_sync_timeout+0x10/0x10
[ 60.376962][ T5832] ? __bch2_wait_on_allocator+0x1f1/0x250
[ 60.382677][ T5832] bch2_btree_update_start+0x1160/0x14e0
[ 60.388301][ T5832] ? bch2_btree_split_leaf+0x121/0x880
[ 60.393754][ T5832] ? __pfx_bch2_btree_update_start+0x10/0x10
[ 60.399738][ T5832] ? __pfx_bch2_trans_update+0x10/0x10
[ 60.405206][ T5832] ? __pfx_closure_sync_fn+0x10/0x10
[ 60.410487][ T5832] ? __do_six_trylock+0x832/0x9f0
[ 60.415508][ T5832] bch2_btree_split_leaf+0x121/0x880
[ 60.420795][ T5832] bch2_trans_commit_error+0x212/0x1390
[ 60.426337][ T5832] ? bch2_journal_replay+0x1a18/0x2a70
[ 60.431791][ T5832] ? six_unlock_ip+0x2ce/0x3e0
[ 60.436547][ T5832] ? bch2_trans_unlock_write+0x892/0xce0
[ 60.442168][ T5832] ? __pfx_bch2_trans_commit_error+0x10/0x10
[ 60.448135][ T5832] ? bch2_trans_unlock_write+0xc2d/0xce0
[ 60.453775][ T5832] ? bch2_btree_path_verify_locks+0x633/0x720
[ 60.459857][ T5832] ? bch2_trans_verify_locks+0x339/0x3c0
[ 60.465500][ T5832] __bch2_trans_commit+0x7f95/0x9520
[ 60.470786][ T5832] ? bch2_journal_replay_key+0x24d/0xeb0
[ 60.476416][ T5832] ? __pfx___bch2_trans_commit+0x10/0x10
[ 60.482040][ T5832] bch2_journal_replay+0x1a18/0x2a70
[ 60.487317][ T5832] ? tick_nohz_tick_stopped+0x82/0xb0
[ 60.492686][ T5832] ? __pfx_bch2_journal_replay+0x10/0x10
[ 60.498307][ T5832] ? vprintk_emit+0x7ed/0xa10
[ 60.502977][ T5832] ? __pfx_vprintk_emit+0x10/0x10
[ 60.508014][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.513029][ T5832] ? __bch2_print+0x17a/0x220
[ 60.517694][ T5832] ? bch2_run_recovery_pass+0x6d/0x1e0
[ 60.523147][ T5832] ? __pfx___bch2_print+0x10/0x10
[ 60.528159][ T5832] ? lockdep_hardirqs_on_prepare+0x43d/0x780
[ 60.534128][ T5832] ? __pfx_lockdep_hardirqs_on_prepare+0x10/0x10
[ 60.540440][ T5832] ? _raw_spin_lock_irq+0xdf/0x120
[ 60.545545][ T5832] bch2_run_recovery_pass+0xf0/0x1e0
[ 60.550822][ T5832] bch2_run_recovery_passes+0x290/0x9f0
[ 60.556364][ T5832] bch2_fs_recovery+0x2666/0x3a90
[ 60.561394][ T5832] ? __pfx_bch2_fs_recovery+0x10/0x10
[ 60.566763][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.571772][ T5832] ? bch2_get_next_online_dev+0x2b/0x4f0
[ 60.577396][ T5832] ? __pfx_lock_release+0x10/0x10
[ 60.582410][ T5832] ? bch2_get_next_online_dev+0x2b/0x4f0
[ 60.588036][ T5832] ? bch2_get_next_online_dev+0x4b9/0x4f0
[ 60.593747][ T5832] ? bch2_get_next_online_dev+0x2b/0x4f0
[ 60.599371][ T5832] ? llist_reverse_order+0x72/0x90
[ 60.604475][ T5832] bch2_fs_start+0x37c/0x610
[ 60.609056][ T5832] bch2_fs_get_tree+0xd8d/0x1740
[ 60.613990][ T5832] ? __pfx_bch2_fs_get_tree+0x10/0x10
[ 60.619354][ T5832] ? generic_parse_monolithic+0x387/0x400
[ 60.625070][ T5832] ? apparmor_capable+0x13b/0x1b0
[ 60.630104][ T5832] vfs_get_tree+0x90/0x2b0
[ 60.634511][ T5832] do_new_mount+0x2be/0xb40
[ 60.639010][ T5832] ? __pfx_do_new_mount+0x10/0x10
[ 60.644027][ T5832] __se_sys_mount+0x2d6/0x3c0
[ 60.648695][ T5832] ? __pfx___se_sys_mount+0x10/0x10
[ 60.653883][ T5832] ? do_syscall_64+0x100/0x230
[ 60.658638][ T5832] ? __x64_sys_mount+0x20/0xc0
[ 60.663393][ T5832] do_syscall_64+0xf3/0x230
[ 60.667881][ T5832] ? clear_bhb_loop+0x35/0x90
[ 60.672546][ T5832] entry_SYSCALL_64_after_hwframe+0x77/0x7f
[ 60.678445][ T5832] RIP: 0033:0x7fe46dd1340a
[ 60.682854][ T5832] Code: d8 64 89 02 48 c7 c0 ff ff ff ff eb a6 e8 8e 04 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
[ 60.702445][ T5832] RSP: 002b:00007ffcf1924ad8 EFLAGS: 00000282 ORIG_RAX: 00000000000000a5
[ 60.710849][ T5832] RAX: ffffffffffffffda RBX: 00007ffcf1924af0 RCX: 00007fe46dd1340a
[ 60.718809][ T5832] RDX: 00000000200058c0 RSI: 0000000020000040 RDI: 00007ffcf1924af0
[ 60.726767][ T5832] RBP: 0000000000000004 R08: 00007ffcf1924b30 R09: 00000000000058df
[ 60.734727][ T5832] R10: 0000000008000000 R11: 0000000000000282 R12: 0000000008000000
[ 60.742685][ T5832] R13: 00007ffcf1924b30 R14: 0000000000000003 R15: 0000000001000000
[ 60.750649][ T5832] </TASK>
[pid 5832] mount("/dev/loop0", "./file0", "bcachefs", MS_NOREMOTELOCK, "inodes_use_key_cache,grpquota,dirnd_compression=lz4,usrquota,fix_errors=yes,no_data_io,fsck,hash," <unfinished ...>
[pid 5829] kill(-2, SIGKILL) = 0
[pid 5829] kill(2, SIGKILL) = 0
[pid 5829] openat(AT_FDCWD, "/sys/fs/fuse/connections", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
[pid 5829] newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=0, ...}, AT_EMPTY_PATH) = 0
[pid 5829] getdents64(3, 0x5555884f96f0 /* 2 entries */, 32768) = 48
[pid 5829] getdents64(3, 0x5555884f96f0 /* 0 entries */, 32768) = 0
[pid 5829] close(3) = 0