Missed "SubmitWindowedPoSt" again #9390

ChaiWenyu1983 · 2022-09-29T06:16:53Z

ChaiWenyu1983
Sep 29, 2022

For the third time, there is no reason why it broke down. Can we still dig the mine happily? Request help! The information is as follows:

sync status:
worker 32781:
Base: [bafy2bzacedkiytchhkq4rhwuerkzpqrznsvfiib74xla6yodhh4ik5dbr2y2k]
Target: [bafy2bzacecbio42j7qgydme6c5n6wgjy6ebiqzhh57n53udfkf4qqz2panfo2] (2204186)
Height diff: 0
Stage: complete
Height: 2204186
Elapsed: 81.529845ms
worker 32782:
Base: [bafy2bzacedkiytchhkq4rhwuerkzpqrznsvfiib74xla6yodhh4ik5dbr2y2k]
Target: [bafy2bzacecryvk5bb7mahr5sv62yvwsj2ktowt3n4mcsi354su3v7gkpg74sa] (2204186)
Height diff: 0
Stage: complete
Height: 2204186
Elapsed: 151.787071ms
worker 32783:
Base: [bafy2bzacecryvk5bb7mahr5sv62yvwsj2ktowt3n4mcsi354su3v7gkpg74sa bafy2bzacecbio42j7qgydme6c5n6wgjy6ebiqzhh57n53udfkf4qqz2panfo2 bafy2bzacedkiytchhkq4rhwuerkzpqrznsvfiib74xla6yodhh4ik5dbr2y2k]
Target: [bafy2bzaceapevspyuwgx4h7nrydzv43ls3vjptw4vnoy3li7kmyhr4aspbru2] (2204186)
Height diff: 0
Stage: complete
Height: 2204186
Elapsed: 293.793228ms

lotus net bandwidth
Segment TotalIn TotalOut RateIn RateOut
Total 36 GB 18 GB 708 kB/s 82 kB/s

lotus net peers | wc -l
193

TippyFlitsUK · 2022-09-29T06:19:06Z

TippyFlitsUK
Sep 29, 2022
Maintainer

Hi @ChaiWenyu1983
Can you please provide miner/worker logs for the period that includes the WindowPoST failure?

2 replies

ChaiWenyu1983 Oct 21, 2022
Author

After I restarted the "miner" service, it was normal for a few days, but it failed again today. I saw the following words: "{" level ":" warn "," ts ":" 2022-10-21T11:36:15.661+0800 "," logger ":" wdpost "," caller ":" wdpost/wdpost_sched. go: 164 "," msg ":" window post scheduler notify channel closed "}"
miner.log

TippyFlitsUK Oct 21, 2022
Maintainer

Look at the logs above that line @ChaiWenyu1983 👇. Your miner is under too much load. What is your system spec?

{"level":"warn","ts":"2022-10-21T11:35:34.459+0800","logger":"fsutil","caller":"fsutil/filesize_unix.go:40","msg":"very slow file size check","took":13.789975915,"path":"/mnt/ssd3/sealing/cache/s-t01862564-1046"}
{"level":"warn","ts":"2022-10-21T11:35:21.670+0800","logger":"stores","caller":"paths/localstorage_cached.go:122","msg":"getting usage is slow, falling back to previous usage","path":"/mnt/ssd3/sealing/cache/s-t01862564-1046","fallback":67034472448,"age":11.001580223}
{"level":"warn","ts":"2022-10-21T11:36:14.462+0800","logger":"stores","caller":"paths/local.go:184","msg":"slow storage stat","took":53.793473539,"reservations":3}
{"level":"warn","ts":"2022-10-21T11:36:14.463+0800","logger":"events","caller":"events/observer.go:61","msg":"listenHeadChanges quit"}
{"level":"warn","ts":"2022-10-21T11:36:14.463+0800","logger":"events","caller":"events/observer.go:61","msg":"listenHeadChanges quit"}
{"level":"info","ts":"2022-10-21T11:36:15.617+0800","logger":"events","caller":"events/observer.go:70","msg":"restarting listenHeadChanges"}
{"level":"info","ts":"2022-10-21T11:36:15.619+0800","logger":"events","caller":"events/observer.go:70","msg":"restarting listenHeadChanges"}
{"level":"warn","ts":"2022-10-21T11:36:15.661+0800","logger":"wdpost","caller":"wdpost/wdpost_sched.go:164","msg":"window post scheduler notifs channel closed"}

ChaiWenyu1983 · 2022-09-29T06:19:22Z

ChaiWenyu1983
Sep 29, 2022
Author

lotus version
Daemon: 1.17.1+mainnet+git.8db6a939c.dirty+api1.5.0
Local: lotus version 1.17.1+mainnet+git.8db6a939c.dirty

0 replies

TippyFlitsUK · 2022-09-29T06:21:13Z

TippyFlitsUK
Sep 29, 2022
Maintainer

We'll need the actual logs @ChaiWenyu1983. Also, you are running a dirty build, is this intentional?

1 reply

ChaiWenyu1983 Sep 29, 2022
Author

I don't know how this "dirty" came into being. It has always existed, but it seems that this is not the cause of the fault, because it has always been normal, and it has only recently become unstable.

TippyFlitsUK · 2022-09-29T06:22:30Z

TippyFlitsUK
Sep 29, 2022
Maintainer

This is an example of miner logs:

2022-09-29T07:19:10.207+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 8, "forRound": 2204199, "baseEpoch": 2204198, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300044, "lookbackEpochs": 900, "networkPowerAtLookback": "21474529578296541184", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T07:19:40.013+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 7, "forRound": 2204200, "baseEpoch": 2204199, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300045, "lookbackEpochs": 900, "networkPowerAtLookback": "21474462538604249088", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T07:20:10.429+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 7, "forRound": 2204201, "baseEpoch": 2204200, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300046, "lookbackEpochs": 900, "networkPowerAtLookback": "21474541840880402432", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T07:20:40.326+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 8, "forRound": 2204202, "baseEpoch": 2204201, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300047, "lookbackEpochs": 900, "networkPowerAtLookback": "21474542143232638976", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T07:21:10.064+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 8, "forRound": 2204203, "baseEpoch": 2204202, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300048, "lookbackEpochs": 900, "networkPowerAtLookback": "21474461739758911488", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T07:21:40.018+0100	INFO	miner	miner/miner.go:475	completed mineOne	{"tookMilliseconds": 11, "forRound": 2204204, "baseEpoch": 2204203, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300049, "lookbackEpochs": 900, "networkPowerAtLookback": "21474461739758911488", "minerPowerAtLookback": "1527345826168832", "isEligible": true, "isWinner": false, "error": null}

1 reply

ChaiWenyu1983 Sep 29, 2022
Author

Please see my reply below. Do you need any more information?

ChaiWenyu1983 · 2022-09-29T06:30:01Z

ChaiWenyu1983
Sep 29, 2022
Author

run in the command line mode of the window. There are too many logs. I ignore "info" and only intercept logs that look abnormal, as shown below:

2022-09-29T08:57:30.169+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 879 to window 0 (awi:0)
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 879 to window 1 (awi:1)
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "879", "task": "seal/v0/finalize", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 879
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T08:57:30.170+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 879} 8} (e:5; a:0): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-879 /mnt/ssd3/sealing/cache/s-t01862564-879 }
2022-09-29T08:57:30.171+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T08:57:30.171+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T08:57:30.172+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 879} 8} (e:4; a:0): {{0 0} /mnt/ssd3/sealing/cache/s-t01862564-879 }
2022-09-29T08:57:36.055+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 51, "forRound": 2203556, "baseEpoch": 2203555, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299401, "lookbackEpochs": 900, "networkPowerAtLookback": "21464975891009961984", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T08:57:37.942+0800 INFO stores paths/local.go:728remove /mnt/ssd3/sealing/unsealed/s-t01862564-879
2022-09-29T08:57:38.507+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T08:57:38.507+0800 DEBUG stores paths/index.go:603not allocating on e5ca515f-ae9f-45bf-82dc-be1da6a3944d, out of space (available: 33068163072, need: 37795712204)
2022-09-29T08:57:38.507+0800 DEBUG stores paths/index.go:603not allocating on 5c15b254-d464-4a65-bb8f-7772b77bc447, out of space (available: 8240238592, need: 37795712204)
2022-09-29T08:57:38.508+0800 DEBUG stores paths/index.go:603not allocating on e5ca515f-ae9f-45bf-82dc-be1da6a3944d, out of space (available: 33068163072, need: 37795712204)
2022-09-29T08:57:38.508+0800 DEBUG stores paths/index.go:603not allocating on 5c15b254-d464-4a65-bb8f-7772b77bc447, out of space (available: 8240238592, need: 37795712204)
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 879 to window 0 (awi:0)
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 879 to window 1 (awi:1)
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "879", "task": "seal/v0/fetch", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 879
2022-09-29T08:57:38.508+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T08:57:38.509+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 879} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-879 /mnt/ssd3/sealing/cache/s-t01862564-879 }
2022-09-29T08:57:38.510+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T08:57:38.510+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T08:57:38.511+0800 DEBUG stores paths/index.go:603not allocating on e5ca515f-ae9f-45bf-82dc-be1da6a3944d, out of space (available: 33068163072, need: 34359738368)
2022-09-29T08:57:38.511+0800 DEBUG stores paths/index.go:603not allocating on 5c15b254-d464-4a65-bb8f-7772b77bc447, out of space (available: 8240238592, need: 34359738368)
2022-09-29T08:57:38.511+0800 DEBUG stores paths/local.go:775moving {{1862564 879} 8}(2) to storage: cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69(se:true; st:false) -> 6a5352bf-df6b-416e-bacb-cf51be4dd14d(se:false; st:true)
2022-09-29T08:57:38.511+0800 DEBUG stores paths/util_unix.go:30 move sector data {"from": "/mnt/ssd3/sealing/sealed/s-t01862564-879", "to": "/mnt/storage/disk4/sealed/s-t01862564-879"}
2022-09-29T08:58:06.010+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 6, "forRound": 2203557, "baseEpoch": 2203556, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299402, "lookbackEpochs": 900, "networkPowerAtLookback": "21465137313060814848", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T08:58:09.321+0800 DEBUG stores paths/local.go:775moving {{1862564 879} 8}(4) to storage: cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69(se:true; st:false) -> 6a5352bf-df6b-416e-bacb-cf51be4dd14d(se:false; st:true)
2022-09-29T08:58:09.321+0800 DEBUG stores paths/util_unix.go:30 move sector data {"from": "/mnt/ssd3/sealing/cache/s-t01862564-879", "to": "/mnt/storage/disk4/cache/s-t01862564-879"}
2022-09-29T08:58:36.401+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 7, "forRound": 2203558, "baseEpoch": 2203557, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299403, "lookbackEpochs": 900, "networkPowerAtLookback": "21464731260725362688", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T09:30:00.725+0800 WARN advmgr sealer/manager.go:399 stub NewSector
2022-09-29T09:30:00.725+0800 INFO sectors pipeline/garbage.go:38 Creating CC sector 881
2022-09-29T09:30:00.728+0800 INFO sectors pipeline/states_sealing.go:52 performing filling up rest of the sector... {"sector": "881"}
2022-09-29T09:30:00.729+0800 WARN sectors pipeline/states_sealing.go:76 Creating 1 filler pieces for sector 881
2022-09-29T09:30:00.729+0800 INFO sectors pipeline/states_sealing.go:92 Pledge {{1862564 881} 8}, contains []
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 0 (awi:0)
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 1 (awi:1)
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "881", "task": "seal/v0/addpiece", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 881
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:30:00.729+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.730+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:0; a:1): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-881 }
2022-09-29T09:30:00.794+0800 WARN advmgr sealer/manager.go:399 stub NewSector
2022-09-29T09:30:00.794+0800 INFO sectors pipeline/garbage.go:38 Creating CC sector 882
2022-09-29T09:30:00.796+0800 INFO sectors pipeline/states_sealing.go:52 performing filling up rest of the sector... {"sector": "882"}
2022-09-29T09:30:00.796+0800 WARN sectors pipeline/states_sealing.go:76 Creating 1 filler pieces for sector 882
2022-09-29T09:30:00.796+0800 INFO sectors pipeline/states_sealing.go:92 Pledge {{1862564 882} 8}, contains []
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 0 (awi:0)
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 1 (awi:1)
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "882", "task": "seal/v0/addpiece", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T09:30:00.796+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 882
2022-09-29T09:30:00.797+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.797+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:30:00.797+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.797+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=34359738368, reserved: -8192
2022-09-29T09:30:00.797+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:0; a:1): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-882 }
2022-09-29T09:30:00.866+0800 WARN advmgr sealer/manager.go:399 stub NewSector

2022-09-29T09:30:00.869+0800 INFO sectors pipeline/states_sealing.go:52 performing filling up rest of the sector... {"sector": "883"}
2022-09-29T09:30:00.869+0800 WARN sectors pipeline/states_sealing.go:76 Creating 1 filler pieces for sector 883
2022-09-29T09:30:00.869+0800 INFO sectors pipeline/states_sealing.go:92 Pledge {{1862564 883} 8}, contains []
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 0 (awi:0)
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 1 (awi:1)
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "883", "task": "seal/v0/addpiece", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 883
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:30:00.869+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:30:00.870+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=68719476736, reserved: -16384
2022-09-29T09:30:00.870+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:0; a:1): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-883 }
2022-09-29T09:30:06.029+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 26, "forRound": 2203621, "baseEpoch": 2203620, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299466, "lookbackEpochs": 900, "networkPowerAtLookback": "21465528849501323264", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:30:08.994+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:30:18.994+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:30:28.995+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:30:36.012+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 8, "forRound": 2203622, "baseEpoch": 2203621, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299467, "lookbackEpochs": 900, "networkPowerAtLookback": "21465609388728057856", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:30:38.996+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:30:48.996+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:30:58.996+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:06.376+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 6, "forRound": 2203623, "baseEpoch": 2203622, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299468, "lookbackEpochs": 900, "networkPowerAtLookback": "21465609611924307968", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:31:08.997+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:18.997+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:28.998+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:36.299+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 7, "forRound": 2203624, "baseEpoch": 2203623, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299469, "lookbackEpochs": 900, "networkPowerAtLookback": "21465584666754252800", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:31:38.998+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:48.998+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:31:58.998+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:32:06.012+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 8, "forRound": 2203625, "baseEpoch": 2203624, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299470, "lookbackEpochs": 900, "networkPowerAtLookback": "21465584958658871296", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:32:08.999+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:32:18.999+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:32:29.000+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:32:36.008+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 5, "forRound": 2203626, "baseEpoch": 2203625, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299471, "lookbackEpochs": 900, "networkPowerAtLookback": "21465584958658871296", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T09:32:39.000+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=103079215104, reserved: -24576
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 0 (awi:0)
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 1 (awi:1)
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "881", "task": "seal/v0/precommit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T09:32:46.033+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 881
2022-09-29T09:32:46.034+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:46.053+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:1; a:0): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-881 }
2022-09-29T09:32:46.054+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:32:46.054+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:46.059+0800 WARN stores paths/local.go:155negative reserved storage: p.reserved=68719476736, reserved: -16384
2022-09-29T09:32:46.059+0800 ERROR stores paths/localstorage_cached.go:105 error getting disk usage {"path": "/mnt/ssd3/sealing/sealed/s-t01862564-881", "error": "file does not exist"}
2022-09-29T09:32:46.059+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:1; a:6): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-881 /mnt/ssd3/sealing/sealed/s-t01862564-881 /mnt/ssd3/sealing/cache/s-t01862564-881 }
2022-09-29T09:32:47.010+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:32:47.010+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:32:47.010+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:32:47.011+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 0 (awi:0)
2022-09-29T09:32:47.011+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 1 (awi:1)
2022-09-29T09:32:47.011+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "883", "task": "seal/v0/precommit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.285125019976941}
2022-09-29T09:32:47.011+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 883
2022-09-29T09:32:47.011+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:47.012+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:1; a:0): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-883 }
2022-09-29T09:32:47.012+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:32:47.012+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:47.014+0800 ERROR stores paths/localstorage_cached.go:105 error getting disk usage {"path": "/mnt/ssd3/sealing/sealed/s-t01862564-883", "error": "file does not exist"}
2022-09-29T09:32:47.014+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:1; a:6): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-883 /mnt/ssd3/sealing/sealed/s-t01862564-883 /mnt/ssd3/sealing/cache/s-t01862564-883 }
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 0 (awi:0)
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 1 (awi:1)
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "882", "task": "seal/v0/precommit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.4918356617182488}
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 882
2022-09-29T09:32:47.027+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:47.028+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:1; a:0): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-882 }
2022-09-29T09:32:47.028+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T09:32:47.028+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T09:32:47.030+0800 ERROR stores paths/localstorage_cached.go:105 error getting disk usage {"path": "/mnt/ssd3/sealing/sealed/s-t01862564-882", "error": "file does not exist"}
2022-09-29T09:32:47.030+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:1; a:6): {{0 0} /mnt/ssd3/sealing/unsealed/s-t01862564-882 /mnt/ssd3/sealing/sealed/s-t01862564-882 /mnt/ssd3/sealing/cache/s-t01862564-882 }

kbackEpochs": 900, "networkPowerAtLookback": "21470797794931408896", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:29:21.388+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T12:29:21.390+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 208235772316, need: 518832049356)
2022-09-29T12:29:21.390+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 208235772316, need: 518832049356)
2022-09-29T12:29:21.390+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T12:29:21.390+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T12:29:21.390+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 0 (awi:0)
2022-09-29T12:29:21.390+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 1 (awi:1)
2022-09-29T12:29:21.390+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "883", "task": "seal/v0/precommit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.4918356617182488}
2022-09-29T12:29:21.391+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 883
2022-09-29T12:29:21.391+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T12:29:21.393+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-883 /mnt/ssd3/sealing/cache/s-t01862564-883 }
2022-09-29T12:29:21.393+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T12:29:21.393+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T12:29:21.396+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-883 /mnt/ssd3/sealing/cache/s-t01862564-883 }
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T12:29:40.640+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 246030919272, need: 518832049356)
2022-09-29T12:29:40.640+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 246030919272, need: 518832049356)
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 0 (awi:0)
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 1 (awi:1)
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "882", "task": "seal/v0/precommit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 1.0466127410446628}
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 882
2022-09-29T12:29:40.640+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T12:29:40.641+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-882 /mnt/ssd3/sealing/cache/s-t01862564-882 }
2022-09-29T12:29:40.641+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for withResources; GPU(s) in use
2022-09-29T12:29:40.648+0800 WARN miner miner/miner.go:473completed mineOne {"tookMilliseconds": 10, "forRound": 2203980, "baseEpoch": 2203979, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": true, "beaconEpoch": 2299825, "lookbackEpochs": 900, "networkPowerAtLookback": "21470802221220495360", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:29:49.188+0800 INFO net/identify identify/id.go:364 failed negotiate identify protocol with peer {"peer": "12D3KooWHog6ACcvfc9V3yZsChZkQruiVQ3ZR9HYWHMVoEzrkYgt", "error": "stream reset"}
2022-09-29T12:30:06.020+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 15, "forRound": 2203981, "baseEpoch": 2203980, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299826, "lookbackEpochs": 900, "networkPowerAtLookback": "21470802526012047360", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:30:19.093+0800 INFO net/identify identify/id.go:364 failed negotiate identify protocol with peer {"peer": "12D3KooWHog6ACcvfc9V3yZsChZkQruiVQ3ZR9HYWHMVoEzrkYgt", "error": "stream reset"}
2022-09-29T12:30:36.009+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 6, "forRound": 2203982, "baseEpoch": 2203981, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299827, "lookbackEpochs": 900, "networkPowerAtLookback": "21470802526012047360", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:31:00.138+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for withResources; GPU(s) in use
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T12:31:00.146+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 278917923636, need: 518832049356)
2022-09-29T12:31:00.146+0800 DEBUG stores paths/index.go:491not selecting on cdf9141e-9aaf-49b8-b3a0-ea7b94c52b69, out of space (available: 278917923636, need: 518832049356)
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 0 (awi:0)
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 1 (awi:1)
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "881", "task": "seal/v0/precommit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 2}
2022-09-29T12:31:00.146+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for startPreparing; GPU(s) in use
2022-09-29T12:31:06.013+0800 INFO miner miner/miner.go:475completed mineOne {"tookMilliseconds": 8, "forRound": 2203983, "baseEpoch": 2203982, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299828, "lookbackEpochs": 900, "networkPowerAtLookback": "21470802838186917888", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

022-09-29T12:41:36.016+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 10, "forRound": 2204004, "baseEpoch": 2204003, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299849, "lookbackEpochs": 900, "networkPowerAtLookback": "21471133181565534208", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:41:53.793+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T12:41:53.794+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 881
2022-09-29T12:41:53.794+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T12:41:53.794+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-882 /mnt/ssd3/sealing/cache/s-t01862564-882 }
2022-09-29T12:41:53.795+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-881 /mnt/ssd3/sealing/cache/s-t01862564-881 }
2022-09-29T12:41:53.795+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for withResources; GPU(s) in use
2022-09-29T12:42:01.631+0800 INFO sectors pipeline/states_sealing.go:459 Sector precommitted: 883
2022-09-29T12:42:06.507+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 7, "forRound": 2204005, "baseEpoch": 2204004, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299850, "lookbackEpochs": 900, "networkPowerAtLookback": "21471214218835066880", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T12:50:06.013+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 7, "forRound": 2204021, "baseEpoch": 2204020, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299866, "lookbackEpochs": 900, "networkPowerAtLookback": "21471420278060711936", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:50:36.007+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:37.013+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:38.018+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:39.024+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:40.030+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:41.035+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:42.039+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:43.044+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:44.049+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:50.055+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:51.060+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:52.066+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:53.071+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:54.078+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:55.083+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:56.397+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:57.403+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:58.406+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:50:59.412+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:00.416+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:01.422+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:02.426+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:03.432+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:04.437+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": dial tcp: lookup api3.drand.sh: Temporary failure in name resolution - doing request: Get "https://drand.cloudflare.com/public/2299867": dial tcp: lookup drand.cloudflare.com: Temporary failure in name resolution - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:15.442+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299867": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299867": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299867": dial tcp: lookup api2.drand.sh: Temporary failure in name resolution - doing request: Get "https://api.drand.sh/public/2299867": dial tcp: lookup api.drand.sh: Temporary failure in name resolution
2022-09-29T12:51:16.992+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 9, "forRound": 2204022, "baseEpoch": 2204020, "baseDeltaSeconds": 76, "nullRounds": 1, "lateStart": true, "beaconEpoch": 2299867, "lookbackEpochs": 900, "networkPowerAtLookback": "21471420581744181248", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:51:17.186+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 7, "forRound": 2204023, "baseEpoch": 2204020, "baseDeltaSeconds": 77, "nullRounds": 2, "lateStart": true, "beaconEpoch": 2299868, "lookbackEpochs": 900, "networkPowerAtLookback": "21471420581744181248", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:51:36.013+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 7, "forRound": 2204024, "baseEpoch": 2204023, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299869, "lookbackEpochs": 900, "networkPowerAtLookback": "21471421184362348544", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T12:53:36.017+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 10, "forRound": 2204028, "baseEpoch": 2204027, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299873, "lookbackEpochs": 900, "networkPowerAtLookback": "21471501812055146496", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:54:18.021+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 8, "forRound": 2204029, "baseEpoch": 2204027, "baseDeltaSeconds": 48, "nullRounds": 1, "lateStart": true, "beaconEpoch": 2299874, "lookbackEpochs": 900, "networkPowerAtLookback": "21471501812055146496", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:54:24.237+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T12:54:24.237+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T12:54:24.238+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-881 /mnt/ssd3/sealing/cache/s-t01862564-881 }
2022-09-29T12:54:36.359+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 5, "forRound": 2204030, "baseEpoch": 2204029, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2299875, "lookbackEpochs": 900, "networkPowerAtLookback": "21471503598761541632", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:55:26.005+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299876": context deadline exceeded - doing request: Get "https://api.drand.sh/public/2299876": context deadline exceeded
2022-09-29T12:55:47.010+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299876": context deadline exceeded - doing request: Get "https://api.drand.sh/public/2299876": context deadline exceeded
2022-09-29T12:56:01.535+0800 INFO sectors pipeline/states_sealing.go:459 Sector precommitted: 882
2022-09-29T12:56:08.016+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299876": context deadline exceeded - doing request: Get "https://api.drand.sh/public/2299876": context deadline exceeded
2022-09-29T12:56:29.021+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299876": context deadline exceeded - doing request: Get "https://api.drand.sh/public/2299876": context deadline exceeded
2022-09-29T12:56:50.026+0800 ERROR miner miner/miner.go:261 failed getting beacon entry: drand failed Get request: no valid clients - doing request: Get "https://api3.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://api2.drand.sh/public/2299876": context deadline exceeded - doing request: Get "https://drand.cloudflare.com/public/2299876": context deadline exceeded - doing request: Get "https://api.drand.sh/public/2299876": context deadline exceeded
2022-09-29T12:56:56.402+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 6, "forRound": 2204031, "baseEpoch": 2204029, "baseDeltaSeconds": 146, "nullRounds": 1, "lateStart": true, "beaconEpoch": 2299876, "lookbackEpochs": 900, "networkPowerAtLookback": "21471503933217636352", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:56:56.598+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 6, "forRound": 2204032, "baseEpoch": 2204029, "baseDeltaSeconds": 146, "nullRounds": 2, "lateStart": true, "beaconEpoch": 2299877, "lookbackEpochs": 900, "networkPowerAtLookback": "21471503933217636352", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:56:56.795+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 8, "forRound": 2204033, "baseEpoch": 2204029, "baseDeltaSeconds": 146, "nullRounds": 3, "lateStart": true, "beaconEpoch": 2299878, "lookbackEpochs": 900, "networkPowerAtLookback": "21471504238019379200", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:56:56.988+0800 WARN miner miner/miner.go:473 completed mineOne {"tookMilliseconds": 8, "forRound": 2204034, "baseEpoch": 2204029, "baseDeltaSeconds": 146, "nullRounds": 4, "lateStart": true, "beaconEpoch": 2299879, "lookbackEpochs": 900, "networkPowerAtLookback": "21471667309337673728", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}
2022-09-29T12:57:06.011+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 9, "forRound": 2204035, "baseEpoch": 2204029, "baseDeltaSeconds": 156, "nullRounds": 5, "lateStart": false, "beaconEpoch": 2299880, "lookbackEpochs": 900, "networkPowerAtLookback": "21471669508360929280", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T14:00:30.290+0800 INFO sectors pipeline/states_sealing.go:559 KOMIT 883 25b189b871487de4dc868ae16b4f103d762f493227e3eba0f041a0ef1f55ef55(2202725); 45bd920194bec043d769d86346511f6cca01a30f020676508b95ed71fbbc2279(2204155); [{34359738368 baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq}]; r:bagboea4b5abcaixpkmxwzateeqxphnhhz5ovm2dlvbdocnai3ebdiw2ffgn7b6ko; d:baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq
2022-09-29T14:00:30.292+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 0 (awi:0)
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 1 (awi:1)
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "883", "task": "seal/v0/commit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_worker.go:429 assign worker sector 883 (ready)
2022-09-29T14:00:30.293+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:00:30.294+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 883} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-883 /mnt/ssd3/sealing/cache/s-t01862564-883 }
2022-09-29T14:00:30.839+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T14:00:30.839+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 0 (awi:0)
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 883 to window 1 (awi:1)
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "883", "task": "seal/v0/commit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 0.09322548208932561}
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_worker.go:429 assign worker sector 883 (ready)
2022-09-29T14:00:31.055+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:00:36.412+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 6, "forRound": 2204162, "baseEpoch": 2204161, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300007, "lookbackEpochs": 900, "networkPowerAtLookback": "21474621901198983168", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T14:19:00.587+0800 INFO sectors pipeline/states_sealing.go:559 KOMIT 882 25b189b871487de4dc868ae16b4f103d762f493227e3eba0f041a0ef1f55ef55(2202725); f582f2845b53fbf259be2f3d9296a3bdac9a0886a74801c038f3c701f06a85bb(2204192); [{34359738368 baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq}]; r:bagboea4b5abcblzugzrcnvu7t5et5miigd4gkkcat6cokhsd64s64lnrloiuzyqn; d:baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 0 (awi:0)
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 1 (awi:1)
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "882", "task": "seal/v0/commit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 1.0466127410446628}
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_worker.go:429 assign worker sector 882 (ready)
2022-09-29T14:19:00.588+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:19:00.589+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 882} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-882 /mnt/ssd3/sealing/cache/s-t01862564-882 }
2022-09-29T14:19:01.543+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T14:19:01.543+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 0 (awi:0)
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 882 to window 1 (awi:1)
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "882", "task": "seal/v0/commit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 1.0466127410446628}
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for startPreparing; GPU(s) in use
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 882
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:19:01.734+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for withResources; GPU(s) in use
2022-09-29T14:19:06.178+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 8, "forRound": 2204199, "baseEpoch": 2204198, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300044, "lookbackEpochs": 900, "networkPowerAtLookback": "21474529578296541184", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

2022-09-29T14:25:59.915+0800 INFO sectors pipeline/states_sealing.go:559 KOMIT 881 25b189b871487de4dc868ae16b4f103d762f493227e3eba0f041a0ef1f55ef55(2202725); 90b9329a57286e58ab5699f18fe9fe41a676b2d7b690d842dd46630b5edddd61(2204206); [{34359738368 baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq}]; r:bagboea4b5abcboq7beck72gubistd4eix5efpp2mhlxdiougvgc3ngzsdjtsstll; d:baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 0 (awi:0)
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 1 (awi:1)
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "881", "task": "seal/v0/commit/1", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 2}
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_worker.go:369 assign worker sector 881
2022-09-29T14:25:59.916+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:25:59.917+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-881 /mnt/ssd3/sealing/cache/s-t01862564-881 }
2022-09-29T14:25:59.917+0800 DEBUG advmgr sealer/sched_worker.go:274 task done {"workerid": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b"}
2022-09-29T14:25:59.917+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 0 queued; 2 open windows
2022-09-29T14:25:59.918+0800 DEBUG advmgr sealer/worker_local.go:165 acquired sector {{1862564 881} 8} (e:6; a:0): {{0 0} /mnt/ssd3/sealing/sealed/s-t01862564-881 /mnt/ssd3/sealing/cache/s-t01862564-881 }
2022-09-29T14:26:00.549+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for withResources; GPU(s) in use
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_common.go:39 SCHED 1 queued; 2 open windows
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_common.go:151 SCHED windows: [{Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]} {Allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 taskCounters:map[] cond: waiting:0} Todo:[]}]
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_common.go:152 SCHED Acceptable win: [[0 1]]
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 0 (awi:0)
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:35 SCHED try assign sqi:0 sector 881 to window 1 (awi:1)
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_assigner_utilization.go:76 SCHED ASSIGNED {"sqi": 0, "sector": "881", "task": "seal/v0/commit/2", "window": 0, "worker": "6faec7cf-a714-4592-a66b-1c3dbd83eb4b", "utilization": 2}
2022-09-29T14:26:00.819+0800 DEBUG advmgr sealer/sched_resources.go:131 sched: not scheduling on worker 6faec7cf-a714-4592-a66b-1c3dbd83eb4b for startPreparing; GPU(s) in use
2022-09-29T14:26:06.011+0800 INFO miner miner/miner.go:475 completed mineOne {"tookMilliseconds": 7, "forRound": 2204213, "baseEpoch": 2204212, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 2300058, "lookbackEpochs": 900, "networkPowerAtLookback": "21475010248757444608", "minerPowerAtLookback": "28415503630336", "isEligible": true, "isWinner": false, "error": null}

5 replies

TippyFlitsUK Sep 29, 2022
Maintainer

Thanks @ChaiWenyu1983
I'm afraid that these logs do not show the failed WindowPoST attempt. You can attach the complete logs as a text file to this thread.
If the dirty build was not intentional, this needs to be resolved.

ChaiWenyu1983 Sep 29, 2022
Author

louts_miner.log.txt

ChaiWenyu1983 Sep 29, 2022
Author

Anything new?

TippyFlitsUK Sep 29, 2022
Maintainer

The attached logs still do not show the WindowPoST @ChaiWenyu1983 . Please make sure that you pipe the logs to a file for the next WindowPoST and attach again here.

ChaiWenyu1983 Oct 9, 2022
Author

Today, "WindowPoST" is not available. The log is attached.
miner.log

Missed "SubmitWindowedPoSt" again #9390

Uh oh!

ChaiWenyu1983 Sep 29, 2022

Replies: 5 comments · 9 replies

Uh oh!

TippyFlitsUK Sep 29, 2022 Maintainer

Uh oh!

ChaiWenyu1983 Oct 21, 2022 Author

Uh oh!

TippyFlitsUK Oct 21, 2022 Maintainer

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

TippyFlitsUK Sep 29, 2022 Maintainer

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

TippyFlitsUK Sep 29, 2022 Maintainer

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

TippyFlitsUK Sep 29, 2022 Maintainer

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

ChaiWenyu1983 Sep 29, 2022 Author

Uh oh!

TippyFlitsUK Sep 29, 2022 Maintainer

Uh oh!

Uh oh!

ChaiWenyu1983 Oct 9, 2022 Author

ChaiWenyu1983
Sep 29, 2022

Replies: 5 comments 9 replies

TippyFlitsUK
Sep 29, 2022
Maintainer

ChaiWenyu1983 Oct 21, 2022
Author

TippyFlitsUK Oct 21, 2022
Maintainer

ChaiWenyu1983
Sep 29, 2022
Author

TippyFlitsUK
Sep 29, 2022
Maintainer

ChaiWenyu1983 Sep 29, 2022
Author

TippyFlitsUK
Sep 29, 2022
Maintainer

ChaiWenyu1983 Sep 29, 2022
Author

ChaiWenyu1983
Sep 29, 2022
Author

TippyFlitsUK Sep 29, 2022
Maintainer

ChaiWenyu1983 Sep 29, 2022
Author

ChaiWenyu1983 Sep 29, 2022
Author

TippyFlitsUK Sep 29, 2022
Maintainer

ChaiWenyu1983 Oct 9, 2022
Author