PANIC: inode has invalid mode: 0x0

[gbsf]

System information

Type	Version/Name
Distribution Name	Archlinux
Distribution Version	rolling
Linux Kernel	5.10.6-arch1-1
Architecture	x86_64
ZFS Version	2.0.1-1
SPL Version	2.0.1-1

Describe the problem you're observing

A couple of days ago, a program (running under Wine, if it matters) either created a corrupted file or caused some system failure that made the file mode become 0.
Since those were only log files, I renamed the enclosing dir to stop the program from trying to access them.

Comparing with other log files created by the application, the correct mode for this file should be S_IFREG|S_ISVTX|0777.
It is stored under a directory with mode S_IFDIR|S_ISUID|S_ISGID|S_ISVTX|0777 and everything is owned by my user.

The pool is backed by a single SATA SSD. I already ran a scrub but no errors were reported.

Describe how to reproduce the problem

I couldn't find a way to reproduce the creation of such corrupted files, but any attempt to access the existing ones will hang with a kernel panic.

Include any warning/errors/backtraces from the system logs

PANIC: inode 716430 has invalid mode: 0x0
Showing stack for process 30162
CPU: 0 PID: 30162 Comm: tree Tainted: P           OE     5.10.6-arch1-1 #1
Hardware name: LENOVO 20217/VIQY0Y1, BIOS 74CN47WW(V3.08) 1/30/2015
Call Trace:
 dump_stack+0x6b/0x83
 vcmn_err.cold+0x58/0x80 [spl]
 zfs_panic_recover+0x75/0x90 [zfs]
 zfs_znode_alloc+0x6d8/0x740 [zfs]
 zfs_zget+0x270/0x2b0 [zfs]
 zfs_dirent_lock+0x36c/0x6c0 [zfs]
 zfs_dirlook+0xad/0x2d0 [zfs]
 ? zfs_zaccess+0x127/0x490 [zfs]
 zfs_lookup+0x1e6/0x3d0 [zfs]
 zpl_lookup+0xf2/0x210 [zfs]
 ? step_into+0xd3/0x700
 __lookup_slow+0x85/0x140
 walk_component+0x141/0x1b0
 path_lookupat+0x5b/0x190
 filename_lookup+0xbe/0x1d0
 vfs_statx+0x86/0x140
 __do_sys_newlstat+0x47/0x80
 do_syscall_64+0x33/0x40
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7fcf46b6631a
Code: ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 f3 0f 1e fa 41 89 f8 48 89 f7 48 89 d6 41 83 f8 01 77 2d b8 06 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 06 c3 0f 1f 44 00 00 48 8b 15 21 1b 0d 00 f7
RSP: 002b:00007ffc141c4ec8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
RAX: ffffffffffffffda RBX: 0000000000000021 RCX: 00007fcf46b6631a
RDX: 00007ffc141c4f10 RSI: 00007ffc141c4f10 RDI: 000055b340320240
RBP: 00007ffc141c5050 R08: 0000000000000001 R09: 00007fcf46bfd0c0
R10: 00007fcf46bfcfc0 R11: 0000000000000246 R12: 000055b3402fc420
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000

[gbsf]

I did some more testing, and the file mode is only lost after a reboot.

[aerusso]

@gbsf I have a few questions, some of them very mundane, some of them might conceivably be dangerous to investigate:

1. Does smartctl tell you the drive is healthy?
2. Are you using ECC ram? Are you getting any ECC errors? Have you done a ram-test recently?
3. Can you snapshot the dataset? Can you zfs send the snapshot (without the panic)? Can you zfs receive that to another pool?
4. Just to be clear, when you stat the file, you get the panic? Can you mv it (same dataset) without the panic? What happens when you cat the file, or append to the file? (You might consider trying to snapshot and restore the dataset with the misbehaving file before doing this).
5. Did the problem go away by itself after you rebooted? If it resolved, what is the state of the file now?
6. Has the problem recurred?
7. If you can cat the file without error, what is cat $file | wc -c, and how does it compare to the size reported by ls?

[Arvedui]

I think I might have the same problem. The error message is the same, the stack trace is basically identical and the problematic file is a log file written by windows application running via wine. I am running archlinux too.

@aerusso

1. yes
2. no
3. yes and yes
4. yes, no and I cannot cat it
5. no it only appreared after reboot
6. not yet

[sdimitro]

Hey @gbsf, is this issue reproducible? If yes, would it be possible to capture a kernel crash dump from the system?

[Xaenalt]

Hey all, I seem to be able to reproduce the issue 100%, but I can't for the life of me figure out how to get it to generate a core dump... I get the panic and everything, but the dump seems to just disappear rather than be written, if someone could help me generate it I'd be happy to upload it

[gbsf]

Hey @gbsf, is this issue reproducible? If yes, would it be possible to capture a kernel crash dump from the system?

Yes, it is reproducible. I don't exactly understand what you mean by kernel crash dump, the panic backtrace is in the issue already. If you mean a memory dump from an affected system, I'm not really setup to capture those. Either way, since the panic is only a symptom of the error, I don't think it'll be very useful. At that point, the inode is already corrupted.

But I managed to create a test case based on the operations Wine performs.
Steps to reproduce:

1. Run ./issue11474
2. Reboot
3. ls test_dir/test_file
4. Kernel panic, ls is hung forever.

issue11474.c.txt

[aerusso]

@gbsf Hey! Thanks for the reproducer! I'm using Debian 5.10.9, and I'm not able to reproduce any issue with your program.

Does this work on a new pool? I.e.,

truncate -s 512M ~/trash-file.loopdev
losetup loop0 ~/trash-file.loopdev
zpool create trashpool loop0

and then run it on that one?

Other facts: I'm on a virtual machine, using the "cloud image". I can try with 5.10.5 relatively easily, if you're able to reproduce on a clean pool.

[gbsf]

I can't seem to be able to reproduce this issue any more, even on the affected pool. @Arvedui, @Xaenalt, can you still reproduce this?

[Xaenalt]

I still have the file/directory in question around, yeah I can still reproduce it

[Xaenalt]

This is all the info I have from the crash, I still can't get it to write the vmcore out

[ 1952.002618] PANIC: inode 950970 has invalid mode: 0xbb22

[ 1952.002620] Showing stack for process 58662
[ 1952.002621] CPU: 2 PID: 58662 Comm: rsync Kdump: loaded Tainted: P           OE     5.10.10-200.fc33.x86_64 #1
[ 1952.002622] Hardware name: Gigabyte Technology Co., Ltd. Z370 AORUS Gaming 7/Z370 AORUS Gaming 7, BIOS F13 03/22/2019
[ 1952.002622] Call Trace:
[ 1952.002627]  dump_stack+0x6b/0x83
[ 1952.002632]  vcmn_err.cold+0x58/0x80 [spl]
[ 1952.002634]  ? kmem_cache_alloc+0xe7/0x1e0
[ 1952.002671]  ? sa_cache_constructor+0x23/0x40 [zfs]
[ 1952.002674]  ? spl_kmem_cache_alloc+0x9b/0x7a0 [spl]
[ 1952.002675]  ? _cond_resched+0x16/0x40
[ 1952.002676]  ? mutex_lock+0xe/0x30
[ 1952.002695]  ? dmu_buf_set_user_ie+0x55/0x80 [zfs]
[ 1952.002724]  zfs_panic_recover+0x5d/0x60 [zfs]
[ 1952.002754]  zfs_znode_alloc+0x658/0x6c0 [zfs]
[ 1952.002786]  zfs_zget+0x19e/0x230 [zfs]
[ 1952.002815]  zfs_dirent_lock+0x336/0x6c0 [zfs]
[ 1952.002845]  zfs_dirlook+0x75/0x280 [zfs]
[ 1952.002874]  ? zfs_zaccess+0x1aa/0x450 [zfs]
[ 1952.002902]  zfs_lookup+0x1b4/0x3a0 [zfs]
[ 1952.002930]  zpl_lookup+0xa1/0x1e0 [zfs]
[ 1952.002931]  ? _cond_resched+0x16/0x40
[ 1952.002933]  __lookup_slow+0x74/0x130
[ 1952.002934]  walk_component+0x11b/0x190
[ 1952.002935]  ? _cond_resched+0x16/0x40
[ 1952.002936]  path_lookupat+0x72/0x1c0
[ 1952.002937]  filename_lookup+0x97/0x180
[ 1952.002940]  ? strncpy_from_user+0x85/0x1a0
[ 1952.002941]  ? getname_flags.part.0+0x45/0x1a0
[ 1952.002942]  vfs_statx+0x64/0x100
[ 1952.002943]  __do_sys_newlstat+0x26/0x40
[ 1952.002944]  ? iterate_dir+0xfe/0x1b0
[ 1952.002946]  ? switch_fpu_return+0x40/0xb0
[ 1952.002947]  ? exit_to_user_mode_prepare+0x64/0x140
[ 1952.002949]  do_syscall_64+0x33/0x40
[ 1952.002951]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1952.002952] RIP: 0033:0x7f0b2e24664a
[ 1952.002953] Code: ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 f3 0f 1e fa 41 89 f8 48 89 f7 48 89 d6 41 83 f8 01 77 2d b8 06 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 06 c3 0f 1f 44 00 00 48 8b 15 f9 27 0d 00 f7
[ 1952.002954] RSP: 002b:00007ffea6a4e908 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
[ 1952.002955] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f0b2e24664a
[ 1952.002956] RDX: 00007ffea6a4ea40 RSI: 00007ffea6a4ea40 RDI: 00007ffea6a4ead0
[ 1952.002956] RBP: 00007ffea6a4ead0 R08: 0000000000000001 R09: 0000000000000000
[ 1952.002957] R10: 00007ffea6a52d00 R11: 0000000000000246 R12: 00007ffea6a4ead0
[ 1952.002958] R13: 00007ffea6a4ea40 R14: 000055922f3f7b50 R15: 00007ffea6a4ea40

[Xaenalt]

Is there a way, just to get things working again, that I could reach in and fix the value for that inode?

Also, I have xattr=sa set, not sure if that's relevant

[Xaenalt]

I narrowed it down to a file in this directory somewhere, and ran zdb on them to try to get an idea of what the results were
Not sure what I'm looking at here, but one of the items in there is the culprit, since issuing ls on the directory causes the panic

zdb-all-objects.gz

[Xaenalt]

Ah, think I found out how to get some info on that inode specifically
The mode there looks really unusual, might have some garbage getting written into that field?

950970.txt