lotus-worker version 1.13.0 - kernel panic panic while deleting cache files

[bruce20319]

Checklist

• This is not a security-related bug/issue. If it is, please follow please follow the security policy.
• This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
• This is not a new feature request. If it is, please file a feature request instead.
• This is not an enhancement request. If it is, please file a improvement suggestion instead.
• I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
• I am running the Latest release, or the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
• I did not make any code changes to lotus.

Lotus component

• lotus daemon - chain sync
• lotus miner - mining and block production
• lotus miner/worker - sealing
• lotus miner - proving(WindowPoSt)
• lotus miner/market - storage deal
• lotus miner/market - retrieval deal
• lotus miner/market - data transfer
• lotus client
• lotus JSON-RPC API
• lotus message management (mpool)
• Other

Lotus Version

version 1.13.0

Describe the Bug

Jan 22 02:02:10 p54-1 lotus-worker[37433]: 2022-01-22T02:02:10.879+0800 INFO main lotus-seal-worker/main.go:187 Starting lotus worker
Jan 22 02:02:10 p54-1 systemd-journald[938]: Suppressed 1734 messages from lotus-w-p.service
Jan 22 02:02:10 p54-1 lotus-worker[37433]: 2022-01-22T02:02:10.882+0800 INFO main lotus-seal-worker/main.go:232 Remote version 1.13.0+mainnet-amd+git.86fa4a26e.dirty.2+api1.2.0
-- Reboot --
Jan 22 10:23:53 p54-1 systemd[1]: Started Lotus Worker.
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.743+0800 INFO main lotus-seal-worker/main.go:187 Starting lotus worker
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.748+0800 INFO main lotus-seal-worker/main.go:232 Remote version 1.13.0+mainnet-amd+git.86fa4a26e.dirty.2+api1.2.0
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.758+0800 INFO badger [email protected]/levels.go:183 All 0 tables opened in 0s
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.769+0800 INFO badger [email protected]/value.go:1158 Replaying file id: 0 at offset: 0
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.769+0800 INFO badger [email protected]/value.go:1178 Replay took: 2.825µs
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.798+0800 INFO badger [email protected]/levels.go:183 All 0 tables opened in 0s
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.807+0800 INFO badger [email protected]/value.go:1158 Replaying file id: 0 at offset: 0
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.807+0800 INFO badger [email protected]/value.go:1178 Replay took: 2.745µs
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.807+0800 INFO main lotus-seal-worker/main.go:351 Opening local storage; connecting to master
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.837+0800 INFO main lotus-seal-worker/main.go:409 Setting up control endpoint at 192.168.1.54:3456
Jan 22 10:23:53 p54-1 lotus-worker[3939]: 2022-01-22T10:23:53.839+0800 INFO main lotus-seal-worker/main.go:512 Making sure no local tasks are running
Jan 22 10:23:54 p54-1 lotus-worker[3939]: 2022-01-22T10:23:54.616+0800 INFO main lotus-seal-worker/main.go:535 Worker registered successfully, waiting for tasks
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.363+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31830} 8} (e:0; a:1): {{0 0} /lotus/worker/p/unsealed/s-t0406478-31830 }
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.363+0800 INFO ffiwrapper ffiwrapper/sealer_cgo.go:62 [HM] Symlink sector {"src": "/lotus/worker/s-t01000-0", "dst": "/lotus/worker/p/unsealed/s-t0406478-31830"}
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.469+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31830} 8} (e:1; a:0): {{0 0} /lotus/worker/p/unsealed/s-t0406478-31830 }
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.492+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31830} 8} (e:1; a:6): {{0 0} /lotus/worker/p/unsealed/s-t0406478-31830 /lotus/worker/p/sealed/s-t0406478-31830 /lotus/worker/p/cache/s-t0406478-31830}
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.494 INFO filcrypto::proofs::api > seal_pre_commit_phase1: start
Jan 22 10:24:05 p54-1 lotus-worker[3939]: 2022-01-22T10:24:05.498 INFO filecoin_proofs::api::seal > seal_pre_commit_phase1:start: SectorId(31830)
Jan 22 10:24:50 p54-1 lotus-worker[3939]: 2022-01-22T10:24:50.609 INFO filecoin_proofs::api::seal > building merkle tree for the original data
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.084+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31657} 8} (e:1; a:0): {{0 0} /lotus/worker/p/unsealed/s-t0406478-31657 }
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.088+0800 INFO stores stores/local.go:621 remove /lotus/worker/p/sealed/s-t0406478-31657
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.093+0800 INFO stores stores/local.go:621 remove /lotus/worker/p/cache/s-t0406478-31657
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.119+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31657} 8} (e:1; a:6): {{0 0} /lotus/worker/p/unsealed/s-t0406478-31657 /lotus/worker/p/sealed/s-t0406478-31657 /lotus/worker/p/cache/s-t0406478-31657}
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.119 INFO filcrypto::proofs::api > seal_pre_commit_phase1: start
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.119 INFO filecoin_proofs::api::seal > seal_pre_commit_phase1:start: SectorId(31657)
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.165+0800 INFO stores stores/http_handler.go:88 SERVE GET /remote/unsealed/s-t0406478-31664
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.182+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31639} 8} (e:6; a:0): {{0 0} /lotus/worker/p/sealed/s-t0406478-31639 /lotus/worker/p/cache/s-t0406478-31639}
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.207+0800 DEBUG advmgr sector-storage/worker_local.go:137 acquired sector {{406478 31639} 8} (e:6; a:0): {{0 0} /lotus/worker/p/sealed/s-t0406478-31639 /lotus/worker/p/cache/s-t0406478-31639}
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.207 INFO filcrypto::proofs::api > seal_pre_commit_phase2: start
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.208 INFO filecoin_proofs::api > validate_cache_for_precommit_phase2:start
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.209 INFO filecoin_proofs::api > validate_cache_for_precommit_phase2:finish
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.209 INFO filecoin_proofs::api::seal > seal_pre_commit_phase2:start
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.220 INFO storage_proofs_porep::stacked::vanilla::proof > replicate_phase2
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.220 INFO storage_proofs_porep::stacked::vanilla::proof > Building trees [1048576 descriptors max available]
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.220 INFO storage_proofs_porep::stacked::vanilla::proof > generating tree c using the GPU
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.220 INFO storage_proofs_porep::stacked::vanilla::proof > Building column hashes
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.242 INFO neptune::proteus::program > Using kernel on CUDA.
Jan 22 10:24:53 p54-1 lotus-worker[3939]: 2022-01-22T10:24:53.306 INFO neptune::proteus::program > Using kernel on CUDA.
Jan 22 10:25:43 p54-1 lotus-worker[3939]: 2022-01-22T10:25:43.448 INFO filecoin_proofs::api::seal > verifying pieces
Jan 22 10:25:43 p54-1 lotus-worker[3939]: 2022-01-22T10:25:43.448 INFO filecoin_proofs::pieces > verifying 1 pieces
Jan 22 10:25:43 p54-1 lotus-worker[3939]: 2022-01-22T10:25:43.448 INFO storage_proofs_porep::stacked::vanilla::proof > replicate_phase1
Jan 22 10:25:43 p54-1 lotus-worker[3939]: 2022-01-22T10:25:43.448 INFO storage_proofs_porep::stacked::vanilla::graph > using parent_cache[2048 / 1073741824]
Jan 22 10:25:43 p54-1 lotus-worker[3939]: 2022-01-22T10:25:43.448 INFO storage_proofs_porep::stacked::vanilla::cache > parent cache: generating /home/lo/tmp/filecoin-parents/v28-sdr-parent-21981246c370f9d76c7a77ab273d94bde0ceb4e938292334960bce05585dc117.cache
Jan 22 10:26:42 p54-1 lotus-worker[3939]: 2022-01-22T10:26:42.234 INFO filecoin_proofs::api::seal > building merkle tree for the original data
Jan 22 10:26:44 p54-1 lotus-worker[3939]: 2022-01-22T10:26:44.612+0800 DEBUG stores stores/http_handler.go:161 served sector file/dir, sectorID={Miner:406478 Number:31664}, fileType=unsealed, path=/lotus/worker/p/unsealed/s-t0406478-31664
Jan 22 10:26:44 p54-1 lotus-worker[3939]: 2022-01-22T10:26:44.619+0800 INFO stores stores/http_handler.go:165 SERVE DELETE /remote/unsealed/s-t0406478-31664
Jan 22 10:26:44 p54-1 lotus-worker[3939]: 2022-01-22T10:26:44.620+0800 INFO stores stores/local.go:621 remove /lotus/worker/p/unsealed/s-t0406478-31664
Jan 22 10:26:45 p54-1 lotus-worker[3939]: 2022-01-22T10:26:45.875+0800 INFO stores stores/http_handler.go:165 SERVE DELETE /remote/sealed/s-t0406478-31664
Jan 22 10:26:45 p54-1 lotus-worker[3939]: 2022-01-22T10:26:45.875+0800 INFO stores stores/local.go:621 remove /lotus/worker/p/sealed/s-t0406478-31664
Jan 22 10:26:45 p54-1 lotus-worker[3939]: 2022-01-22T10:26:45.878+0800 INFO stores stores/http_handler.go:165 SERVE DELETE /remote/cache/s-t0406478-31664
Jan 22 10:26:45 p54-1 lotus-worker[3939]: 2022-01-22T10:26:45.879+0800 INFO stores stores/local.go:621 remove /lotus/worker/p/cache/s-t0406478-31664
Jan 22 10:28:58 p54-1 systemd[1]: Stopping Lotus Worker...

Logging Information

1845 Jan 21 19:36:25 p54-1 kernel: [19888.292883] WARNING: CPU: 45 PID: 40869 at /build/linux-ySSlYG/linux-4.15.0/mm/truncate.c:359 truncate_inode_pages_range+0x38c/0x960
     1846 Jan 21 19:36:25 p54-1 kernel: [19888.292883] Modules linked in: nvidia_uvm(OE) joydev snd_hda_codec_hdmi binfmt_misc nls_iso8859_1 nvidia_drm(POE) edac_mce_amd nvidia
          _modeset(POE) snd_hda_intel snd_usb_audio snd_hda_codec snd_usbmidi_lib snd_hda_core snd_rawmidi kvm_amd snd_hwdep snd_seq_device snd_pcm eeepc_wmi kvm snd_timer wmi_
          bmof snd asus_wmi irqbypass sparse_keymap nvidia(POE) soundcore shpchp k10temp mac_hid sch_fq_codel ib_iser rdma_cm iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscs
          i scsi_transport_iscsi ip_tables x_tables autofs4 btrfs zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c
           raid1 multipath linear hid_generic usbhid hid raid0 crct10dif_pclmul crc32_pclmul ghash_clmulni_intel nouveau pcbc aesni_intel mxm_wmi video aes_x86_64 crypto_simd t
          tm glue_helper
     1847 Jan 21 19:36:25 p54-1 kernel: [19888.292908]  cryptd drm_kms_helper ixgbe igb syscopyarea sysfillrect nvme dca sysimgblt i2c_algo_bit ahci nvme_core fb_sys_fops mdio
          ptp libahci pps_core drm i2c_piix4 wmi
     1848 Jan 21 19:36:25 p54-1 kernel: [19888.292916] CPU: 45 PID: 40869 Comm: lotus-worker Tainted: P    B      OE    4.15.0-166-generic #174-Ubuntu
     1849 Jan 21 19:36:25 p54-1 kernel: [19888.292916] Hardware name: System manufacturer System Product Name/PRIME TRX40-PRO S, BIOS 1101 06/05/2020
     1850 Jan 21 19:36:25 p54-1 kernel: [19888.292917] RIP: 0010:truncate_inode_pages_range+0x38c/0x960
     1851 Jan 21 19:36:25 p54-1 kernel: [19888.292918] RSP: 0018:ffffb8e1cf68bc18 EFLAGS: 00010286
     1852 Jan 21 19:36:25 p54-1 kernel: [19888.292919] RAX: 0000000000000024 RBX: 000000000056e883 RCX: 0000000000000006
     1853 Jan 21 19:36:25 p54-1 kernel: [19888.292919] RDX: 0000000000000000 RSI: ffff98a08d3564d8 RDI: ffff98a08d3564d0
     1854 Jan 21 19:36:25 p54-1 kernel: [19888.292919] RBP: ffffb8e1cf68bdd8 R08: 00000000000006df R09: 0000000000000004
     1855 Jan 21 19:36:25 p54-1 kernel: [19888.292920] R10: 0000000000000000 R11: 0000000000000001 R12: ffff988473eb86b0
     1856 Jan 21 19:36:25 p54-1 kernel: [19888.292920] R13: fffff19bc6e53000 R14: 000000000000000e R15: ffffb8e1cf68bca8
     1857 Jan 21 19:36:25 p54-1 kernel: [19888.292921] FS:  00007ffe457fe700(0000) GS:ffff98a08d340000(0000) knlGS:0000000000000000
     1858 Jan 21 19:36:25 p54-1 kernel: [19888.292922] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
     1859 Jan 21 19:36:25 p54-1 kernel: [19888.292922] CR2: 000000c001099000 CR3: 000000288d3f8000 CR4: 0000000000340ee0
     1860 Jan 21 19:36:25 p54-1 kernel: [19888.292922] Call Trace:
     1861 Jan 21 19:36:25 p54-1 kernel: [19888.292926]  truncate_inode_pages_final+0x4c/0x60
     1862 Jan 21 19:36:25 p54-1 kernel: [19888.292929]  ext4_evict_inode+0x111/0x5d0
     1863 Jan 21 19:36:25 p54-1 kernel: [19888.292931]  evict+0xca/0x1a0
     1864 Jan 21 19:36:25 p54-1 kernel: [19888.292932]  iput+0x19c/0x230
     1865 Jan 21 19:36:25 p54-1 kernel: [19888.292933]  do_unlinkat+0x19c/0x320
     1866 Jan 21 19:36:25 p54-1 kernel: [19888.292934]  SyS_unlinkat+0x33/0x50
     1867 Jan 21 19:36:25 p54-1 kernel: [19888.292936]  do_syscall_64+0x73/0x130
     1868 Jan 21 19:36:25 p54-1 kernel: [19888.292938]  entry_SYSCALL_64_after_hwframe+0x41/0xa6
     1869 Jan 21 19:36:25 p54-1 kernel: [19888.292939] RIP: 0033:0x599a7b
1870 Jan 21 19:36:25 p54-1 kernel: [19888.292939] RSP: 002b:000000c00c44b068 EFLAGS: 00000216 ORIG_RAX: 0000000000000107
     1871 Jan 21 19:36:25 p54-1 kernel: [19888.292940] RAX: ffffffffffffffda RBX: 000000c000055000 RCX: 0000000000599a7b
     1872 Jan 21 19:36:25 p54-1 kernel: [19888.292940] RDX: 0000000000000000 RSI: 000000c0067e91a0 RDI: ffffffffffffff9c
     1873 Jan 21 19:36:25 p54-1 kernel: [19888.292940] RBP: 000000c00c44b0d8 R08: 00007ffff7fa3a01 R09: 0000000000000000
     1874 Jan 21 19:36:25 p54-1 kernel: [19888.292941] R10: 00007fffcc3b01e8 R11: 0000000000000216 R12: 000000c0067e91a0
     1875 Jan 21 19:36:25 p54-1 kernel: [19888.292941] R13: 0000000000000001 R14: 000000c0001f5860 R15: ffffffffffffffff
     1876 Jan 21 19:36:25 p54-1 kernel: [19888.292942] Code: ff ff 85 c0 0f 85 ba 01 00 00 48 8b 85 48 fe ff ff 49 39 c5 0f 84 be fc ff ff 49 89 c5 eb b2 48 c7 c7 f8 64 6b 8b e
          8 16 a4 7c 00 <0f> 0b e9 5d fe ff ff 49 8b 4d 20 48 8d 41 ff 83 e1 01 49 8b 4d
     1877 Jan 21 19:36:25 p54-1 kernel: [19888.292949] ---[ end trace f72aad88c2441989 ]---
     1878 Jan 21 19:36:25 p54-1 kernel: [19888.331363] ------------[ cut here ]------------

Repo Steps

No response

[Reiers]

Hi @bruce20319

Thanks for the report. The issue you are experiencing lies elsewhere.

Moving this issue to Lotus Discussions for help and troubleshooting.

Closing Lotus issue ticket.

[LexLuthr]

@bruce20319 Hey, this is not a lotus bug. It seems like a simple kernel panic on truncate option. So, while lotus was deleting the cache file, it requested the OS to do so. The part of this delete operation is to remove the inode corresponding to that file. The inode truncate API for the kernel is where the panic occurred. If this is a one time thing, then I would suggest to ignore it. But if it is reproducible then you should file a bug with Linux kernel.

[LexLuthr]

I am archiving this discussion as there has been no new update from the author.