Sectors stuck in committing stage

[Suyu6]

root@suyu:/data1# lotus-miner sectors list -fast -seal-time
ID State OnChain Active Deals
0 Committing NO NO CC

root@suyu:/data2/logs# lotus-miner sectors status -log 0
SectorID: 0
Status: Committing
CIDcommD: baga6ea4seaqomqafu276g53zko4k23xzh4h4uecjwicbmvhsuqi7o4bhthhm4aq
CIDcommR: bagboea4b5abcavjii4wewpsxktacuz4lfxakxha5n2vih26iyfmh2q6qh7ww4xjm
Ticket: b4b05de3e308ae65ab383250be959724971311c42d8da3c89b5fc427b6d3e786
TicketH: 172615
Seed: fe7dd414178f1997e4f780b35eb323420be14ca3a260d912ffce374bd962d73b
SeedH: 176069
Precommit: bafy2bzacecjicfmx27vbb3kjzvnnijgetl4zgwrnbszogz5y3wb2y7x5knpxy
Commit:
Proof:
Deals: [0]
Retries: 0

Event Log:
0. 2021-08-18 13:55:36 +0800 CST: [event;sealing.SectorStartCC] {"User":{"ID":0,"SectorType":9}}

1.  2021-08-18 13:57:40 +0800 CST:  [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":68719476736,"PieceCID":{"/":"baga6ea4seaqomqafu276g53zko4k23xzh4h4uecjwicbmvhsuqi7o4bhthhm4aq"}}]}}
   

2.  2021-08-18 13:57:40 +0800 CST:  [event;sealing.SectorTicket]    {"User":{"TicketValue":"tLBd4+MIrmWrODJQvpWXJJcTEcQtjaPIm1/EJ7bT54Y=","TicketEpoch":172615}}
   

3.  2021-08-18 18:11:50 +0800 CST:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
    seal pre commit(1) failed: storage call error 101: worker restarted
   

4.  2021-08-18 18:12:50 +0800 CST:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
   

5.  2021-08-18 22:46:50 +0800 CST:  [event;sealing.SectorPreCommit1]        {"User":{"PreCommit1Out":"eyJyZWdpc3RlcmVkX3Byb29mIjoiU3RhY2tlZERyZzY0R2lCVjFfMSIsImxhYmVscyI6eyJTdGFja2VkRHJnNjRHaUJWMSI6eyJsYWJlbHMiOlt7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci0xIiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci0yIiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci0zIiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci00Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci01Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci02Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci03Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci04Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci05Iiwic2l6ZSI6MjE0NzQ4MzY0OCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJsYXllci0xMCIsInNpemUiOjIxNDc0ODM2NDgsInJvd3NfdG9fZGlzY2FyZCI6N30seyJwYXRoIjoiL2RhdGEyL3dvcmtlci9jYWNoZS9zLXQwMTM1NzMtMCIsImlkIjoibGF5ZXItMTEiLCJzaXplIjoyMTQ3NDgzNjQ4LCJyb3dzX3RvX2Rpc2NhcmQiOjd9XSwiX2giOm51bGx9fSwiY29uZmlnIjp7InBhdGgiOiIvZGF0YTIvd29ya2VyL2NhY2hlL3MtdDAxMzU3My0wIiwiaWQiOiJ0cmVlLWQiLCJzaXplIjo0Mjk0OTY3Mjk1LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LCJjb21tX2QiOlsyMzAsNjQsNSwxNjYsMTkxLDIyNywxMTksMTIxLDgzLDE4NCwxNzMsMTEwLDI0OSw2MywxNSwyMDIsMTYsNzMsMTc4LDQsMjIsODQsMjQyLDE2NCwxNywyNDcsMTEyLDM5LDE1MywyMDYsMjA2LDJdfQ=="}}
   

6.  2021-08-18 23:04:21 +0800 CST:  [event;sealing.SectorPreCommit2]        {"User":{"Sealed":{"/":"bagboea4b5abcavjii4wewpsxktacuz4lfxakxha5n2vih26iyfmh2q6qh7ww4xjm"},"Unsealed":{"/":"baga6ea4seaqomqafu276g53zko4k23xzh4h4uecjwicbmvhsuqi7o4bhthhm4aq"}}}
   

7.  2021-08-19 09:59:10 +0800 CST:  [event;sealing.SectorRetryPreCommit]    {"User":{}}
   

8.  2021-08-19 09:59:11 +0800 CST:  [event;sealing.SectorPreCommitted]      {"User":{"Message":{"/":"bafy2bzacecjicfmx27vbb3kjzvnnijgetl4zgwrnbszogz5y3wb2y7x5knpxy"},"PreCommitDeposit":"25704713285373782140","PreCommitInfo":{"SealProof":9,"SectorNumber":0,"SealedCID":{"/":"bagboea4b5abcavjii4wewpsxktacuz4lfxakxha5n2vih26iyfmh2q6qh7ww4xjm"},"SealRandEpoch":172615,"DealIDs":[],"Expiration":1728303,"ReplaceCapacity":false,"ReplaceSectorDeadline":0,"ReplaceSectorPartition":0,"ReplaceSectorNumber":0}}}
   

9.  2021-08-19 10:02:29 +0800 CST:  [event;sealing.SectorPreCommitLanded]   {"User":{"TipSet":"AXGg5AIghewVBnfNCGkusaZdSX7xZ5xRuy8lqNi5SeOEknhIDDMBcaDkAiAhW+yKx4GjujACP2BfWV2fZl3eXMugvdPUFPs8tWrzFwFxoOQCIDpspJ2fsIAPdyQNhRQmk/26S4hlcTCYHYLc/zC5Lmr8AXGg5AIg2CFvUvTT70S3hkTfdx3waNZOnyLxdS4+j/7ORImJqjI="}}
   

10.  2021-08-19 11:17:29 +0800 CST:  [event;sealing.SectorSeedReady] {"User":{"SeedValue":"/n3UFBePGZfk94CzXrMjQgvhTKOiYNkS/843S9li1zs=","SeedEpoch":176069}}
    

root@suyu:/data2/logs# tail -f miner.log
2021-08-19T17:13:36.068+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176788, "baseEpoch": 176787, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:14:06.005+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176789, "baseEpoch": 176787, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:14:36.255+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176790, "baseEpoch": 176789, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:15:06.005+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 2, "forRound": 176791, "baseEpoch": 176790, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:15:36.004+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176792, "baseEpoch": 176791, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:16:06.005+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176793, "baseEpoch": 176792, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:16:36.006+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176794, "baseEpoch": 176793, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:17:06.006+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176795, "baseEpoch": 176794, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:17:36.196+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176796, "baseEpoch": 176795, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}
2021-08-19T17:18:06.401+0800 INFO miner miner/miner.go:465 completed mineOne {"tookMilliseconds": 1, "forRound": 176797, "baseEpoch": 176796, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "-1", "minerPowerAtLookback": "0", "isEligible": false, "isWinner": false, "error": null}

root@suyu:/data2/logs# lotus --version
lotus version 1.10.0+calibnet+git.764fa9dae

root@suyu:/data2/logs# cat /proc/version
Linux version 5.4.0-81-generic (buildd@lgw01-amd64-052) (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #91-Ubuntu SMP Thu Jul 15 19:09:17 UTC 2021

root@suyu:/data2/logs# lotus-miner info
Chain: [sync ok] [basefee 100 aFIL]
Miner: t013573 (64 GiB sectors)
Power: 0 / 4.67 Pi (0.0000%)
Raw: 0 B / 4.034 PiB (0.0000%)
Committed: 0 B
Proving: 0 B
Below minimum power threshold, no blocks will be won
Deals: 0, 0 B
Active: 0, 0 B (Verified: 0, 0 B)

Miner Balance: 25.705 FIL
PreCommit: 23.369 FIL
Pledge: 0
Vesting: 0
Available: 2.336 FIL
Market Balance: 0
Locked: 0
Available: 0
Worker Balance: 510 FIL
Total Spendable: 512.336 FIL

Sectors:
Total: 1
Committing: 1

root@suyu:/data2/logs# lotus-worker info
Worker version: 1.0.0
CLI version: lotus-worker version 1.10.0+calibnet+git.764fa9dae

Session: 83ec3059-c578-422c-ac4e-34e0cf9f7636
Enabled: true
Hostname: zly
CPUs: 64; GPUs: [GeForce RTX 3090]
RAM: 251.6 GiB; Swap: 8 GiB
Reserved memory: 7.843 GiB
Task types: FIN GET UNS C1 C2 PC2 PC1 AP

58a3ffdb-eff9-4be1-b006-aa217af17d84:
Weight: 10; Use: Seal
Local: /data2/worker

I can't find out what the problem is, I'm stuck at this stage.

[dayou5168]

Do you ever restart the worker and miner?
look like no jobs is doing.

[Suyu6]

I do reboot, so how can I fix this？

[Suyu6]

But I have another machine, which has not been restarted, and it is also stuck in the committing stage. I don't know how to solve this problem.

[Suyu6]

I have a machine that has been working fine since I restarted it, but some machines are still stuck in the committing stage, and I check the work logs like this.

This is the log of the machine that is stuck in the committing phase.

root@suyu:~# tail -f /data1/logs/worker.2021_08_20.out
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 5)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 6)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 7)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 8)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 9)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 10)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 11)
2021-08-20T11:37:20.422 TRACE storage_proofs_porep::stacked::vanilla::params > verify encoding
2021-08-20T11:37:20.422 INFO filecoin_proofs::api::seal > seal_commit_phase1:finish: SectorId(1)
2021-08-20T11:37:20.471 INFO filcrypto::proofs::api > seal_commit_phase1: finish

This is a log of the machine in normal operation.

2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 6)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 7)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 8)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 9)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 10)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify labeling (layer: 11)
2021-08-20T10:00:14.506 TRACE storage_proofs_porep::stacked::vanilla::params > verify encoding
2021-08-20T10:00:14.506 INFO filecoin_proofs::api::seal > seal_commit_phase1:finish: SectorId(0)
2021-08-20T10:00:14.546 INFO filcrypto::proofs::api > seal_commit_phase1: finish
2021-08-20T10:00:16.080 INFO filcrypto::proofs::api > seal_commit_phase2: start
2021-08-20T10:00:16.148 INFO filecoin_proofs::api::seal > seal_commit_phase2:start: SectorId(0)
2021-08-20T10:00:16.148 INFO filecoin_proofs::caches > trying parameters memory cache for: STACKED[68719476736]
2021-08-20T10:00:16.148 INFO filecoin_proofs::caches > no params in memory cache for STACKED[68719476736]
2021-08-20T10:00:16.150 INFO storage_proofs_core::parameter_cache > parameter set identifier for cache: layered_drgporep::PublicParams{ graph: stacked_graph::StackedGraph{expansion_degree: 8 base_graph: drgraph::BucketGraph{size: 2147483648; degree: 6; hasher: poseidon_hasher} }, challenges: LayerChallenges { layers: 11, max_count: 18 }, tree: merkletree-poseidon_hasher-8-8-2 }
2021-08-20T10:00:16.151 INFO storage_proofs_core::parameter_cache > ensuring that all ancestor directories for: "/data2/v28-64GB/v28-stacked-proof-of-replication-merkletree-poseidon_hasher-8-8-2-sha256_hasher-96f1b4a04c5c51e4759bbf224bbc2ef5a42c7100f16ec0637123f16a845ddfb2.params" exist
2021-08-20T10:00:16.151 INFO storage_proofs_core::parameter_cache > checking cache_path: "/data2/v28-64GB/v28-stacked-proof-of-replication-merkletree-poseidon_hasher-8-8-2-sha256_hasher-96f1b4a04c5c51e4759bbf224bbc2ef5a42c7100f16ec0637123f16a845ddfb2.params" for parameters
2021-08-20T10:00:17.924 INFO storage_proofs_core::parameter_cache > read parameters from cache "/data2/v28-64GB/v28-stacked-proof-of-replication-merkletree-poseidon_hasher-8-8-2-sha256_hasher-96f1b4a04c5c51e4759bbf224bbc2ef5a42c7100f16ec0637123f16a845ddfb2.params"
2021-08-20T10:00:17.925 INFO filecoin_proofs::api::seal > got groth params (68719476736) while sealing
2021-08-20T10:00:17.925 INFO filecoin_proofs::api::seal > snark_proof:start
2021-08-20T10:00:17.943 INFO bellperson::groth16::prover > Bellperson 0.14.2 is being used!
2021-08-20T10:01:48.331 INFO bellperson::groth16::prover > starting proof timer
2021-08-20T10:01:50.418 INFO bellperson::gpu::locks > GPU is available for FFT!
2021-08-20T10:01:50.418 DEBUG bellperson::gpu::locks > Acquiring GPU lock at "/tmp/bellman.gpu.lock" ...
2021-08-20T10:01:50.418 DEBUG bellperson::gpu::locks > GPU lock acquired!
2021-08-20T10:02:22.785 INFO bellperson::gpu::fft > FFT: 1 working device(s) selected.
2021-08-20T10:02:22.785 INFO bellperson::gpu::fft > FFT: Device 0: GeForce RTX 3090
2021-08-20T10:02:22.785 INFO bellperson::domain > GPU FFT kernel instantiated!
2021-08-20T10:04:48.758 DEBUG bellperson::gpu::locks > GPU lock released!
2021-08-20T10:04:55.482 INFO bellperson::gpu::locks > GPU is available for Multiexp!
2021-08-20T10:04:55.482 DEBUG bellperson::gpu::locks > Acquiring GPU lock at "/tmp/bellman.gpu.lock" ...
2021-08-20T10:04:55.482 DEBUG bellperson::gpu::locks > GPU lock acquired!
2021-08-20T10:04:55.559 INFO bellperson::gpu::multiexp > Multiexp: 1 working device(s) selected. (CPU utilization: 0)

I found out through the logs that the seal_commit_phase1 phase does not go into the seal_commit_phase2 phase, so I have been stuck in committing for almost four days now, does anyone know why? How do I fix this problem?

[dayou5168]

Looks it's stuck in commit1 and the miner did'nt schedule. here is my suggestion: upgrade to 1.11.1. and restart all the process. specify log level to debug in miner and worker . see what's happenning

[LexLuthr]

@Suyu6 Hey, are you still facing this problem? If not, then can you tell us how you fixed it?

[Suyu6]

Try changing to a newer version