Bug 203279 - BUG: failure at fs/btrfs/ctree.h:3500/assfail()!
Summary: BUG: failure at fs/btrfs/ctree.h:3500/assfail()!
Status: NEW
Alias: None
Product: File System
Classification: Unclassified
Component: btrfs (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: BTRFS virtual assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-04-12 01:32 UTC by Jungyeon
Modified: 2020-03-09 09:47 UTC (History)
2 users (show)

See Also:
Kernel Version: 5.0.0
Tree: Mainline
Regression: No


Attachments
images and programs (150.00 KB, application/x-tar)
2019-04-12 01:32 UTC, Jungyeon
Details

Description Jungyeon 2019-04-12 01:32:37 UTC
Created attachment 282313 [details]
images and programs

- Overview
After mounting crafted image and running the attached program, I got this segmentation fault while running attached program.
I also tried to reproduce on vm, but it only report warning below.

LKL is Linux Kernel Library. poc_01.c is a program that calls lists of system calls in userspace and the craft image is a potentially faulty image to test error cases.
https://gts3.org/~jungyeon/btrfs-combined
at the link above, I uploaded the executable file required for this test.

The image is intentionally fuzzed from a normal btrfs image for testing.
Compile options for BTRFS are as follows.
CONFIG_BTRFS_FS=y
CONFIG_BTRFS_FS_POSIX_ACL=y
CONFIG_BTRFS_FS_CHECK_INTEGRITY=y
# CONFIG_BTRFS_FS_RUN_SANITY_TESTS is not set
CONFIG_BTRFS_DEBUG=y
CONFIG_BTRFS_ASSERT=y
CONFIG_BTRFS_FS_REF_VERIFY=y

[LKL]
- Reproduces 
./btrfs-combined -t btrfs -i tmp.img -p poc_01.c.raw -v
(poc_01.c shows it's internal programs)

- Kernel messages
[    0.000000] Linux version 5.0.0+ (jungyeon@pounce) (gcc version 5.5.0 20171010 (Ubuntu 5.5.0-12ubuntu1~16.04)) #1 Wed Apr 10 13:24:28 EDT 2019
[    0.000000] memblock address range: 0x14ddb8000000 - 0x14ddbffff000
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 32319
[    0.000000] Kernel command line: mem=128M virtio_mmio.device=316@0x1000000:1
[    0.000000] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.000000] Memory available: 129044k/131068k RAM
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 4096
[    0.000000] lkl: irqs initialized
[    0.000000] clocksource: lkl: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000001] lkl: time and timers initialized (irq2)
[    0.000011] pid_max: default: 4096 minimum: 301
[    0.000071] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.000080] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
[    0.001490] printk: console [lkl_console0] enabled
[    0.001524] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.001535] xor: automatically using best checksumming function   8regs     
[    0.002479] raid6: using algorithm int64x2 gen() 0 MB/s
[    0.002489] raid6: .... xor() 0 MB/s, rmw enabled
[    0.002497] raid6: using intx1 recovery algorithm
[    0.002535] clocksource: Switched to clocksource lkl
[    0.002830] virtio-mmio: Registering device virtio-mmio.0 at 0x1000000-0x100013b, IRQ 1.
[    0.003175] workingset: timestamp_bits=62 max_order=15 bucket_order=0
[    0.005201] virtio-mmio virtio-mmio.0: Failed to enable 64-bit or 32-bit DMA.  Trying to continue, but this might not work.
[    0.005411] virtio_blk virtio0: [vda] 262144 512-byte logical blocks (134 MB/128 MiB)
[    0.006027] random: get_random_bytes called from init_oops_id+0x35/0x40 with crng_init=0
[    0.006724] Btrfs loaded, crc32c=crc32c-generic, debug=on, assert=on, integrity-checker=on, ref-verify=on
[    0.007156] Warning: unable to open an initial console.
[    0.007199] This architecture does not have kernel memory protection.
[    0.007207] Run /init as init process
[    0.008300] BTRFS: device fsid a62e00e8-e94e-4200-8217-12444de93c2e devid 1 transid 8 /dev/0000fe00
[    0.008612] BTRFS info (device vda): disk space caching is enabled
[    0.008626] BTRFS info (device vda): has skinny extents
[    0.012042] BTRFS critical (device vda): corrupt leaf: root=1 block=29417472 slot=7, bad key order, prev (7205759403792793606 84 2378154706) current (7 132 0)
write at off 0x240e000 len 0x1000
addr: to 0x14ddc9d1d000 from 0x14ddbf982000
[    0.012198] BTRFS info (device vda): read error corrected: ino 0 off 29417472 (dev /dev/0000fe00 sector 73840)
[    0.013305] BTRFS critical (device vda): corrupt leaf: root=5 block=29409280 slot=26 ino=259 file_offset=0, invalid ram_bytes for uncompressed inline extent, have 33 expect 262177
write at off 0x240c000 len 0x1000
addr: to 0x14ddc9d1b000 from 0x14ddbf991000
[    0.013448] BTRFS info (device vda): read error corrected: ino 0 off 29409280 (dev /dev/0000fe00 sector 73824)
	v12 = syscall(SYS_open, (long)v2, 65536, 0);
	syscall(SYS_getdents64, (long)v12, (long)v1, 2344);
write at off 0x2401000 len 0x1000
addr: to 0x14ddc9d10000 from 0x14ddbf986000
write at off 0x4401000 len 0x1000
addr: to 0x14ddcbd10000 from 0x14ddbf986000
write at off 0x2400000 len 0x1000
addr: to 0x14ddc9d0f000 from 0x14ddbf993000
write at off 0x4400000 len 0x1000
addr: to 0x14ddcbd0f000 from 0x14ddbf993000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v12);
	v14 = syscall(SYS_open, (long)v13, 66, 438);
	syscall(SYS_symlink, (long)v2, (long)v15);
	syscall(SYS_pwrite64, (long)v14, (long)v1, 7633, 6687);
	syscall(SYS_lseek, (long)v14, 4057, 4);
	syscall(SYS_removexattr, (long)v4, (long)v16);
	syscall(SYS_symlink, (long)v9, (long)v17);
	syscall(SYS_pread64, (long)v14, (long)v0, 7793, 2148);
	syscall(SYS_getdents64, (long)v12, (long)v1, 3802);
write at off 0xc00000 len 0x3000
addr: to 0x14ddc850f000 from 0x14ddbfe00000
write at off 0x2405000 len 0x1000
addr: to 0x14ddc9d14000 from 0x14ddbf990000
write at off 0x4405000 len 0x1000
addr: to 0x14ddcbd14000 from 0x14ddbf990000
write at off 0x2406000 len 0x1000
addr: to 0x14ddc9d15000 from 0x14ddbf999000
write at off 0x4406000 len 0x1000
addr: to 0x14ddcbd15000 from 0x14ddbf999000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v14);
	syscall(SYS_symlink, (long)v10, (long)v18);
	syscall(SYS_setxattr, (long)v8, (long)v20, (long)v19, 21, 1);
	syscall(SYS_symlink, (long)v10, (long)v21);
	syscall(SYS_unlink, (long)v11);
	syscall(SYS_fdatasync, (long)v14);
	syscall(SYS_write, (long)v14, (long)v1, 5159);
	syscall(SYS_chmod, (long)v4, 3072);
write at off 0xc03000 len 0x1000
addr: to 0x14ddc8512000 from 0x14ddbfe03000
write at off 0xc04000 len 0x2000
addr: to 0x14ddc8513000 from 0x14ddbfe00000
write at off 0x2407000 len 0x1000
addr: to 0x14ddc9d16000 from 0x14ddbf99a000
write at off 0x4407000 len 0x1000
addr: to 0x14ddcbd16000 from 0x14ddbf99a000
write at off 0x2408000 len 0x1000
addr: to 0x14ddc9d17000 from 0x14ddbf99b000
write at off 0x4408000 len 0x1000
addr: to 0x14ddcbd17000 from 0x14ddbf99b000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fdatasync, (long)v14);
write at off 0x2409000 len 0x1000
addr: to 0x14ddc9d18000 from 0x14ddbf984000
write at off 0x240a000 len 0x2000
addr: to 0x14ddc9d19000 from 0x14ddbf99c000
write at off 0x4409000 len 0x1000
addr: to 0x14ddcbd18000 from 0x14ddbf984000
write at off 0x440a000 len 0x2000
addr: to 0x14ddcbd19000 from 0x14ddbf99c000
write at off 0x240c000 len 0x1000
addr: to 0x14ddc9d1b000 from 0x14ddbf991000
write at off 0x440c000 len 0x1000
addr: to 0x14ddcbd1b000 from 0x14ddbf991000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v12);
	syscall(SYS_pwrite64, (long)v14, (long)v1, 7846, 880);
	syscall(SYS_symlink, (long)v5, (long)v22);
	syscall(SYS_newlstat, (long)v2, (long)v1);
	syscall(SYS_symlink, (long)v8, (long)v23);
	syscall(SYS_unlink, (long)v6);
	syscall(SYS_symlink, (long)v5, (long)v24);
	syscall(SYS_readlink, (long)v13, (long)v1, 8192);
	syscall(SYS_getdents64, (long)v12, (long)v1, 5766);
write at off 0xc06000 len 0x1000
addr: to 0x14ddc8515000 from 0x14ddbfe03000
write at off 0xc07000 len 0x2000
addr: to 0x14ddc8516000 from 0x14ddbfe00000
write at off 0x240d000 len 0x1000
addr: to 0x14ddc9d1c000 from 0x14ddbf99f000
write at off 0x240e000 len 0x2000
addr: to 0x14ddc9d1d000 from 0x14ddbf982000
write at off 0x440d000 len 0x1000
addr: to 0x14ddcbd1c000 from 0x14ddbf99f000
write at off 0x440e000 len 0x2000
addr: to 0x14ddcbd1d000 from 0x14ddbf982000
write at off 0x2410000 len 0x1000
addr: to 0x14ddc9d1f000 from 0x14ddbf9a0000
write at off 0x4410000 len 0x1000
addr: to 0x14ddcbd1f000 from 0x14ddbf9a0000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v14);
	syscall(SYS_removexattr, (long)v22, (long)v25);
	v26 = syscall(SYS_open, (long)v4, 65536, 0);
	syscall(SYS_pread64, (long)v14, (long)v0, 7888, 2052);
	syscall(SYS_setxattr, (long)v18, (long)v28, (long)v27, 98, 1);
	syscall(SYS_utimes, (long)v9, (long)v1);
	syscall(SYS_getdents64, (long)v26, (long)v1, 1200);
	syscall(SYS_pwrite64, (long)v14, (long)v1, 6539, 7423);
	syscall(SYS_mkdir, (long)v29, 511);
write at off 0x2411000 len 0x3000
addr: to 0x14ddc9d20000 from 0x14ddbf9a3000
write at off 0x4411000 len 0x3000
addr: to 0x14ddcbd20000 from 0x14ddbf9a3000
write at off 0x2414000 len 0x1000
addr: to 0x14ddc9d23000 from 0x14ddbf9a6000
write at off 0x4414000 len 0x1000
addr: to 0x14ddcbd23000 from 0x14ddbf9a6000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v26);
	syscall(SYS_lseek, (long)v14, 2491, 0);
write at off 0x2415000 len 0x3000
addr: to 0x14ddc9d24000 from 0x14ddbf9a7000
write at off 0x4415000 len 0x3000
addr: to 0x14ddcbd24000 from 0x14ddbf9a7000
write at off 0x2418000 len 0x1000
addr: to 0x14ddc9d27000 from 0x14ddbf9aa000
write at off 0x4418000 len 0x1000
addr: to 0x14ddcbd27000 from 0x14ddbf9aa000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_rename, (long)v18, (long)v21);
write at off 0x2419000 len 0x3000
addr: to 0x14ddc9d28000 from 0x14ddbf9ab000
write at off 0x4419000 len 0x3000
addr: to 0x14ddcbd28000 from 0x14ddbf9ab000
write at off 0x241c000 len 0x1000
addr: to 0x14ddc9d2b000 from 0x14ddbf9ae000
write at off 0x441c000 len 0x1000
addr: to 0x14ddcbd2b000 from 0x14ddbf9ae000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_rename, (long)v10, (long)v30);
	syscall(SYS_getdents64, (long)v26, (long)v1, 3043);
write at off 0x241d000 len 0x3000
addr: to 0x14ddc9d2c000 from 0x14ddbf9af000
write at off 0x441d000 len 0x3000
addr: to 0x14ddcbd2c000 from 0x14ddbf9af000
write at off 0x2420000 len 0x1000
addr: to 0x14ddc9d2f000 from 0x14ddbf9b2000
write at off 0x4420000 len 0x1000
addr: to 0x14ddcbd2f000 from 0x14ddbf9b2000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v12);
	syscall(SYS_fallocate, (long)v14, 65, 6250, 1726);
	syscall(SYS_pwrite64, (long)v14, (long)v1, 7616, 8005);
	syscall(SYS_symlink, (long)v21, (long)v31);
	syscall(SYS_newstat, (long)v4, (long)v1);
	syscall(SYS_write, (long)v14, (long)v1, 7418);
	syscall(SYS_pwrite64, (long)v14, (long)v1, 263, 5053);
	syscall(SYS_symlink, (long)v4, (long)v32);
	syscall(SYS_rmdir, (long)v3);
write at off 0x2421000 len 0x3000
addr: to 0x14ddc9d30000 from 0x14ddbf9b4000
write at off 0x4421000 len 0x3000
addr: to 0x14ddcbd30000 from 0x14ddbf9b4000
write at off 0x2424000 len 0x1000
addr: to 0x14ddc9d33000 from 0x14ddbf9b8000
write at off 0x4424000 len 0x1000
addr: to 0x14ddcbd33000 from 0x14ddbf9b8000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v26);
	syscall(SYS_access, (long)v5, 1);
	syscall(SYS_ftruncate, (long)v14, 1932);
	syscall(SYS_listxattr, (long)v24, (long)v1, 4259);
write at off 0x2427000 len 0x3000
addr: to 0x14ddc9d36000 from 0x14ddbf9bc000
write at off 0x4427000 len 0x3000
addr: to 0x14ddcbd36000 from 0x14ddbf9bc000
write at off 0x242a000 len 0x1000
addr: to 0x14ddc9d39000 from 0x14ddbf9bf000
write at off 0x442a000 len 0x1000
addr: to 0x14ddcbd39000 from 0x14ddbf9bf000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fdatasync, (long)v14);
	syscall(SYS_pread64, (long)v14, (long)v0, 4854, 6327);
	syscall(SYS_mkdir, (long)v33, 511);
	syscall(SYS_unlink, (long)v32);
	syscall(SYS_pread64, (long)v14, (long)v0, 2005, 2802);
write at off 0x242b000 len 0x4000
addr: to 0x14ddc9d3a000 from 0x14ddbf9c0000
write at off 0x442b000 len 0x4000
addr: to 0x14ddcbd3a000 from 0x14ddbf9c0000
write at off 0x242f000 len 0x1000
addr: to 0x14ddc9d3e000 from 0x14ddbf9c4000
write at off 0x442f000 len 0x1000
addr: to 0x14ddcbd3e000 from 0x14ddbf9c4000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v14);
	syscall(SYS_setxattr, (long)v2, (long)v35, (long)v34, 9, 1);
	syscall(SYS_utimes, (long)v22, (long)v1);
write at off 0x2430000 len 0x3000
addr: to 0x14ddc9d3f000 from 0x14ddbf9c5000
write at off 0x2433000 len 0x1000
addr: to 0x14ddc9d42000 from 0x14ddbf9c9000
write at off 0x4430000 len 0x3000
addr: to 0x14ddcbd3f000 from 0x14ddbf9c5000
write at off 0x4433000 len 0x1000
addr: to 0x14ddcbd42000 from 0x14ddbf9c9000
write at off 0x2434000 len 0x1000
addr: to 0x14ddc9d43000 from 0x14ddbf9ca000
write at off 0x4434000 len 0x1000
addr: to 0x14ddcbd43000 from 0x14ddbf9ca000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fsync, (long)v26);
	syscall(SYS_fallocate, (long)v14, 65, 2531, 530);
	syscall(SYS_write, (long)v14, (long)v1, 3660);
	syscall(SYS_access, (long)v23, 1);
write at off 0xc09000 len 0x1000
addr: to 0x14ddc8518000 from 0x14ddbfe03000
write at off 0xc0a000 len 0x2000
addr: to 0x14ddc8519000 from 0x14ddbfe00000
write at off 0x2435000 len 0x1000
addr: to 0x14ddc9d44000 from 0x14ddbf9cc000
write at off 0x4435000 len 0x1000
addr: to 0x14ddcbd44000 from 0x14ddbf9cc000
write at off 0x2437000 len 0x2000
addr: to 0x14ddc9d46000 from 0x14ddbf9ce000
write at off 0x4437000 len 0x2000
addr: to 0x14ddcbd46000 from 0x14ddbf9ce000
write at off 0x2439000 len 0x1000
addr: to 0x14ddc9d48000 from 0x14ddbf9d0000
write at off 0x4439000 len 0x1000
addr: to 0x14ddcbd48000 from 0x14ddbf9d0000
write at off 0x10000 len 0x1000
addr: to 0x14ddc791f000 from 0x14ddbfe3c000
	syscall(SYS_fdatasync, (long)v14);
	syscall(SYS_mkdir, (long)v36, 511);
	syscall(SYS_fsync, (long)v26);
	syscall(SYS_newstat, (long)v22, (long)v1);
	syscall(SYS_mkdir, (long)v37, 511);
	syscall(SYS_mkdir, (long)v38, 511);
	syscall(SYS_mkdir, (long)v39, 511);
	syscall(SYS_chmod, (long)v4, 3072);
	syscall(SYS_rmdir, (long)v38);
	syscall(SYS_symlink, (long)v23, (long)v40);
	syscall(SYS_link, (long)v9, (long)v41);
	syscall(SYS_fsync, (long)v14);
	syscall(SYS_truncate, (long)v15, 6627);
	syscall(SYS_readlink, (long)v31, (long)v1, 8192);
	syscall(SYS_access, (long)v9, 4);
	syscall(SYS_access, (long)v17, 0);
	syscall(SYS_access, (long)v5, 4);
	syscall(SYS_rmdir, (long)v36);
	syscall(SYS_newstat, (long)v30, (long)v1);
	syscall(SYS_fallocate, (long)v14, 65, 2038, 3689);
[    0.031459] BTRFS critical (device vda): corrupt leaf: root=5 block=29376512 slot=17, bad key order, prev (18446744073709551606 128 12619776) current (266 12 258)
[    0.031467] BTRFS info (device vda): leaf 29376512 gen 9 total ptrs 42 free space 21 owner 5
[    0.031470] BTRFS info (device vda): refs 4 lock (w:1 r:0 bw:1 br:0 sw:0 sr:0) lock_owner 13 current 13
[    0.031484] 	item 0 key (259 108 0) itemoff 3962 itemsize 33
[    0.031488] 		inline extent data size 12
[    0.031492] 	item 1 key (261 1 0) itemoff 3802 itemsize 160
[    0.031496] 		inode generation 7 size 0 mode 100644
[    0.031499] 	item 2 key (261 12 258) itemoff 3789 itemsize 13
[    0.031503] 	item 3 key (261 24 2038346239) itemoff 3692 itemsize 97
[    0.031507] 	item 4 key (262 1 0) itemoff 3532 itemsize 160
[    0.031511] 		inode generation 7 size 4 mode 100644
[    0.031515] 	item 5 key (262 12 258) itemoff 3516 itemsize 16
[    0.031518] 	item 6 key (262 108 0) itemoff 3491 itemsize 25
[    0.031522] 		inline extent data size 4
[    0.031526] 	item 7 key (263 1 0) itemoff 3331 itemsize 160
[    0.031529] 		inode generation 7 size 0 mode 10644
[    0.031533] 	item 8 key (263 12 258) itemoff 3317 itemsize 14
[    0.031537] 	item 9 key (263 12 276) itemoff 3299 itemsize 18
[    0.031540] 	item 10 key (265 1 0) itemoff 3139 itemsize 160
[    0.031544] 		inode generation 9 size 13569 mode 100644
[    0.031547] 	item 11 key (265 12 257) itemoff 3121 itemsize 18
[    0.031551] 	item 12 key (265 108 0) itemoff 3068 itemsize 53
[    0.031554] 		extent data disk bytenr 12619776 nr 4096
[    0.031558] 		extent data offset 0 nr 4096 ram 4096
[    0.031562] 	item 13 key (265 108 4096) itemoff 3015 itemsize 53
[    0.031565] 		extent data disk bytenr 0 nr 0
[    0.031569] 		extent data offset 0 nr 4096 ram 12288
[    0.031575] 	item 14 key (265 108 8192) itemoff 2962 itemsize 53
[    0.031579] 		extent data disk bytenr 12623872 nr 8192
[    0.031582] 		extent data offset 0 nr 8192 ram 8192
[    0.031586] 	item 15 key (266 1 0) itemoff 2802 itemsize 160
[    0.031589] 		inode generation 9 size 1 mode 120777
[    0.031594] 	item 16 key (18446744073709551606 128 12619776) itemoff 2790 itemsize 12
[    0.031597] 	item 17 key (266 12 258) itemoff 2772 itemsize 18
[    0.031601] 	item 18 key (266 108 0) itemoff 2750 itemsize 22
[    0.031605] 		inline extent data size 1
[    0.031608] 	item 19 key (267 1 0) itemoff 2590 itemsize 160
[    0.031612] 		inode generation 9 size 12 mode 120777
[    0.031614] 	item 20 key (267 12 258) itemoff 2572 itemsize 18
[    0.031617] 	item 21 key (267 108 0) itemoff 2539 itemsize 33
[    0.031619] 		inline extent data size 12
[    0.031622] 	item 22 key (268 1 0) itemoff 2379 itemsize 160
[    0.031625] 		inode generation 9 size 11 mode 120777
[    0.031629] 	item 23 key (268 12 257) itemoff 2361 itemsize 18
[    0.031633] 	item 24 key (268 108 0) itemoff 2329 itemsize 32
[    0.031637] 		inline extent data size 11
[    0.031641] 	item 25 key (270 1 0) itemoff 2169 itemsize 160
[    0.031644] 		inode generation 9 size 11 mode 120777
[    0.031649] 	item 26 key (270 12 256) itemoff 2151 itemsize 18
[    0.031652] 	item 27 key (270 108 0) itemoff 2119 itemsize 32
[    0.031656] 		inline extent data size 11
[    0.031660] 	item 28 key (271 1 0) itemoff 1959 itemsize 160
[    0.031662] 		inode generation 9 size 14 mode 120777
[    0.031664] 	item 29 key (271 12 256) itemoff 1941 itemsize 18
[    0.031667] 	item 30 key (271 108 0) itemoff 1906 itemsize 35
[    0.031669] 		inline extent data size 14
[    0.031673] 	item 31 key (272 1 0) itemoff 1746 itemsize 160
[    0.031676] 		inode generation 9 size 11 mode 120777
[    0.031681] 	item 32 key (272 12 257) itemoff 1728 itemsize 18
[    0.031684] 	item 33 key (272 108 0) itemoff 1696 itemsize 32
[    0.031687] 		inline extent data size 11
[    0.031691] 	item 34 key (273 1 0) itemoff 1536 itemsize 160
[    0.031696] 		inode generation 9 size 16 mode 42755
[    0.031701] 	item 35 key (273 12 258) itemoff 1518 itemsize 18
[    0.031704] 	item 36 key (273 84 3486671785) itemoff 1480 itemsize 38
[    0.031708] 		dir oid 276 type 2
[    0.031711] 	item 37 key (273 96 2) itemoff 1442 itemsize 38
[    0.031714] 	item 38 key (274 1 0) itemoff 1282 itemsize 160
[    0.031716] 		inode generation 9 size 12 mode 120777
[    0.031720] 	item 39 key (274 12 258) itemoff 1264 itemsize 18
[    0.031724] 	item 40 key (274 108 0) itemoff 1231 itemsize 33
[    0.031728] 		inline extent data size 12
[    0.031732] 	item 41 key (276 1 0) itemoff 1071 itemsize 160
[    0.031735] 		inode generation 9 size 0 mode 42755
[    0.031739] assertion failed: 0, file: fs/btrfs/disk-io.c, line: 4109
[    0.031742] BUG: failure at fs/btrfs/ctree.h:3500/assfail()!
[    0.031746] Kernel panic - not syncing: BUG!
[    0.031749] Call Trace:
[    0.031758] (____ptrval____):  [<5564872af291>] vscnprintf+0x11/0x40
[    0.031765] (____ptrval____):  [<556486f45f84>] text.37815+0xb4/0x210
[    0.031769] (____ptrval____):  [<556486f6f62a>] vprintk_default+0x1a/0x20
[    0.031775] (____ptrval____):  [<55648706d955>] btrfs_mark_buffer_dirty+0x2c5/0x2d0
[    0.031781] (____ptrval____):  [<55648702641e>] __push_leaf_left+0xc9e/0xfe0
[    0.031785] (____ptrval____):  [<5564870182aa>] push_leaf_left+0x3ba/0x3e0
[    0.031791] (____ptrval____):  [<5564870ceb6b>] btrfs_get_token_32+0x1db/0x340
[    0.031795] (____ptrval____):  [<556487011521>] split_leaf+0x341/0xe20
[    0.031799] (____ptrval____):  [<5564870114d0>] split_leaf+0x2f0/0xe20
[    0.031804] (____ptrval____):  [<55648701499f>] leaf_space_used+0x12f/0x1e0
[    0.031810] (____ptrval____):  [<556486f41c56>] arch_local_irq_restore+0x46/0x60
[    0.031814] (____ptrval____):  [<55648700fbe1>] btrfs_search_slot+0x1af1/0x1f70
[    0.031820] (____ptrval____):  [<556487016edb>] btrfs_insert_empty_items+0x39b/0x500
[    0.031825] (____ptrval____):  [<5564871874c2>] btrfs_commit_inode_delayed_items+0x252/0x1650
[    0.031829] (____ptrval____):  [<5564870ed0aa>] read_extent_buffer+0x18a/0x280
[    0.031833] (____ptrval____):  [<556486f41c56>] arch_local_irq_restore+0x46/0x60
[    0.031837] (____ptrval____):  [<5564870eb500>] release_extent_buffer+0xa0/0x2e0
[    0.031842] (____ptrval____):  [<556486f6543c>] .L.str.17+0xc/0x37
[    0.031847] (____ptrval____):  [<556486faf379>] kmem_cache_alloc+0x179/0x190
[    0.031852] (____ptrval____):  [<55648713f463>] btrfs_log_inode+0x3c3/0x4130
[    0.031856] (____ptrval____):  [<5564870ed0aa>] read_extent_buffer+0x18a/0x280
[    0.031860] (____ptrval____):  [<55648706c85a>] btree_read_extent_buffer_pages+0x13a/0x5e0
[    0.031864] (____ptrval____):  [<556486f41c56>] arch_local_irq_restore+0x46/0x60
[    0.031868] (____ptrval____):  [<556486fcd878>] __iget+0x28/0x30
[    0.031872] (____ptrval____):  [<556486f6543c>] .L.str.17+0xc/0x37
[    0.031877] (____ptrval____):  [<556486f6554e>] .L.str.26+0x0/0x12
[    0.031880] (____ptrval____):  [<5564870a5d30>] btrfs_find_actor+0x0/0xb0
[    0.031884] (____ptrval____):  [<556486fcf0cc>] ilookup5+0x5c/0xc0
[    0.031888] (____ptrval____):  [<5564870a5d30>] btrfs_find_actor+0x0/0xb0
[    0.031893] (____ptrval____):  [<556487097df6>] btrfs_iget_path+0xb6/0xf10
[    0.031897] (____ptrval____):  [<556486f41c56>] arch_local_irq_restore+0x46/0x60
[    0.031902] (____ptrval____):  [<556487143896>] log_new_dir_dentries+0x6c6/0xce0
[    0.031906] (____ptrval____):  [<556487143682>] log_new_dir_dentries+0x4b2/0xce0
[    0.031911] (____ptrval____):  [<55648713b9b2>] btrfs_log_inode_parent+0x1752/0x18d0
[    0.031915] (____ptrval____):  [<556486f9a127>] pagevec_lookup_range_tag+0x27/0x40
[    0.031919] (____ptrval____):  [<5564870ad980>] btrfs_permission+0x0/0x160
[    0.031923] (____ptrval____):  [<556486f88b47>] __filemap_fdatawait_range+0x87/0x140
[    0.031927] (____ptrval____):  [<556486f6543c>] .L.str.17+0xc/0x37
[    0.031932] (____ptrval____):  [<55648713a240>] btrfs_log_dentry_safe+0x80/0xa0
[    0.031936] (____ptrval____):  [<5564870be059>] btrfs_sync_file+0x4f9/0x820
[    0.031940] (____ptrval____):  [<556486f41c56>] arch_local_irq_restore+0x46/0x60
[    0.031944] (____ptrval____):  [<556486fe21b0>] vfs_fsync_range+0x40/0x80
[    0.031947] 
[    0.031952] ---[ end Kernel panic - not syncing: BUG! ]---
btrfs-combined: lib/posix-host.c:302: panic: Assertion `0' failed.


[VM]
- Reproduces
gcc poc_01.c
mkdir test
mount -t btrfs tmp.img test
cp a.out test
cd test
sudo ./a.out
umount test
dmesg

- Kernel messages
[   19.210672] BTRFS: device fsid a62e00e8-e94e-4200-8217-12444de93c2e devid 1 transid 8 /dev/sdb
[   40.878479] cc1 (1892) used greatest stack depth: 13240 bytes left
[  102.888441] BTRFS info (device sdb): disk space caching is enabled
[  102.888442] BTRFS info (device sdb): has skinny extents
[  102.889564] BTRFS critical (device sdb): corrupt leaf: root=1 block=29417472 slot=7, bad key order, prev (7205759403792793606 84 2378154706) current (7 132 0)
[  102.892462] BTRFS info (device sdb): read error corrected: ino 0 off 29417472 (dev /dev/sdb sector 73840)
[  102.894292] BTRFS critical (device sdb): corrupt leaf: root=5 block=29409280 slot=26 ino=259 file_offset=0, invalid ram_bytes for uncompressed inline extent, have 33 expect 262177
[  102.897479] BTRFS info (device sdb): read error corrected: ino 0 off 29409280 (dev /dev/sdb sector 73824)
[  114.120614] ------------[ cut here ]------------
[  114.120616] BTRFS: Transaction aborted (error -17)
[  114.120639] WARNING: CPU: 0 PID: 1931 at fs/btrfs/extent-tree.c:3011 btrfs_run_delayed_refs+0x14b/0x180
[  114.120640] Modules linked in:
[  114.120642] CPU: 0 PID: 1931 Comm: umount Not tainted 5.0.0 #11
[  114.120643] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[  114.120645] RIP: 0010:btrfs_run_delayed_refs+0x14b/0x180
[  114.120647] Code: 5e 41 5f c3 48 8b 53 50 3e 48 0f ba aa c0 0c 00 00 02 72 1b 83 f8 fb 74 16 89 c6 48 c7 c7 88 9e e3 9e 89 04 24 e8 65 8b d3 ff <0f> 0b 8b 04 24 89 c1 ba c3 0b 00 00 48 c7 c6 e0 5e c4 9e 48 89 df
[  114.120648] RSP: 0018:ffffa62c80d13d08 EFLAGS: 00010282
[  114.120649] RAX: 0000000000000000 RBX: ffff92c1ef3306e8 RCX: 0000000000000006
[  114.120650] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff92c1f7a15410
[  114.120651] RBP: ffff92c1eb50f400 R08: 0000000000008268 R09: ffffffff9f727614
[  114.120651] R10: ffffcced88af9800 R11: 00000000000001c7 R12: ffff92c1f63f4158
[  114.120652] R13: ffffffffffffffff R14: ffff92c1f63f4140 R15: ffff92c1f63f41a0
[  114.120654] FS:  00007f6ed9cfb840(0000) GS:ffff92c1f7a00000(0000) knlGS:0000000000000000
[  114.120657] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  114.120658] CR2: 000055b8180a1120 CR3: 0000000231946001 CR4: 00000000001606f0
[  114.120659] Call Trace:
[  114.120674]  commit_cowonly_roots+0xa1/0x2b0
[  114.120678]  ? btrfs_qgroup_account_extents+0xf5/0x230
[  114.120680]  btrfs_commit_transaction+0x356/0x970
[  114.120682]  close_ctree+0x2dd/0x360
[  114.120687]  generic_shutdown_super+0x62/0x110
[  114.120690]  kill_anon_super+0x9/0x20
[  114.120694]  btrfs_kill_super+0xd/0x90
[  114.120697]  deactivate_locked_super+0x35/0x60
[  114.120700]  cleanup_mnt+0x36/0x70
[  114.120705]  task_work_run+0x75/0x90
[  114.120708]  exit_to_usermode_loop+0x93/0xa0
[  114.120710]  do_syscall_64+0xba/0xf0
[  114.120715]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  114.120716] RIP: 0033:0x7f6ed95da487
[  114.120718] Code: 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 31 f6 e9 09 00 00 00 66 0f 1f 84 00 00 00 00 00 b8 a6 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e1 c9 2b 00 f7 d8 64 89 01 48
[  114.120719] RSP: 002b:00007ffcf03aa7e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
[  114.120720] RAX: 0000000000000000 RBX: 00000000017cd050 RCX: 00007f6ed95da487
[  114.120721] RDX: 0000000000000001 RSI: 0000000000000000 RDI: 00000000017d11f0
[  114.120722] RBP: 00000000017d11f0 R08: 0000000000000000 R09: 0000000000000015
[  114.120722] R10: 00000000000006b2 R11: 0000000000000246 R12: 00007f6ed9ae383c
[  114.120723] R13: 0000000000000000 R14: 00000000017cd230 R15: 00007ffcf03aaa70
[  114.120724] ---[ end trace edabf8b94e771465 ]---
[  114.120726] BTRFS: error (device sdb) in btrfs_run_delayed_refs:3011: errno=-17 Object already exists
[  114.122275] BTRFS info (device sdb): forced readonly
[  114.122277] BTRFS warning (device sdb): Skipping commit of aborted transaction.
[  114.122279] BTRFS: error (device sdb) in cleanup_transaction:1831: errno=-17 Object already exists
[  114.124399] BTRFS error (device sdb): commit super ret -17
Comment 1 Qu Wenruo 2019-07-16 04:45:32 UTC
This BUG_ON() is triggered when tree block get modified with CONFIG_BTRFS_FS_CHECK_INTEGRITY.

The check is only done with that config, and is designed to info developer that some of its code is screwing up tree key order at runtime.

Since the BUG_ON() itself is only for developer and it's designed to work, so it won't be removed.

The root cause looks like it's some cross leaf corruption, which can be addressed by this patch:
[PATCH 5/5] btrfs: ctree: Checking key orders before merged tree blocks

Thanks,
Qu
Comment 2 Viney Bhatia 2020-03-09 09:47:14 UTC Comment hidden (spam)

Note You need to log in before you can comment on or make changes to this bug.