Still a pretty bad time on 5.4.6 with fuse_request_end.

Still a pretty bad time on 5.4.6 with fuse_request_end.

[Kyle Sanderson]

[400280.179731] BUG: unable to handle page fault for address: 0000000044000000
[400280.179842] #PF: supervisor instruction fetch in kernel mode
[400280.179938] #PF: error_code(0x0010) - not-present page
[400280.180032] PGD 0 P4D 0
[400280.180125] Oops: 0010 [#1] PREEMPT SMP NOPTI
[400280.180221] CPU: 5 PID: 6894 Comm: mergerfs Not tainted 5.4.6-gentoo #1
[400280.180318] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
BIOS 1.1c 06/25/2019
[400280.180424] RIP: 0010:0x44000000
[400280.180520] Code: Bad RIP value.
[400280.180610] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
[400280.180706] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
0000000000000001
[400280.180805] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
ffff88ed53bd5600
[400280.180904] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
ffffb155c1227c28
[400280.181003] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
ffff88eb184b8808
[400280.181103] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
ffff88ed53b45e80
[400280.181657] FS:  00007ff8076fc700(0000) GS:ffff88ed5fb40000(0000)
knlGS:0000000000000000
[400280.182211] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[400280.182532] CR2: 0000000043ffffd6 CR3: 000000084812a000 CR4:
00000000003406e0
[400280.183084] Call Trace:
[400280.183419]  ? fuse_request_end+0xae/0x1c0 [fuse]
[400280.183751]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
[400280.184084]  ? fuse_dev_write+0x6e/0xa0 [fuse]
[400280.184413]  ? do_iter_readv_writev+0x150/0x1c0
[400280.184736]  ? do_iter_write+0x80/0x190
[400280.185056]  ? vfs_writev+0xa3/0x100
[400280.185383]  ? __fget+0x73/0xb0
[400280.185699]  ? do_writev+0x65/0x100
[400280.186020]  ? do_syscall_64+0x54/0x190
[400280.186342]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[400280.186668] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
tveeprom snd dvb_core crc32c_intel soundcore pcspkr
ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
raid6_pq dm_mirror
[400280.186787]  dm_region_hash dm_log_writes dm_log_userspace dm_log
dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
pata_cmd64x
[400280.190120]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
nvme_fabrics virtio_net net_failover failover virtio_crypto
crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
virtio_console virtio_blk virtio_scsi virtio_ring virtio
[400280.194465] CR2: 0000000044000000
[400280.194787] ---[ end trace 74cb513785034f62 ]---
[400280.241518] RIP: 0010:0x44000000
[400280.241864] Code: Bad RIP value.
[400280.242181] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
[400280.242503] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
0000000000000001
[400280.243055] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
ffff88ed53bd5600
[400280.243607] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
ffffb155c1227c28
[400280.244158] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
ffff88eb184b8808
[400280.244707] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
ffff88ed53b45e80
[400280.245260] FS:  00007ff8076fc700(0000) GS:ffff88ed5fb40000(0000)
knlGS:0000000000000000
[400280.245813] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[400280.246134] CR2: 0000000043ffffd6 CR3: 000000084812a000 CR4:
00000000003406e0
[444999.511865] potentially unexpected fatal signal 6.
[444999.512234] CPU: 2 PID: 4341 Comm: rtorrent scgi Tainted: G      D
          5.4.6-gentoo #1
[444999.512783] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
BIOS 1.1c 06/25/2019
[444999.513329] RIP: 0033:0x7f6ce5da5ffb
[444999.513635] Code: da b8 ea 00 00 00 0f 05 48 3d 00 f0 ff ff 77 3f
41 89 c0 41 ba 08 00 00 00 31 d2 4c 89 ce bf 02 00 00 00 b8 0e 00 00
00 0f 05 <48> 8b 8c 24 08 01 00 00 64 48 33 0c 25 28 00 00 00 44 89 c0
75 1d
[444999.514421] RSP: 002b:00007f6cda9b9dc0 EFLAGS: 00000246 ORIG_RAX:
000000000000000e
[444999.514424] RAX: 0000000000000000 RBX: 0000000000000006 RCX:
00007f6ce5da5ffb
[444999.514426] RDX: 0000000000000000 RSI: 00007f6cda9b9dc0 RDI:
0000000000000002
[444999.514427] RBP: 00007f6cd40020d0 R08: 0000000000000000 R09:
00007f6cda9b9dc0
[444999.514428] R10: 0000000000000008 R11: 0000000000000246 R12:
00007f6cd46d7cb0
[444999.514430] R13: 00007f6cda9ba160 R14: 0000000000000002 R15:
0000000000000000
[444999.514431] FS:  00007f6cda9bb700 GS:  0000000000000000
[461505.766196] saa7164 0000:02:00.0: DVB: adapter 1 frontend 0
frequency 0 out of range (54000000..858000000)
[548849.079581] saa7164 0000:02:00.0: DVB: adapter 1 frontend 0
frequency 0 out of range (54000000..858000000)
[634641.506417] saa7164 0000:02:00.0: DVB: adapter 0 frontend 0
frequency 0 out of range (54000000..858000000)
[696992.559904] potentially unexpected fatal signal 6.
[696992.560225] CPU: 5 PID: 17827 Comm: rtorrent scgi Tainted: G
D           5.4.6-gentoo #1
[696992.567610] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
BIOS 1.1c 06/25/2019
[696992.568172] RIP: 0033:0x7febaf26cffb
[696992.568478] Code: da b8 ea 00 00 00 0f 05 48 3d 00 f0 ff ff 77 3f
41 89 c0 41 ba 08 00 00 00 31 d2 4c 89 ce bf 02 00 00 00 b8 0e 00 00
00 0f 05 <48> 8b 8c 24 08 01 00 00 64 48 33 0c 25 28 00 00 00 44 89 c0
75 1d
[696992.569259] RSP: 002b:00007feba38d8dc0 EFLAGS: 00000246 ORIG_RAX:
000000000000000e
[696992.569262] RAX: 0000000000000000 RBX: 0000000000000006 RCX:
00007febaf26cffb
[696992.569263] RDX: 0000000000000000 RSI: 00007feba38d8dc0 RDI:
0000000000000002
[696992.569264] RBP: 000055db261423f0 R08: 0000000000000000 R09:
00007feba38d8dc0
[696992.569265] R10: 0000000000000008 R11: 0000000000000246 R12:
000055db5c16fc90
[696992.569266] R13: 00007feba38d9160 R14: 0000000000000002 R15:
0000000000000000
[696992.569267] FS:  00007feba38da700 GS:  0000000000000000
[721144.741527] saa7164 0000:02:00.0: DVB: adapter 0 frontend 0
frequency 0 out of range (54000000..858000000)
[727177.875112] BUG: kernel NULL pointer dereference, address: 0000000000000005
[727177.875447] #PF: supervisor instruction fetch in kernel mode
[727177.875767] #PF: error_code(0x0010) - not-present page
[727177.876085] PGD 0 P4D 0
[727177.876401] Oops: 0010 [#2] PREEMPT SMP NOPTI
[727177.876721] CPU: 6 PID: 6919 Comm: mergerfs Tainted: G      D
     5.4.6-gentoo #1
[727177.877271] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
BIOS 1.1c 06/25/2019
[727177.877824] RIP: 0010:0x5
[727177.878142] Code: Bad RIP value.
[727177.878456] RSP: 0018:ffffb155c12cfc88 EFLAGS: 00010206
[727177.878776] RAX: 0000000000000005 RBX: ffff88ed52fbdaa0 RCX:
0000000000000001
[727177.879324] RDX: 0000000000000000 RSI: ffffb155c74e3d98 RDI:
ffff88ed4a4e6600
[727177.879871] RBP: ffff88ed4a4e6600 R08: 0000000000000000 R09:
ffffb155c12cfc28
[727177.880419] R10: ffffb155c12cfb8c R11: 0000000000000000 R12:
ffff88ed52fbdab0
[727177.880967] R13: 0000000000000005 R14: ffffb155c12cfd28 R15:
ffff88ed539ee980
[727177.881516] FS:  00007f45f3d17700(0000) GS:ffff88ed5fb80000(0000)
knlGS:0000000000000000
[727177.882066] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[727177.882386] CR2: ffffffffffffffdb CR3: 000000084838a000 CR4:
00000000003406e0
[727177.882933] Call Trace:
[727177.883266]  ? fuse_request_end+0xae/0x1c0 [fuse]
[727177.883597]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
[727177.883927]  ? fuse_dev_write+0x6e/0xa0 [fuse]
[727177.884255]  ? do_iter_readv_writev+0x150/0x1c0
[727177.884575]  ? do_iter_write+0x80/0x190
[727177.884893]  ? vfs_writev+0xa3/0x100
[727177.885209]  ? __switch_to+0x21/0x3f0
[727177.885530]  ? __call_rcu+0xc3/0x190
[727177.885848]  ? get_max_files+0x10/0x10
[727177.886169]  ? __fget+0x73/0xb0
[727177.886485]  ? do_writev+0x65/0x100
[727177.886803]  ? do_syscall_64+0x54/0x190
[727177.887122]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[727177.887446] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
tveeprom snd dvb_core crc32c_intel soundcore pcspkr
ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
raid6_pq dm_mirror
[727177.887564]  dm_region_hash dm_log_writes dm_log_userspace dm_log
dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
pata_cmd64x
[727177.890877]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
nvme_fabrics virtio_net net_failover failover virtio_crypto
crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
virtio_console virtio_blk virtio_scsi virtio_ring virtio
[727177.895163] CR2: 0000000000000005
[727177.895480] ---[ end trace 74cb513785034f63 ]---
[727178.401799] RIP: 0010:0x44000000
[727178.402142] Code: Bad RIP value.
[727178.402453] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
[727178.402769] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
0000000000000001
[727178.403312] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
ffff88ed53bd5600
[727178.403854] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
ffffb155c1227c28
[727178.404395] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
ffff88eb184b8808
[727178.404938] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
ffff88ed53b45e80
[727178.405482] FS:  00007f45f3d17700(0000) GS:ffff88ed5fb80000(0000)
knlGS:0000000000000000
[727178.406027] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[727178.406343] CR2: 0000000043ffffd6 CR3: 000000084838a000 CR4:
00000000003406e0
[743393.910213] BUG: kernel NULL pointer dereference, address: 0000000000000005
[743393.910548] #PF: supervisor instruction fetch in kernel mode
[743393.910868] #PF: error_code(0x0010) - not-present page
[743393.911187] PGD 0 P4D 0
[743393.911503] Oops: 0010 [#3] PREEMPT SMP NOPTI
[743393.911823] CPU: 7 PID: 6921 Comm: mergerfs Tainted: G      D
     5.4.6-gentoo #1
[743393.912372] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
BIOS 1.1c 06/25/2019
[743393.912925] RIP: 0010:0x5
[743393.913243] Code: Bad RIP value.
[743393.913558] RSP: 0018:ffffb155c12dfc88 EFLAGS: 00010206
[743393.913878] RAX: 0000000000000005 RBX: ffff88ed58471660 RCX:
0000000000000001
[743393.914426] RDX: 0000000000000000 RSI: ffffb155c74e3d98 RDI:
ffff88ed4a4e6600
[743393.914973] RBP: ffff88ed4a4e6600 R08: 0000000000000000 R09:
ffffb155c12dfc28
[743393.915521] R10: ffffb155c12dfb8c R11: 0000000000000000 R12:
ffff88ed58471670
[743393.916068] R13: 0000000000000005 R14: ffffb155c12dfd28 R15:
ffff88ed539ee980
[743393.916617] FS:  00007f45f2b11700(0000) GS:ffff88ed5fbc0000(0000)
knlGS:0000000000000000
[743393.917168] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[743393.917487] CR2: ffffffffffffffdb CR3: 000000084838a000 CR4:
00000000003406e0
[743393.918034] Call Trace:
[743393.918366]  ? fuse_request_end+0xae/0x1c0 [fuse]
[743393.918696]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
[743393.919027]  ? fuse_dev_write+0x6e/0xa0 [fuse]
[743393.919354]  ? do_iter_readv_writev+0x150/0x1c0
[743393.919675]  ? do_iter_write+0x80/0x190
[743393.919992]  ? vfs_writev+0xa3/0x100
[743393.920309]  ? preempt_count_sub+0x5/0x90
[743393.920626]  ? _raw_spin_unlock+0x12/0x30
[743393.920948]  ? __call_rcu+0xc3/0x190
[743393.921265]  ? get_max_files+0x10/0x10
[743393.921584]  ? __fget+0x73/0xb0
[743393.921901]  ? do_writev+0x65/0x100
[743393.922220]  ? do_syscall_64+0x54/0x190
[743393.922537]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[743393.922861] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
tveeprom snd dvb_core crc32c_intel soundcore pcspkr
ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
raid6_pq dm_mirror
[743393.922978]  dm_region_hash dm_log_writes dm_log_userspace dm_log
dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
pata_cmd64x
[743393.926289]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
nvme_fabrics virtio_net net_failover failover virtio_crypto
crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
virtio_console virtio_blk virtio_scsi virtio_ring virtio
[743393.937567] CR2: 0000000000000005
[743393.937884] ---[ end trace 74cb513785034f64 ]---
[743393.991952] RIP: 0010:0x44000000
[743393.992275] Code: Bad RIP value.
[743393.992588] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
[743393.992907] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
0000000000000001
[743393.993455] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
ffff88ed53bd5600
[743393.994001] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
ffffb155c1227c28
[743393.994549] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
ffff88eb184b8808
[743393.995097] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
ffff88ed53b45e80
[743393.995646] FS:  00007f45f2b11700(0000) GS:ffff88ed5fbc0000(0000)
knlGS:0000000000000000
[743393.996196] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[743393.996515] CR2: 0000000043ffffd6 CR3: 000000084838a000 CR4:
00000000003406e0

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Greg KH]

On Sat, Jan 04, 2020 at 05:15:30PM -0800, Kyle Sanderson wrote:
> [400280.179731] BUG: unable to handle page fault for address: 0000000044000000
> [400280.179842] #PF: supervisor instruction fetch in kernel mode
> [400280.179938] #PF: error_code(0x0010) - not-present page
> [400280.180032] PGD 0 P4D 0
> [400280.180125] Oops: 0010 [#1] PREEMPT SMP NOPTI
> [400280.180221] CPU: 5 PID: 6894 Comm: mergerfs Not tainted 5.4.6-gentoo #1

"still"?

When did this show up?  What were you doing to cause the issue?  Can you
run 'git bisect' to find the problem commit?  When/where did you report
this problem in the past?

thanks,

greg k-h

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Miklos Szeredi]

Hi,

Thanks for the report.

Is this readily reproducible?

Can you please do an "echo t > /proc/sysrq-trigger" after you see the
hang, and send the output.   Make sure you have enough dmesg buffer:

 - either add "log_buf_len=4M" to the kernel boot command
 - or recompile the kernel with CONFIG_LOG_BUF_SHIFT=22

Thanks,
Miklos


On Sun, Jan 5, 2020 at 2:15 AM Kyle Sanderson <kyle.leet@gmail.com> wrote:
>
> [400280.179731] BUG: unable to handle page fault for address: 0000000044000000
> [400280.179842] #PF: supervisor instruction fetch in kernel mode
> [400280.179938] #PF: error_code(0x0010) - not-present page
> [400280.180032] PGD 0 P4D 0
> [400280.180125] Oops: 0010 [#1] PREEMPT SMP NOPTI
> [400280.180221] CPU: 5 PID: 6894 Comm: mergerfs Not tainted 5.4.6-gentoo #1
> [400280.180318] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
> BIOS 1.1c 06/25/2019
> [400280.180424] RIP: 0010:0x44000000
> [400280.180520] Code: Bad RIP value.
> [400280.180610] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
> [400280.180706] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
> 0000000000000001
> [400280.180805] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
> ffff88ed53bd5600
> [400280.180904] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
> ffffb155c1227c28
> [400280.181003] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
> ffff88eb184b8808
> [400280.181103] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
> ffff88ed53b45e80
> [400280.181657] FS:  00007ff8076fc700(0000) GS:ffff88ed5fb40000(0000)
> knlGS:0000000000000000
> [400280.182211] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [400280.182532] CR2: 0000000043ffffd6 CR3: 000000084812a000 CR4:
> 00000000003406e0
> [400280.183084] Call Trace:
> [400280.183419]  ? fuse_request_end+0xae/0x1c0 [fuse]
> [400280.183751]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
> [400280.184084]  ? fuse_dev_write+0x6e/0xa0 [fuse]
> [400280.184413]  ? do_iter_readv_writev+0x150/0x1c0
> [400280.184736]  ? do_iter_write+0x80/0x190
> [400280.185056]  ? vfs_writev+0xa3/0x100
> [400280.185383]  ? __fget+0x73/0xb0
> [400280.185699]  ? do_writev+0x65/0x100
> [400280.186020]  ? do_syscall_64+0x54/0x190
> [400280.186342]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [400280.186668] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
> s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
> ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
> nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
> snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
> tveeprom snd dvb_core crc32c_intel soundcore pcspkr
> ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
> crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
> libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
> ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
> igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
> squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
> zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
> raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
> dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
> raid6_pq dm_mirror
> [400280.186787]  dm_region_hash dm_log_writes dm_log_userspace dm_log
> dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
> dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
> dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
> xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
> nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
> 3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
> scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
> arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
> pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
> sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
> sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
> pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
> pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
> pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
> pata_cmd64x
> [400280.190120]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
> iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
> nvme_fabrics virtio_net net_failover failover virtio_crypto
> crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
> virtio_console virtio_blk virtio_scsi virtio_ring virtio
> [400280.194465] CR2: 0000000044000000
> [400280.194787] ---[ end trace 74cb513785034f62 ]---
> [400280.241518] RIP: 0010:0x44000000
> [400280.241864] Code: Bad RIP value.
> [400280.242181] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
> [400280.242503] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
> 0000000000000001
> [400280.243055] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
> ffff88ed53bd5600
> [400280.243607] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
> ffffb155c1227c28
> [400280.244158] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
> ffff88eb184b8808
> [400280.244707] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
> ffff88ed53b45e80
> [400280.245260] FS:  00007ff8076fc700(0000) GS:ffff88ed5fb40000(0000)
> knlGS:0000000000000000
> [400280.245813] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [400280.246134] CR2: 0000000043ffffd6 CR3: 000000084812a000 CR4:
> 00000000003406e0
> [444999.511865] potentially unexpected fatal signal 6.
> [444999.512234] CPU: 2 PID: 4341 Comm: rtorrent scgi Tainted: G      D
>           5.4.6-gentoo #1
> [444999.512783] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
> BIOS 1.1c 06/25/2019
> [444999.513329] RIP: 0033:0x7f6ce5da5ffb
> [444999.513635] Code: da b8 ea 00 00 00 0f 05 48 3d 00 f0 ff ff 77 3f
> 41 89 c0 41 ba 08 00 00 00 31 d2 4c 89 ce bf 02 00 00 00 b8 0e 00 00
> 00 0f 05 <48> 8b 8c 24 08 01 00 00 64 48 33 0c 25 28 00 00 00 44 89 c0
> 75 1d
> [444999.514421] RSP: 002b:00007f6cda9b9dc0 EFLAGS: 00000246 ORIG_RAX:
> 000000000000000e
> [444999.514424] RAX: 0000000000000000 RBX: 0000000000000006 RCX:
> 00007f6ce5da5ffb
> [444999.514426] RDX: 0000000000000000 RSI: 00007f6cda9b9dc0 RDI:
> 0000000000000002
> [444999.514427] RBP: 00007f6cd40020d0 R08: 0000000000000000 R09:
> 00007f6cda9b9dc0
> [444999.514428] R10: 0000000000000008 R11: 0000000000000246 R12:
> 00007f6cd46d7cb0
> [444999.514430] R13: 00007f6cda9ba160 R14: 0000000000000002 R15:
> 0000000000000000
> [444999.514431] FS:  00007f6cda9bb700 GS:  0000000000000000
> [461505.766196] saa7164 0000:02:00.0: DVB: adapter 1 frontend 0
> frequency 0 out of range (54000000..858000000)
> [548849.079581] saa7164 0000:02:00.0: DVB: adapter 1 frontend 0
> frequency 0 out of range (54000000..858000000)
> [634641.506417] saa7164 0000:02:00.0: DVB: adapter 0 frontend 0
> frequency 0 out of range (54000000..858000000)
> [696992.559904] potentially unexpected fatal signal 6.
> [696992.560225] CPU: 5 PID: 17827 Comm: rtorrent scgi Tainted: G
> D           5.4.6-gentoo #1
> [696992.567610] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
> BIOS 1.1c 06/25/2019
> [696992.568172] RIP: 0033:0x7febaf26cffb
> [696992.568478] Code: da b8 ea 00 00 00 0f 05 48 3d 00 f0 ff ff 77 3f
> 41 89 c0 41 ba 08 00 00 00 31 d2 4c 89 ce bf 02 00 00 00 b8 0e 00 00
> 00 0f 05 <48> 8b 8c 24 08 01 00 00 64 48 33 0c 25 28 00 00 00 44 89 c0
> 75 1d
> [696992.569259] RSP: 002b:00007feba38d8dc0 EFLAGS: 00000246 ORIG_RAX:
> 000000000000000e
> [696992.569262] RAX: 0000000000000000 RBX: 0000000000000006 RCX:
> 00007febaf26cffb
> [696992.569263] RDX: 0000000000000000 RSI: 00007feba38d8dc0 RDI:
> 0000000000000002
> [696992.569264] RBP: 000055db261423f0 R08: 0000000000000000 R09:
> 00007feba38d8dc0
> [696992.569265] R10: 0000000000000008 R11: 0000000000000246 R12:
> 000055db5c16fc90
> [696992.569266] R13: 00007feba38d9160 R14: 0000000000000002 R15:
> 0000000000000000
> [696992.569267] FS:  00007feba38da700 GS:  0000000000000000
> [721144.741527] saa7164 0000:02:00.0: DVB: adapter 0 frontend 0
> frequency 0 out of range (54000000..858000000)
> [727177.875112] BUG: kernel NULL pointer dereference, address: 0000000000000005
> [727177.875447] #PF: supervisor instruction fetch in kernel mode
> [727177.875767] #PF: error_code(0x0010) - not-present page
> [727177.876085] PGD 0 P4D 0
> [727177.876401] Oops: 0010 [#2] PREEMPT SMP NOPTI
> [727177.876721] CPU: 6 PID: 6919 Comm: mergerfs Tainted: G      D
>      5.4.6-gentoo #1
> [727177.877271] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
> BIOS 1.1c 06/25/2019
> [727177.877824] RIP: 0010:0x5
> [727177.878142] Code: Bad RIP value.
> [727177.878456] RSP: 0018:ffffb155c12cfc88 EFLAGS: 00010206
> [727177.878776] RAX: 0000000000000005 RBX: ffff88ed52fbdaa0 RCX:
> 0000000000000001
> [727177.879324] RDX: 0000000000000000 RSI: ffffb155c74e3d98 RDI:
> ffff88ed4a4e6600
> [727177.879871] RBP: ffff88ed4a4e6600 R08: 0000000000000000 R09:
> ffffb155c12cfc28
> [727177.880419] R10: ffffb155c12cfb8c R11: 0000000000000000 R12:
> ffff88ed52fbdab0
> [727177.880967] R13: 0000000000000005 R14: ffffb155c12cfd28 R15:
> ffff88ed539ee980
> [727177.881516] FS:  00007f45f3d17700(0000) GS:ffff88ed5fb80000(0000)
> knlGS:0000000000000000
> [727177.882066] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [727177.882386] CR2: ffffffffffffffdb CR3: 000000084838a000 CR4:
> 00000000003406e0
> [727177.882933] Call Trace:
> [727177.883266]  ? fuse_request_end+0xae/0x1c0 [fuse]
> [727177.883597]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
> [727177.883927]  ? fuse_dev_write+0x6e/0xa0 [fuse]
> [727177.884255]  ? do_iter_readv_writev+0x150/0x1c0
> [727177.884575]  ? do_iter_write+0x80/0x190
> [727177.884893]  ? vfs_writev+0xa3/0x100
> [727177.885209]  ? __switch_to+0x21/0x3f0
> [727177.885530]  ? __call_rcu+0xc3/0x190
> [727177.885848]  ? get_max_files+0x10/0x10
> [727177.886169]  ? __fget+0x73/0xb0
> [727177.886485]  ? do_writev+0x65/0x100
> [727177.886803]  ? do_syscall_64+0x54/0x190
> [727177.887122]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [727177.887446] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
> s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
> ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
> nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
> snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
> tveeprom snd dvb_core crc32c_intel soundcore pcspkr
> ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
> crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
> libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
> ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
> igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
> squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
> zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
> raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
> dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
> raid6_pq dm_mirror
> [727177.887564]  dm_region_hash dm_log_writes dm_log_userspace dm_log
> dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
> dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
> dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
> xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
> nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
> 3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
> scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
> arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
> pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
> sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
> sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
> pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
> pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
> pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
> pata_cmd64x
> [727177.890877]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
> iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
> nvme_fabrics virtio_net net_failover failover virtio_crypto
> crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
> virtio_console virtio_blk virtio_scsi virtio_ring virtio
> [727177.895163] CR2: 0000000000000005
> [727177.895480] ---[ end trace 74cb513785034f63 ]---
> [727178.401799] RIP: 0010:0x44000000
> [727178.402142] Code: Bad RIP value.
> [727178.402453] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
> [727178.402769] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
> 0000000000000001
> [727178.403312] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
> ffff88ed53bd5600
> [727178.403854] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
> ffffb155c1227c28
> [727178.404395] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
> ffff88eb184b8808
> [727178.404938] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
> ffff88ed53b45e80
> [727178.405482] FS:  00007f45f3d17700(0000) GS:ffff88ed5fb80000(0000)
> knlGS:0000000000000000
> [727178.406027] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [727178.406343] CR2: 0000000043ffffd6 CR3: 000000084838a000 CR4:
> 00000000003406e0
> [743393.910213] BUG: kernel NULL pointer dereference, address: 0000000000000005
> [743393.910548] #PF: supervisor instruction fetch in kernel mode
> [743393.910868] #PF: error_code(0x0010) - not-present page
> [743393.911187] PGD 0 P4D 0
> [743393.911503] Oops: 0010 [#3] PREEMPT SMP NOPTI
> [743393.911823] CPU: 7 PID: 6921 Comm: mergerfs Tainted: G      D
>      5.4.6-gentoo #1
> [743393.912372] Hardware name: Supermicro Super Server/A2SDi-8C-HLN4F,
> BIOS 1.1c 06/25/2019
> [743393.912925] RIP: 0010:0x5
> [743393.913243] Code: Bad RIP value.
> [743393.913558] RSP: 0018:ffffb155c12dfc88 EFLAGS: 00010206
> [743393.913878] RAX: 0000000000000005 RBX: ffff88ed58471660 RCX:
> 0000000000000001
> [743393.914426] RDX: 0000000000000000 RSI: ffffb155c74e3d98 RDI:
> ffff88ed4a4e6600
> [743393.914973] RBP: ffff88ed4a4e6600 R08: 0000000000000000 R09:
> ffffb155c12dfc28
> [743393.915521] R10: ffffb155c12dfb8c R11: 0000000000000000 R12:
> ffff88ed58471670
> [743393.916068] R13: 0000000000000005 R14: ffffb155c12dfd28 R15:
> ffff88ed539ee980
> [743393.916617] FS:  00007f45f2b11700(0000) GS:ffff88ed5fbc0000(0000)
> knlGS:0000000000000000
> [743393.917168] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [743393.917487] CR2: ffffffffffffffdb CR3: 000000084838a000 CR4:
> 00000000003406e0
> [743393.918034] Call Trace:
> [743393.918366]  ? fuse_request_end+0xae/0x1c0 [fuse]
> [743393.918696]  ? fuse_dev_do_write+0x2a0/0x3e0 [fuse]
> [743393.919027]  ? fuse_dev_write+0x6e/0xa0 [fuse]
> [743393.919354]  ? do_iter_readv_writev+0x150/0x1c0
> [743393.919675]  ? do_iter_write+0x80/0x190
> [743393.919992]  ? vfs_writev+0xa3/0x100
> [743393.920309]  ? preempt_count_sub+0x5/0x90
> [743393.920626]  ? _raw_spin_unlock+0x12/0x30
> [743393.920948]  ? __call_rcu+0xc3/0x190
> [743393.921265]  ? get_max_files+0x10/0x10
> [743393.921584]  ? __fget+0x73/0xb0
> [743393.921901]  ? do_writev+0x65/0x100
> [743393.922220]  ? do_syscall_64+0x54/0x190
> [743393.922537]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [743393.922861] Modules linked in: nfsd auth_rpcgss nfs_acl tda18271
> s5h1411 cfg80211 rfkill 8021q garp stp mrp llc xt_length xt_conntrack
> ip6table_filter ip6_tables cachefiles x86_pkg_temp_thermal
> nf_conntrack_ftp kvm_intel nf_conntrack nf_defrag_ipv4 kvm irqbypass
> snd_pcm coretemp crct10dif_pclmul saa7164 snd_timer crc32_pclmul
> tveeprom snd dvb_core crc32c_intel soundcore pcspkr
> ghash_clmulni_intel videodev mc i2c_ismt acpi_cpufreq xts aesni_intel
> crypto_simd cryptd glue_helper crc32_generic cbc sha256_generic
> libsha256 ixgb ixgbe tulip cxgb3 cxgb mdio cxgb4 vxge bonding vxlan
> ip6_udp_tunnel udp_tunnel macvlan vmxnet3 tg3 sky2 r8169 pcnet32 mii
> igb dca i2c_algo_bit i2c_core e1000 bnx2 atl1c msdos fat cramfs
> squashfs fuse xfs nfs lockd grace sunrpc fscache jfs reiserfs btrfs
> zstd_decompress zstd_compress ext4 jbd2 ext2 mbcache linear raid10
> raid1 raid0 dm_zero dm_verity reed_solomon dm_thin_pool dm_switch
> dm_snapshot dm_raid raid456 async_raid6_recov async_memcpy async_pq
> raid6_pq dm_mirror
> [743393.922978]  dm_region_hash dm_log_writes dm_log_userspace dm_log
> dm_integrity async_xor async_tx xor dm_flakey dm_era dm_delay dm_crypt
> dm_cache_smq dm_cache dm_persistent_data libcrc32c dm_bufio
> dm_bio_prison dm_mod dax firewire_core crc_itu_t sl811_hcd xhci_pci
> xhci_hcd usb_storage mpt3sas raid_class aic94xx libsas lpfc nvmet_fc
> nvmet qla2xxx megaraid_sas megaraid_mbox megaraid_mm aacraid sx8 hpsa
> 3w_9xxx 3w_xxxx 3w_sas mptsas scsi_transport_sas mptfc
> scsi_transport_fc mptspi mptscsih mptbase imm parport sym53c8xx initio
> arcmsr aic7xxx aic79xx scsi_transport_spi sr_mod cdrom sg sd_mod
> pdc_adma sata_inic162x sata_mv ata_piix ahci libahci sata_qstor
> sata_vsc sata_uli sata_sis sata_sx4 sata_nv sata_via sata_svw
> sata_sil24 sata_sil sata_promise pata_via pata_jmicron pata_marvell
> pata_sis pata_netcell pata_pdc202xx_old pata_atiixp pata_amd pata_ali
> pata_it8213 pata_pcmcia pata_serverworks pata_oldpiix pata_artop
> pata_it821x pata_hpt3x2n pata_hpt3x3 pata_hpt37x pata_hpt366
> pata_cmd64x
> [743393.926289]  pata_sil680 pata_pdc2027x nvme_fc nvme_rdma rdma_cm
> iw_cm ib_cm ib_core ipv6 crc_ccitt nf_defrag_ipv6 configfs
> nvme_fabrics virtio_net net_failover failover virtio_crypto
> crypto_engine virtio_mmio virtio_pci virtio_balloon virtio_rng
> virtio_console virtio_blk virtio_scsi virtio_ring virtio
> [743393.937567] CR2: 0000000000000005
> [743393.937884] ---[ end trace 74cb513785034f64 ]---
> [743393.991952] RIP: 0010:0x44000000
> [743393.992275] Code: Bad RIP value.
> [743393.992588] RSP: 0018:ffffb155c1227c88 EFLAGS: 00010206
> [743393.992907] RAX: 0000000044000000 RBX: ffff88eb184b87f8 RCX:
> 0000000000000001
> [743393.993455] RDX: 0000000000000000 RSI: ffffb155c0857dc0 RDI:
> ffff88ed53bd5600
> [743393.994001] RBP: ffff88ed53bd5600 R08: 0000000000000000 R09:
> ffffb155c1227c28
> [743393.994549] R10: ffffb155c1227b8c R11: 0000000000000000 R12:
> ffff88eb184b8808
> [743393.995097] R13: 0000000044000000 R14: ffffb155c1227d28 R15:
> ffff88ed53b45e80
> [743393.995646] FS:  00007f45f2b11700(0000) GS:ffff88ed5fbc0000(0000)
> knlGS:0000000000000000
> [743393.996196] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [743393.996515] CR2: 0000000043ffffd6 CR3: 000000084838a000 CR4:
> 00000000003406e0

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[michael+lkml]

From: Michael Stapelberg <michael+lkml@stapelberg.ch>

Hey,

I recently ran into this, too. The symptom for me is that processes using the
affected FUSE file system hang indefinitely, sync(2) system calls hang
indefinitely, and even triggering an abort via echo 1 >
/sys/fs/fuse/connections/*/abort does not get the file system unstuck (there is
always 1 request still pending). Only removing power will get the machine
unstuck.

I’m triggering this when building packages for https://distr1.org/, which uses a
FUSE daemon (written in Go using the jacobsa/fuse package) to provide package
contents.

I bisected the issue to commit
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=2b319d1f6f92a4ced9897678113d176ee16ae85d

With that commit, I run into a kernel oops within ≈1 minute after starting my
batch build. With the commit before, I can batch build for many minutes without
issues.

…and just in case it matters, building linux from HEAD
(f757165705e92db62f85a1ad287e9251d1f2cd82) with that commit reverted results in
a working kernel, too.

Find below a backtrace full from kgdb, with fs/fuse/dev.c compiled with -O0:

(gdb) bt full
#0  0xffff888139a36600 in ?? ()
No symbol table info available.
#1  0xffffffff8137b368 in fuse_request_end (fc=0xffff888139a36600,
req=0xffff8880b7f333b8) at fs/fuse/dev.c:328
        fiq = 0xffff888139a36648
        async = true
#2  0xffffffff8137f488 in fuse_dev_do_write (fud=0xffff888139a36600,
cs=0xffffc9000dd7fa58, nbytes=4294967294) at fs/fuse/dev.c:1911
        err = 0
        fc = 0xffff888139a36600
        fpq = 0xffff8881390e5148
        req = 0xffff8880b7f333b8
        oh = {len = 16, error = -2, unique = 2692038}
#3  0xffffffff8137f569 in fuse_dev_write (iocb=0xffffc9000093be48,
from=0xffffc9000093be20) at fs/fuse/dev.c:1933
        cs = {write = 0, req = 0xffff8880b7f333b8, iter =
0xffffc9000093be20, pipebufs = 0x0 <fixed_percpu_data>, currbuf = 0x0
<fixed_percpu_data>, pipe = 0x0 <fixed_percpu_data>, nr_segs = 0,
          pg = 0x0 <fixed_percpu_data>, len = 0, offset = 24, move_pages = 0}
        fud = 0xffff8881390e5140
#4  0xffffffff811fe4de in call_write_iter (file=<optimized out>,
iter=<optimized out>, kio=<optimized out>) at
./include/linux/fs.h:1902
No locals.
#5  new_sync_write (filp=0xffff888123800800, buf=<optimized out>,
len=<optimized out>, ppos=0xffffc9000093bee8) at fs/read_write.c:483
        iov = {iov_base = 0xc00082a008, iov_len = 16}
        kiocb = {ki_filp = 0xffff888123800800, ki_pos = 0, ki_complete
= 0x0 <fixed_percpu_data>, private = 0x0 <fixed_percpu_data>, ki_flags
= 0, ki_hint = 0, ki_ioprio = 0, ki_cookie = 0}
        iter = {type = 5, iov_offset = 0, count = 0, {iov =
0xffffc9000093be20, kvec = 0xffffc9000093be20, bvec =
0xffffc9000093be20, pipe = 0xffffc9000093be20}, {nr_segs = 0, {head =
0,
              start_head = 0}}}
        ret = <optimized out>
#6  0xffffffff811fe594 in __vfs_write (file=<optimized out>,
p=<optimized out>, count=<optimized out>, pos=<optimized out>) at
fs/read_write.c:496
No locals.
#7  0xffffffff81200fa4 in vfs_write (pos=<optimized out>, count=16,
buf=<optimized out>, file=<optimized out>) at fs/read_write.c:558
        ret = 16
        ret = <optimized out>
#8  vfs_write (file=0xffff888123800800, buf=0xc00082a008 "\020",
count=16, pos=0xffffc9000093bee8) at fs/read_write.c:542
        ret = 16
#9  0xffffffff81201252 in ksys_write (fd=<optimized out>,
buf=0xc00082a008 "\020", count=16) at fs/read_write.c:611
        pos = 0
        ppos = <optimized out>
        f = <optimized out>
        ret = 824642281480
#10 0xffffffff812012e5 in __do_sys_write (count=<optimized out>,
buf=<optimized out>, fd=<optimized out>) at fs/read_write.c:623
No locals.
#11 __se_sys_write (count=<optimized out>, buf=<optimized out>,
fd=<optimized out>) at fs/read_write.c:620
        ret = <optimized out>
        ret = <optimized out>
#12 __x64_sys_write (regs=<optimized out>) at fs/read_write.c:620
No locals.
#13 0xffffffff810027f8 in do_syscall_64 (nr=<optimized out>,
regs=0xffffc9000093bf58) at arch/x86/entry/common.c:294
        ti = <optimized out>
#14 0xffffffff81e0007c in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:175
No locals.
#15 0x0000000000000000 in ?? ()
No symbol table info available.

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Miklos Szeredi]

On Sun, Feb 9, 2020 at 9:09 AM <michael+lkml@stapelberg.ch> wrote:
>
> From: Michael Stapelberg <michael+lkml@stapelberg.ch>
>
> Hey,
>
> I recently ran into this, too. The symptom for me is that processes using the
> affected FUSE file system hang indefinitely, sync(2) system calls hang
> indefinitely, and even triggering an abort via echo 1 >
> /sys/fs/fuse/connections/*/abort does not get the file system unstuck (there is
> always 1 request still pending). Only removing power will get the machine
> unstuck.
>
> I’m triggering this when building packages for https://distr1.org/, which uses a
> FUSE daemon (written in Go using the jacobsa/fuse package) to provide package
> contents.
>
> I bisected the issue to commit
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=2b319d1f6f92a4ced9897678113d176ee16ae85d
>
> With that commit, I run into a kernel oops within ≈1 minute after starting my
> batch build. With the commit before, I can batch build for many minutes without
> issues.

Pretty weird.   I'm not seeing how this could change behavior, as the
args->end value is not changed after being initialized, and so moving
the test later should not make a difference.

Could you print out the complete contents of req->args?

Thanks,
Miklos

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Michael Stapelberg]

Sure: here’s a backtrace and req->args printed:

(gdb) bt full
#0  0xffffffff82000ff3 in __x86_indirect_thunk_r8 () at
arch/x86/lib/retpoline.S:40
No locals.
#1  0xffffffff8137ec68 in fuse_request_end (fc=0xffff88813a57be00,
req=0xffff88813a5a3770) at fs/fuse/dev.c:329
        fiq = 0xffff88813a57be48
        async = true
#2  0xffffffff81382d88 in fuse_dev_do_write (fud=0xffff88813a57be00,
cs=0xffffc90002fafa00, nbytes=4294967294) at fs/fuse/dev.c:1912
        err = 0
        fc = 0xffff88813a57be00
        fpq = 0xffff888132815f48
        req = 0xffff88813a5a3770
        oh = {
          len = 16,
          error = -2,
          unique = 66942
        }
#3  0xffffffff81382e69 in fuse_dev_write (iocb=0xffffc900008cbe48,
from=0xffffc900008cbe20) at fs/fuse/dev.c:1934
        cs = {
          write = 0,
          req = 0xffff88813a5a3770,
          iter = 0xffffc900008cbe20,
          pipebufs = 0x0 <fixed_percpu_data>,
          currbuf = 0x0 <fixed_percpu_data>,
          pipe = 0x0 <fixed_percpu_data>,
          nr_segs = 0,
          pg = 0x0 <fixed_percpu_data>,
          len = 0,
          offset = 24,
          move_pages = 0
        }
        fud = 0xffff888132815f40
#4  0xffffffff8120122e in call_write_iter (file=<optimized out>,
iter=<optimized out>, kio=<optimized out>) at
./include/linux/fs.h:1901
No locals.
#5  new_sync_write (filp=0xffff888119886b00, buf=<optimized out>,
len=<optimized out>, ppos=0xffffc900008cbee8) at fs/read_write.c:483
        iov = {
          iov_base = 0xc0008ec008,
          iov_len = 16
        }
        kiocb = {
          ki_filp = 0xffff888119886b00,
          ki_pos = 0,
          ki_complete = 0x0 <fixed_percpu_data>,
          private = 0x0 <fixed_percpu_data>,
          ki_flags = 0,
          ki_hint = 0,
          ki_ioprio = 0,
          ki_cookie = 0
        }
        iter = {
          type = 5,
          iov_offset = 0,
          count = 0,
          {
            iov = 0xffffc900008cbe20,
            kvec = 0xffffc900008cbe20,
            bvec = 0xffffc900008cbe20,
            pipe = 0xffffc900008cbe20
          },
          {
            nr_segs = 0,
            {
              head = 0,
              start_head = 0
            }
          }
        }
        ret = <optimized out>
#6  0xffffffff812012e4 in __vfs_write (file=<optimized out>,
p=<optimized out>, count=<optimized out>, pos=<optimized out>) at
fs/read_write.c:496
No locals.
#7  0xffffffff81203f04 in vfs_write (pos=<optimized out>, count=16,
buf=<optimized out>, file=<optimized out>) at fs/read_write.c:558
        ret = 16
        ret = <optimized out>
#8  vfs_write (file=0xffff888119886b00, buf=0xc0008ec008 "\020",
count=16, pos=0xffffc900008cbee8) at fs/read_write.c:542
        ret = 16
#9  0xffffffff812041b2 in ksys_write (fd=<optimized out>,
buf=0xc0008ec008 "\020", count=16) at fs/read_write.c:611
        pos = 0
        ppos = <optimized out>
        f = <optimized out>
        ret = 824643076104
#10 0xffffffff81204245 in __do_sys_write (count=<optimized out>,
buf=<optimized out>, fd=<optimized out>) at fs/read_write.c:623
No locals.
#11 __se_sys_write (count=<optimized out>, buf=<optimized out>,
fd=<optimized out>) at fs/read_write.c:620
        ret = <optimized out>
        ret = <optimized out>
#12 __x64_sys_write (regs=<optimized out>) at fs/read_write.c:620
No locals.
#13 0xffffffff810028a8 in do_syscall_64 (nr=<optimized out>,
regs=0xffffc900008cbf58) at arch/x86/entry/common.c:294
        ti = <optimized out>
#14 0xffffffff81e0007c in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:175
No locals.
#15 0x0000000000000000 in ?? ()
No symbol table info available.

(gdb) p *req->args
$5 = {
  nodeid = 18446683600620026424,
  opcode = 2167928246,
  in_numargs = 65535,
  out_numargs = 65535,
  force = false,
  noreply = false,
  nocreds = false,
  in_pages = false,
  out_pages = false,
  out_argvar = true,
  page_zeroing = true,
  page_replace = false,
  in_args = {{
      size = 978828800,
      value = 0x2fafce0
    }, {
      size = 978992728,
      value = 0xffffffff8138efaa <fuse_alloc_forget+26>
    }, {
      size = 50002688,
      value = 0xffffffff8138635f <fuse_lookup_name+255>
    }},
  out_args = {{
      size = 570,
      value = 0xffffc90002fafb10
    }, {
      size = 6876,
      value = 0x3000000001adc
    }},
  end = 0x1000100000001
}

Independently, as a separate test, I have also modified the source like this:

bool async;
bool async_early = req->args->end;

if (test_and_set_bit(FR_FINISHED, &req->flags))
goto put_request;

async = req->args->end;

…and printed the value of async and async_early. async is true,
async_early is false.

Perhaps some other routine is modifying the request, and checking
req->args->end early enough masks that bug?

On Tue, Feb 11, 2020 at 11:55 AM Miklos Szeredi <miklos@szeredi.hu> wrote:
>
> On Sun, Feb 9, 2020 at 9:09 AM <michael+lkml@stapelberg.ch> wrote:
> >
> > From: Michael Stapelberg <michael+lkml@stapelberg.ch>
> >
> > Hey,
> >
> > I recently ran into this, too. The symptom for me is that processes using the
> > affected FUSE file system hang indefinitely, sync(2) system calls hang
> > indefinitely, and even triggering an abort via echo 1 >
> > /sys/fs/fuse/connections/*/abort does not get the file system unstuck (there is
> > always 1 request still pending). Only removing power will get the machine
> > unstuck.
> >
> > I’m triggering this when building packages for https://distr1.org/, which uses a
> > FUSE daemon (written in Go using the jacobsa/fuse package) to provide package
> > contents.
> >
> > I bisected the issue to commit
> > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=2b319d1f6f92a4ced9897678113d176ee16ae85d
> >
> > With that commit, I run into a kernel oops within ≈1 minute after starting my
> > batch build. With the commit before, I can batch build for many minutes without
> > issues.
>
> Pretty weird.   I'm not seeing how this could change behavior, as the
> args->end value is not changed after being initialized, and so moving
> the test later should not make a difference.
>
> Could you print out the complete contents of req->args?
>
> Thanks,
> Miklos

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Miklos Szeredi]

On Wed, Feb 12, 2020 at 8:58 AM Michael Stapelberg
<michael+lkml@stapelberg.ch> wrote:

> (gdb) p *req->args
> $5 = {
>   nodeid = 18446683600620026424,
>   opcode = 2167928246,
>   in_numargs = 65535,
>   out_numargs = 65535,
>   force = false,
>   noreply = false,
>   nocreds = false,
>   in_pages = false,
>   out_pages = false,
>   out_argvar = true,
>   page_zeroing = true,
>   page_replace = false,
>   in_args = {{
>       size = 978828800,
>       value = 0x2fafce0
>     }, {
>       size = 978992728,
>       value = 0xffffffff8138efaa <fuse_alloc_forget+26>
>     }, {
>       size = 50002688,
>       value = 0xffffffff8138635f <fuse_lookup_name+255>
>     }},
>   out_args = {{
>       size = 570,
>       value = 0xffffc90002fafb10
>     }, {
>       size = 6876,
>       value = 0x3000000001adc
>     }},
>   end = 0x1000100000001
> }

Okay, that looks like rubbish, the request was possibly freed and overwritten.

> Independently, as a separate test, I have also modified the source like this:
>
> bool async;
> bool async_early = req->args->end;
>
> if (test_and_set_bit(FR_FINISHED, &req->flags))
> goto put_request;
>
> async = req->args->end;
>
> …and printed the value of async and async_early. async is true,
> async_early is false.

Can you save and print out the value of req->opcode before the
test_and_set_bit()?

Thanks,
Miklos

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Michael Stapelberg]

Unfortunately not: when I change the code like so:

    bool async;
    uint32_t opcode_early = req->args->opcode;

    if (test_and_set_bit(FR_FINISHED, &req->flags))
        goto put_request;

    async = req->args->end;

…gdb only reports:

(gdb) bt
#0  0x000000a700000001 in ?? ()
#1  0xffffffff8137fc99 in fuse_copy_finish (cs=0x20000ffffffff) at
fs/fuse/dev.c:681
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

But maybe that’s a hint in and of itself?

On Wed, Feb 12, 2020 at 9:34 AM Miklos Szeredi <miklos@szeredi.hu> wrote:
>
> On Wed, Feb 12, 2020 at 8:58 AM Michael Stapelberg
> <michael+lkml@stapelberg.ch> wrote:
>
> > (gdb) p *req->args
> > $5 = {
> >   nodeid = 18446683600620026424,
> >   opcode = 2167928246,
> >   in_numargs = 65535,
> >   out_numargs = 65535,
> >   force = false,
> >   noreply = false,
> >   nocreds = false,
> >   in_pages = false,
> >   out_pages = false,
> >   out_argvar = true,
> >   page_zeroing = true,
> >   page_replace = false,
> >   in_args = {{
> >       size = 978828800,
> >       value = 0x2fafce0
> >     }, {
> >       size = 978992728,
> >       value = 0xffffffff8138efaa <fuse_alloc_forget+26>
> >     }, {
> >       size = 50002688,
> >       value = 0xffffffff8138635f <fuse_lookup_name+255>
> >     }},
> >   out_args = {{
> >       size = 570,
> >       value = 0xffffc90002fafb10
> >     }, {
> >       size = 6876,
> >       value = 0x3000000001adc
> >     }},
> >   end = 0x1000100000001
> > }
>
> Okay, that looks like rubbish, the request was possibly freed and overwritten.
>
> > Independently, as a separate test, I have also modified the source like this:
> >
> > bool async;
> > bool async_early = req->args->end;
> >
> > if (test_and_set_bit(FR_FINISHED, &req->flags))
> > goto put_request;
> >
> > async = req->args->end;
> >
> > …and printed the value of async and async_early. async is true,
> > async_early is false.
>
> Can you save and print out the value of req->opcode before the
> test_and_set_bit()?
>
> Thanks,
> Miklos

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Miklos Szeredi]

[-- Attachment #1: Type: text/plain, Size: 755 bytes --]

On Wed, Feb 12, 2020 at 10:38 AM Michael Stapelberg
<michael+lkml@stapelberg.ch> wrote:
>
> Unfortunately not: when I change the code like so:
>
>     bool async;
>     uint32_t opcode_early = req->args->opcode;
>
>     if (test_and_set_bit(FR_FINISHED, &req->flags))
>         goto put_request;
>
>     async = req->args->end;
>
> …gdb only reports:
>
> (gdb) bt
> #0  0x000000a700000001 in ?? ()
> #1  0xffffffff8137fc99 in fuse_copy_finish (cs=0x20000ffffffff) at
> fs/fuse/dev.c:681
> Backtrace stopped: previous frame inner to this frame (corrupt stack?)
>
> But maybe that’s a hint in and of itself?

Yep, it's a stack use after return bug.   Attached patch should fix
it, though I haven't tested it.

Thanks,
Miklos

[-- Attachment #2: fuse-fix-stack-use-after-return.patch --]
[-- Type: text/x-patch, Size: 1488 bytes --]

---
 fs/fuse/dev.c    |    6 +++---
 fs/fuse/fuse_i.h |    2 ++
 2 files changed, 5 insertions(+), 3 deletions(-)

--- a/fs/fuse/dev.c
+++ b/fs/fuse/dev.c
@@ -276,12 +276,10 @@ static void flush_bg_queue(struct fuse_c
 void fuse_request_end(struct fuse_conn *fc, struct fuse_req *req)
 {
 	struct fuse_iqueue *fiq = &fc->iq;
-	bool async;
 
 	if (test_and_set_bit(FR_FINISHED, &req->flags))
 		goto put_request;
 
-	async = req->args->end;
 	/*
 	 * test_and_set_bit() implies smp_mb() between bit
 	 * changing and below intr_entry check. Pairs with
@@ -324,7 +322,7 @@ void fuse_request_end(struct fuse_conn *
 		wake_up(&req->waitq);
 	}
 
-	if (async)
+	if (test_bit(FR_ASYNC, &req->flags))
 		req->args->end(fc, req->args, req->out.h.error);
 put_request:
 	fuse_put_request(fc, req);
@@ -471,6 +469,8 @@ static void fuse_args_to_req(struct fuse
 	req->in.h.opcode = args->opcode;
 	req->in.h.nodeid = args->nodeid;
 	req->args = args;
+	if (args->end)
+		set_bit(FR_ASYNC, &req->flags);
 }
 
 ssize_t fuse_simple_request(struct fuse_conn *fc, struct fuse_args *args)
--- a/fs/fuse/fuse_i.h
+++ b/fs/fuse/fuse_i.h
@@ -301,6 +301,7 @@ struct fuse_io_priv {
  * FR_SENT:		request is in userspace, waiting for an answer
  * FR_FINISHED:		request is finished
  * FR_PRIVATE:		request is on private list
+ * FR_ASYNC:		request is asynchronous
  */
 enum fuse_req_flag {
 	FR_ISREPLY,
@@ -314,6 +315,7 @@ enum fuse_req_flag {
 	FR_SENT,
 	FR_FINISHED,
 	FR_PRIVATE,
+	FR_ASYNC,
 };
 
 /**

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Michael Stapelberg]

I confirm that the patch fixes the issue I was seeing. Thanks a lot!

On Wed, Feb 12, 2020 at 8:36 PM Miklos Szeredi <miklos@szeredi.hu> wrote:
>
> On Wed, Feb 12, 2020 at 10:38 AM Michael Stapelberg
> <michael+lkml@stapelberg.ch> wrote:
> >
> > Unfortunately not: when I change the code like so:
> >
> >     bool async;
> >     uint32_t opcode_early = req->args->opcode;
> >
> >     if (test_and_set_bit(FR_FINISHED, &req->flags))
> >         goto put_request;
> >
> >     async = req->args->end;
> >
> > …gdb only reports:
> >
> > (gdb) bt
> > #0  0x000000a700000001 in ?? ()
> > #1  0xffffffff8137fc99 in fuse_copy_finish (cs=0x20000ffffffff) at
> > fs/fuse/dev.c:681
> > Backtrace stopped: previous frame inner to this frame (corrupt stack?)
> >
> > But maybe that’s a hint in and of itself?
>
> Yep, it's a stack use after return bug.   Attached patch should fix
> it, though I haven't tested it.
>
> Thanks,
> Miklos

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Vivek Goyal]

On Wed, Feb 12, 2020 at 08:36:11PM +0100, Miklos Szeredi wrote:
> On Wed, Feb 12, 2020 at 10:38 AM Michael Stapelberg
> <michael+lkml@stapelberg.ch> wrote:
> >
> > Unfortunately not: when I change the code like so:
> >
> >     bool async;
> >     uint32_t opcode_early = req->args->opcode;
> >
> >     if (test_and_set_bit(FR_FINISHED, &req->flags))
> >         goto put_request;
> >
> >     async = req->args->end;
> >
> > …gdb only reports:
> >
> > (gdb) bt
> > #0  0x000000a700000001 in ?? ()
> > #1  0xffffffff8137fc99 in fuse_copy_finish (cs=0x20000ffffffff) at
> > fs/fuse/dev.c:681
> > Backtrace stopped: previous frame inner to this frame (corrupt stack?)
> >
> > But maybe that’s a hint in and of itself?
> 
> Yep, it's a stack use after return bug.   Attached patch should fix
> it, though I haven't tested it.

I think I have noticed couple of crashes in fuse_request_end() while
it was trying to call req->args->end() and I suspect this patch might
fix the issue.

Just that I have not been able to reproduce it reliably to be able test
it.

Vivek

> 
> Thanks,
> Miklos

> ---
>  fs/fuse/dev.c    |    6 +++---
>  fs/fuse/fuse_i.h |    2 ++
>  2 files changed, 5 insertions(+), 3 deletions(-)
> 
> --- a/fs/fuse/dev.c
> +++ b/fs/fuse/dev.c
> @@ -276,12 +276,10 @@ static void flush_bg_queue(struct fuse_c
>  void fuse_request_end(struct fuse_conn *fc, struct fuse_req *req)
>  {
>  	struct fuse_iqueue *fiq = &fc->iq;
> -	bool async;
>  
>  	if (test_and_set_bit(FR_FINISHED, &req->flags))
>  		goto put_request;
>  
> -	async = req->args->end;
>  	/*
>  	 * test_and_set_bit() implies smp_mb() between bit
>  	 * changing and below intr_entry check. Pairs with
> @@ -324,7 +322,7 @@ void fuse_request_end(struct fuse_conn *
>  		wake_up(&req->waitq);
>  	}
>  
> -	if (async)
> +	if (test_bit(FR_ASYNC, &req->flags))
>  		req->args->end(fc, req->args, req->out.h.error);
>  put_request:
>  	fuse_put_request(fc, req);
> @@ -471,6 +469,8 @@ static void fuse_args_to_req(struct fuse
>  	req->in.h.opcode = args->opcode;
>  	req->in.h.nodeid = args->nodeid;
>  	req->args = args;
> +	if (args->end)
> +		set_bit(FR_ASYNC, &req->flags);
>  }
>  
>  ssize_t fuse_simple_request(struct fuse_conn *fc, struct fuse_args *args)
> --- a/fs/fuse/fuse_i.h
> +++ b/fs/fuse/fuse_i.h
> @@ -301,6 +301,7 @@ struct fuse_io_priv {
>   * FR_SENT:		request is in userspace, waiting for an answer
>   * FR_FINISHED:		request is finished
>   * FR_PRIVATE:		request is on private list
> + * FR_ASYNC:		request is asynchronous
>   */
>  enum fuse_req_flag {
>  	FR_ISREPLY,
> @@ -314,6 +315,7 @@ enum fuse_req_flag {
>  	FR_SENT,
>  	FR_FINISHED,
>  	FR_PRIVATE,
> +	FR_ASYNC,
>  };
>  
>  /**

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Bruno Thomsen]

Hi,

First of all, sorry for the incorrect reply as I was not subscribed to
the mailing list.

A colleague and I have tested Miklos patch[1] on top of Fedora 31
5.5.7 kernel and it fixes a kernel oops[2] when using rootless
containers in Podman. Fix has been running for a few days now,
and the issue was normally reproducible within a few minutes.

Tested-by: Bruno Thomsen <bruno.thomsen@gmail.com>

/Bruno

[1] https://lore.kernel.org/linux-fsdevel/CAJfpegvBguKcNZk-p7sAtSuNH_7HfdCyYvo8Wh7X6P=hT=kPrA@mail.gmail.com/

[2] Oops when running podman workload.
kernel: BUG: kernel NULL pointer dereference, address: 0000000000000001
kernel: #PF: supervisor instruction fetch in kernel mode
kernel: #PF: error_code(0x0010) - not-present page
kernel: PGD 8000000e4cd85067 P4D 8000000e4cd85067 PUD e4cd80067 PMD 0
kernel: Oops: 0010 [#1] SMP PTI
kernel: CPU: 27 PID: 3422 Comm: fuse-overlayfs Not tainted
5.5.5-200.fc31.x86_64 #1
kernel: Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS
?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31
04/01/2014
kernel: RIP: 0010:0x1
kernel: Code: Bad RIP value.
kernel: RSP: 0018:ffffaa0d4196fc30 EFLAGS: 00010202
kernel: RAX: 0000000000000001 RBX: ffff8b5f344c2250 RCX: 0000000000000000
kernel: RDX: 0000000000000000 RSI: ffffaa0d4932fbb8 RDI: ffff8b65ac586800
kernel: RBP: ffff8b5f344c2240 R08: ffff8b5f344c22a0 R09: ffffaa0d4196fbd0
kernel: R10: ffff8b65a5c71888 R11: 0000000000000001 R12: ffff8b65ac586800
kernel: R13: 0000000000000001 R14: ffff8b65ab535dc0 R15: ffff8b5f344c2240
kernel: FS:  00007fb4239a7b80(0000) GS:ffff8b65b98c0000(0000)
knlGS:0000000000000000
kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
kernel: CR2: ffffffffffffffd7 CR3: 0000000e4cd38004 CR4: 0000000000360ee0
kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
kernel: Call Trace:
kernel:  ? fuse_request_end+0xbc/0x1f0 [fuse]
kernel:  ? fuse_dev_do_write+0x25e/0xe70 [fuse]
kernel:  ? lookup_fast+0xca/0x280
kernel:  ? fuse_dev_write+0x53/0x90 [fuse]
kernel:  ? do_iter_readv_writev+0x158/0x1d0
kernel:  ? do_iter_write+0x7d/0x190
kernel:  ? vfs_writev+0xa6/0xf0
kernel:  ? _copy_to_user+0x28/0x30
kernel:  ? readlink_copy+0x5a/0x80
kernel:  ? do_writev+0x6b/0x110
kernel:  ? do_syscall_64+0x5b/0x1c0
kernel:  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
kernel: Modules linked in: tun ip6t_REJECT nf_reject_ipv6
ip6t_rpfilter ipt_REJECT nf_reject_ipv4 xt_conntrack ebtable_nat
ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_>
kernel: CR2: 0000000000000001

Re: Still a pretty bad time on 5.4.6 with fuse_request_end.

[Greg KH]

On Fri, Mar 06, 2020 at 10:31:42AM +0100, Bruno Thomsen wrote:
> Hi,
> 
> First of all, sorry for the incorrect reply as I was not subscribed to
> the mailing list.
> 
> A colleague and I have tested Miklos patch[1] on top of Fedora 31
> 5.5.7 kernel and it fixes a kernel oops[2] when using rootless
> containers in Podman. Fix has been running for a few days now,
> and the issue was normally reproducible within a few minutes.
> 
> Tested-by: Bruno Thomsen <bruno.thomsen@gmail.com>
> 
> /Bruno
> 
> [1] https://lore.kernel.org/linux-fsdevel/CAJfpegvBguKcNZk-p7sAtSuNH_7HfdCyYvo8Wh7X6P=hT=kPrA@mail.gmail.com/

Any plan on getting this merged into Linus's tree?

greg k-h