Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Attempted to advance past end of bvec iter #12041

Closed
risto42 opened this issue May 13, 2021 · 31 comments
Closed

Attempted to advance past end of bvec iter #12041

risto42 opened this issue May 13, 2021 · 31 comments
Labels
Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang)

Comments

@risto42
Copy link

risto42 commented May 13, 2021

System information

Type | Version/Name
--- | Linux version 5.12.3-arch1-1 (linux@archlinux) (gcc (GCC) 10.2.0, GNU ld (GNU Binutils) 2.36.1) #1 SMP PREEMPT Wed, 12 May 2021 17:54:18 +0000
Distribution Name | Archlinux
Distribution Version |
Linux Kernel | 5.12.3
Architecture | x86_64
ZFS Version | 2.0.4-1
SPL Version | 2.0.4-1

Describe the problem you're observing

after updating now that zfs-dkms/zfs-utils 2.0.4-2 can build on 5.12.x,
I noticed the traceback below in my logs

Describe how to reproduce the problem

not sure

Include any warning/errors/backtraces from the system logs

mai 13 12:09:39 sarchx64 kernel: ------------[ cut here ]------------
mai 13 12:09:39 sarchx64 kernel: Attempted to advance past end of bvec iter
mai 13 12:09:39 sarchx64 kernel: WARNING: CPU: 10 PID: 893850 at include/linux/bvec.h:105 iov_iter_advance+0x39a/0x3b0
mai 13 12:09:39 sarchx64 kernel: Modules linked in: ip_set bonding tls nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_limit nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables >
mai 13 12:09:39 sarchx64 kernel:  acpi_call(OE) nfs_ssc drm fuse agpgart bpf_preload ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 hid_logitech_hidpp hid_logitech_dj ata_generic pata_acpi crc32c_int>
mai 13 12:09:39 sarchx64 kernel: CPU: 10 PID: 893850 Comm: hg Tainted: P           OE     5.12.3-arch1-1 #1
mai 13 12:09:39 sarchx64 kernel: Hardware name: Supermicro H8SGL/H8SGL, BIOS 3.5b       03/18/2016
mai 13 12:09:39 sarchx64 kernel: RIP: 0010:iov_iter_advance+0x39a/0x3b0
mai 13 12:09:39 sarchx64 kernel: Code: 8a fe ff ff 4d 89 e1 45 31 d2 e9 42 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 28 77 1a a9 c6 05 6d 15 70 01 01 e8 bc f4 57 00 <0f> 0b 4c 8b 4b 18 eb b6 66 66 2e 0f 1f 84 0>
mai 13 12:09:39 sarchx64 kernel: RSP: 0018:ffffa40e29407bd8 EFLAGS: 00010286
mai 13 12:09:39 sarchx64 kernel: RAX: 0000000000000000 RBX: ffffa40e29407d40 RCX: ffff98585fd186e8
mai 13 12:09:39 sarchx64 kernel: RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff98585fd186e0
mai 13 12:09:39 sarchx64 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: ffffa40e29407a08
mai 13 12:09:39 sarchx64 kernel: R10: ffffa40e29407a00 R11: ffffffffa98cc448 R12: ffff985242e16540
mai 13 12:09:39 sarchx64 kernel: R13: ffff9855758c5dc0 R14: ffffa40e29407c98 R15: ffffa40e29407d40
mai 13 12:09:39 sarchx64 kernel: FS:  00007f74697bd740(0000) GS:ffff98585fd00000(0000) knlGS:0000000000000000
mai 13 12:09:39 sarchx64 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
mai 13 12:09:39 sarchx64 kernel: CR2: 00007f746787b024 CR3: 00000004b4abc000 CR4: 00000000000406e0
mai 13 12:09:39 sarchx64 kernel: Call Trace:
mai 13 12:09:39 sarchx64 kernel:  zpl_iter_write+0x184/0x1a0 [zfs]
mai 13 12:09:39 sarchx64 kernel:  do_iter_readv_writev+0x130/0x190
mai 13 12:09:39 sarchx64 kernel:  do_iter_write+0x7c/0x1b0
mai 13 12:09:39 sarchx64 kernel:  iter_file_splice_write+0x2ba/0x430
mai 13 12:09:39 sarchx64 kernel:  direct_splice_actor+0x2c/0x40
mai 13 12:09:39 sarchx64 kernel:  splice_direct_to_actor+0xf6/0x220
mai 13 12:09:39 sarchx64 kernel:  ? do_splice_direct+0xd0/0xd0
mai 13 12:09:39 sarchx64 kernel:  do_splice_direct+0x8b/0xd0
mai 13 12:09:39 sarchx64 kernel:  do_sendfile+0x322/0x490
mai 13 12:09:39 sarchx64 kernel:  __x64_sys_sendfile64+0x63/0xc0
mai 13 12:09:39 sarchx64 kernel:  do_syscall_64+0x33/0x40
mai 13 12:09:39 sarchx64 kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
mai 13 12:09:39 sarchx64 kernel: RIP: 0033:0x7f74692d498e
mai 13 12:09:39 sarchx64 kernel: Code: c3 0f 1f 00 4c 89 d2 4c 89 c6 e9 cd fd ff ff 0f 1f 44 00 00 31 c0 c3 0f 1f 44 00 00 f3 0f 1e fa 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d b2 c4 0>
mai 13 12:09:39 sarchx64 kernel: RSP: 002b:00007ffc2cfd4fb8 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
mai 13 12:09:39 sarchx64 kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f74692d498e
mai 13 12:09:39 sarchx64 kernel: RDX: 00007ffc2cfd4fc0 RSI: 0000000000000003 RDI: 0000000000000004
mai 13 12:09:39 sarchx64 kernel: RBP: 0000557fa9e88768 R08: 0000000000000000 R09: 00007f7469783990
mai 13 12:09:39 sarchx64 kernel: R10: 0000000000800000 R11: 0000000000000246 R12: 0000000000000003
mai 13 12:09:39 sarchx64 kernel: R13: 00007ffc2cfd4fc0 R14: 0000000000800000 R15: 0000557fa9af8d40
mai 13 12:09:39 sarchx64 kernel: ---[ end trace 75c594ed02ce9de1 ]---
@risto42 risto42 added Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang) labels May 13, 2021
@kernelOfTruth
Copy link
Contributor

the same just happened with up-to-date master (zfs-9999 & zfs-kmod-9999 ebuilds on Gentoo) and 5.12.4 based kernel on zfs root:

[    5.950363] ------------[ cut here ]------------
[    5.950365] Attempted to advance past end of bvec iter
[    5.950374] WARNING: CPU: 0 PID: 923 at include/linux/bvec.h:105 iov_iter_advance+0x39e/0x3b0
[    5.950380] Modules linked in: zfs(POE) zunicode(POE) zzstd(OE) zlua(OE) zavl(POE) icp(POE) zcommon(POE) znvpair(POE) spl(OE)
[    5.950387] CPU: 0 PID: 923 Comm: cp Tainted: P           OE   T 5.12.4-zen-prjc #1
[    5.950389] Hardware name: ASUS All Series/P9D WS, BIOS 2202 05/14/2015
[    5.950390] RIP: 0010:iov_iter_advance+0x39e/0x3b0
[    5.950393] Code: 85 fe ff ff 4d 89 e1 45 31 d2 e9 3f ff ff ff 48 89 f1 e9 70 ff ff ff 48 c7 c7 18 f3 40 a2 c6 05 73 bb 77 01 01 e8 32 cd 4c 00 <0f> 0b 4c 8b 4b 18 eb b6 66 2e 0f 1f 84 00 00 00 00 00 41 57 41 56
[    5.950394] RSP: 0018:ffffbd2b03c7fbb8 EFLAGS: 00010286
[    5.950396] RAX: 0000000000000000 RBX: ffffbd2b03c7fd40 RCX: ffffbd2b03c7f9e8
[    5.950397] RDX: ffffbd2b03c7f9f0 RSI: 00000000fffeffff RDI: ffffffffa3454948
[    5.950398] RBP: 0000000000000000 R08: 0000000000000000 R09: c0000000fffeffff
[    5.950399] R10: 0000000000000001 R11: 0000000000000001 R12: ffff97c1f923ee00
[    5.950400] R13: ffff97c108f44000 R14: ffffbd2b03c7fc78 R15: ffffbd2b03c7fd40
[    5.950401] FS:  0000000001c523c0(0000) GS:ffff97c7fec00000(0000) knlGS:0000000000000000
[    5.950402] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    5.950403] CR2: 00000000004c7f20 CR3: 00000005da234002 CR4: 00000000001706f0
[    5.950404] Call Trace:
[    5.950407]  zio_do_crypt_abd+0x15b2/0x2e30 [zfs]
[    5.950449]  do_iter_readv_writev+0x14f/0x1b0
[    5.950453]  do_iter_write+0x7b/0x1b0
[    5.950456]  iter_file_splice_write+0x279/0x3a0
[    5.950459]  direct_splice_actor+0x27/0x40
[    5.950461]  splice_direct_to_actor+0xf8/0x240
[    5.950463]  ? opipe_prep.part.0+0xa0/0xa0
[    5.950465]  do_splice_direct+0x89/0xd0
[    5.950467]  do_sendfile+0x341/0x4c0
[    5.950469]  __x64_sys_sendfile64+0xa0/0xc0
[    5.950472]  do_syscall_64+0x33/0x80
[    5.950475]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[    5.950479] RIP: 0033:0x55de0a
[    5.950480] Code: c3 0f 1f 80 00 00 00 00 4c 89 d2 4c 89 c6 e9 bd fd ff ff 0f 1f 44 00 00 31 c0 c3 0f 1f 44 00 00 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 e0 ff ff ff f7 d8 64 89 01 48
[    5.950481] RSP: 002b:00007ffc14e31488 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
[    5.950483] RAX: ffffffffffffffda RBX: 0000000001000000 RCX: 000000000055de0a
[    5.950484] RDX: 0000000000000000 RSI: 0000000000000003 RDI: 0000000000000004
[    5.950485] RBP: 00007ffc14e32f75 R08: 0000000000000001 R09: 0000000000000000
[    5.950485] R10: 0000000001000000 R11: 0000000000000246 R12: 0000000000000003
[    5.950486] R13: 0000000000000004 R14: 0000000000000000 R15: 0000000000000000
[    5.950488] ---[ end trace 14e1b8317f8bcd80 ]---

zfs-kmod-9999:

GIT update -->
   repository:               https://github.com/openzfs/zfs.git
   updating from commit:     485b50bb9e6772240af32fba434ddb8ebfa8cede
   to commit:                7457b024ba2be2cf742e07239c20a1c3f3fa9c72

according to:
https://patchwork.kernel.org/project/linux-block/patch/1491204212-9952-8-git-send-email-dmonakhov@openvz.org/

This simply means that we endup dereferencing/corrupting random memory
region.

For safity reason let truncate iterator size to zero which
will break external iteration loop which prevent us from unpredictable
memory range corruption. And even it caller ignores an error, it will
corrupt it's own bvecs, not others.

sounds pretty serious in terms of filesystem usage

maybe raise severity of the issue ?

@kernelOfTruth
Copy link
Contributor

no zfs filesystem encryption used, the only pool mounted was the root pool

@kernelOfTruth
Copy link
Contributor

Doesn't happen on 5.11.21-based kernel, btw, no related error messages on dmesg output - so only on 5.12 (or beyond) it seems

@kernelOfTruth
Copy link
Contributor

@risto42 you're trying to build ZFS 2.0.4 against an unsupported kernel version, btw:

Linux: compatible with 3.10 - 5.11 kernels

https://github.com/openzfs/zfs/releases/tag/zfs-2.0.4

one might assume that 5.12 is supported according to the changes but if I recall correctly there were additional changes against 5.12 in master branch

@risto42
Copy link
Author

risto42 commented May 16, 2021

Normally there were some patches for 5.12 pulled in...
https://aur.archlinux.org/cgit/aur.git/log/?h=zfs-dkms

@kernelOfTruth
Copy link
Contributor

thanks for the link !

for reference:
https://github.com/openzfs/zfs/commit/938a7a375b2c18fef621fb30d71bec0c19e94142.patch Linux 5.12 compat: idmapped mounts
and
https://github.com/openzfs/zfs/commit/8122746cc52741e2d010aa0ad8e0f15ab24bbf28.patch Linux 5.12 update: bio_max_segs() replaces BIO_MAX_PAGES

are the patches

so it seems additional changes are needed

@PiMaker
Copy link

PiMaker commented May 17, 2021

Also reported here (#11967 (comment) ff.) by several people, including myself. Seems harmless to me so far, but should still be fixed.

@BtbN
Copy link
Contributor

BtbN commented May 18, 2021

Happening here as well with NFS4 server-side copy:

------------[ cut here ]------------
Attempted to advance past end of bvec iter
WARNING: CPU: 6 PID: 3187221 at include/linux/bvec.h:105 iov_iter_advance+0x39a/0x3b0
Modules linked in: zfs(PO) zunicode(PO) zzstd(O) zlua(O) zcommon(PO) znvpair(PO) zavl(PO) icp(PO) spl(O)
CPU: 6 PID: 3187221 Comm: copy thread Tainted: P           O      5.12.4-gentoo #2
Hardware name: Supermicro AS -1014S-WTRT/H12SSW-NT, BIOS 1.3 11/25/2020
RIP: 0010:iov_iter_advance+0x39a/0x3b0
Code: 8a fe ff ff 4d 89 e1 45 31 d2 e9 42 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 58 a7 0c 95 c6 05 f7 8d bd 01 01 e8 65 c8 90 00 <0f> 0b 4c 8b 4b 18 eb b6 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00
RSP: 0018:ffff9ce6dc9cbb90 EFLAGS: 00010286
RAX: 0000000000000000 RBX: ffff9ce6dc9cbcf0 RCX: ffff9511ce992d98
RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff9511ce992d90
RBP: 0000000000000000 R08: 0000000000000000 R09: ffff9ce6dc9cb9c8
R10: 0000000000000001 R11: 0000000000000001 R12: ffff94dd6018a240
R13: ffff94d8dac5ee40 R14: ffff9ce6dc9cbcf0 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff9511ce980000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fa01bcf8058 CR3: 0000000385c12000 CR4: 0000000000350ee0
Call Trace:
 zio_do_crypt_abd+0x1b54/0x2bf0 [zfs]
 do_iter_readv_writev+0x152/0x1b0
 do_iter_write+0x7c/0x1b0
 iter_file_splice_write+0x288/0x420
 direct_splice_actor+0x2c/0x40
 splice_direct_to_actor+0xeb/0x210
 ? pipe_to_sendpage+0xa0/0xa0
 do_splice_direct+0x8b/0xd0
 vfs_copy_file_range+0x1b6/0x460
 nfsd4_do_copy+0x49/0x130
 ? nfsd4_copy+0x3b0/0x3b0
 nfsd4_do_async_copy+0x4e/0x170
 kthread+0x11b/0x140
 ? __kthread_bind_mask+0x60/0x60
 ret_from_fork+0x22/0x30
---[ end trace 6b804130054420b6 ]---

Nothing encrypted here either. 2.1.0_rc5 on Kernel 5.12.4.

@JohnyPeaN
Copy link

I have the same issue. It seems that wine triggers this consistently. Doesn't happen on 5.11
zfs 2.1.99.r174.g7457b024b
kernel 5.12.4-MANJARO

[St máj 19 16:00:10 2021] Attempted to advance past end of bvec iter
[St máj 19 16:00:10 2021] Modules linked in: rfcomm xt_CHECKSUM xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_filter bridge stp llc iptable_nat xt_MASQUERADE cmac nf_nat algif_hash nf_conntrack algif_skcipher af_alg nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c bnep nct6775 hwmon_vid vfat fat hid_logitech_hidpp joydev mousedev iwlmvm mac80211 btusb btrtl btbcm btintel libarc4 bluetooth iwlwifi hid_logitech_dj ecdh_generic ecc cfg80211 igb r8169 realtek mdio_devres dca rfkill libphy zfs(POE) snd_hda_codec_realtek zunicode(POE) intel_rapl_msr snd_hda_codec_generic intel_rapl_common zzstd(OE) ledtrig_audio snd_usb_audio snd_hda_intel zlua(OE) snd_intel_dspcfg snd_intel_sdw_acpi sch_fq_pie uvcvideo sch_pie snd_hda_codec zavl(POE) snd_usbmidi_lib icp(POE) videobuf2_vmalloc snd_rawmidi videobuf2_memops winesync snd_hda_core videobuf2_v4l2 snd_seq_device edac_mce_amd snd_hwdep videobuf2_common uinput crct10dif_pclmul zcommon(POE)
[St máj 19 16:00:10 2021]  crc32_pclmul snd_pcm ghash_clmulni_intel videodev aesni_intel znvpair(POE) snd_timer i2c_dev crypto_simd snd cryptd sp5100_tco mc spl(OE) rapl wmi_bmof zenpower(OE) i2c_piix4 soundcore vhost_scsi target_core_mod pinctrl_amd vhost_net mac_hid acpi_cpufreq tun vhost vhost_iotlb tap kvm_amd ccp rng_core kvm fuse irqbypass crypto_user bpf_preload ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 usbhid crc32c_intel xhci_pci xhci_pci_renesas ata_generic pata_acpi zram nouveau mxm_wmi wmi radeon i915 video intel_agp intel_gtt amdgpu gpu_sched i2c_algo_bit drm_ttm_helper ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops cec drm agpgart
[St máj 19 16:00:10 2021] CPU: 13 PID: 6420 Comm: python3 Tainted: P           OE     5.12.4-157-tkg-cfs #1
[St máj 19 16:00:10 2021] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./X570 Phantom Gaming X, BIOS P4.30 04/14/2021
[St máj 19 16:00:10 2021] RIP: 0010:iov_iter_advance+0x3a1/0x3b0
[St máj 19 16:00:10 2021] Code: 83 fe ff ff 4d 89 e1 45 31 d2 e9 27 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 78 f1 a0 8b c6 05 0a 2b 10 01 01 e8 5f 20 5e 00 <0f> 0b 4c 8b 4b 18 eb b6 0f 1f 80 00 00 00 00 41 57 49 89 d7 41 56
[St máj 19 16:00:10 2021] RSP: 0018:ffffa3882df2fc30 EFLAGS: 00010286
[St máj 19 16:00:10 2021] RAX: 0000000000000000 RBX: ffffa3882df2fd90 RCX: 0000000000000027
[St máj 19 16:00:10 2021] RDX: ffff93fa7ef58428 RSI: 0000000000000001 RDI: ffff93fa7ef58420
[St máj 19 16:00:10 2021] RBP: 0000000000000000 R08: 0000000000000001 R09: 00000000ffffffea
[St máj 19 16:00:10 2021] R10: ffff93fa7eb50000 R11: ffffa3882df2fa00 R12: ffff93ec2612f680
[St máj 19 16:00:10 2021] R13: 0000000000000000 R14: ffffa3882df2fce8 R15: ffffa3882df2fd90
[St máj 19 16:00:10 2021] FS:  00007f44c35cf740(0000) GS:ffff93fa7ef40000(0000) knlGS:0000000000000000
[St máj 19 16:00:10 2021] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[St máj 19 16:00:10 2021] CR2: 00007f44c2ae6000 CR3: 000000022f344000 CR4: 00000000003506e0
[St máj 19 16:00:10 2021] Call Trace:
[St máj 19 16:00:10 2021]  zpl_iter_write+0x186/0x1b0     [zfs]
[St máj 19 16:00:10 2021]  do_iter_readv_writev+0x12a/0x190
[St máj 19 16:00:10 2021]  do_iter_write.part.0+0x2c/0x160
[St máj 19 16:00:10 2021]  iter_file_splice_write+0x273/0x3d0
[St máj 19 16:00:10 2021]  do_splice_direct+0x1a2/0x450
[St máj 19 16:00:10 2021]  do_sendfile+0x275/0x510
[St máj 19 16:00:10 2021]  __x64_sys_sendfile64+0x60/0xc0
[St máj 19 16:00:10 2021]  do_syscall_64+0x33/0x40
[St máj 19 16:00:10 2021]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[St máj 19 16:00:10 2021] RIP: 0033:0x7f44c38390de
[St máj 19 16:00:10 2021] Code: c3 0f 1f 00 4c 89 d2 4c 89 c6 e9 fd fd ff ff 0f 1f 44 00 00 31 c0 c3 0f 1f 44 00 00 f3 0f 1e fa 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 62 bd 0c 00 f7 d8 64 89 01 48
[St máj 19 16:00:10 2021] RSP: 002b:00007ffdc62eb078 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
[St máj 19 16:00:10 2021] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007f44c38390de
[St máj 19 16:00:10 2021] RDX: 00007ffdc62eb080 RSI: 0000000000000004 RDI: 0000000000000005
[St máj 19 16:00:10 2021] RBP: 000055f51f39ca28 R08: 0000000000000000 R09: 00007f44c30349b0
[St máj 19 16:00:10 2021] R10: 0000000000800000 R11: 0000000000000246 R12: 0000000000000004
[St máj 19 16:00:10 2021] R13: 00007ffdc62eb080 R14: 0000000000800000 R15: 000055f51f08bcd0

@kernelOfTruth
Copy link
Contributor

It seems that wine triggers this consistently.

it's independent from wine usage

I'm running zfs on my root partition and it was the only zfs pool/zpool mounted during bootup with 5.12.4 and still got it.

You got several occurrences of that message in dmesg ?

@JohnyPeaN
Copy link

You got several occurrences of that message in dmesg ?

No, only once per boot. But I can use the array for hours (copy, delete, snapshots, scrub) wihout error and seconds after starting wine (actually its proton with specific big prefix with game) it occurs. I might have missed an occurence (I thought it didn't happen always ie. ran the same game and didn't notice this), but now it seems to be 100% chance. I'm not actively runnig 5.12 now because of this, only testing because I think in one instatnce after this and reboot I had data rollback. New data after triggering this was gone, but pool wasn't corrupted and scrub completed without errors, but after testing this situation again the new data was written.

@jypma
Copy link

jypma commented May 21, 2021

I'm seeing it fairly quickly after booting:

[  412.905658] ------------[ cut here ]------------
[  412.905661] Attempted to advance past end of bvec iter
[  412.905667] WARNING: CPU: 11 PID: 2836 at include/linux/bvec.h:105 iov_iter_advance+0x3a1/0x3b0
[  412.905676] Modules linked in: xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype iptable_filter iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c br_netfilter bridge stp llc ccm sr_mod cdrom snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic hid_logitech_hidpp snd_usb_audio uas usb_storage snd_usbmidi_lib wacom snd_rawmidi snd_seq_device btusb btrtl btbcm btintel uvcvideo bluetooth videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev ecdh_generic mc hid_logitech_dj ecc joydev mousedev snd_sof_pci_intel_cnl snd_sof_intel_hda_common soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_sof snd_sof_xtensa_dsp soundwire_bus snd_soc_skl snd_soc_hdac_hda x86_pkg_temp_thermal snd_hda_ext_core intel_powerclamp snd_soc_sst_ipc coretemp snd_soc_sst_dsp snd_soc_acpi_intel_match vfat snd_soc_acpi iwlmvm kvm_intel fat snd_soc_core iTCO_wdt mei_hdcp intel_pmc_bxt mei_wdt ee1004
[  412.905724]  iTCO_vendor_support intel_rapl_msr intel_wmi_thunderbolt wmi_bmof mac80211 kvm ext4 i915 snd_compress ac97_bus snd_pcm_dmaengine libarc4 irqbypass crct10dif_pclmul crc32_pclmul snd_hda_intel ghash_clmulni_intel crc32c_generic aesni_intel crc32c_intel snd_intel_dspcfg crc16 mbcache snd_intel_sdw_acpi jbd2 iwlwifi crypto_simd snd_hda_codec cryptd rapl snd_hda_core i2c_algo_bit intel_cstate cfg80211 intel_uncore psmouse e1000e snd_hwdep drm_kms_helper snd_pcm thunderbolt pcspkr thinkpad_acpi i2c_i801 mei_me snd_timer i2c_smbus cec mei processor_thermal_device ucsi_acpi processor_thermal_rfim typec_ucsi intel_lpss_pci processor_thermal_mbox platform_profile intel_gtt intel_lpss processor_thermal_rapl ledtrig_audio typec idma64 syscopyarea intel_rapl_common rfkill sysfillrect sysimgblt intel_pch_thermal intel_soc_dts_iosf fb_sys_fops roles wmi snd soundcore int3403_thermal int340x_thermal_zone video mac_hid int3400_thermal acpi_thermal_rel acpi_pad drm fuse agpgart bpf_preload
[  412.905772]  ip_tables x_tables usbhid zfs(POE) zunicode(POE) zzstd(OE) zlua(OE) zavl(POE) icp(POE) rtsx_pci_sdmmc mmc_core zcommon(POE) serio_raw znvpair(POE) atkbd spl(OE) libps2 rtsx_pci xhci_pci xhci_pci_renesas i8042 serio vmd
[  412.905788] CPU: 11 PID: 2836 Comm: DOM Worker Tainted: P           OE     5.12.4-arch1-2 #1
[  412.905791] Hardware name: LENOVO 20TQCTO1WW/20TQCTO1WW, BIOS N30ET36W (1.19 ) 03/08/2021
[  412.905792] RIP: 0010:iov_iter_advance+0x3a1/0x3b0
[  412.905811] Code: 8a fe ff ff 4d 89 e1 45 31 d2 e9 42 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 38 73 fa b5 c6 05 66 4b 70 01 01 e8 d0 c9 57 00 <0f> 0b 4c 8b 4b 18 eb b6 0f 1f 80 00 00 00 00 41 57 41 56 41 55 41
[  412.905813] RSP: 0018:ffffab8ce1b0bc48 EFLAGS: 00010286
[  412.905815] RAX: 0000000000000000 RBX: ffffab8ce1b0bda8 RCX: 0000000000000027
[  412.905816] RDX: ffff9fa55d6d86e8 RSI: 0000000000000001 RDI: ffff9fa55d6d86e0
[  412.905817] RBP: 0000000000000000 R08: 0000000000000000 R09: ffffab8ce1b0ba78
[  412.905818] R10: ffffab8ce1b0ba70 R11: ffffffffb66cc448 R12: ffff9f9e0ebfc840
[  412.905819] R13: 0000000000000000 R14: ffffab8ce1b0bd00 R15: ffffab8ce1b0bda8
[  412.905820] FS:  00007f2ebd6ff640(0000) GS:ffff9fa55d6c0000(0000) knlGS:0000000000000000
[  412.905822] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  412.905823] CR2: 00000e4c5f103b38 CR3: 000000014da3e004 CR4: 00000000007706e0
[  412.905825] PKRU: 55555554
[  412.905825] Call Trace:
[  412.905829]  zpl_iter_write+0x18b/0x1b0 [zfs]
[  412.905933]  do_iter_readv_writev+0x12d/0x190
[  412.905938]  do_iter_write+0x7c/0x1b0
[  412.905941]  iter_file_splice_write+0x2b8/0x430
[  412.905945]  do_splice+0x327/0x6e0
[  412.905947]  __do_splice+0xe7/0x160
[  412.905949]  __x64_sys_splice+0x94/0x110
[  412.905951]  do_syscall_64+0x33/0x40
[  412.905955]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  412.905958] RIP: 0033:0x7f2ef4dbab53
[  412.905959] Code: e8 02 64 f8 ff 44 8b 4c 24 2c 4c 8b 44 24 20 89 c5 4c 8b 54 24 18 8b 54 24 28 b8 13 01 00 00 48 8b 74 24 10 8b 7c 24 08 0f 05 <48> 3d 00 f0 ff ff 77 35 89 ef 48 89 44 24 08 e8 49 64 f8 ff 48 8b
[  412.905961] RSP: 002b:00007f2ebd6fba30 EFLAGS: 00000293 ORIG_RAX: 0000000000000113
[  412.905963] RAX: ffffffffffffffda RBX: 00007f2ebd6fb9b0 RCX: 00007f2ef4dbab53
[  412.905964] RDX: 0000000000000100 RSI: 0000000000000000 RDI: 0000000000000103
[  412.905965] RBP: 0000000000000000 R08: 0000000000003745 R09: 0000000000000000
[  412.905966] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f2ebe225680
[  412.905967] R13: 0000000000000001 R14: 00007f2ec11c4538 R15: fffffffffffffffc
[  412.905970] ---[ end trace 3c86c50ce9daa248 ]---

Not sure what triggers it yet, nor if there any other side-effects.

@mabod
Copy link

mabod commented May 25, 2021

It happened to me today as well. And when I check the journal I see it 21 times since 5. May. Looks like it happens to me almost once a day. I have not noticed any negative side effect yet.

@siebenmann
Copy link
Contributor

This is happening for me on the latest git tip, currently 0989d79, on 5.12, also from zpl_iter_write(). Based on inspection of the Linux kernel code, this warning comes from bvec_iter_advance() in include/linux/bvec.h, when the caller attempts to advance the byte range past the end of the bvec. This check is also in 5.11, but it can't be hit because iov_iter_advance() in lib/iov_iter.c doesn't have a special case for bvec iters that winds up calling bvec_iter_advace(); instead it falls through to a more generic case that advances the bvec iter without performing this check. Given this, the underlying issue is probably present in 5.11 and previous kernels, it's just not being warned about there.

Further debugging would likely take instrumenting this code somehow (maybe bpftrace can do it these days) to examine the difference between what ZFS is asking for the advance and how much the bvec iter actually says it contains, and then determining what's happening to create that difference.

The warning is a WARN_ONCE(), so I believe that this message will trigger only once per boot.

@kernelOfTruth
Copy link
Contributor

Given this, the underlying issue is probably present in 5.11 and previous kernels, it's just not being warned about there.

agreed, got the same assumption

there is one commit directly mentioning iov_iter_advance() related to iter_read:

9ac535e Remove iov_iter_advance() from iter_read

I wonder if it's potentially related to this message and behavior in any way

@siebenmann
Copy link
Contributor

I think that this is probably exactly the write side of 9ac535e aka pull #11378. I added instrumentation to zpl_iter_write() and the two uses in zfs_uio.c of iov_iter_advance() and as far as I can tell the iov_iter is always advanced by the time that zpl_iter_write() makes its own call to iov_iter_advance(). Specifically, the code I added in zpl_iter_write() (just before the if (wrote > 0) is:

        size_t iremain = iov_iter_count(from);
        if (wrote > iremain || count > iremain) {
                printk("zpl_iter_write: wrote more than remain: wrote %zd remain %zu count %zu uio_skip %d int_type %d\n", wrote, iremain, count, uio.uio_skip, iov_iter_type(from));
        } else {
                printk("GOOD zpl_iter_write: wrote %zd remain %d count %zu\n", wrote, iremain, count);
        }

This constantly logs messages from the first side of the condition (my usual test is to build Go from source):

kernel: zpl_iter_write: wrote more than remain: wrote 1792 remain 0 count 1792 uio_skip 0 int_type 4
kernel: zpl_iter_write: wrote more than remain: wrote 36 remain 0 count 36 uio_skip 0 int_type 4
kernel: zpl_iter_write: wrote more than remain: wrote 65536 remain 0 count 65536 uio_skip 0 int_type 16

I haven't seen a message from the second case yet. A type 4 is ITER_IOVEC; a type 16 is ITER_BVEC and the first one reported also triggers the warning.

I think this means that something in the code that zpl_iter_write() calls is advancing the iter itself, exhausting it entirely by the time the IO is done. I don't think this is in ZFS code; instead I think it's somewhere in the general kernel code. I lack enough knowledge of kernel internals to say where. Advancing the iter this way may be dangerous in some cases; if there is a short write (that doesn't entirely exhaust the iter), we will presumably over-advance the iter.

@comrade-meowski
Copy link

I noticed this for the first time today and went back through the logs looking for it as well.

One instance back on 19th - when I would have still been running 5.12.3 - and three in the last two days running on 5.12.4. This is consistent with the once per boot as I really only reboot for kernel upgrades and if I cross reference the journalctl errors with the boot times they match up pretty closely.

Checking my laptop which runs the same kernel+zfs builds the same error has been occurring unnoticed there as well, starting back on the 8th at which point it would have been running 5.12.3 + 2.1.0-rc4.

Distribution Name | Ubuntu
Distribution Version | 21.04
Linux Kernel | 5.12.3 & 5.12.4
Architecture | x86_64
ZFS Version | 2.1.0-rc4 & 2.1.0-rc5

@kernelOfTruth
Copy link
Contributor

kernelOfTruth commented May 26, 2021

linux 5.11 kernel is EOL already (5.11.22) so from a security standpoint it would be nice to be able to upgrade to 5.12 kernels with the knowledge and certainty that there's no data jeopardising issues lying somewhere (the zfs tests runs on master didn't show any issues so far, I assume - so it should be safe with a bit a weird lingering after-taste)

@BtbN
Copy link
Contributor

BtbN commented May 28, 2021

Easy way to reliably trigger this:

xfs_io -fc "pwrite 0 5M" testfile
xfs_io -fc "copy_range testfile" testfile.copy

rincebrain added a commit to rincebrain/zfs that referenced this issue May 29, 2021
It seems like this should have gone with openzfs#11378.

Closes: openzfs#12041

Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
@kernelOfTruth
Copy link
Contributor

kernelOfTruth commented May 29, 2021

I think that this is probably exactly the write side of 9ac535e aka pull #11378. I added instrumentation to zpl_iter_write() and the two uses in zfs_uio.c of iov_iter_advance() and as far as I can tell the iov_iter is always advanced by the time that zpl_iter_write() makes its own call to iov_iter_advance(). Specifically, the code I added in zpl_iter_write() (just before the if (wrote > 0) is:

        size_t iremain = iov_iter_count(from);
        if (wrote > iremain || count > iremain) {
                printk("zpl_iter_write: wrote more than remain: wrote %zd remain %zu count %zu uio_skip %d int_type %d\n", wrote, iremain, count, uio.uio_skip, iov_iter_type(from));
        } else {
                printk("GOOD zpl_iter_write: wrote %zd remain %d count %zu\n", wrote, iremain, count);
        }

This constantly logs messages from the first side of the condition (my usual test is to build Go from source):

kernel: zpl_iter_write: wrote more than remain: wrote 1792 remain 0 count 1792 uio_skip 0 int_type 4
kernel: zpl_iter_write: wrote more than remain: wrote 36 remain 0 count 36 uio_skip 0 int_type 4
kernel: zpl_iter_write: wrote more than remain: wrote 65536 remain 0 count 65536 uio_skip 0 int_type 16

I haven't seen a message from the second case yet. A type 4 is ITER_IOVEC; a type 16 is ITER_BVEC and the first one reported also triggers the warning.

I think this means that something in the code that zpl_iter_write() calls is advancing the iter itself, exhausting it entirely by the time the IO is done. I don't think this is in ZFS code; instead I think it's somewhere in the general kernel code. I lack enough knowledge of kernel internals to say where. Advancing the iter this way may be dangerous in some cases; if there is a short write (that doesn't entirely exhaust the iter), we will presumably over-advance the iter.

I wonder if the change from #12155 Remove iov_iter_advance() for iter_write

would output "GOOD zpl_iter_write: wrote [...]"

rincebrain added a commit to rincebrain/zfs that referenced this issue May 30, 2021
It seems like this should have gone with openzfs#11378.

The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.

Closes: openzfs#12041

Suggested-by: @siebenmann
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
@JohnyPeaN
Copy link

@rincebrain your patch seems to solve this for me.

@kernelOfTruth
Copy link
Contributor

confirmed, no occurrence anymore of the error message/warning in kernel logs

@rincebrain
Copy link
Contributor

@rincebrain your patch seems to solve this for me.

I appreciate the confirmation, but this absolutely was all @siebenmann's research, I just did the couple of line deletions he suggested.

@JohnyPeaN
Copy link

Thanks goes to all involved @rincebrain, @siebenmann and @kernelOfTruth. I have tested this on kernel 5.12.8 and today 5.13-rc4 and both seem to work fine without warnings. Also tried usual aplications, file operations and scrub. Everything went fine. I think this could be merged.

tonyhutter pushed a commit that referenced this issue Jun 2, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with #11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue #11378
Closes #12041
Closes #12155
(cherry picked from commit 3f81aba)
Signed-off-by: Jonathon Fernyhough <jonathon@m2x.dev>
tonyhutter pushed a commit to tonyhutter/zfs that referenced this issue Jun 2, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with openzfs#11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue openzfs#11378
Closes openzfs#12041
Closes openzfs#12155
(cherry picked from commit 3f81aba)
Signed-off-by: Jonathon Fernyhough <jonathon@m2x.dev>
@zviratko
Copy link

zviratko commented Jun 3, 2021

For what it's worth, emerge --sync triggers this reliably for me :-) which is probably why some gentoo users noticed this

Was there ever any risk of corruption or was it harmless?

behlendorf pushed a commit to behlendorf/zfs that referenced this issue Jun 3, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with openzfs#11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue openzfs#11378
Closes openzfs#12041
Closes openzfs#12155
@tuxzz
Copy link

tuxzz commented Jun 6, 2021

Happened twice today while copying large files.
OS is Archlinux. Kernel is Linux TukuZaZa-D1 5.12.9-zen1-1-zen #1 ZEN SMP PREEMPT Thu, 03 Jun 2021 11:36:07 +0000 x86_64 GNU/Linux

[   19.985476] ------------[ cut here ]------------
[   19.985480] Attempted to advance past end of bvec iter
[   19.985488] WARNING: CPU: 13 PID: 6176 at include/linux/bvec.h:105 iov_iter_advance+0x3a1/0x3b0
[   19.985496] Modules linked in: xt_state nf_nat_h323 nf_conntrack_h323 nf_nat_pptp nf_conntrack_pptp nf_nat_tftp nf_conntrack_tftp nf_nat_sip nf_conntrack_sip xt_CHECKSUM nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c crc32c_generic iptable_filter bridge stp llc cmac algif_hash algif_skcipher af_alg bnep vfat fat amdgpu intel_rapl_msr intel_rapl_common iwlmvm edac_mce_amd kvm_amd ccp rng_core mac80211 kvm snd_hda_codec_realtek libarc4 btusb snd_hda_codec_generic btrtl btbcm ledtrig_audio btintel snd_hda_codec_hdmi gpu_sched bluetooth iwlwifi i2c_algo_bit irqbypass snd_hda_intel drm_ttm_helper crct10dif_pclmul ttm snd_intel_dspcfg wmi_bmof crc32_pclmul crc32c_intel snd_intel_sdw_acpi ghash_clmulni_intel drm_kms_helper snd_hda_codec aesni_intel snd_hda_core cfg80211 r8169
[   19.985548]  mousedev cec ecdh_generic crypto_simd snd_hwdep snd_pcm cryptd ecc syscopyarea joydev sp5100_tco realtek crc16 snd_timer rapl sysfillrect mdio_devres sysimgblt snd libphy fb_sys_fops soundcore k10temp rfkill i2c_piix4 pcspkr pinctrl_amd wmi mac_hid acpi_cpufreq tcp_bbr pkcs8_key_parser crypto_user drm fuse agpgart bpf_preload ip_tables x_tables usbhid zfs(POE) zunicode(POE) zzstd(OE) zlua(OE) zavl(POE) icp(POE) zcommon(POE) xhci_pci znvpair(POE) spl(OE) xhci_pci_renesas
[   19.985580] CPU: 13 PID: 6176 Comm: kcminit_startup Tainted: P           OE     5.12.9-zen1-1-zen #1
[   19.985583] Hardware name: Micro-Star International Co., Ltd. MS-7C37/MPG X570 GAMING PLUS (MS-7C37), BIOS A.C0 01/25/2021
[   19.985585] RIP: 0010:iov_iter_advance+0x3a1/0x3b0
[   19.985588] Code: 83 fe ff ff 4d 89 e1 45 31 d2 e9 27 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 38 4f 9a 8f c6 05 07 eb 82 01 01 e8 86 63 65 00 <0f> 0b 4c 8b 4b 18 eb b6 0f 1f 80 00 00 00 00 41 57 49 89 d7 41 56
[   19.985590] RSP: 0018:ffffb5a0d9067c30 EFLAGS: 00010286
[   19.985593] RAX: 0000000000000000 RBX: ffffb5a0d9067d90 RCX: 0000000000000027
[   19.985594] RDX: ffff96cceed586e8 RSI: 0000000000000001 RDI: ffff96cceed586e0
[   19.985596] RBP: 0000000000000000 R08: 0000000000000001 R09: 00000000ffffffea
[   19.985597] R10: ffff96cd2f248580 R11: ffffb5a0d90679f8 R12: ffff96be67c7cd80
[   19.985599] R13: 0000000000000000 R14: ffffb5a0d9067ce8 R15: ffffb5a0d9067d90
[   19.985600] FS:  00007fbde8f6b840(0000) GS:ffff96cceed40000(0000) knlGS:0000000000000000
[   19.985602] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   19.985604] CR2: 000055daa4bab308 CR3: 0000000197bcc000 CR4: 0000000000350ee0
[   19.985606] Call Trace:
[   19.985610]  zpl_iter_write+0x18b/0x1b0 [zfs]
[   19.985726]  do_iter_readv_writev+0x12f/0x190
[   19.985730]  do_iter_write.part.0+0x31/0x160
[   19.985733]  iter_file_splice_write+0x278/0x3d0
[   19.985739]  do_splice_direct+0x1a7/0x460
[   19.985742]  do_sendfile+0x36f/0x540
[   19.985746]  __x64_sys_sendfile64+0xaa/0xc0
[   19.985749]  do_syscall_64+0x33/0x40
[   19.985754]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   19.985757] RIP: 0033:0x7fbdecf1f0de
[   19.985760] Code: c3 0f 1f 00 4c 89 d2 4c 89 c6 e9 fd fd ff ff 0f 1f 44 00 00 31 c0 c3 0f 1f 44 00 00 f3 0f 1e fa 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 62 bd 0c 00 f7 d8 64 89 01 48
[   19.985761] RSP: 002b:00007ffdc2fe7d08 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
[   19.985764] RAX: ffffffffffffffda RBX: 00007fbde0005bb0 RCX: 00007fbdecf1f0de
[   19.985765] RDX: 0000000000000000 RSI: 000000000000000e RDI: 000000000000000f
[   19.985766] RBP: 000000000000000e R08: 0000000000000000 R09: 000000000000002f
[   19.985768] R10: 000000007ffff000 R11: 0000000000000246 R12: 000000000000000f
[   19.985769] R13: 00007ffdc2fe90a0 R14: 00007ffdc2fe7e30 R15: 000055daa4c49600
[   19.985773] ---[ end trace 1f3e1aecf8d8038f ]---

@BtbN
Copy link
Contributor

BtbN commented Jun 6, 2021

You mean despite the fix being applied?

@kernelOfTruth
Copy link
Contributor

Happened twice today while copying large files.
OS is Archlinux. Kernel is Linux TukuZaZa-D1 5.12.9-zen1-1-zen #1 ZEN SMP PREEMPT Thu, 03 Jun 2021 11:36:07 +0000 x86_64 GNU/Linux

[   19.985476] ------------[ cut here ]------------
[   19.985480] Attempted to advance past end of bvec iter
[   19.985488] WARNING: CPU: 13 PID: 6176 at include/linux/bvec.h:105 iov_iter_advance+0x3a1/0x3b0
[   19.985496] Modules linked in: xt_state nf_nat_h323 nf_conntrack_h323 nf_nat_pptp nf_conntrack_pptp nf_nat_tftp nf_conntrack_tftp nf_nat_sip nf_conntrack_sip xt_CHECKSUM nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c crc32c_generic iptable_filter bridge stp llc cmac algif_hash algif_skcipher af_alg bnep vfat fat amdgpu intel_rapl_msr intel_rapl_common iwlmvm edac_mce_amd kvm_amd ccp rng_core mac80211 kvm snd_hda_codec_realtek libarc4 btusb snd_hda_codec_generic btrtl btbcm ledtrig_audio btintel snd_hda_codec_hdmi gpu_sched bluetooth iwlwifi i2c_algo_bit irqbypass snd_hda_intel drm_ttm_helper crct10dif_pclmul ttm snd_intel_dspcfg wmi_bmof crc32_pclmul crc32c_intel snd_intel_sdw_acpi ghash_clmulni_intel drm_kms_helper snd_hda_codec aesni_intel snd_hda_core cfg80211 r8169
[   19.985548]  mousedev cec ecdh_generic crypto_simd snd_hwdep snd_pcm cryptd ecc syscopyarea joydev sp5100_tco realtek crc16 snd_timer rapl sysfillrect mdio_devres sysimgblt snd libphy fb_sys_fops soundcore k10temp rfkill i2c_piix4 pcspkr pinctrl_amd wmi mac_hid acpi_cpufreq tcp_bbr pkcs8_key_parser crypto_user drm fuse agpgart bpf_preload ip_tables x_tables usbhid zfs(POE) zunicode(POE) zzstd(OE) zlua(OE) zavl(POE) icp(POE) zcommon(POE) xhci_pci znvpair(POE) spl(OE) xhci_pci_renesas
[   19.985580] CPU: 13 PID: 6176 Comm: kcminit_startup Tainted: P           OE     5.12.9-zen1-1-zen #1
[   19.985583] Hardware name: Micro-Star International Co., Ltd. MS-7C37/MPG X570 GAMING PLUS (MS-7C37), BIOS A.C0 01/25/2021
[   19.985585] RIP: 0010:iov_iter_advance+0x3a1/0x3b0
[   19.985588] Code: 83 fe ff ff 4d 89 e1 45 31 d2 e9 27 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 38 4f 9a 8f c6 05 07 eb 82 01 01 e8 86 63 65 00 <0f> 0b 4c 8b 4b 18 eb b6 0f 1f 80 00 00 00 00 41 57 49 89 d7 41 56
[   19.985590] RSP: 0018:ffffb5a0d9067c30 EFLAGS: 00010286
[   19.985593] RAX: 0000000000000000 RBX: ffffb5a0d9067d90 RCX: 0000000000000027
[   19.985594] RDX: ffff96cceed586e8 RSI: 0000000000000001 RDI: ffff96cceed586e0
[   19.985596] RBP: 0000000000000000 R08: 0000000000000001 R09: 00000000ffffffea
[   19.985597] R10: ffff96cd2f248580 R11: ffffb5a0d90679f8 R12: ffff96be67c7cd80
[   19.985599] R13: 0000000000000000 R14: ffffb5a0d9067ce8 R15: ffffb5a0d9067d90
[   19.985600] FS:  00007fbde8f6b840(0000) GS:ffff96cceed40000(0000) knlGS:0000000000000000
[   19.985602] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   19.985604] CR2: 000055daa4bab308 CR3: 0000000197bcc000 CR4: 0000000000350ee0
[   19.985606] Call Trace:
[   19.985610]  zpl_iter_write+0x18b/0x1b0 [zfs]
[   19.985726]  do_iter_readv_writev+0x12f/0x190
[   19.985730]  do_iter_write.part.0+0x31/0x160
[   19.985733]  iter_file_splice_write+0x278/0x3d0
[   19.985739]  do_splice_direct+0x1a7/0x460
[   19.985742]  do_sendfile+0x36f/0x540
[   19.985746]  __x64_sys_sendfile64+0xaa/0xc0
[   19.985749]  do_syscall_64+0x33/0x40
[   19.985754]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   19.985757] RIP: 0033:0x7fbdecf1f0de
[   19.985760] Code: c3 0f 1f 00 4c 89 d2 4c 89 c6 e9 fd fd ff ff 0f 1f 44 00 00 31 c0 c3 0f 1f 44 00 00 f3 0f 1e fa 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 62 bd 0c 00 f7 d8 64 89 01 48
[   19.985761] RSP: 002b:00007ffdc2fe7d08 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
[   19.985764] RAX: ffffffffffffffda RBX: 00007fbde0005bb0 RCX: 00007fbdecf1f0de
[   19.985765] RDX: 0000000000000000 RSI: 000000000000000e RDI: 000000000000000f
[   19.985766] RBP: 000000000000000e R08: 0000000000000000 R09: 000000000000002f
[   19.985768] R10: 000000007ffff000 R11: 0000000000000246 R12: 000000000000000f
[   19.985769] R13: 00007ffdc2fe90a0 R14: 00007ffdc2fe7e30 R15: 000055daa4c49600
[   19.985773] ---[ end trace 1f3e1aecf8d8038f ]---

which version of the kernel module are you using ?

I haven't seen this so far - up to 5.12.8

behlendorf pushed a commit to behlendorf/zfs that referenced this issue Jun 8, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with openzfs#11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue openzfs#11378
Closes openzfs#12041
Closes openzfs#12155
@KenMacD
Copy link

KenMacD commented Jun 9, 2021

Just got this with 2.1.0-rc6:

------------[ cut here ]------------
Attempted to advance past end of bvec iter
WARNING: CPU: 4 PID: 757066 at include/linux/bvec.h:105 iov_iter_advance+0x39a/0x3b0
Modules linked in: bluetooth ecdh_generic ecc crc16 snd_seq_dummy snd_hrtimer snd_seq snd_seq_device xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype br_netfilter ccm snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic af_packet joydev mousedev hid_multitouch hid_sensor_custom_intel_hinge hid_sensor_accel_3d hid_sensor_als hid_sensor_gyro_3d hid_sensor_trigger industrialio_triggered_buffer kfifo_buf hid_sensor_iio_common industrialio hid_sensor_custom hid_sensor_hub intel_ishtp_loader intel_ishtp_hid snd_sof_pci_intel_tgl snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_sof snd_sof_xtensa_dsp snd_hda_ext_core snd_soc_acpi_intel_match snd_soc_acpi soundwire_bus ledtrig_audio snd_soc_core i2c_designware_platform ip6table_nat iTCO_wdt mei_wdt intel_pmc_bxt iptable_nat mei_hdcp nf_nat watchdog i2c_designware_core snd_compress ac97_bus snd_pcm_dmaengine
 intel_rapl_msr xt_conntrack wmi_bmof snd_hda_intel nf_conntrack iwlmvm nf_defrag_ipv6 snd_intel_dspcfg snd_intel_sdw_acpi nf_defrag_ipv4 libcrc32c crc32c_generic msr mac80211 snd_hda_codec x86_pkg_temp_thermal intel_powerclamp ip6t_rpfilter i915 coretemp ipt_rpfilter snd_hda_core crc32_pclmul snd_hwdep ghash_clmulni_intel aesni_intel snd_pcm libaes cmdlinepart crypto_simd evdev cryptd libarc4 input_leds led_class intel_cstate ip6table_raw snd_timer mac_hid iptable_raw intel_spi_pci intel_uncore iwlwifi uvcvideo psmouse intel_spi xt_pkttype serio_raw deflate snd videobuf2_vmalloc videobuf2_memops cec nf_log_ipv6 nls_iso8859_1 spi_nor videobuf2_v4l2 mei_me i2c_i801 efi_pstore tpm_crb nls_cp437 nf_log_ipv4 mtd videobuf2_common i2c_smbus soundcore nf_log_common vfat intel_lpss_pci mei drm_kms_helper tpm_tis intel_lpss xt_LOG tpm_tis_core idma64 cfg80211 intel_ish_ipc processor_thermal_device xt_tcpudp videodev virt_dma fat intel_gtt tpm ucsi_acpi processor_thermal_rfim
 processor_thermal_mbox processor_thermal_rapl rfkill typec_ucsi intel_ishtp i2c_algo_bit mc intel_rapl_common fb_sys_fops syscopyarea typec ip6table_filter sysfillrect 8250_pci sysimgblt intel_soc_dts_iosf ip6_tables rng_core roles sch_fq_codel iptable_filter wmi ctr tiny_power_button button battery i2c_hid_acpi i2c_hid int3403_thermal int340x_thermal_zone soc_button_array int3400_thermal video pinctrl_tigerlake acpi_pad intel_pmc_core intel_hid acpi_thermal_rel sparse_keymap acpi_tad ac loop cpufreq_powersave tun tap macvlan veth bridge stp llc kvm_intel kvm drm agpgart backlight irqbypass fuse i2c_core pstore configfs efivarfs ip_tables x_tables autofs4 hid_generic usbhid hid rtsx_pci_sdmmc mmc_core xhci_pci xhci_pci_renesas xhci_hcd atkbd libps2 thunderbolt usbcore nvme crc32c_intel nvme_core rtsx_pci t10_pi crc_t10dif crct10dif_
mon crct10dif_pclmul crct10dif_common i8042 rtc_cmos serio dm_mod zfs(PO) zunicode(PO) zzstd(O) zlua(O) zavl(PO) icp(PO)
 zcommon(PO) znvpair(PO) spl(O)
CPU: 4 PID: 757066 Comm: ThreadPoolForeg Tainted: P           O      5.12.7 #1-NixOS
Hardware name: Dell Inc. Latitude 7420/0125XH, BIOS 1.6.0 05/06/2021
RIP: 0010:iov_iter_advance+0x39a/0x3b0
Code: 8a fe ff ff 4d 89 e1 45 31 d2 e9 42 ff ff ff 49 89 f2 e9 70 ff ff ff 48 c7 c7 30 68 ba 9e c6 05 dc 8b fd 00 01 e8 8e da 3e 00 <0f> 0b 4c 8b 4b 18 eb b6 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00
RSP: 0018:ffffa8440ee3bc18 EFLAGS: 00010286
RAX: 0000000000000000 RBX: ffffa8440ee3bd78 RCX: ffff92592f718648
RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff92592f718640
RBP: 0000000000000000 R08: ffffffff9ef392e8 R09: 0000000000009ffb
R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000000
R13: ffffa8440ee3bcd0 R14: ffffa8440ee3bd78 R15: ffff925282b25600
FS:  00007f96a65d5640(0000) GS:ffff92592f700000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00002e263d4c1000 CR3: 00000001d915c002 CR4: 0000000000770ee0
PKRU: 55555554
Call Trace:
 zpl_iter_write+0x169/0x190 [zfs]
 do_iter_readv_writev+0x152/0x1b0
 do_iter_write+0x7c/0x1b0
 iter_file_splice_write+0x28d/0x410
 direct_splice_actor+0x2c/0x40
 splice_direct_to_actor+0xeb/0x210
 ? generic_file_splice_read+0x1b0/0x1b0
 do_splice_direct+0x8b/0xd0
 do_sendfile+0x310/0x450
 do_syscall_64+0x33/0x40
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f96d013d89a
Code: 48 89 da 4c 89 ce 5b e9 04 fe ff ff 0f 1f 40 00 31 c0 5b c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 49 89 ca b8 28 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a6 85 0c 00 f7 d8 64 89 01 48
RSP: 002b:00007f96a65d3828 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 00007f96a65d3aa0 RCX: 00007f96d013d89a
RDX: 0000000000000000 RSI: 0000000000000080 RDI: 000000000000009b
RBP: 00007f96a65d3870 R08: 00007f96a65d35d8 R09: 0000000000000000
R10: 0000000000000042 R11: 0000000000000246 R12: 00007f96a65d3be0
R13: 0000000000000042 R14: 0000000000000000 R15: 00007f96a65d3aa0
---[ end trace bf1fd1cadbc5df3e ]---

@JohnyPeaN
Copy link

@KenMacD

Just got this with 2.1.0-rc6:

2.1.0-rc6 doesnt contain this fix. You have to eighter pull master or wait for next tagged release (or apply #12178 to 2.1.0-rc6).

behlendorf pushed a commit to behlendorf/zfs that referenced this issue Jun 9, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with openzfs#11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue openzfs#11378
Closes openzfs#12041
Closes openzfs#12155
tonyhutter pushed a commit that referenced this issue Jun 23, 2021
The additional iter advance is incorrect, as copy_from_iter() has
already done the right thing.  This will result in the following
warning being printed to the console as of the 5.12 kernel.

    Attempted to advance past end of bvec iter

This change should have been included with #11378 when a
similar change was made on the read side.

Suggested-by: @siebenmann
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Rich Ercolani <rincebrain@gmail.com>
Issue #11378
Closes #12041
Closes #12155
(cherry picked from commit 3f81aba)
Signed-off-by: Jonathon Fernyhough <jonathon@m2x.dev>
@sammko
Copy link

sammko commented Jun 28, 2021

Could this have caused a ZFS-8000-8A? I had one file marked as corrupted. The devices in the pool all had 0 errors. Reading the entire file did not result in any IO errors and I believe the file was not corrupt at all (not certain on this). I removed the file, but the error state remained until I ran a scrub. I don't know what would have happened if I ran the scrub with the file still present. The only error I found in kernel logs is the one from this issue. I am not familiar enough with ZFS to know if the described situation can arise under normal conditions, but it does not make sense to me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang)
Projects
None yet
Development

No branches or pull requests