Bug 217138
Summary: | [xfstests] XFS: Assertion failed: xfs_bmap_validate_extent(ip, whichfork, &rec) == NULL, file: fs/xfs/libxfs/xfs_inode_fork.c, line: 557 | ||
---|---|---|---|
Product: | File System | Reporter: | Zorro Lang (zlang) |
Component: | XFS | Assignee: | FileSystem/XFS Default Virtual Assignee (filesystem_xfs) |
Status: | NEW --- | ||
Severity: | normal | ||
Priority: | P1 | ||
Hardware: | All | ||
OS: | Linux | ||
Kernel Version: | v6.3-rc0 | Subsystem: | |
Regression: | No | Bisected commit-id: | |
Attachments: | console.log |
Description
Zorro Lang
2023-03-05 06:21:02 UTC
[ 854.173089] run fstests generic/270 at 2023-03-12 13:58:29 [ 856.833887] memfd_create() without MFD_EXEC nor MFD_NOEXEC_SEAL, pid=110193 'systemd' [ 849.010141] restraintd[2857]: *** Current Time: Sun Mar 12 13:58:32 2023 Localwatchdog at: Tue Mar 14 13:47:32 2023 [ 857.976080] XFS (pmem0): DAX enabled. Warning: EXPERIMENTAL, use at your own risk [ 857.985038] XFS (pmem0): Mounting V5 Filesystem e50966df-cb79-4d0c-9600-17be31022868 [ 858.005751] XFS (pmem0): Ending clean mount [ 858.012146] XFS (pmem0): Quotacheck needed: Please wait. [ 858.025572] XFS (pmem0): Quotacheck: Done. [ 865.178004] XFS: Assertion failed: xfs_bmap_validate_extent(ip, whichfork, &rec) == NULL, file: fs/xfs/libxfs/xfs_inode_fork.c, line: 559 [ 865.190634] ------------[ cut here ]------------ [ 865.195296] WARNING: CPU: 39 PID: 110331 at fs/xfs/xfs_message.c:104 assfail+0x54/0x70 [xfs] [ 865.204026] Modules linked in: loop rfkill intel_rapl_msr intel_rapl_common intel_uncore_frequency intel_uncore_frequency_common ipmi_ssif i10nm_edac nfit x86_pkg_temp_thermal intel_powerclamp coretemp mlx5_ib mgag200 i2c_algo_bit drm_shmem_helper ib_uverbs dell_smbios drm_kms_helper kvm_intel iTCO_wdt iTCO_vendor_support sunrpc dcdbas kvm irqbypass rapl intel_cstate acpi_ipmi ib_core intel_uncore ipmi_si dax_pmem nd_pmem syscopyarea wmi_bmof dell_wmi_descriptor pcspkr dax_hmem isst_if_mbox_pci mei_me i2c_i801 ipmi_devintf sysfillrect isst_if_mmio mei sysimgblt isst_if_common i2c_smbus intel_vsec ipmi_msghandler acpi_power_meter drm fuse xfs libcrc32c sd_mod t10_pi sg mlx5_core crct10dif_pclmul crc32_pclmul crc32c_intel mlxfw ahci libahci tls ghash_clmulni_intel psample megaraid_sas tg3 libata pci_hyperv_intf wmi dm_mirror dm_region_hash dm_log dm_mod [ 865.279707] CPU: 39 PID: 110331 Comm: 110035.fsstress Kdump: loaded Not tainted 6.3.0-rc1+ #1 [ 865.288254] Hardware name: Dell Inc. PowerEdge R750/0PJ80M, BIOS 1.5.4 12/17/2021 [ 865.295761] RIP: 0010:assfail+0x54/0x70 [xfs] [ 865.300361] Code: c1 48 ba 00 00 00 00 00 fc ff df 48 89 c1 83 e0 07 48 c1 e9 03 0f b6 14 11 38 c2 7f 04 84 d2 75 10 80 3d fe 16 2f 00 00 75 15 <0f> 0b c3 cc cc cc cc 48 c7 c7 10 46 9c c1 e8 89 ac ff d4 eb e2 0f [ 865.319133] RSP: 0018:ffa0000038f6efc8 EFLAGS: 00010246 [ 865.324384] RAX: 0000000000000000 RBX: ffa0000038f6f050 RCX: 1ffffffff83388c2 [ 865.331544] RDX: 0000000000000004 RSI: ffa0000038f6ed30 RDI: ffffffffc1820a00 [ 865.338700] RBP: ff11000723a9c040 R08: 00000000ffffffea R09: ffa0000038f6ecd7 [ 865.345867] R10: fff3fc00071edd9a R11: 0000000000000001 R12: ff11000723a9c000 [ 865.353018] R13: ffa0000038f6f030 R14: ff1100108dee11c8 R15: 0000000000000000 [ 865.360178] FS: 00007fdd43d29740(0000) GS:ff11002035c00000(0000) knlGS:0000000000000000 [ 865.368288] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 865.374062] CR2: 0000000000d50538 CR3: 00000006b3594003 CR4: 0000000000771ee0 [ 865.381223] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 865.388380] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 865.395538] PKRU: 55555554 [ 865.398285] Call Trace: [ 865.400767] <TASK> [ 865.402899] xfs_iextents_copy+0x4ec/0x6e0 [xfs] [ 865.407746] ? xfs_bmap_validate_extent+0x1e3/0x2a0 [xfs] [ 865.413370] ? __pfx_xfs_iextents_copy+0x10/0x10 [xfs] [ 865.418747] ? xfs_inode_to_log_dinode+0x8d7/0x1370 [xfs] [ 865.424389] ? do_raw_spin_unlock+0x55/0x1f0 [ 865.428698] xfs_inode_item_format_data_fork+0x9c9/0x10f0 [xfs] [ 865.434864] xfs_inode_item_format+0x6b3/0xb40 [xfs] [ 865.440079] ? trace_contention_end+0x177/0x1f0 [ 865.444645] ? __pfx_xfs_inode_item_format+0x10/0x10 [xfs] [ 865.450386] xlog_cil_insert_format_items+0x2b2/0x5f0 [xfs] [ 865.456206] xlog_cil_insert_items+0xe2/0x1060 [xfs] [ 865.461429] ? __lock_acquired+0x209/0x830 [ 865.465566] ? __pfx___lock_acquired+0x10/0x10 [ 865.470037] ? __pfx___down_read_trylock+0x10/0x10 [ 865.474864] ? __pfx_xlog_cil_insert_items+0x10/0x10 [xfs] [ 865.480600] ? xlog_cil_commit+0x59/0x690 [xfs] [ 865.485373] xlog_cil_commit+0xa3/0x690 [xfs] [ 865.489981] __xfs_trans_commit+0x8c3/0xec0 [xfs] [ 865.494936] ? __pfx___xfs_trans_commit+0x10/0x10 [xfs] [ 865.500395] ? __pfx_xfs_trans_alloc_inode+0x10/0x10 [xfs] [ 865.506131] xfs_iomap_write_direct+0x362/0x630 [xfs] [ 865.511439] ? __pfx_xfs_iomap_write_direct+0x10/0x10 [xfs] [ 865.517253] ? xfs_direct_write_iomap_begin+0x8ad/0xd80 [xfs] [ 865.523249] ? rcu_read_lock_sched_held+0x43/0x80 [ 865.527996] xfs_direct_write_iomap_begin+0x8d6/0xd80 [xfs] [ 865.533812] ? slab_free_freelist_hook+0x11d/0x1d0 [ 865.538639] ? __pfx_xfs_direct_write_iomap_begin+0x10/0x10 [xfs] [ 865.544960] ? __xfs_trans_commit+0x8cd/0xec0 [xfs] [ 865.550074] ? kmem_cache_free+0xf9/0x3c0 [ 865.554161] ? __pfx_xfs_direct_write_iomap_begin+0x10/0x10 [xfs] [ 865.560496] iomap_iter+0x341/0xe40 [ 865.564037] dax_iomap_rw+0x216/0x3a0 [ 865.567735] ? __pfx_dax_iomap_rw+0x10/0x10 [ 865.571998] ? xfs_file_write_checks+0x4b6/0x960 [xfs] [ 865.577388] xfs_file_dax_write+0x278/0x9d0 [xfs] [ 865.582323] ? __pfx_xfs_file_dax_write+0x10/0x10 [xfs] [ 865.587770] ? __mutex_lock+0x741/0x1490 [ 865.591732] ? xfs_file_write_iter+0x236/0x6a0 [xfs] [ 865.596932] do_iter_readv_writev+0x199/0x300 [ 865.601327] ? __pfx_do_iter_readv_writev+0x10/0x10 [ 865.606248] ? selinux_file_permission+0x356/0x440 [ 865.611096] do_iter_write+0x11f/0x3b0 [ 865.614883] iter_file_splice_write+0x5a5/0xaf0 [ 865.619471] ? __pfx_iter_file_splice_write+0x10/0x10 [ 865.624548] ? lock_acquire+0x1d8/0x660 [ 865.628425] ? __pfx_lock_acquire+0x10/0x10 [ 865.632677] do_splice+0x3d9/0xcc0 [ 865.636117] ? __pfx_do_splice+0x10/0x10 [ 865.640077] ? __might_fault+0xbc/0x160 [ 865.643958] __do_splice+0x102/0x1d0 [ 865.647574] ? __pfx___do_splice+0x10/0x10 [ 865.651721] __x64_sys_splice+0x151/0x210 [ 865.655778] do_syscall_64+0x59/0x90 [ 865.659399] ? do_syscall_64+0x69/0x90 [ 865.663175] ? lockdep_hardirqs_on+0x79/0x100 [ 865.667565] ? do_syscall_64+0x69/0x90 [ 865.671346] ? do_syscall_64+0x69/0x90 [ 865.675133] ? do_syscall_64+0x69/0x90 [ 865.678914] ? do_syscall_64+0x69/0x90 [ 865.682692] ? lockdep_hardirqs_on+0x79/0x100 [ 865.687081] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 865.692166] RIP: 0033:0x7fdd43b4ec8a [ 865.695772] Code: d8 64 89 02 48 c7 c0 ff ff ff ff eb b9 0f 1f 00 f3 0f 1e fa 49 89 ca 64 8b 04 25 18 00 00 00 85 c0 75 15 b8 13 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 7e c3 0f 1f 44 00 00 41 54 48 83 ec 30 44 89 [ 865.714543] RSP: 002b:00007fff2a17aa78 EFLAGS: 00000246 ORIG_RAX: 0000000000000113 [ 865.722144] RAX: ffffffffffffffda RBX: 0000000000010000 RCX: 00007fdd43b4ec8a [ 865.729303] RDX: 0000000000000005 RSI: 0000000000000000 RDI: 0000000000000006 [ 865.736461] RBP: 0000000000000005 R08: 0000000000010000 R09: 0000000000000000 [ 865.743624] R10: 00007fff2a17aac0 R11: 0000000000000246 R12: 0000000000010000 [ 865.750788] R13: 0000000000000004 R14: 000000000001e468 R15: 0000000000000000 [ 865.757977] </TASK> [ 865.760199] irq event stamp: 305803 [ 865.763717] hardirqs last enabled at (305813): [<ffffffff95ffacab>] __up_console_sem+0x6b/0x80 [ 865.772436] hardirqs last disabled at (305822): [<ffffffff95ffac90>] __up_console_sem+0x50/0x80 [ 865.781154] softirqs last enabled at (305770): [<ffffffff982eb156>] __do_softirq+0x616/0x9c7 [ 865.789699] softirqs last disabled at (305765): [<ffffffff95e48ff6>] __irq_exit_rcu+0x136/0x2a0 [ 865.798421] ---[ end trace 0000000000000000 ]--- # Get the debug information which asked by Darrick: [ 865.803066] XFS (pmem0): bmbt_rec: startoff=11594, startblock=11594, blockcount=0, state=0x0....validation returned addr 0x00000000d67d9cc8 [ 865.803066] Still can reproduce this issue on linux v6.3-rc2+. Besides pmem device, I hit this issue on 64k pagesize aarch64 [1] machine too. [1] FSTYP -- xfs (debug) PLATFORM -- Linux/aarch64 ampere-mtsnow-altramax-49 6.3.0-rc2+ #1 SMP PREEMPT_DYNAMIC Sat Mar 18 04:48:48 EDT 2023 MKFS_OPTIONS -- -f -b size=65536 -m crc=1,finobt=1,reflink=1,rmapbt=0,bigtime=1,inobtcount=1 /dev/nvme0n1p4 MOUNT_OPTIONS -- -o context=system_u:object_r:root_t:s0 /dev/nvme0n1p4 /mnt/xfstests/scratch generic/650 _check_xfs_filesystem: filesystem on /dev/nvme0n1p5 has dirty log (see /var/lib/xfstests/results//generic/650.full for details) ./common/xfs: line 715: 514331 Segmentation fault (core dumped) $XFS_REPAIR_PROG -n $extra_options $extra_log_options $extra_rt_options $device > $tmp.repair 2>&1 _check_xfs_filesystem: filesystem on /dev/nvme0n1p5 is inconsistent (r) (see /var/lib/xfstests/results//generic/650.full for details) _check_dmesg: something found in dmesg (see /var/lib/xfstests/results//generic/650.dmesg) - output mismatch (see /var/lib/xfstests/results//generic/650.out.bad) --- tests/generic/650.out 2023-03-18 05:05:09.431268800 -0400 +++ /var/lib/xfstests/results//generic/650.out.bad 2023-03-18 09:26:13.099142159 -0400 @@ -1,2 +1,259 @@ QA output created by 650 Silence is golden. +fsstress: check_cwd stat64() returned -1 with errno: 5 (Input/output error) +fsstress: check_cwd stat64() returned -1 with errno: 5 (Input/output error) +fsstress: check_cwd stat64() returned -1 with errno: 5 (Input/output error) +fsstress: check_cwd failure +fsstress: check_cwd failure ... (Run 'diff -u /var/lib/xfstests/tests/generic/650.out /var/lib/xfstests/results//generic/650.out.bad' to see the entire diff) Ran: generic/650 Failures: generic/650 Failed 1 of 1 tests [16046.257289] XFS: Assertion failed: xfs_bmap_validate_extent(ip, whichfork, &rec) == NULL, file: fs/xfs/libxfs/xfs_inode_fork.c, line: 557 [16046.269683] ------------[ cut here ]------------ [16046.274289] WARNING: CPU: 109 PID: 514058 at fs/xfs/xfs_message.c:104 assfail+0x6c/0x90 [xfs] [16046.282946] Modules linked in: overlay dm_zero dm_log_writes dm_thin_pool dm_persistent_data dm_bio_prison sg dm_snapshot dm_bufio ext4 mbcache jbd2 loop dm_flakey dm_mod tls rfkill sunrpc vfat fat ast acpi_ipmi drm_shmem_helper ipmi_ssif drm_kms_helper arm_spe_pmu syscopyarea sysfillrect sysimgblt ipmi_devintf ipmi_msghandler arm_dmc620_pmu arm_cmn cppc_cpufreq arm_dsu_pmu drm fuse xfs libcrc32c crct10dif_ce nvme ghash_ce nvme_core sha2_ce sha256_arm64 sha1_ce sbsa_gwdt nvme_common igb i2c_designware_platform i2c_algo_bit i2c_designware_core xgene_hwmon [last unloaded: scsi_debug] [16046.334506] CPU: 109 PID: 514058 Comm: kworker/u256:10 Kdump: loaded Tainted: G W I 6.3.0-rc2+ #1 [16046.344582] Hardware name: GIGABYTE R152-P31-00/MP32-AR1-00, BIOS F31n (SCP: 2.10.20220810) 09/30/2022 [16046.353876] Workqueue: writeback wb_workfn (flush-259:0) [16046.359181] pstate: 80400009 (Nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--) [16046.366131] pc : assfail+0x6c/0x90 [xfs] [16046.370182] lr : assfail+0x38/0x90 [xfs] [16046.374233] sp : ffff80005206e550 [16046.377535] x29: ffff80005206e550 x28: ffffad52485aae74 x27: 0000000000000000 [16046.384663] x26: ffff080524799ac0 x25: 0000000000000050 x24: ffff08070f1101d8 [16046.391790] x23: ffff80005206e630 x22: ffffad527672f9e0 x21: ffff080524799b00 [16046.398917] x20: dfff800000000000 x19: ffff80005206e650 x18: ffff80005206e4e8 [16046.406043] x17: 26202c6b726f6668 x16: ffffad52735e1340 x15: 28746e657478655f [16046.413170] x14: 65746164696c6176 x13: 0000000000000001 x12: ffff70000a40dc2b [16046.420297] x11: 1ffff0000a40dc2a x10: ffff70000a40dc2a x9 : ffffad52729aab58 [16046.427423] x8 : 0000000041b58ab3 x7 : 00000000f1f1f1f1 x6 : 00000000ffffffc0 [16046.434550] x5 : 0000000000000021 x4 : 00000000ffffffca x3 : 1ffff5aa490ee736 [16046.441677] x2 : 0000000000000000 x1 : 0000000000000004 x0 : 0000000000000000 [16046.448803] Call trace: [16046.451238] assfail+0x6c/0x90 [xfs] [16046.454942] xfs_iextents_copy+0x480/0x670 [xfs] [16046.459688] xfs_inode_item_format_data_fork+0x544/0x9b0 [xfs] [16046.465649] xfs_inode_item_format+0x614/0x970 [xfs] [16046.470741] xlog_cil_insert_format_items.constprop.0+0x1f8/0x478 [xfs] [16046.477483] xlog_cil_insert_items+0xd4/0xee0 [xfs] [16046.482488] xlog_cil_commit+0xa4/0x600 [xfs] [16046.486973] __xfs_trans_commit+0x7e8/0xe18 [xfs] [16046.491804] xfs_trans_commit+0x18/0x28 [xfs] [16046.496288] xfs_bmapi_convert_delalloc+0x848/0xa68 [xfs] [16046.501815] xfs_map_blocks+0x4a0/0xfb0 [xfs] [16046.506300] iomap_writepage_map+0x258/0xb20 [16046.510560] iomap_do_writepage+0x308/0x698 [16046.514733] write_cache_pages+0x35c/0xac0 [16046.518819] iomap_writepages+0x4c/0xc0 [16046.522644] xfs_vm_writepages+0x124/0x198 [xfs] [16046.527389] do_writepages+0x148/0x4e0 [16046.531127] __writeback_single_inode+0x140/0xc50 [16046.535821] writeback_sb_inodes+0x3c8/0xbe8 [16046.540079] wb_writeback+0x2bc/0xc08 [16046.543731] wb_do_writeback+0x220/0x928 [16046.547643] wb_workfn+0x13c/0x630 [16046.551034] process_one_work+0x798/0x1660 [16046.555120] worker_thread+0x3cc/0xc38 [16046.558859] kthread+0x238/0x2a0 [16046.562077] ret_from_fork+0x10/0x20 [16046.565642] irq event stamp: 0 [16046.568685] hardirqs last enabled at (0): [<0000000000000000>] 0x0 [16046.574941] hardirqs last disabled at (0): [<ffffad5272816968>] copy_process+0x1118/0x3fe8 [16046.583193] softirqs last enabled at (0): [<ffffad527281699c>] copy_process+0x114c/0x3fe8 [16046.591445] softirqs last disabled at (0): [<0000000000000000>] 0x0 [16046.597700] ---[ end trace 0000000000000000 ]--- [16046.603400] XFS: Assertion failed: xfs_bmap_validate_extent(ip, whichfork, &rec) == NULL, file: fs/xfs/libxfs/xfs_inode_fork.c, line: 557 [16046.615925] ------------[ cut here ]------------ Thanks, Zorro |