Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Mined blocks became orphan blocks #5128

Closed
Tracked by #5310
liangping opened this issue Dec 6, 2020 · 34 comments
Closed
Tracked by #5310

Mined blocks became orphan blocks #5128

liangping opened this issue Dec 6, 2020 · 34 comments
Labels
area/mining Area: Mining need/analysis Hint: Needs Analysis P2 P2: Should be resolved

Comments

@liangping
Copy link

liangping commented Dec 6, 2020

Describe the bug

We mined some blocks,but don't know why these blocks are not exists on chain.

2020-12-06T01:23:36.133Z        INFO    storageminer    storage/miner.go:251    Computing WinningPoSt ;[{SealProof:8 SectorNumber:25272 SealedCID:bagboea4b5abcbe2cyns3zmw3mhhlftwx3im76ytulqdpfkivvmh7tf5bub46qzrk}]; [194 38 156 168 46 37 44 32 46 145 33 78 103 176 212 16 46 155 183 43 24 72 86 19 54 56 37 183 139 26 184 11]
2020-12-06T01:23:41.759Z        INFO    storageminer    storage/miner.go:258    GenerateWinningPoSt took 5.626304116s
2020-12-06T01:23:42.157Z        INFO    miner   miner/miner.go:448      mined new block {"cid": "bafy2bzaceaj6mkgqeh6qrnl4jrqwxptuanijcpgg6eo2dzspnxewj3bzbhp7k", "height": "297048", "miner": "f03339", "parents": ["f07830","f02520","f030347","f02777","f020331","f020522"], "took": 6.035145888}
2020-12-05T23:20:06.100Z        INFO    storageminer    storage/miner.go:251    Computing WinningPoSt ;[{SealProof:3 SectorNumber:16435 SealedCID:bagboea4b5abcb4t4fybuumey4xfiefynlhqqrdlmzfoyg7uqwym7vrx75d6uwzc5}]; [182 6 130 38 137 107 109 218 22 88 224 234 22 86 97 212 80 201 160 117 242 136 51 129 201 109 113 41 181 201 28 175]
2020-12-05T23:20:07.577Z        WARN    sectors storage-sealing/states_sealing.go:355   revert in interactive commit sector step
2020-12-05T23:20:11.758Z        INFO    storageminer    storage/miner.go:258    GenerateWinningPoSt took 5.657667875s
2020-12-05T23:20:12.203Z        INFO    miner   miner/miner.go:448      mined new block {"cid": "bafy2bzaceceuzscc5kxhkc4eytak4wlbmemdd4m3e7dqlmmsrb37hva4p7zri", "height": "296801", "miner": "f03339", "parents": ["f034548","f023530","f022374","f010253"], "took": 6.113739295}
@rjan90
Copy link
Contributor

rjan90 commented Dec 6, 2020

I have the same issue:

2020-12-05T07:43:06.188+0100	INFO	storageminer	storage/miner.go:249	Computing WinningPoSt ;[{SealProof:3 SectorNumber:947 SealedCID:bagboea4b5abcbh6hg62qalt3q6kohkgt2ejpr5c3tajslfz7ttkl5f34ovxn2xkr}]; [165 153 91 108 41 240 123 113 41 74 54 137 43 226 78 220 142 188 162 130 12 145 99 42 151 92 221 70 100 35 180 249]
2020-12-05T07:43:19.185+0100	INFO	miner	miner/miner.go:446	mined new block	{"cid": "bafy2bzaceacog7hihrux7lzokp2r5mbzbw4cwji66zyiczfs7quqcwlxkif4g", "height": "294807", "miner": "f023467", "parents": ["f045756","f086204","f023530","f065881"], "took": 13.008040787}

My miner says it has mined a block, but there is no record of it on filfox: https://filfox.info/en/tipset/294807. And my balance on my miner does not seem to have been credited with funds for mining the block.

@ribasushi
Copy link
Collaborator

Extra context after analyzing @rjan90's ( daemon/miner interleaved, unfiltered, chain-specific) logs:

daemon:

...
2020-12-05T07:42:51.422+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacec3mord6iv2tkyswgmac5gqu5socon3nxjwy6w2lsgrhwi37afykw bafy2bzacedtv32gqmzplmh3e52gcdlpikrzszqsthepavgvya6wbzwmp45ar4 bafy2bzacebngj4gorzqwgsrnz4f2abrjaiy5xqtyo6eizskrp37vkmmblr7nw bafy2bzacecpo7yf3tb5mx5hkxlowawvxajjdzcobyph7jwuseckzyj3pckyy4 bafy2bzaced3gmopjx2qa6uhav24gycivg42mpxwm2cwblrtkvo5m55ntz6c56]
2020-12-05T07:42:51.422+0100	INFO	chain	chain/sync_manager.go:313	worker 196200 syncing in [bafy2bzacec3mord6iv2tkyswgmac5gqu5socon3nxjwy6w2lsgrhwi37afykw bafy2bzacedtv32gqmzplmh3e52gcdlpikrzszqsthepavgvya6wbzwmp45ar4 bafy2bzacebngj4gorzqwgsrnz4f2abrjaiy5xqtyo6eizskrp37vkmmblr7nw bafy2bzacecpo7yf3tb5mx5hkxlowawvxajjdzcobyph7jwuseckzyj3pckyy4 bafy2bzaced3gmopjx2qa6uhav24gycivg42mpxwm2cwblrtkvo5m55ntz6c56]
2020-12-05T07:42:51.422+0100	INFO	chain	chain/sync_manager.go:321	worker 196200 done; took 2.585µs
2020-12-05T07:43:00.195+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c]
2020-12-05T07:43:00.195+0100	INFO	chain	chain/sync_manager.go:313	worker 196201 syncing in [bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c]
2020-12-05T07:43:00.255+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.056118421, "height": "294806", "age": 0.2556542}
2020-12-05T07:43:00.256+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c] (height=294806)
2020-12-05T07:43:00.259+0100	INFO	chain	chain/sync_manager.go:321	worker 196201 done; took 63.61833ms
2020-12-05T07:43:00.286+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y]
2020-12-05T07:43:00.286+0100	INFO	chain	chain/sync_manager.go:313	worker 196202 syncing in [bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y]
2020-12-05T07:43:00.374+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.081746647, "height": "294806", "age": 0.374647378}
2020-12-05T07:43:00.375+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y] (height=294806)
2020-12-05T07:43:00.378+0100	INFO	chain	chain/sync_manager.go:321	worker 196202 done; took 92.438616ms
2020-12-05T07:43:00.465+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs]
2020-12-05T07:43:00.465+0100	INFO	chain	chain/sync_manager.go:313	worker 196203 syncing in [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs]
2020-12-05T07:43:00.473+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs]
2020-12-05T07:43:00.473+0100	INFO	chain	chain/sync_manager.go:313	worker 196204 syncing in [bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs]
2020-12-05T07:43:00.620+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.141931676, "height": "294806", "age": 0.620124985}
2020-12-05T07:43:00.621+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y] (height=294806)
2020-12-05T07:43:00.624+0100	INFO	chain	chain/sync_manager.go:321	worker 196203 done; took 159.036586ms
2020-12-05T07:43:01.053+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.574176514, "height": "294806", "age": 1.053657125}
2020-12-05T07:43:01.054+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y] (height=294806)
2020-12-05T07:43:01.068+0100	INFO	chain	chain/sync_manager.go:321	worker 196204 done; took 594.890124ms
2020-12-05T07:43:06.158+0100	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 390651}
2020-12-05T07:43:06.176+0100	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 390651, "took": 0.01792677}
2020-12-05T07:43:06.178+0100	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 390651}
2020-12-05T07:43:06.178+0100	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 390651, "took": 0.000075211}

miner:

2020-12-05T07:43:06.184+0100	INFO	miner	miner/miner.go:384	Time delta between now and our mining base: 6s (nulls: 0)
2020-12-05T07:43:06.188+0100	INFO	storageminer	storage/miner.go:249	Computing WinningPoSt ;[{SealProof:3 SectorNumber:947 SealedCID:bagboea4b5abcbh6hg62qalt3q6kohkgt2ejpr5c3tajslfz7ttkl5f34ovxn2xkr}]; [165 153 91 108 41 240 123 113 41 74 54 137 43 226 78 220 142 188 162 130 12 145 99 42 151 92 221 70 100 35 180 249]
2

daemon:

2020-12-05T07:43:09.496+0100	WARN	sub	sub/incoming.go:103	Received block with large delay 9 from miner f01248
2020-12-05T07:43:09.506+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu]
2020-12-05T07:43:09.506+0100	INFO	chain	chain/sync_manager.go:313	worker 196205 syncing in [bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu]
2020-12-05T07:43:11.259+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 1.749010366, "height": "294806", "age": 11.259375307}
2020-12-05T07:43:11.260+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y] (height=294806)
2020-12-05T07:43:11.263+0100	INFO	chain	chain/sync_manager.go:321	worker 196205 done; took 1.757215376s

miner:

2020-12-05T07:43:18.553+0100	INFO	storageminer	storage/miner.go:256	GenerateWinningPoSt took 12.365091178s
2020-12-05T07:43:19.185+0100	INFO	miner	miner/miner.go:446	mined new block	{"cid": "bafy2bzaceacog7hihrux7lzokp2r5mbzbw4cwji66zyiczfs7quqcwlxkif4g", "height": "294807", "miner": "f023467", "parents": ["f045756","f086204","f023530","f065881"], "took": 13.008040787}

daemon:

2020-12-05T07:43:24.322+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y]
2020-12-05T07:43:24.323+0100	INFO	chain	chain/sync_manager.go:313	worker 196206 syncing in [bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y]
2020-12-05T07:43:24.323+0100	INFO	chain	chain/sync_manager.go:321	worker 196206 done; took 3.516µs
2020-12-05T07:43:30.026+0100	WARN	chain	chain/sync.go:1418	(fork detected) synced header chain ([bafy2bzaceacog7hihrux7lzokp2r5mbzbw4cwji66zyiczfs7quqcwlxkif4g] - 294807) does not link to our best block ([bafy2bzacedfvsxgydrwdu7rallk3gwpejdwhtaypfguuo4fyxjxr5cdiyrkrs bafy2bzacedo2zxkbi2ivrbfxo3fntkplb7pzlqsdj7g5vdtkjm7lkez2klu7c bafy2bzacecqw3bdbsezqiqbajlgukwmeiqxh3dpmqhkfi4ghoxltmkej6kajs bafy2bzacea4w5mvq66zdelwy6epx4lysk6ngf3y5fkgtqy2ioas76eiz3yjbu bafy2bzaceabk67pg3ee7qs5yczmvlxpi57pxckur2vwitsbh3govjeeqoas2y] - 294806)
2020-12-05T07:43:30.203+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274]
2020-12-05T07:43:30.203+0100	INFO	chain	chain/sync_manager.go:313	worker 196207 syncing in [bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274]
2020-12-05T07:43:30.249+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.043314988, "height": "294807", "age": 0.24995765}
2020-12-05T07:43:30.253+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274] (height=294807)
2020-12-05T07:43:30.256+0100	INFO	chain	chain/sync_manager.go:321	worker 196207 done; took 53.048279ms
2020-12-05T07:43:30.292+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq]
2020-12-05T07:43:30.292+0100	INFO	chain	chain/sync_manager.go:313	worker 196208 syncing in [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq]
2020-12-05T07:43:30.579+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.282073688, "height": "294807", "age": 0.579594614}
2020-12-05T07:43:30.580+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274] (height=294807)
2020-12-05T07:43:30.583+0100	INFO	chain	chain/sync_manager.go:321	worker 196208 done; took 291.363842ms
2020-12-05T07:43:30.798+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacedmzlhzuojzqsbcmjocnkrfvuv4voa7slid4eu44xaxpsb3glflhm]
2020-12-05T07:43:30.798+0100	INFO	chain	chain/sync_manager.go:313	worker 196209 syncing in [bafy2bzacedmzlhzuojzqsbcmjocnkrfvuv4voa7slid4eu44xaxpsb3glflhm]
2020-12-05T07:43:32.071+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 1.272436981, "height": "294807", "age": 2.071576055}
2020-12-05T07:43:32.072+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq bafy2bzacedmzlhzuojzqsbcmjocnkrfvuv4voa7slid4eu44xaxpsb3glflhm bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274] (height=294807)
2020-12-05T07:43:32.075+0100	INFO	chain	chain/sync_manager.go:321	worker 196209 done; took 1.27695272s
2020-12-05T07:43:32.251+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq bafy2bzacedmzlhzuojzqsbcmjocnkrfvuv4voa7slid4eu44xaxpsb3glflhm bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274]
2020-12-05T07:43:32.251+0100	INFO	chain	chain/sync_manager.go:313	worker 196210 syncing in [bafy2bzaceacbcb52yovodkmsd24wtqmkpv5pr7fzku3epoxyvprqfhzdixtmq bafy2bzacedmzlhzuojzqsbcmjocnkrfvuv4voa7slid4eu44xaxpsb3glflhm bafy2bzaceantfyrayhthe6rpgdx4w22k253jsqrrtuqf7mjsym32qbxxpk274]
2020-12-05T07:43:32.251+0100	INFO	chain	chain/sync_manager.go:321	worker 196210 done; took 3.486µs
2020-12-05T07:43:33.702+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.059845512, "height": "294807", "age": 3.702158975}
2020-12-05T07:43:36.280+0100	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 390652}
2020-12-05T07:43:36.339+0100	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 390652, "took": 0.058778123}
2020-12-05T07:43:36.360+0100	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 390652}
2020-12-05T07:43:36.360+0100	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 390652, "took": 0.000080951}
2020-12-05T07:44:00.215+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzacecta3hejaejj24po73ggg6s24jbtdj3dzdfcg32zigegm43kiqxqa]
2020-12-05T07:44:00.215+0100	INFO	chain	chain/sync_manager.go:313	worker 196211 syncing in [bafy2bzacecta3hejaejj24po73ggg6s24jbtdj3dzdfcg32zigegm43kiqxqa]
2020-12-05T07:44:00.250+0100	INFO	chain	chain/sync_manager.go:231	selected sync target: [bafy2bzaceakwgq2vri6nnsvytynmocorsr5qckpgwklzywsk6yz3zszshtt4m]
2020-12-05T07:44:00.250+0100	INFO	chain	chain/sync_manager.go:313	worker 196212 syncing in [bafy2bzaceakwgq2vri6nnsvytynmocorsr5qckpgwklzywsk6yz3zszshtt4m]
2020-12-05T07:44:00.308+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.052863574, "height": "294808", "age": 0.308125405}
...

@karalabe
Copy link
Contributor

karalabe commented Dec 7, 2020

Just to drop my own logs into this too

{"level":"info","ts":"2020-12-07T12:22:14.357+0200","logger":"miner","caller":"miner/miner.go:446","msg":"mined new block","cid":"bafy2bzacecowouxymgwh2gdv7a5kak3j6tcov3auvi57l6hsjlriag74mn43w","height":"301005","miner":"f019100","parents":["f01235","f02438"],"took":7.915629864}
{"level":"warn","ts":"2020-12-07T12:22:30.015+0200","logger":"chain","caller":"chain/sync.go:1418","msg":"(fork detected) synced header chain ([bafy2bzacecowouxymgwh2gdv7a5kak3j6tcov3auvi57l6hsjlriag74mn43w] - 301005) does not link to our best block ([bafy2bzaceanch4iqikxtqnvaa4534w5muhmrx5bbwdglu5pcujkxlsold5tjy bafy2bzacedgozb2qo3ovf26jrdvjkzq2ahqq7e7ql57bhsrpaag2ibreadmtq bafy2bzaceauhz7v5rh3wg5tppmq22nl63ctav34mcnyzdqsudzlvz6bhktwru] - 301004)"}
[...]
{"level":"info","ts":"2020-12-07T12:22:30.200+0200","logger":"chain","caller":"chain/sync_manager.go:231","msg":"selected sync target: [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds]"}
{"level":"info","ts":"2020-12-07T12:22:30.200+0200","logger":"chain","caller":"chain/sync_manager.go:313","msg":"worker 64740 syncing in [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds]"}
{"level":"info","ts":"2020-12-07T12:22:30.221+0200","logger":"chain","caller":"chain/sync.go:718","msg":"block validation","took":0.017481549,"height":"301005","age":0.221774635}
{"level":"info","ts":"2020-12-07T12:22:30.222+0200","logger":"chainstore","caller":"store/store.go:513","msg":"New heaviest tipset! [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds] (height=301005)"}
{"level":"info","ts":"2020-12-07T12:22:30.224+0200","logger":"chain","caller":"chain/sync_manager.go:321","msg":"worker 64740 done; took 23.328461ms"}
{"level":"info","ts":"2020-12-07T12:22:30.278+0200","logger":"chain","caller":"chain/sync_manager.go:231","msg":"selected sync target: [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi]"}
{"level":"info","ts":"2020-12-07T12:22:30.278+0200","logger":"chain","caller":"chain/sync_manager.go:313","msg":"worker 64741 syncing in [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi]"}
{"level":"info","ts":"2020-12-07T12:22:30.305+0200","logger":"chain","caller":"chain/sync.go:718","msg":"block validation","took":0.024912436,"height":"301005","age":0.305359898}
{"level":"info","ts":"2020-12-07T12:22:30.305+0200","logger":"chainstore","caller":"store/store.go:513","msg":"New heaviest tipset! [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds] (height=301005)"}

@jennijuju jennijuju changed the title Mined blocks disappeared Mined orphan blocks Dec 7, 2020
@jennijuju
Copy link
Member

Just to drop my own logs into this too

{"level":"info","ts":"2020-12-07T12:22:14.357+0200","logger":"miner","caller":"miner/miner.go:446","msg":"mined new block","cid":"bafy2bzacecowouxymgwh2gdv7a5kak3j6tcov3auvi57l6hsjlriag74mn43w","height":"301005","miner":"f019100","parents":["f01235","f02438"],"took":7.915629864}
{"level":"warn","ts":"2020-12-07T12:22:30.015+0200","logger":"chain","caller":"chain/sync.go:1418","msg":"(fork detected) synced header chain ([bafy2bzacecowouxymgwh2gdv7a5kak3j6tcov3auvi57l6hsjlriag74mn43w] - 301005) does not link to our best block ([bafy2bzaceanch4iqikxtqnvaa4534w5muhmrx5bbwdglu5pcujkxlsold5tjy bafy2bzacedgozb2qo3ovf26jrdvjkzq2ahqq7e7ql57bhsrpaag2ibreadmtq bafy2bzaceauhz7v5rh3wg5tppmq22nl63ctav34mcnyzdqsudzlvz6bhktwru] - 301004)"}
[...]
{"level":"info","ts":"2020-12-07T12:22:30.200+0200","logger":"chain","caller":"chain/sync_manager.go:231","msg":"selected sync target: [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds]"}
{"level":"info","ts":"2020-12-07T12:22:30.200+0200","logger":"chain","caller":"chain/sync_manager.go:313","msg":"worker 64740 syncing in [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds]"}
{"level":"info","ts":"2020-12-07T12:22:30.221+0200","logger":"chain","caller":"chain/sync.go:718","msg":"block validation","took":0.017481549,"height":"301005","age":0.221774635}
{"level":"info","ts":"2020-12-07T12:22:30.222+0200","logger":"chainstore","caller":"store/store.go:513","msg":"New heaviest tipset! [bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds] (height=301005)"}
{"level":"info","ts":"2020-12-07T12:22:30.224+0200","logger":"chain","caller":"chain/sync_manager.go:321","msg":"worker 64740 done; took 23.328461ms"}
{"level":"info","ts":"2020-12-07T12:22:30.278+0200","logger":"chain","caller":"chain/sync_manager.go:231","msg":"selected sync target: [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi]"}
{"level":"info","ts":"2020-12-07T12:22:30.278+0200","logger":"chain","caller":"chain/sync_manager.go:313","msg":"worker 64741 syncing in [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi]"}
{"level":"info","ts":"2020-12-07T12:22:30.305+0200","logger":"chain","caller":"chain/sync.go:718","msg":"block validation","took":0.024912436,"height":"301005","age":0.305359898}
{"level":"info","ts":"2020-12-07T12:22:30.305+0200","logger":"chainstore","caller":"store/store.go:513","msg":"New heaviest tipset! [bafy2bzacea7a6jdejvi2fvjz2mhtjtdqfie3xgsvium4ok5n65sng5dcj7imi bafy2bzaceavbuns5xrq6hq43drfelljjqzrg5g3mq4viu5oh5bloqujly67ds] (height=301005)"}

Adding more info on re-org stats for investigation

2020-12-03T01:12:07.371573443+02:00, 2, 1
2020-12-03T05:09:17.121628673+02:00, 2, 1
2020-12-03T05:37:07.991860951+02:00, 2, 1
2020-12-03T06:51:35.255042573+02:00, 2, 1
2020-12-03T10:06:42.357456178+02:00, 2, 1
2020-12-03T10:37:35.021801263+02:00, 2, 1
2020-12-03T11:16:12.566822696+02:00, 2, 1
2020-12-03T11:16:53.599180733+02:00, 2, 1
2020-12-03T11:18:36.462167063+02:00, 2, 1
2020-12-03T12:35:06.349006788+02:00, 2, 1
2020-12-03T16:55:30.347190056+02:00, 2, 1
2020-12-03T18:13:33.712640775+02:00, 2, 1
2020-12-03T19:15:51.643412947+02:00, 2, 1
2020-12-03T20:39:08.462691577+02:00, 2, 1
2020-12-04T03:16:45.350259747+02:00, 2, 1
2020-12-04T04:17:05.038062875+02:00, 2, 1
2020-12-04T04:42:06.559813043+02:00, 2, 1
2020-12-04T04:42:35.450721172+02:00, 2, 1
2020-12-04T18:26:40.881701422+02:00, 2, 1
2020-12-04T18:27:34.116681466+02:00, 2, 1
2020-12-04T20:23:38.084812701+02:00, 2, 1
2020-12-04T20:33:05.083550326+02:00, 2, 1
2020-12-04T22:12:10.37865816+02:00, 2, 1
2020-12-05T02:54:02.983656572+02:00, 2, 1
2020-12-05T02:54:48.875035915+02:00, 2, 1
2020-12-05T03:06:04.873921928+02:00, 2, 1
2020-12-05T04:09:06.58531939+02:00, 2, 1
2020-12-05T05:15:38.111868988+02:00, 2, 1
2020-12-05T10:19:36.823794891+02:00, 2, 1
2020-12-05T10:45:30.112700436+02:00, 2, 1
2020-12-05T12:58:30.462550443+02:00, 2, 1
2020-12-05T17:22:35.036766114+02:00, 2, 1
2020-12-05T18:45:32.691629301+02:00, 2, 1
2020-12-05T18:46:04.474540961+02:00, 2, 1
2020-12-05T20:14:04.110858079+02:00, 2, 1
2020-12-05T20:14:36.127732168+02:00, 2, 1
2020-12-05T22:53:26.288007117+02:00, 2, 1
2020-12-06T01:29:03.734177879+02:00, 2, 1
2020-12-06T03:09:05.569543815+02:00, 2, 1
2020-12-06T03:11:35.063730573+02:00, 2, 1
2020-12-06T03:14:38.971517692+02:00, 2, 1
2020-12-06T03:21:40.521391649+02:00, 2, 1
2020-12-06T03:25:16.984660731+02:00, 2, 1
2020-12-06T03:47:33.913737344+02:00, 2, 1
2020-12-06T04:09:08.156230384+02:00, 2, 1
2020-12-06T05:59:34.991265548+02:00, 2, 1
2020-12-06T06:01:34.758289804+02:00, 2, 1
2020-12-06T07:30:01.653758959+02:00, 2, 1
2020-12-06T11:56:37.809007518+02:00, 2, 1
2020-12-06T14:36:02.666839493+02:00, 2, 1
2020-12-06T15:27:05.053999291+02:00, 2, 1
2020-12-06T15:32:34.054135249+02:00, 2, 1
2020-12-06T16:33:34.63631349+02:00, 2, 1
2020-12-06T17:58:34.763647062+02:00, 2, 1
2020-12-06T19:32:36.077051012+02:00, 2, 1
2020-12-06T21:07:38.139673852+02:00, 2, 1
2020-12-06T21:53:32.768946417+02:00, 2, 1
2020-12-06T21:54:05.865239726+02:00, 2, 1
2020-12-06T22:19:16.232806539+02:00, 2, 1
2020-12-07T01:25:36.013241447+02:00, 2, 1
2020-12-07T02:49:07.255453261+02:00, 2, 1
2020-12-07T06:16:04.294243798+02:00, 2, 1
2020-12-07T08:41:08.82699884+02:00, 2, 1
2020-12-07T11:41:36.226332418+02:00, 2, 1
2020-12-07T13:45:04.989241359+02:00, 2, 1
2020-12-07T21:23:32.698675952+02:00, 2, 1
2020-12-07T22:11:04.74932754+02:00, 2, 1

@jennijuju jennijuju changed the title Mined orphan blocks Mined orphan became blocks Dec 7, 2020
@jennijuju jennijuju changed the title Mined orphan became blocks Mined blocks became orphan blocks Dec 7, 2020
@karalabe
Copy link
Contributor

karalabe commented Dec 7, 2020

I have something more interesting:

{"level":"warn","ts":"2020-12-07T12:22:08.138+0200","logger":"sub","caller":"sub/incoming.go:103","msg":"Received block with large delay 8 from miner f01248"}

This is the block that was missing from my parent set. It arrived 8 seconds after the supposed mining deadline for it. It was included by 2 other miner, but not by mine. Also it's a bit odd that tipsets usually have many blocks, but this one only had 3.


A similar issue was reported by others too:

https://filecoinproject.slack.com/archives/C0179RNEMU4/p1607376039092500?thread_ts=1607374426.086200&cid=C0179RNEMU4

2020-12-05T07:43:09.496+0100	WARN	sub	sub/incoming.go:103	Received block with large delay 9 from miner f01248

Same miner caused it. Are we sure this is accidental and not deliberate?

@karalabe
Copy link
Contributor

karalabe commented Dec 7, 2020

Logging out the most delayed blocks from the last day

     25 from miner f035364"}
     26 from miner f02838"}
     28 from miner f02528"}
     31 from miner f021479"}
     31 from miner f022030"}
     31 from miner f025002"}
     33 from miner f014395"}
     33 from miner f02438"}
     33 from miner f024972"}
     34 from miner f01012"}
     35 from miner f01235"}
     39 from miner f020330"}
     42 from miner f02303"}
     42 from miner f09037"}
     43 from miner f023530"}
     51 from miner f023200"}
     53 from miner f02500"}
     59 from miner f01782"}
     87 from miner f02770"}
     89 from miner f061503"}
    106 from miner f09652"}
    300 from miner f01248"}

@raulk
Copy link
Member

raulk commented Dec 16, 2020

I have been analysing the logs of miners that reported their blocks not getting on chain.

The problem isn’t that the mined block isn’t being propagated to the network and therefore not included on chain.

The problem is that shortly after the miner wins the round and starts minting the block (fixed 6 second cutoff), a new block from the parent tipset arrives.

The syncer component accepts the block, but the miner has already committed to the stale base. Now, this becomes a probabilistic dilemma.

  1. Do we abort the mining and restart it with the block that arrived shortly after the cutoff? If we do that, we risk slipping the window and emitting our amended mined block too late.
  2. Do we continue regardless?

We basically need to be on the same side as all other miners. Otherwise we risk our block being rejected. Whether we pick 1 or 2, we may be on the wrong side.

For all instances reported here, the miner happened to be on the wrong side, i.e. mining on top of a tipset that was missing a block that your own syncer accepted.

It’s a bit of a paradox, and I think that something needs to be more intelligent here. Note: Ethereum deals with similar situations with the ommer construction.


Upon discussing the above with @magik6k, winning PoSt is the most expensive part of mining a block (as also noted in the logs above), and the good news is that we can reuse it, because "randomness for winning PoSt comes from drand, not the VRF chain".

So what we should consider here is:

  1. if our mining base changes before we have published our block to the network, we can rebase the block on top of the parent. This requires recomputing the state of the parent with the new block, which may be cheap or expensive depending on how many messages the new block includes that were not included in the previous mining base.
  2. if our mining base changes after we have published our block to the network, there's nothing we can do, because publishing a second block is a slashable consensus offence.

The risk here is that the recomputation of state could make our block publishing window slip, but it seems to be a fair tradeoff. If we want to make this more intelligent, we can track the time it took to compute the previous mining base state, and estimate the time it would take to recompute to take the decision.

I suspect that with this logic, all the cases of abandoned blocks reported in this thread would've not taken place.

@raulk
Copy link
Member

raulk commented Dec 16, 2020

Another note: it's also worth noting that while we suspected of gossipsub block propagation being the issue, it still needs to be elucidated why these blocks seemed to have arrived seemingly late. Note that block validation is a blocking step in propagation, and there's a bit of state fetching and computation involved there, which we might be able to alleviate by keeping caches of worker keys and what not.

@rjan90
Copy link
Contributor

rjan90 commented Feb 11, 2021

Adding another case of a mined block, becoming orphan-block that I experienced during the night:
Daemon / Miner interleaved logs:

2021-02-11T04:03:39.241+0100	WARN	sub	sub/incoming.go:104	Received block with large delay 9 from miner f0117565
2021-02-11T04:03:39.316+0100	INFO	chain	chain/sync.go:718	block validation	{"took": 0.057688658, "height": "490207", "age": 9.31606337}
2021-02-11T04:03:39.317+0100	INFO	chainstore	store/store.go:513	New heaviest tipset! [bafy2bzacedczwy347tnbvicpey3es2urr73z5uh6mqmsa6fjmgc4hlgnvzm4q bafy2bzacebstedzzv2sz5ydgzi2deaeb65sgxzckyav2qlf3scoabcwmcab6m bafy2bzacebhfwkjqcpcookbfsriimh7ngcc64aaw6vnqfs444ifs4uy2hwsx2 bafy2bzacebj4ec2ba4nexrslhioudj5i3gfvtfoexmxg3mz2aebsii3hqvnbi bafy2bzaceaaxw44vloxpw5qewjr47zhpfcutsppjstb5h6tpmtp2zrdnuek6o bafy2bzaceccytb3wu67y4zjw7of3gkbk2u42ragwb4zc7sn2alngahr5ei3hy bafy2bzaceaya3d2pxljjjvru6tuwam7i6b24sudnr5qocnmkme4zqim3g52ri] (height=490207)
2021-02-11T04:03:39.321+0100	INFO	chain	chain/sync_manager.go:322	worker 242455 done; took 67.187905ms
2021-02-11T04:03:39.696+0100	INFO	storageminer	storage/miner.go:259	Computing WinningPoSt ;[{SealProof:3 SectorNumber:687 SealedCID:bagboea4b5abcazvchpeb4glgyx2i5m7eon6fqhwq36vqllbw2riacc5qogrxjyss}]; [216 119 234 133 84 233 78 152 137 214 90 141 148 6 152 186 153 144 238 221 48 165 135 174 185 170 180 123 172 88 116 187]
2021-02-11T04:03:39.696 INFO filcrypto::proofs::api > generate_winning_post: start

2021-02-11T04:03:39.727+0100	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedczwy347tnbvicpey3es2urr73z5uh6mqmsa6fjmgc4hlgnvzm4q bafy2bzacebstedzzv2sz5ydgzi2deaeb65sgxzckyav2qlf3scoabcwmcab6m bafy2bzacebhfwkjqcpcookbfsriimh7ngcc64aaw6vnqfs444ifs4uy2hwsx2 bafy2bzacebj4ec2ba4nexrslhioudj5i3gfvtfoexmxg3mz2aebsii3hqvnbi bafy2bzaceaaxw44vloxpw5qewjr47zhpfcutsppjstb5h6tpmtp2zrdnuek6o bafy2bzaceccytb3wu67y4zjw7of3gkbk2u42ragwb4zc7sn2alngahr5ei3hy bafy2bzaceaya3d2pxljjjvru6tuwam7i6b24sudnr5qocnmkme4zqim3g52ri]
2021-02-11T04:03:39.727+0100	INFO	chain	chain/sync_manager.go:314	worker 242456 syncing in [bafy2bzacedczwy347tnbvicpey3es2urr73z5uh6mqmsa6fjmgc4hlgnvzm4q bafy2bzacebstedzzv2sz5ydgzi2deaeb65sgxzckyav2qlf3scoabcwmcab6m bafy2bzacebhfwkjqcpcookbfsriimh7ngcc64aaw6vnqfs444ifs4uy2hwsx2 bafy2bzacebj4ec2ba4nexrslhioudj5i3gfvtfoexmxg3mz2aebsii3hqvnbi bafy2bzaceaaxw44vloxpw5qewjr47zhpfcutsppjstb5h6tpmtp2zrdnuek6o bafy2bzaceccytb3wu67y4zjw7of3gkbk2u42ragwb4zc7sn2alngahr5ei3hy bafy2bzaceaya3d2pxljjjvru6tuwam7i6b24sudnr5qocnmkme4zqim3g52ri]
2021-02-11T04:03:39.727+0100	INFO	chain	chain/sync_manager.go:322	worker 242456 done; took 4.088µs

2021-02-11T04:03:53.292+0100	INFO	storageminer	storage/miner.go:266	GenerateWinningPoSt took 13.595479445s

2021-02-11T04:03:53.336+0100	INFO	messagepool	messagepool/selection.go:639	get pending messages done	{"took": 0.027132092}
2021-02-11T04:03:53.518+0100	INFO	messagepool	messagepool/selection.go:109	create message chains done	{"took": 0.18161917}
2021-02-11T04:03:53.522+0100	INFO	messagepool	messagepool/selection.go:222	merge message chains done	{"took": 0.001312218}
2021-02-11T04:03:53.522+0100	WARN	messagepool	messagepool/selection.go:384	optimal selection failed to pack a block; picked 176 messages with random selection
2021-02-11T04:03:53.522+0100	INFO	messagepool	messagepool/selection.go:89	message selection done	{"took": 0.227713416}

2021-02-11T04:03:53.755+0100	INFO	miner	miner/miner.go:448	mined new block	{"cid": "bafy2bzaceafubqlp7ax6q6qaip4oz5wo3vjt5er4difpwri7nwprfd7bu6imc", "height": "490208", "miner": "f023467", "parents": ["f035364","f02528","f023495","f02770","f078899","f03134"], "took": 17.475400506}

@rjan90
Copy link
Contributor

rjan90 commented Feb 11, 2021

So the specs for my miner/lotus node is:
EPYC 7302
256 GB ECC RAM
SSD-disks

it is only used as miner/lotus-node, and not as a sealing-machine

@William8Work
Copy link

This continues in v1.4.2 with the latest codes updates:

2021-02-20T03:16:36.153-0800	INFO	miner	miner/miner.go:383	Time delta between now and our mining base: 6s (nulls: 0)
2021-02-20T03:16:36.158-0800	INFO	storageminer	storage/miner.go:256	Computing WinningPoSt ;[{SealProof:8 SectorNumber:1201 SealedCID:bagboea4b5abcaq4z5qpnji4za5hycsxnpqdnyncm2tbp6tdwcabkm5xfuyxkubtj}]; [150 86 146 0 124 149 193 95 30 190 51 122 193 103 156 20 200 52 173 241 81 77 109 65 99 126 152 1 12 104 64 63]
2021-02-20T03:16:41.575-0800	INFO	storageminer	storage/miner.go:263	GenerateWinningPoSt took 5.416831789s
2021-02-20T03:16:48.585-0800    INFO      miner   miner/miner.go:447      mined new block {"cid": "bafy2bzacec5tqqhwhk5hnkdnplyt4nxr3exjtuxjy2vijt27at2djh7iy555e", "height": "517114",
 "miner": "f08399", "parents": ["f087256","f02779","f022361","f061051"], "took": 12.442497419}

The miner spec is:
EPYC 7601
256 GB RAM
2080 Ti
256 GB SWAP on Nvme
Spinning disks for storage

@William8Work
Copy link

William8Work commented Feb 21, 2021

I don't know what to look for at the daemon logs but here are the entries around the 2021-02-20T03:16:36 timing when this happened. The last four lines have this:

2021-02-20T03:17:11.851-0800 WARN sub sub/incoming.go:104 Received block with large delay 11 from miner f08399

2021-02-20T03:16:00.482-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedswitq2kh7iixdbwexlxsr7zggkloj3ilk7e6wdgw27ujcwbkr34]
2021-02-20T03:16:00.482-0800	INFO	chain	chain/sync_manager.go:314	worker 23503 syncing in [bafy2bzacedswitq2kh7iixdbwexlxsr7zggkloj3ilk7e6wdgw27ujcwbkr34]
2021-02-20T03:16:00.647-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.157724139, "height": "517112", "age": 0.647383651}
2021-02-20T03:16:00.648-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceds22mcc6nem27fxts42jxmml5jkxmzrod47ub5ii57zwaw4oj4va bafy2bzaceayoxefva3lybhfjy2xbnsbyak4j2gkqrmov47qyrgdhhh25qbjis bafy2bzacedswitq2kh7iixdbwexlxsr7zggkloj3ilk7e6wdgw27ujcwbkr34] (height=517112)
2021-02-20T03:16:00.648-0800	INFO	chain	chain/sync_manager.go:322	worker 23503 done; took 165.661688ms
2021-02-20T03:16:03.540-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568153 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:16:03.582-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568434 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:16:03.638-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568850 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:16:06.004-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612957}
2021-02-20T03:16:06.054-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612957, "took": 0.050075871}
2021-02-20T03:16:06.057-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612957}
2021-02-20T03:16:06.057-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612957, "took": 0.000042966}
2021-02-20T03:16:16.378-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1qfs3riydqtifogsefemnn5wxflddxeynrk6l5ay", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 265, "method": "0", "height": "517112", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (2.513738307726146736 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:16.382-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1ks3omvogrpu5cbviqjqmxvywow6nxkulp7q22ci", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 220, "method": "0", "height": "517112", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (5.261247748892092929 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:16.383-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1trosh3lylxyjl3jzir4wrz5ghpxucne4jyhk4xq", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 265, "method": "0", "height": "517112", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (80.467791883025377049 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:29.779-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c]
2021-02-20T03:16:29.779-0800	INFO	chain	chain/sync_manager.go:314	worker 23504 syncing in [bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c]
2021-02-20T03:16:29.782-0800	WARN	chain	chain/sync.go:750	Got block from the future, but within threshold1613819790 1613819789
2021-02-20T03:16:29.858-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy]
2021-02-20T03:16:29.858-0800	INFO	chain	chain/sync_manager.go:314	worker 23505 syncing in [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy]
2021-02-20T03:16:29.866-0800	WARN	chain	chain/sync.go:750	Got block from the future, but within threshold1613819790 1613819789
2021-02-20T03:16:29.960-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.177725622, "height": "517113", "age": -0.039903314}
2021-02-20T03:16:29.960-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] (height=517113)
2021-02-20T03:16:29.960-0800	INFO	chain	chain/sync_manager.go:322	worker 23504 done; took 181.761853ms
2021-02-20T03:16:29.998-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.131987079, "height": "517113", "age": -0.001921035}
2021-02-20T03:16:29.998-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] (height=517113)
2021-02-20T03:16:29.998-0800	INFO	chain	chain/sync_manager.go:322	worker 23505 done; took 140.071486ms
2021-02-20T03:16:30.216-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw]
2021-02-20T03:16:30.216-0800	INFO	chain	chain/sync_manager.go:314	worker 23506 syncing in [bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw]
2021-02-20T03:16:30.273-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.053497119, "height": "517113", "age": 0.273667375}
2021-02-20T03:16:30.274-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] (height=517113)
2021-02-20T03:16:30.274-0800	INFO	chain	chain/sync_manager.go:322	worker 23506 done; took 58.249675ms
2021-02-20T03:16:30.292-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedu5hglpaj3y2vr3sktjc2olboperm5rfbflsfqjcq4rgabpl7czy]
2021-02-20T03:16:30.292-0800	INFO	chain	chain/sync_manager.go:314	worker 23507 syncing in [bafy2bzacedu5hglpaj3y2vr3sktjc2olboperm5rfbflsfqjcq4rgabpl7czy]
2021-02-20T03:16:30.371-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.075572085, "height": "517113", "age": 0.371693103}
2021-02-20T03:16:30.373-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw bafy2bzacedu5hglpaj3y2vr3sktjc2olboperm5rfbflsfqjcq4rgabpl7czy bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] (height=517113)
2021-02-20T03:16:30.373-0800	INFO	chain	chain/sync_manager.go:322	worker 23507 done; took 81.307135ms
2021-02-20T03:16:36.089-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612958}
2021-02-20T03:16:36.140-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612958, "took": 0.050713043}
2021-02-20T03:16:36.143-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612958}
2021-02-20T03:16:36.143-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612958, "took": 0.000164349}
2021-02-20T03:16:37.928-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1qyozilcye3c53zccychzxrfebet5msttvtru2ni", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 264, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (4.332772795703004263 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:37.929-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1eaqbm737nai6bg555ymj4peidul3v2j6fhufc3a", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 263, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (2.510591021383995942 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:37.963-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=18275559, available=51998468, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:37.963-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=18275559, available=51998468, use=34721049 (RetCode=7)
2021-02-20T03:16:37.963-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:37.963-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:37.963-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3rjua53xjpmn37bgipum5kb7zinugttz5qwnq5slglbq37qupnl4nffrfnapuoobglsxjrw3vbp3xw3i7y2wa", "to": "f0123261", "nonce": 945625, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:39.216-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=23836076, available=52150631, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:39.216-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=23836076, available=52150631, use=34721049 (RetCode=7)
2021-02-20T03:16:39.216-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:39.216-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:39.216-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sv26sha3ncbekgcxlbkf57cv6ke277rfljhj5kz3sjm4mfoikun5yya2fzkoz74bz4wj6ih6unxfkwr6fpgq", "to": "f0130727", "nonce": 483601, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:39.217-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=23836076, available=55145051, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:39.217-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=23836076, available=55145051, use=34721049 (RetCode=7)
2021-02-20T03:16:39.217-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:39.217-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:39.217-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sv26sha3ncbekgcxlbkf57cv6ke277rfljhj5kz3sjm4mfoikun5yya2fzkoz74bz4wj6ih6unxfkwr6fpgq", "to": "f0130727", "nonce": 483602, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:39.719-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=29281776, available=59263706, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:39.719-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=29281776, available=59263706, use=34721049 (RetCode=7)
2021-02-20T03:16:39.719-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:39.719-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:39.719-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sduokm4m7eesap5tub35gtsafo2g5eiyzsiv3wzu62nsijmlqxhck7flf7hoyc7uui255cqlz3t2mvkoayda", "to": "f073844", "nonce": 439594, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:42.078-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1yvjq3uarsebeac2lk7c2tl54q4l66bcqvkqfw4y", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 264, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (2.320197309587920546 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:48.409-0800	INFO	messagepool	messagepool/selection.go:109	create message chains done	{"took": 0.117102936}
2021-02-20T03:16:48.411-0800	INFO	messagepool	messagepool/selection.go:222	merge message chains done	{"took": 0.001216432}
2021-02-20T03:16:48.412-0800	WARN	messagepool	messagepool/selection.go:384	optimal selection failed to pack a block; picked 155 messages with random selection
2021-02-20T03:16:48.412-0800	INFO	messagepool	messagepool/selection.go:89	message selection done	{"took": 0.137550254}
2021-02-20T03:16:52.190-0800	WARN	sub	sub/incoming.go:104	Received block with large delay 22 from miner f0120983
2021-02-20T03:16:52.196-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebzw5uwts5mw4mimiyc5sq3cz6cysknnd6ppgswvwe6fbgln4lxc6]
2021-02-20T03:16:52.197-0800	INFO	chain	chain/sync_manager.go:314	worker 23508 syncing in [bafy2bzacebzw5uwts5mw4mimiyc5sq3cz6cysknnd6ppgswvwe6fbgln4lxc6]
2021-02-20T03:16:52.267-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.067915461, "height": "517113", "age": 22.267831125}
2021-02-20T03:16:52.268-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy bafy2bzacebzw5uwts5mw4mimiyc5sq3cz6cysknnd6ppgswvwe6fbgln4lxc6 bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw bafy2bzacedu5hglpaj3y2vr3sktjc2olboperm5rfbflsfqjcq4rgabpl7czy bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] (height=517113)
2021-02-20T03:16:52.269-0800	INFO	chain	chain/sync_manager.go:322	worker 23508 done; took 72.089156ms
2021-02-20T03:16:57.811-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1qyozilcye3c53zccychzxrfebet5msttvtru2ni", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 264, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (4.332772795703004263 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:57.813-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1eaqbm737nai6bg555ymj4peidul3v2j6fhufc3a", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 263, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (2.510591021383995942 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:16:57.827-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=23185602, available=50178340, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:57.827-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=23185602, available=50178340, use=34721049 (RetCode=7)
2021-02-20T03:16:57.827-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:57.827-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:57.827-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3s4nczzqtcbjx3bope5ufh5vr4mdbwhpuejerwnn763jdd6qnymudnu3rye7ifqjtreroh23jjgkviviptuaq", "to": "f0150666", "nonce": 12428, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:57.828-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=23185602, available=53701309, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:57.828-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=23185602, available=53701309, use=34721049 (RetCode=7)
2021-02-20T03:16:57.828-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:57.828-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:57.828-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3s4nczzqtcbjx3bope5ufh5vr4mdbwhpuejerwnn763jdd6qnymudnu3rye7ifqjtreroh23jjgkviviptuaq", "to": "f0150666", "nonce": 12429, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:16:57.829-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=23185602, available=56828849, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:16:57.829-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=23185602, available=56828849, use=34721049 (RetCode=7)
2021-02-20T03:16:57.829-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:16:57.829-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:16:57.829-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3s4nczzqtcbjx3bope5ufh5vr4mdbwhpuejerwnn763jdd6qnymudnu3rye7ifqjtreroh23jjgkviviptuaq", "to": "f0150666", "nonce": 12430, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:00.013-0800	WARN	chain	chain/sync.go:1414	(fork detected) synced header chain ([bafy2bzacec5tqqhwhk5hnkdnplyt4nxr3exjtuxjy2vijt27at2djh7iy555e] - 517114) does not link to our best block ([bafy2bzacedzf4wqp3qa77yryrcpqmju4o2boixslwpdp3azg6cw4zd5i5tgjy bafy2bzacebzw5uwts5mw4mimiyc5sq3cz6cysknnd6ppgswvwe6fbgln4lxc6 bafy2bzaceahgwfzwflpaqri5yhxhtxu6sz65sl5urhfjhvjikjeh6xeoftxgw bafy2bzacedu5hglpaj3y2vr3sktjc2olboperm5rfbflsfqjcq4rgabpl7czy bafy2bzacednm7lkwgw42c5xetc2uqtbcs2vrjipk7qczgryzzlaajzy7g5h3c] - 517113)
2021-02-20T03:17:00.209-0800	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacec3iv3fm4sgwczqmbp2rrk3xvj53gt6uonzqis2rygmq56zrqcizk]
2021-02-20T03:17:00.209-0800	INFO	chain	chain/sync_manager.go:314	worker 23509 syncing in [bafy2bzacec3iv3fm4sgwczqmbp2rrk3xvj53gt6uonzqis2rygmq56zrqcizk]
2021-02-20T03:17:00.665-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=49750451, available=50176845, use=718940 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:00.665-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=49750451, available=50176845, use=718940 (RetCode=7)
2021-02-20T03:17:00.665-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:00.665-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:00.665-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3wxbd75u4n73zwkh2vzqjqrwjht7gyjcypy5pystwi6wnnq6uiwia4yfnspy7ktzq7n6zzr6zfvydnqkmm3hq", "to": "f021961", "nonce": 57583, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:00.805-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=18653859, available=51998468, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:00.805-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=18653859, available=51998468, use=34721049 (RetCode=7)
2021-02-20T03:17:00.805-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:00.805-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:00.805-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3rjua53xjpmn37bgipum5kb7zinugttz5qwnq5slglbq37qupnl4nffrfnapuoobglsxjrw3vbp3xw3i7y2wa", "to": "f0123261", "nonce": 945625, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:01.139-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=47512974, available=47999534, use=718940 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:01.139-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=47512974, available=47999534, use=718940 (RetCode=7)
2021-02-20T03:17:01.139-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:01.139-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:01.139-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3r722n3zykfkhfao4yfzoctlsswnmvqfder6f6pa2fwjdokh3pnmc4azep3af5puz56tgaods3bf2ybjydyia", "to": "f02528", "nonce": 106504, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:01.205-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=24023276, available=52150631, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:01.205-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=24023276, available=52150631, use=34721049 (RetCode=7)
2021-02-20T03:17:01.205-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:01.205-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:01.205-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sv26sha3ncbekgcxlbkf57cv6ke277rfljhj5kz3sjm4mfoikun5yya2fzkoz74bz4wj6ih6unxfkwr6fpgq", "to": "f0130727", "nonce": 483601, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:01.206-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=24023276, available=55145051, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:01.206-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=24023276, available=55145051, use=34721049 (RetCode=7)
2021-02-20T03:17:01.206-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:01.206-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:01.206-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sv26sha3ncbekgcxlbkf57cv6ke277rfljhj5kz3sjm4mfoikun5yya2fzkoz74bz4wj6ih6unxfkwr6fpgq", "to": "f0130727", "nonce": 483602, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:01.338-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=29468976, available=59263706, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-02-20T03:17:01.338-0800	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=29468976, available=59263706, use=34721049 (RetCode=7)
2021-02-20T03:17:01.338-0800	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-02-20T03:17:01.338-0800	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49
2021-02-20T03:17:01.338-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sduokm4m7eesap5tub35gtsafo2g5eiyzsiv3wzu62nsijmlqxhck7flf7hoyc7uui255cqlz3t2mvkoayda", "to": "f073844", "nonce": 439594, "method": "7", "height": "517113", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v2/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:49"}
2021-02-20T03:17:02.044-0800	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f1yvjq3uarsebeac2lk7c2tl54q4l66bcqvkqfw4y", "to": "f13sb4pa34qzf35txnan4fqjfkwwqgldz6ekh5trq", "nonce": 264, "method": "0", "height": "517113", "error": "failed to transfer funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).send.func3\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:341\n  - transfer failed when deducting funds (2.320197309587920546 FIL): not enough funds (RetCode=6):\n    github.com/filecoin-project/lotus/chain/vm.(*VM).transfer\n        /home/filecoin/filecoin/lotus/chain/vm/vm.go:931"}
2021-02-20T03:17:05.239-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 5.026435035, "height": "517114", "age": 5.239814427}
2021-02-20T03:17:05.240-0800	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacec3iv3fm4sgwczqmbp2rrk3xvj53gt6uonzqis2rygmq56zrqcizk] (height=517114)
2021-02-20T03:17:05.240-0800	INFO	chain	chain/sync_manager.go:322	worker 23509 done; took 5.030822616s
2021-02-20T03:17:07.068-0800	WARN	sub	sub/incoming.go:104	Received block with large delay 7 from miner f035364
2021-02-20T03:17:07.601-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568153 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:17:07.644-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568434 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:17:07.699-0800	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568850 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-02-20T03:17:08.016-0800	WARN	sub	sub/incoming.go:104	Received block with large delay 8 from miner f0101611
2021-02-20T03:17:11.845-0800	INFO	chain	chain/sync.go:710	block validation	{"took": 0.06829356, "height": "517114", "age": 11.845242602}
2021-02-20T03:17:11.850-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612959}
2021-02-20T03:17:11.851-0800	WARN	sub	sub/incoming.go:104	Received block with large delay 11 from miner f08399
2021-02-20T03:17:11.968-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612959, "took": 0.117644613}
2021-02-20T03:17:11.970-0800	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 612959}
2021-02-20T03:17:11.970-0800	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 612959, "took": 0.00006221}

@rjan90
Copy link
Contributor

rjan90 commented Feb 21, 2021

@raulk Look at @William8Work's case. Here the delayed block came in after he had finished computing and published his block to the network:

2021-02-20T03:16:48.585-0800    INFO      miner   miner/miner.go:447      mined new block {"cid": "bafy2bzacec5tqqhwhk5hnkdnplyt4nxr3exjtuxjy2vijt27at2djh7iy555e", "height": "517114",
 "miner": "f08399", "parents": ["f087256","f02779","f022361","f061051"], "took": 12.442497419}
2021-02-20T03:16:52.190-0800	WARN	sub	sub/incoming.go:104	Received block with large delay 22 from miner f0120983

@William8Work
Copy link

Thank you @rjan90.

@raulk do you know what causes these large delay? have we tried any code fixes to address either of your two options?

@William8Work
Copy link

Copy some conversation from the slack channel as it's being archived:


WillTechMusing  11 hours ago
mined a block but not getting onto the chain is definitely dissatisfying. I don't know how often does this happen. It may happen to many miners.

Patrick - Factor8 Solutions  11 hours ago
i have  a  bunch of them

WillTechMusing  11 hours ago
:cry:

WillTechMusing  11 hours ago
could we prioritize the fix @jennijuju @Magik6k @raulk?

raulk  7 hours ago
hey, i investigated this a few weeks ago. if I recall correctly, what happens is that:
your miner gets elected to mine a block.
it waits for 6 seconds to collect blocks from the network to form the parent tipset
it mines the block on top of the collected parent tipset — let’s call this the committed parent tipset
another block arrives, and your local node might accept it, but your miner already started mining on top of the committed parent tipset
your miner finishes mining and pushes the block out to the network
your block might get discarded or included, depending on whether the other miners chose to discard or include the block you received after you began mining
note that mining on a tipset-based construction is by definition a probabilistic process; it is not a competitive process (e.g. Bitcoin or EthHash), nor do you know how many leaders have been elected ahead of time. the logic for waiting, mining and re-mining can be adjusted in one direction or another, but there will always be edge cases that lead to some valid blocks being discarded. Ideally, implementations will reduce the overall probability to end up with orphaned blocks, but it’s a non-trivial issue.
and my conclusion is that it’s not simplifiable to “block propagation was slow” (edited) 

WillTechMusing  6 hours ago
Thanks @raulk. The analysis make lots of senses. Two flows of thoughts:
The Fixing Path - would it be possible after the miner finishes the mining before pushing the block out to the network, check if the parent tipset has changed (similiar to one of the suggestions you had in the github). If new block has arrived, get the miner adjust (rebase) and run the mining again. It may not fix the real problem but it's like a "retry" but even just have of these retry, this problem might get largely reduced and mitigated.
The Forgiveness Path - whenever orphan block is mined, if there is no easy fix to the real problem, could it allow the miner not "count" this block as rewards into winning rate? For example, if a miner is expecting 5 days to win a block, with this forgiveness, it doesn't require another 5 days to win next block? Understood the block winning period is a probabilistic but this approach will be like forget about this problematic winning incident. The miner's long term winning rate won't be effected.

@William8Work
Copy link

Looks like another instance happened to my miner again yesterday. A block was mined but no rewards. So I searched the log and saw the miner log:

2021-03-15T07:29:15.891-0700 INFO miner miner/miner.go:447 mined new block {"cid": "bafy2bzacebr6gjzekmbnml6froljlqm3crde6nbdolvmiyhxwj7amh3uidfai", "height": "583739", "miner": "f08399", "parents": ["f01248","f09037"], "took": 9.547289037}

Here is the daemon logs:

2021-03-15T07:29:15.746-0700	INFO	messagepool	messagepool/selection.go:109	create message chains done	{"took": 0.115959084}
2021-03-15T07:29:15.746-0700	INFO	messagepool	messagepool/selection.go:89	message selection done	{"took": 0.12909289}
2021-03-15T07:29:16.597-0700	WARN	vm	vm/syscalls.go:314	seal verify in batch failed	{"miner": "f0153078", "sectorNumber": "17045", "err": "invalid proof"}
2021-03-15T07:29:30.000-0700	WARN	chain	chain/sync.go:1414	(fork detected) synced header chain ([bafy2bzacebr6gjzekmbnml6froljlqm3crde6nbdolvmiyhxwj7amh3uidfai] - 583739) does not link to our best block ([bafy2bzaced4rcobjdb2hljwzmndnuxry347ewhgpxcvyyoonqdb5ngfuugure bafy2bzacebrv55wuaifblrslot27gvtrlf2hobz6ju2t3dmaxda2mbf75a5m4 bafy2bzacec5yihjtpmf5nyipiklohrivfgi3swhbimnopz5d6kgqmpnvxzwbu] - 583738)
2021-03-15T07:29:30.165-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2]
2021-03-15T07:29:30.165-0700	INFO	chain	chain/sync_manager.go:314	worker 227107 syncing in [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2]
2021-03-15T07:29:30.223-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa]
2021-03-15T07:29:30.223-0700	INFO	chain	chain/sync_manager.go:314	worker 227108 syncing in [bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa]
2021-03-15T07:29:30.232-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc]
2021-03-15T07:29:30.232-0700	INFO	chain	chain/sync_manager.go:314	worker 227109 syncing in [bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc]
2021-03-15T07:29:30.251-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.083335186, "height": "583739", "age": 0.251635413}
2021-03-15T07:29:30.252-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2] (height=583739)
2021-03-15T07:29:30.252-0700	INFO	chain	chain/sync_manager.go:322	worker 227107 done; took 86.985634ms
2021-03-15T07:29:30.274-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde]
2021-03-15T07:29:30.274-0700	INFO	chain	chain/sync_manager.go:314	worker 227110 syncing in [bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde]
2021-03-15T07:29:30.291-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu]
2021-03-15T07:29:30.292-0700	INFO	chain	chain/sync_manager.go:314	worker 227111 syncing in [bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu]
2021-03-15T07:29:30.308-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e]
2021-03-15T07:29:30.308-0700	INFO	chain	chain/sync_manager.go:314	worker 227112 syncing in [bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e]
2021-03-15T07:29:30.332-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.105560444, "height": "583739", "age": 0.332455319}
2021-03-15T07:29:30.333-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa] (height=583739)
2021-03-15T07:29:30.333-0700	INFO	chain	chain/sync_manager.go:322	worker 227108 done; took 110.539624ms
2021-03-15T07:29:30.345-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.108287178, "height": "583739", "age": 0.345928608}
2021-03-15T07:29:30.346-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa] (height=583739)
2021-03-15T07:29:30.346-0700	INFO	chain	chain/sync_manager.go:322	worker 227109 done; took 114.598911ms
2021-03-15T07:29:30.378-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.100139169, "height": "583739", "age": 0.378535972}
2021-03-15T07:29:30.379-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde] (height=583739)
2021-03-15T07:29:30.379-0700	INFO	chain	chain/sync_manager.go:322	worker 227110 done; took 105.02885ms
2021-03-15T07:29:30.384-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.084169032, "height": "583739", "age": 0.384401071}
2021-03-15T07:29:30.385-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde] (height=583739)
2021-03-15T07:29:30.385-0700	INFO	chain	chain/sync_manager.go:322	worker 227111 done; took 93.331087ms
2021-03-15T07:29:30.430-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.116745461, "height": "583739", "age": 0.430845649}
2021-03-15T07:29:30.432-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e] (height=583739)
2021-03-15T07:29:30.433-0700	INFO	chain	chain/sync_manager.go:322	worker 227112 done; took 125.143944ms
2021-03-15T07:29:31.632-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebuzghis6bdapxazuykktpjrijeowrkiiwinwifde3xemftlq2xzs]
2021-03-15T07:29:31.632-0700	INFO	chain	chain/sync_manager.go:314	worker 227113 syncing in [bafy2bzacebuzghis6bdapxazuykktpjrijeowrkiiwinwifde3xemftlq2xzs]
2021-03-15T07:29:31.717-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.080136536, "height": "583739", "age": 1.717517506}
2021-03-15T07:29:31.718-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacebuzghis6bdapxazuykktpjrijeowrkiiwinwifde3xemftlq2xzs bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e] (height=583739)
2021-03-15T07:29:31.718-0700	INFO	chain	chain/sync_manager.go:322	worker 227113 done; took 86.590456ms
2021-03-15T07:29:34.093-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebuzghis6bdapxazuykktpjrijeowrkiiwinwifde3xemftlq2xzs bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e]
2021-03-15T07:29:34.093-0700	INFO	chain	chain/sync_manager.go:314	worker 227114 syncing in [bafy2bzacebuzghis6bdapxazuykktpjrijeowrkiiwinwifde3xemftlq2xzs bafy2bzacea4s33zczodu6hywuwdihpkhqlclgmxzong34njh3qcla7lbydtn2 bafy2bzacecngijy3nivpzzrm4redrio5zdgprerqovj347gdcjf4leuwefffu bafy2bzacealc7beqlr4ltc2dzjhmwi6uhzsb4hfsdpukllm6z5rbtryvu24gc bafy2bzacebgxrr5lqa6ipl2t2evlfsbiztimlc3g45blq2bxln53of4knzpoa bafy2bzaceclcrkhvirs5mdwtiablf565lnhtscjtg3mtqqrivijgx74msvmde bafy2bzaceasrqmgna3ympj4rttrhz4p4ckskmb5hhae5lnmyy4hi34gkddy3e]
2021-03-15T07:29:34.093-0700	INFO	chain	chain/sync_manager.go:322	worker 227114 done; took 3.309µs
2021-03-15T07:29:35.021-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=55783833, available=58394552, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-03-15T07:29:35.022-0700	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=55783833, available=58394552, use=34721049 (RetCode=7)
2021-03-15T07:29:35.022-0700	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-03-15T07:29:35.022-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64
2021-03-15T07:29:35.022-0700	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sahli75oz4gazkgoun2uwupek5kw24hzerv63xo6r7fexnm7wiqhb6civaizyy6qpvus3ddurkqzzpj7xsba", "to": "f0223103", "nonce": 57145, "method": "7", "height": "583739", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64"}
2021-03-15T07:29:35.023-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=55669216, available=61654031, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-03-15T07:29:35.023-0700	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=55669216, available=61654031, use=34721049 (RetCode=7)
2021-03-15T07:29:35.023-0700	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-03-15T07:29:35.023-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64
2021-03-15T07:29:35.023-0700	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sahli75oz4gazkgoun2uwupek5kw24hzerv63xo6r7fexnm7wiqhb6civaizyy6qpvus3ddurkqzzpj7xsba", "to": "f0223103", "nonce": 57146, "method": "7", "height": "583739", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64"}
2021-03-15T07:29:35.024-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=55669216, available=65056781, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-03-15T07:29:35.024-0700	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=55669216, available=65056781, use=34721049 (RetCode=7)
2021-03-15T07:29:35.024-0700	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-03-15T07:29:35.024-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64
2021-03-15T07:29:35.024-0700	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sahli75oz4gazkgoun2uwupek5kw24hzerv63xo6r7fexnm7wiqhb6civaizyy6qpvus3ddurkqzzpj7xsba", "to": "f0223103", "nonce": 57147, "method": "7", "height": "583739", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64"}
2021-03-15T07:29:35.025-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=55783833, available=68602802, use=34721049 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-03-15T07:29:35.025-0700	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=55783833, available=68602802, use=34721049 (RetCode=7)
2021-03-15T07:29:35.025-0700	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-03-15T07:29:35.025-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64
2021-03-15T07:29:35.025-0700	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3sahli75oz4gazkgoun2uwupek5kw24hzerv63xo6r7fexnm7wiqhb6civaizyy6qpvus3ddurkqzzpj7xsba", "to": "f0223103", "nonce": 57148, "method": "7", "height": "583739", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64"}
2021-03-15T07:29:40.381-0700	WARN	chainxchg	exchange/peer_tracker.go:180	log failure called on peer not in trackerpeerid12D3KooWAL6m6LosKfmT4Znpqcg9fQEYA2M5bViU1CRd5RDRH52R
2021-03-15T07:29:40.381-0700	WARN	chainxchg	exchange/client.go:119	could not send request to peer 12D3KooWAL6m6LosKfmT4Znpqcg9fQEYA2M5bViU1CRd5RDRH52R: failed to read chainxchg response: reading cid field t.Parents failed: stream reset
2021-03-15T07:29:40.750-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.064006771, "height": "583739", "age": 10.750177657}
2021-03-15T07:29:40.757-0700	WARN	sub	sub/incoming.go:104	Received block with large delay 10 from miner f08399

@raulk
Copy link
Member

raulk commented Mar 17, 2021

@William8Work could you please add more logs from the moment that your miner won the round? We need to get the exact timeline of events.

@hyunmoon
Copy link

hyunmoon commented Mar 17, 2021

@William8Work
At height 583738, there were 3 miners but your miner only saw 2 of them as parents.
If you try to peer connect to the missing one (f023200), I'm sure it will fail.

@William8Work
Copy link

@raulk here are additional logs from the daemon. Happy to provide more if you need them:

021-03-15T07:29:40.757-0700	WARN	sub	sub/incoming.go:104	Received block with large delay 10 from miner f08399
2021-03-15T07:29:40.758-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679584}
2021-03-15T07:29:40.893-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679584, "took": 0.135495539}
2021-03-15T07:29:40.896-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679584}
2021-03-15T07:29:40.896-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679584, "took": 0.000048748}
12:41:35@g1wrk06:~$ grep -ai -A100 '2021-03-15T07:29:40' /media/lotus/logs/daemon.log 
2021-03-15T07:29:40.381-0700	WARN	chainxchg	exchange/peer_tracker.go:180	log failure called on peer not in trackerpeerid12D3KooWAL6m6LosKfmT4Znpqcg9fQEYA2M5bViU1CRd5RDRH52R
2021-03-15T07:29:40.381-0700	WARN	chainxchg	exchange/client.go:119	could not send request to peer 12D3KooWAL6m6LosKfmT4Znpqcg9fQEYA2M5bViU1CRd5RDRH52R: failed to read chainxchg response: reading cid field t.Parents failed: stream reset
2021-03-15T07:29:40.750-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.064006771, "height": "583739", "age": 10.750177657}
2021-03-15T07:29:40.757-0700	WARN	sub	sub/incoming.go:104	Received block with large delay 10 from miner f08399
2021-03-15T07:29:40.758-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679584}
2021-03-15T07:29:40.893-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679584, "took": 0.135495539}
2021-03-15T07:29:40.896-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679584}
2021-03-15T07:29:40.896-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679584, "took": 0.000048748}
2021-03-15T07:30:00.192-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6]
2021-03-15T07:30:00.192-0700	INFO	chain	chain/sync_manager.go:314	worker 227115 syncing in [bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6]
2021-03-15T07:30:00.235-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedf4tocfix6bdb4lm43gijfbvdyh6nzbdd2jcyfodtf7bnhed62xi]
2021-03-15T07:30:00.235-0700	INFO	chain	chain/sync_manager.go:314	worker 227116 syncing in [bafy2bzacedf4tocfix6bdb4lm43gijfbvdyh6nzbdd2jcyfodtf7bnhed62xi]
2021-03-15T07:30:00.270-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceabvxrzje4qfzvnrrbbwqfvgk776l4wyrdqotpm4pn424vc7mofus]
2021-03-15T07:30:00.270-0700	INFO	chain	chain/sync_manager.go:314	worker 227117 syncing in [bafy2bzaceabvxrzje4qfzvnrrbbwqfvgk776l4wyrdqotpm4pn424vc7mofus]
2021-03-15T07:30:00.283-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.085386993, "height": "583740", "age": 0.283580973}
2021-03-15T07:30:00.284-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6] (height=583740)
2021-03-15T07:30:00.284-0700	INFO	chain	chain/sync_manager.go:322	worker 227115 done; took 91.667408ms
2021-03-15T07:30:00.313-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.07404366, "height": "583740", "age": 0.313438243}
2021-03-15T07:30:00.314-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6 bafy2bzacedf4tocfix6bdb4lm43gijfbvdyh6nzbdd2jcyfodtf7bnhed62xi] (height=583740)
2021-03-15T07:30:00.314-0700	INFO	chain	chain/sync_manager.go:322	worker 227116 done; took 78.520279ms
2021-03-15T07:30:00.417-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.142019817, "height": "583740", "age": 0.417203975}
2021-03-15T07:30:00.418-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceabvxrzje4qfzvnrrbbwqfvgk776l4wyrdqotpm4pn424vc7mofus bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6 bafy2bzacedf4tocfix6bdb4lm43gijfbvdyh6nzbdd2jcyfodtf7bnhed62xi] (height=583740)
2021-03-15T07:30:00.418-0700	INFO	chain	chain/sync_manager.go:322	worker 227117 done; took 148.373468ms
2021-03-15T07:30:01.376-0700	WARN	auth	auth/handler.go:39	JWT Verification failed (originating from 10.1.18.153:38708): JWT Verification failed: jwt: HMAC verification failed
2021-03-15T07:30:01.798-0700	WARN	auth	auth/handler.go:39	JWT Verification failed (originating from 10.1.18.151:55860): JWT Verification failed: jwt: HMAC verification failed
2021-03-15T07:30:01.915-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebube3filunyrrnt64g2hb3fxuk6lzdscobze7d6v5d2gyzow6g6u]
2021-03-15T07:30:01.915-0700	INFO	chain	chain/sync_manager.go:314	worker 227118 syncing in [bafy2bzacebube3filunyrrnt64g2hb3fxuk6lzdscobze7d6v5d2gyzow6g6u]
2021-03-15T07:30:03.591-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 1.6708668, "height": "583740", "age": 3.591889158}
2021-03-15T07:30:03.592-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceabvxrzje4qfzvnrrbbwqfvgk776l4wyrdqotpm4pn424vc7mofus bafy2bzacebube3filunyrrnt64g2hb3fxuk6lzdscobze7d6v5d2gyzow6g6u bafy2bzaceaq3n46r3br3nerqqddsxp762twxe3qj5czaeiivsi3cy32h6cuk6 bafy2bzacedf4tocfix6bdb4lm43gijfbvdyh6nzbdd2jcyfodtf7bnhed62xi] (height=583740)
2021-03-15T07:30:03.593-0700	INFO	chain	chain/sync_manager.go:322	worker 227118 done; took 1.677793485s
2021-03-15T07:30:06.036-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679585}
2021-03-15T07:30:06.065-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679585, "took": 0.029071493}
2021-03-15T07:30:06.068-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679585}
2021-03-15T07:30:06.068-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679585, "took": 0.000059184}
2021-03-15T07:30:08.125-0700	WARN	sub	sub/incoming.go:104	Received block with large delay 278 from miner f0119997
2021-03-15T07:30:10.230-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568153 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-03-15T07:30:10.681-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568434 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-03-15T07:30:11.236-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 1568850 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed:
    github.com/filecoin-project/lotus/chain/stmgr.GetStorageDeal
        /home/filecoin/filecoin/lotus/chain/stmgr/utils.go:290
2021-03-15T07:30:30.188-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs]
2021-03-15T07:30:30.188-0700	INFO	chain	chain/sync_manager.go:314	worker 227119 syncing in [bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs]
2021-03-15T07:30:30.252-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.060953213, "height": "583741", "age": 0.252783264}
2021-03-15T07:30:30.253-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:30.253-0700	INFO	chain	chain/sync_manager.go:322	worker 227119 done; took 65.005459ms
2021-03-15T07:30:30.307-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq]
2021-03-15T07:30:30.307-0700	INFO	chain	chain/sync_manager.go:314	worker 227120 syncing in [bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq]
2021-03-15T07:30:30.353-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacecsh2yfla37a5ddtrmcarudrvj2tzhhtfpzewqjoymvdshw2fimao]
2021-03-15T07:30:30.353-0700	INFO	chain	chain/sync_manager.go:314	worker 227121 syncing in [bafy2bzacecsh2yfla37a5ddtrmcarudrvj2tzhhtfpzewqjoymvdshw2fimao]
2021-03-15T07:30:30.389-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.077551149, "height": "583741", "age": 0.389177081}
2021-03-15T07:30:30.389-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:30.390-0700	INFO	chain	chain/sync_manager.go:322	worker 227120 done; took 82.37086ms
2021-03-15T07:30:30.396-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm]
2021-03-15T07:30:30.396-0700	INFO	chain	chain/sync_manager.go:314	worker 227122 syncing in [bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm]
2021-03-15T07:30:30.438-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaced2ow7ucsm2aj7sfcz2fdq7tcyir62jvaiysdgxwismgcbimphfly]
2021-03-15T07:30:30.438-0700	INFO	chain	chain/sync_manager.go:314	worker 227123 syncing in [bafy2bzaced2ow7ucsm2aj7sfcz2fdq7tcyir62jvaiysdgxwismgcbimphfly]
2021-03-15T07:30:30.476-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.075462211, "height": "583741", "age": 0.476668526}
2021-03-15T07:30:30.477-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:30.477-0700	INFO	chain	chain/sync_manager.go:322	worker 227122 done; took 80.757724ms
2021-03-15T07:30:30.689-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.333055232, "height": "583741", "age": 0.689731344}
2021-03-15T07:30:30.690-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacecsh2yfla37a5ddtrmcarudrvj2tzhhtfpzewqjoymvdshw2fimao bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:30.690-0700	INFO	chain	chain/sync_manager.go:322	worker 227121 done; took 337.550906ms
2021-03-15T07:30:30.836-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.393170157, "height": "583741", "age": 0.836283241}
2021-03-15T07:30:30.837-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacecsh2yfla37a5ddtrmcarudrvj2tzhhtfpzewqjoymvdshw2fimao bafy2bzaced2ow7ucsm2aj7sfcz2fdq7tcyir62jvaiysdgxwismgcbimphfly bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:30.837-0700	INFO	chain	chain/sync_manager.go:322	worker 227123 done; took 398.824241ms
2021-03-15T07:30:31.799-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacea7zjn6wuh4jvawromjeanefoi2vyhiyfqf37ggi3wgwxeyqx2ooc]
2021-03-15T07:30:31.799-0700	INFO	chain	chain/sync_manager.go:314	worker 227124 syncing in [bafy2bzacea7zjn6wuh4jvawromjeanefoi2vyhiyfqf37ggi3wgwxeyqx2ooc]
2021-03-15T07:30:31.876-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.073819046, "height": "583741", "age": 1.876442759}
2021-03-15T07:30:31.877-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacea7zjn6wuh4jvawromjeanefoi2vyhiyfqf37ggi3wgwxeyqx2ooc bafy2bzacecsh2yfla37a5ddtrmcarudrvj2tzhhtfpzewqjoymvdshw2fimao bafy2bzaced2ow7ucsm2aj7sfcz2fdq7tcyir62jvaiysdgxwismgcbimphfly bafy2bzaceatj5i34jyw37oegumsovefvgqtui7aqxrzma7hql4askwkgkeveq bafy2bzacecf2uzrq5yhcrqcrdugwg3zlchclu6ktwzrm2ijdkukj3zfnzetsm bafy2bzacedulri2ssakjran2cwwrb2wkxf23222fe3jo6wcxm7ag6hl6b6ezs] (height=583741)
2021-03-15T07:30:31.877-0700	INFO	chain	chain/sync_manager.go:322	worker 227124 done; took 77.704669ms
2021-03-15T07:30:36.352-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679586}
2021-03-15T07:30:36.392-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679586, "took": 0.04006966}
2021-03-15T07:30:36.396-0700	INFO	drand	drand/drand.go:141	start fetching randomness	{"round": 679586}
2021-03-15T07:30:36.396-0700	INFO	drand	drand/drand.go:151	done fetching randomness	{"round": 679586, "took": 0.000184544}
2021-03-15T07:30:39.060-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: not enough gas: used=54695828, available=55340635, use=718940 (RetCode=7):
    github.com/filecoin-project/lotus/chain/vm.(*Runtime).chargeGasInternal
        /home/filecoin/filecoin/lotus/chain/vm/runtime.go:575
2021-03-15T07:30:39.060-0700	WARN	vm	vm/runtime.go:376	vmctx send failed: to: f04, method: 8: ret: [], err: not enough gas: used=54695828, available=55340635, use=718940 (RetCode=7)
2021-03-15T07:30:39.060-0700	WARN	vm	vm/runtime.go:332	Abortf: failed to submit proof for bulk verification
2021-03-15T07:30:39.060-0700	WARN	vm	vm/runtime.go:145	VM.Call failure: failed to submit proof for bulk verification (RetCode=7):
    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess
        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64
2021-03-15T07:30:39.060-0700	WARN	vm	vm/vm.go:534	Send actor error	{"from": "f3q77nyqujbdl2typrhrsxbr3v5nvbd5oz7vy63rcwc2i3i4mt4cbgzgd7l3z73jqxqjk3rpmiea6lx5daes4a", "to": "f0135467", "nonce": 1921281, "method": "7", "height": "583741", "error": "failed to submit proof for bulk verification (RetCode=7):\n    github.com/filecoin-project/specs-actors/v3/actors/builtin.RequireSuccess\n        /root/go/pkg/mod/github.com/filecoin-project/specs-actors/[email protected]/actors/builtin/shared.go:64"}
2021-03-15T07:30:59.661-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacecpwb5ujwyhr3t7hs3pqf7gwp5te6d5vjqruczxvgyxlxn3rspu72]
2021-03-15T07:30:59.661-0700	INFO	chain	chain/sync_manager.go:314	worker 227125 syncing in [bafy2bzacecpwb5ujwyhr3t7hs3pqf7gwp5te6d5vjqruczxvgyxlxn3rspu72]
2021-03-15T07:30:59.667-0700	WARN	chain	chain/sync.go:750	Got block from the future, but within threshold1615818660 1615818659
2021-03-15T07:30:59.754-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.087909625, "height": "583742", "age": -0.245047771}
2021-03-15T07:30:59.755-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacecpwb5ujwyhr3t7hs3pqf7gwp5te6d5vjqruczxvgyxlxn3rspu72] (height=583742)
2021-03-15T07:30:59.756-0700	INFO	chain	chain/sync_manager.go:322	worker 227125 done; took 94.450876ms
2021-03-15T07:31:00.178-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceayyzwgr3qcdu6vikefxtgztjw74obrvnh6cuyui4lygw7ohyrooi]
2021-03-15T07:31:00.178-0700	INFO	chain	chain/sync_manager.go:314	worker 227126 syncing in [bafy2bzaceayyzwgr3qcdu6vikefxtgztjw74obrvnh6cuyui4lygw7ohyrooi]
2021-03-15T07:31:00.258-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedcwkjzrdbmhscwuhfotiuuhipiymtubcvii5f6cozrwjd3s7bjie]
2021-03-15T07:31:00.258-0700	INFO	chain	chain/sync_manager.go:314	worker 227127 syncing in [bafy2bzacedcwkjzrdbmhscwuhfotiuuhipiymtubcvii5f6cozrwjd3s7bjie]
2021-03-15T07:31:00.262-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.079810408, "height": "583742", "age": 0.262551643}
2021-03-15T07:31:00.263-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacecpwb5ujwyhr3t7hs3pqf7gwp5te6d5vjqruczxvgyxlxn3rspu72 bafy2bzaceayyzwgr3qcdu6vikefxtgztjw74obrvnh6cuyui4lygw7ohyrooi] (height=583742)
2021-03-15T07:31:00.263-0700	INFO	chain	chain/sync_manager.go:322	worker 227126 done; took 85.13173ms
2021-03-15T07:31:00.346-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.083510684, "height": "583742", "age": 0.346412145}
2021-03-15T07:31:00.347-0700	INFO	chainstore	store/store.go:583	New heaviest tipset! [bafy2bzacedcwkjzrdbmhscwuhfotiuuhipiymtubcvii5f6cozrwjd3s7bjie bafy2bzacecpwb5ujwyhr3t7hs3pqf7gwp5te6d5vjqruczxvgyxlxn3rspu72 bafy2bzaceayyzwgr3qcdu6vikefxtgztjw74obrvnh6cuyui4lygw7ohyrooi] (height=583742)
2021-03-15T07:31:00.347-0700	INFO	chain	chain/sync_manager.go:322	worker 227127 done; took 89.192129ms
2021-03-15T07:31:00.566-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebsad2mvft34kede2wt4js4vojahovw52i55zjuvso72f3qfmxju6]
2021-03-15T07:31:00.566-0700	INFO	chain	chain/sync_manager.go:314	worker 227128 syncing in [bafy2bzacebsad2mvft34kede2wt4js4vojahovw52i55zjuvso72f3qfmxju6]
2021-03-15T07:31:00.605-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebbms4roq7jians3sh5dn3hy3l6yu3jig34awy3veieafbnbc3w5m]
2021-03-15T07:31:00.605-0700	INFO	chain	chain/sync_manager.go:314	worker 227129 syncing in [bafy2bzacebbms4roq7jians3sh5dn3hy3l6yu3jig34awy3veieafbnbc3w5m]
2021-03-15T07:31:00.649-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.078331701, "height": "583742", "age": 0.649700356}

@William8Work
Copy link

the miner log:

2021-03-15T07:29:15.891-0700	INFO	miner	miner/miner.go:447	mined new block	{"cid": "bafy2bzacebr6gjzekmbnml6froljlqm3crde6nbdolvmiyhxwj7amh3uidfai", "height": "583739", "miner": "f08399", "parents": ["f01248","f09037"], "took": 9.547289037}
2021-03-15T07:29:25.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:29:25.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:25.462-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:25.462-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:29:35.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:29:35.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:35.248-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:35.248-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:29:40.918-0700	INFO	miner	miner/miner.go:383	Time delta between now and our mining base: 10s (nulls: 0)
2021-03-15T07:29:44.031-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 9 queued; 26 open windows
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.750903498s
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.100973427s
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.397832315s
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.040-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.294515103s
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.297441749s
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.104035491s
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.754102883s
2021-03-15T07:29:44.043-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.400904819s
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.311293895s
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.767921435s
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.117928264s
2021-03-15T07:29:44.057-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.414781321s
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.769870492s
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.119904813s
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.41676285s
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.059-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.313526592s
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.424320043s
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.321085969s
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.7777141s
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.067-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.127717142s
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.322820909s
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.779508453s
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:396	not allocating on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.129499632s
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.426349703s
2021-03-15T07:29:44.069-0700	DEBUG	stores	stores/index.go:396	not allocating on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] [] [24 25 4 5 17 18]]
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched.go:465	SCHED try assign sqi:8 sector 2716 to window 24
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched.go:472	SCHED ASSIGNED sqi:8 sector 2716 task seal/v0/precommit/1 to window 24
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched_worker.go:368	assign worker sector 2716
2021-03-15T07:29:44.088-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:44.089-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m6.44704247s
2021-03-15T07:29:44.090-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m22.343740867s
2021-03-15T07:29:44.090-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m6.80040649s
2021-03-15T07:29:44.090-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m37.150400424s
2021-03-15T07:29:44.153-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:44.153-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:29:44.153-0700	WARN	advmgr	sector-storage/manager_calltracker.go:149	canceling started (not running) work seal/v0/precommit/1([[{"ID":{"Miner":8399,"Number":2716},"ProofType":8},"reqWD9nJS52FLo9p1ipkwZexRvnLabfqiSsN38E2Ppc=",[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]]])
2021-03-15T07:29:44.153-0700	DEBUG	advmgr	sector-storage/sched_worker.go:278	task done	{"workerid": "5fddc4b5-e25b-4971-b551-59512ff59ef0"}
2021-03-15T07:29:44.154-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:44.167-0700	WARN	sectors	storage-sealing/fsm.go:535	sector 2716 got error event sealing.SectorSealPreCommit1Failed: seal pre commit(1) failed: storage call error 0: failed to acquire sector {8399 2716} from remote (tried [{c29fa847-7eab-45cb-82fb-64a7c52b4c9d [http://10.1.18.153:3456/remote/unsealed/s-t08399-2716] 10 true false false}]): 1 error occurred:
	* fetch error http://10.1.18.153:3456/remote/unsealed/s-t08399-2716 (storage c29fa847-7eab-45cb-82fb-64a7c52b4c9d) -> /media/lotus/worker/unsealed/fetching/s-t08399-2716: non-200 code: 500


2021-03-15T07:29:44.178-0700	INFO	sectors	storage-sealing/states_failed.go:25	SealPreCommit1Failed(2716), waiting 59.821949921s before retrying
2021-03-15T07:29:44.214-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:44.214-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:29:45.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:29:45.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:45.251-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:45.251-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:29:55.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:29:55.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:29:55.250-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:29:55.250-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:01.484-0700	WARN	advmgr	sector-storage/manager.go:323	stub NewSector
2021-03-15T07:30:01.484-0700	INFO	sectors	storage-sealing/garbage.go:17	Pledge {{8399 3375} 8}, contains []
2021-03-15T07:30:01.484-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 9 queued; 26 open windows
2021-03-15T07:30:01.500-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.857650089s
2021-03-15T07:30:01.500-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.754405254s
2021-03-15T07:30:01.500-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.211010973s
2021-03-15T07:30:01.500-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.560977104s
2021-03-15T07:30:01.503-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.757000068s
2021-03-15T07:30:01.503-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.213706618s
2021-03-15T07:30:01.503-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.563676827s
2021-03-15T07:30:01.503-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.86051715s
2021-03-15T07:30:01.514-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.871357521s
2021-03-15T07:30:01.514-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.768143214s
2021-03-15T07:30:01.514-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.224760545s
2021-03-15T07:30:01.514-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.574737366s
2021-03-15T07:30:01.516-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.769927226s
2021-03-15T07:30:01.516-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.576588356s
2021-03-15T07:30:01.516-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.226651289s
2021-03-15T07:30:01.516-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.873485797s
2021-03-15T07:30:01.522-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.776362852s
2021-03-15T07:30:01.522-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.233075403s
2021-03-15T07:30:01.522-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.583068226s
2021-03-15T07:30:01.522-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.879930119s
2021-03-15T07:30:01.524-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.881451923s
2021-03-15T07:30:01.524-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.778241684s
2021-03-15T07:30:01.524-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.234864765s
2021-03-15T07:30:01.524-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.584840766s
2021-03-15T07:30:01.548-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:01.548-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] [] [24 25 4 5 17 18]]
2021-03-15T07:30:01.548-0700	DEBUG	advmgr	sector-storage/sched.go:465	SCHED try assign sqi:8 sector 3375 to window 24
2021-03-15T07:30:01.549-0700	DEBUG	advmgr	sector-storage/sched.go:472	SCHED ASSIGNED sqi:8 sector 3375 task seal/v0/addpiece to window 24
2021-03-15T07:30:01.549-0700	DEBUG	advmgr	sector-storage/sched_worker.go:368	assign worker sector 3375
2021-03-15T07:30:01.549-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:01.550-0700	DEBUG	stores	stores/index.go:401	not allocating on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m23.907259581s
2021-03-15T07:30:01.550-0700	DEBUG	stores	stores/index.go:401	not allocating on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h9m39.804008725s
2021-03-15T07:30:01.550-0700	DEBUG	stores	stores/index.go:401	not allocating on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h4m54.610567209s
2021-03-15T07:30:01.550-0700	DEBUG	stores	stores/index.go:401	not allocating on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m24.260629301s
2021-03-15T07:30:01.606-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:01.606-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:01.606-0700	DEBUG	advmgr	sector-storage/sched_worker.go:278	task done	{"workerid": "5fddc4b5-e25b-4971-b551-59512ff59ef0"}
2021-03-15T07:30:01.606-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:01.661-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:01.661-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:01.690-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:01.750-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:01.750-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:05.188-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:30:05.188-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:05.249-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:05.249-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:06.092-0700	INFO	miner	miner/miner.go:383	Time delta between now and our mining base: 6s (nulls: 0)
2021-03-15T07:30:15.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:30:15.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:15.250-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:15.250-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:18.728-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StorageStat': fsstat: path not found:
    github.com/filecoin-project/lotus/extern/sector-storage/stores.init
        /home/filecoin/filecoin/lotus/extern/sector-storage/stores/local.go:649
2021-03-15T07:30:18.771-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StorageStat': fsstat: path not found:
    github.com/filecoin-project/lotus/extern/sector-storage/stores.init
        /home/filecoin/filecoin/lotus/extern/sector-storage/stores/local.go:649
2021-03-15T07:30:18.808-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StorageStat': do request:
    github.com/filecoin-project/lotus/extern/sector-storage/stores.(*Remote).FsStat
        /home/filecoin/filecoin/lotus/extern/sector-storage/stores/remote.go:392
  - Get "http://10.1.18.152:3457/remote/stat/bdde36fc-8330-4a55-8d45-fa327466ba83": dial tcp 10.1.18.152:3457: connect: connection refused
2021-03-15T07:30:18.813-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StorageStat': fsstat: path not found:
    github.com/filecoin-project/lotus/extern/sector-storage/stores.init
        /home/filecoin/filecoin/lotus/extern/sector-storage/stores/local.go:649
2021-03-15T07:30:18.831-0700	WARN	rpc	[email protected]/handler.go:279	error in RPC call to 'Filecoin.StorageStat': fsstat: path not found:
    github.com/filecoin-project/lotus/extern/sector-storage/stores.init
        /home/filecoin/filecoin/lotus/extern/sector-storage/stores/local.go:649
2021-03-15T07:30:25.187-0700	WARN	advmgr	sector-storage/sched_worker.go:213	failed to check worker session	{"error": "RPC client error: sendRequest failed: Post \"http://10.1.18.152:3457/rpc/v0\": dial tcp 10.1.18.152:3457: connect: connection refused"}
2021-03-15T07:30:25.187-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 8 queued; 26 open windows
2021-03-15T07:30:25.276-0700	DEBUG	advmgr	sector-storage/sched.go:449	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:<nil>} todo:[]}]
2021-03-15T07:30:25.276-0700	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[] [] [] [] [] [] [] []]
2021-03-15T07:30:35.048-0700	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 9 queued; 26 open windows
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.317419553s
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.774043145s
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.124026489s
2021-03-15T07:30:35.063-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.420872884s
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.321353878s
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.127935566s
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.778037374s
2021-03-15T07:30:35.067-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.424833469s
2021-03-15T07:30:35.070-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.324648067s
2021-03-15T07:30:35.071-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.781284794s
2021-03-15T07:30:35.071-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.071-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.131272877s
2021-03-15T07:30:35.071-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.428121436s
2021-03-15T07:30:35.071-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.326698172s
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.783409651s
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.133394088s
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.430240091s
2021-03-15T07:30:35.073-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.330213631s
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.786831192s
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.136812433s
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.43366062s
2021-03-15T07:30:35.076-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.799902568s
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.150016149s
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.446919732s
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.089-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.343632607s
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.44977661s
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.346564017s
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.153129765s
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.803202538s
2021-03-15T07:30:35.092-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:324	not selecting on bdde36fc-8330-4a55-8d45-fa327466ba83, didn't receive heartbeats for 298h10m13.349427367s
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:324	not selecting on c29fa847-7eab-45cb-82fb-64a7c52b4c9d, didn't receive heartbeats for 307h1m57.80607744s
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:319	not selecting on 15a2dfed-7559-47d4-9b7a-50d32cddf1ca, out of space (available: 451152465920, need: 518832049356)
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:324	not selecting on d99133c0-a166-44dc-bd27-763e2772b330, didn't receive heartbeats for 108h5m28.156070673s
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:324	not selecting on 7cde6e8b-d94d-4cba-aa41-8fe49d96e380, didn't receive heartbeats for 46h5m57.452919292s
2021-03-15T07:30:35.095-0700	DEBUG	stores	stores/index.go:319	not selecting on 650d586e-6e43-4203-a5f4-9661f3e4b789, out of space (available: 451152465920, need: 518832049356)

@rjan90
Copy link
Contributor

rjan90 commented Mar 25, 2021

Had another case of a orphan-block yesterday. Here is the interleaved daemon / miner logs:

2021-03-24T19:17:06.152+0100	INFO	miner	miner/miner.go:383	Time delta between now and our mining base: 6s (nulls: 0)
2021-03-24T19:17:06.156+0100	INFO	storageminer	storage/miner.go:256	Computing WinningPoSt ;[{SealProof:8 SectorNumber:1693 SealedCID:bagboea4b5abcawuxx7pkrvkh46nv2fqtwduymyi3whpsn65pv5wckhnolipptozr}]; [181 63 46 90 66 96 26 108 213 152 60 29 149 251 142 143 195 235 73 131 187 242 108 109 60 197 70 117 23 6 10 28]
2021-03-24T19:17:06.158 INFO filcrypto::proofs::api > generate_winning_post: start
2021-03-24T19:17:06.160 INFO filecoin_proofs::api::post > generate_winning_post:start
2021-03-24T19:17:06.160 INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
2021-03-24T19:17:06.160 INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
2021-03-24T19:17:06.164 INFO storage_proofs_core::compound_proof > vanilla_proofs:start
2021-03-24T19:17:10.418 INFO storage_proofs_core::compound_proof > vanilla_proofs:finish
2021-03-24T19:17:10.511 INFO storage_proofs_core::compound_proof > snark_proof:start
2021-03-24T19:17:10.511 INFO bellperson::groth16::prover > Bellperson 0.12.5 is being used!
2021-03-24T19:17:10.738 INFO bellperson::groth16::prover > starting proof timer
2021-03-24T19:17:10.757 INFO bellperson::gpu::locks > GPU is available for FFT!
2021-03-24T19:17:10.757 WARN bellperson::domain > Cannot instantiate GPU FFT kernel! Error: GPUError: No working GPUs found!
2021-03-24T19:17:17.974 INFO bellperson::groth16::prover > prover time: 7.235588363s
2021-03-24T19:17:17.981 INFO storage_proofs_core::compound_proof > snark_proof:finish
2021-03-24T19:17:17.981 INFO filecoin_proofs::api::post > generate_winning_post:finish
2021-03-24T19:17:17.982 INFO filcrypto::proofs::api > generate_winning_post: finish
2021-03-24T19:17:17.982+0100	INFO	storageminer	storage/miner.go:263	GenerateWinningPoSt took 11.826296657s

2021-03-24T19:17:19.135+0100	WARN	sub	sub/incoming.go:104	received block with large delay from miner	{"block": "bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs", "delay": 19, "miner": "f02500"}
2021-03-24T19:17:19.148+0100	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs]
2021-03-24T19:17:19.148+0100	INFO	chain	chain/sync_manager.go:314	worker 97397 syncing in [bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs]
### 2021-03-24T19:17:19.162+0100	INFO	miner	miner/miner.go:447	mined new block	{"cid": "bafy2bzacedmpy53tl6blfztcyp5q327acmphbrpiih4yeq3niks7hfvaebvxg", "height": "610115", "miner": "f023467", "parents": ["f02303","f096943","f024483","f0154294"], "took": 13.015044643}
2021-03-24T19:17:19.210+0100	INFO	chain	chain/sync.go:710	block validation	{"took": 0.055423771, "height": "610114", "age": 19.210695429}
2021-03-24T19:17:19.217+0100	INFO	chainstore	store/store.go:582	New heaviest tipset! [bafy2bzacedqcuhtjkcy7fin7zyjcjhazdlyxzo45jpn66cjrfmo2tcojwu2p4 bafy2bzaceabrp6mphsetdzvmfw3rk7osinq6qvc2awbfzm47srakilx3tjitg bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs bafy2bzacec3gfpq4pwa4qm3vgev6pi2itqck3oke3zthekv2m53kyouhsfnpa bafy2bzacecvxykbkam6mav74mxn54oyqhrr3t6jnjcp3jut3wq7torgkmocxy] (height=610114)
2021-03-24T19:17:19.220+0100	INFO	chain	chain/sync_manager.go:322	worker 97397 done; took 72.377574ms
2021-03-24T19:17:20.219+0100	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzacedqcuhtjkcy7fin7zyjcjhazdlyxzo45jpn66cjrfmo2tcojwu2p4 bafy2bzaceabrp6mphsetdzvmfw3rk7osinq6qvc2awbfzm47srakilx3tjitg bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs bafy2bzacec3gfpq4pwa4qm3vgev6pi2itqck3oke3zthekv2m53kyouhsfnpa bafy2bzacecvxykbkam6mav74mxn54oyqhrr3t6jnjcp3jut3wq7torgkmocxy]
2021-03-24T19:17:20.219+0100	INFO	chain	chain/sync_manager.go:314	worker 97398 syncing in [bafy2bzacedqcuhtjkcy7fin7zyjcjhazdlyxzo45jpn66cjrfmo2tcojwu2p4 bafy2bzaceabrp6mphsetdzvmfw3rk7osinq6qvc2awbfzm47srakilx3tjitg bafy2bzacebigbcmeopjsmtnltcs7v7b7fzbnru3vczqgfj4ljutauwiw6y3zs bafy2bzacec3gfpq4pwa4qm3vgev6pi2itqck3oke3zthekv2m53kyouhsfnpa bafy2bzacecvxykbkam6mav74mxn54oyqhrr3t6jnjcp3jut3wq7torgkmocxy]
2021-03-24T19:17:20.219+0100	INFO	chain	chain/sync_manager.go:322	worker 97398 done; took 4.228µs

This time the delayed block came in after my GenerateWinningPoSt had finished. The mined new block is highlighted with ### in the log.

@rjan90
Copy link
Contributor

rjan90 commented Mar 30, 2021

A new case of an orphan block this morning. This time it was a bit different, as there is no logs of a large delay of a block:

Interleaved miner / lotus logs:

2021-03-30T07:04:36.134+0200	INFO	storageminer	storage/miner.go:256	Computing WinningPoSt ;[{SealProof:8 SectorNumber:1952 SealedCID:bagboea4b5abca7gzifcdzxzpavg7vjp2q3dojr6fo6sbh6i74bsbq4w63sp2boqe}]; [97 27 71 88 128 141 254 178 50 240 114 235 228 19 109 227 34 174 171 242 79 231 246 172 41 95 75 250 183 33 88 86]


2021-03-30T07:04:36.764+0200	INFO	chain	chain/sync.go:710	block validation	{"took": 1.994078336, "height": "625809", "age": 6.764206773}
2021-03-30T07:04:36.768+0200	INFO	chainstore	store/store.go:582	New heaviest tipset! [bafy2bzacebisjhumqxxevbvziqjal6l3mptpl22bka4kdrg5uqlsh4e2unspo bafy2bzacecomttodu2imo3bjofxhq4nx2t5iplonxetwwmbfo6gkavdnftktc bafy2bzacedhmksvbsrdkolcsdf2g6kgtiquvmqhddouedc45zbbatuimt6wb4 bafy2bzacebr4xdz4zhl6ds53fscmmgvr2vbpjfluqta4rdb7z5sjmzhnh2lpc bafy2bzaceaboy6tf5cbbaqoczccuzk3jyiunsycajtwqareb2yos72ku7roje bafy2bzacebrnirajy3d47a2bpwkp4n44ztu6gc3scmwvzlihjm3i4djinbcpa bafy2bzacedyrkskv2qqxfmeyvsx3ykeht5xtou2vysdvunc6xcb3crpyhqh7w bafy2bzaceblrvyodbiekniikl4h2ujygc27qiohrcptpgsvdwdkr72lnd5564] (height=625809)
2021-03-30T07:04:36.772+0200	INFO	chain	chain/sync_manager.go:322	worker 193966 done; took 2.01094294s


2021-03-30T07:04:50.420+0200	INFO	miner	miner/miner.go:447	mined new block	{"cid": "bafy2bzacecmtdnrxhyse65erljqfdcebd5fi7km6dyatfqhj4wcwvxghrgnay", "height": "625810", "miner": "f023467", "parents": ["f0242420","f099239","f024015","f02438","f0119997","f034710","f023198"], "took": 14.298089616}

2021-03-30T07:05:00.036+0200	WARN	chain	chain/sync.go:1414	(fork detected) synced header chain ([bafy2bzacecmtdnrxhyse65erljqfdcebd5fi7km6dyatfqhj4wcwvxghrgnay] - 625810) does not link to our best block ([bafy2bzacebisjhumqxxevbvziqjal6l3mptpl22bka4kdrg5uqlsh4e2unspo bafy2bzacecomttodu2imo3bjofxhq4nx2t5iplonxetwwmbfo6gkavdnftktc bafy2bzacedhmksvbsrdkolcsdf2g6kgtiquvmqhddouedc45zbbatuimt6wb4 bafy2bzacebr4xdz4zhl6ds53fscmmgvr2vbpjfluqta4rdb7z5sjmzhnh2lpc bafy2bzaceaboy6tf5cbbaqoczccuzk3jyiunsycajtwqareb2yos72ku7roje bafy2bzacebrnirajy3d47a2bpwkp4n44ztu6gc3scmwvzlihjm3i4djinbcpa bafy2bzacedyrkskv2qqxfmeyvsx3ykeht5xtou2vysdvunc6xcb3crpyhqh7w bafy2bzaceblrvyodbiekniikl4h2ujygc27qiohrcptpgsvdwdkr72lnd5564] - 625809)

@magik6k magik6k added the need/analysis Hint: Needs Analysis label Apr 9, 2021
@magik6k magik6k added the area/mining Area: Mining label Apr 9, 2021
@cerblue
Copy link

cerblue commented Apr 19, 2021

Another repro from f010088 on Apr 16, 2021:

Miner+Daemon log:
Apr 16 06:50:41 lotus-miner[45485]: {"level":"info","ts":"2021-04-16T06:50:41.671Z","logger":"storageminer","caller":"storage/miner.go:263","msg":"GenerateWinningPoSt took 5.612808983s"}
Apr 16 06:50:43 lotus-miner[45485]: {"level":"info","ts":"2021-04-16T06:50:43.412Z","logger":"miner","caller":"miner/miner.go:447","msg":"mined new block","cid":"bafy2bzaceb2bha27ib3ipqpnaisf2ri3moge3ohymthoj2qlct3cqakhcffkw","height":"674982","miner":"f010088","parents":["f0155050","f02775","f0155049","f0127627","f02770"],"took":7.374005391}
Apr 16 06:50:46 lotus[356181]: {"level":"warn","ts":"2021-04-16T06:50:46.888Z","logger":"sub","caller":"sub/incoming.go:104","msg":"received block with large delay from miner","block":"bafy2bzacedxpz73e7deqxq46rlflik3ktjr5hz3gxws2jo3zikkymch2i2yxc","delay":16,"miner":"f0142337"}
Apr 16 06:51:00 lotus[356181]: {"level":"warn","ts":"2021-04-16T06:51:00.014Z","logger":"chain","caller":"chain/sync.go:1414","msg":"(fork detected) synced header chain ([bafy2bzaceb2bha27ib3ipqpnaisf2ri3moge3ohymthoj2qlct3cqakhcffkw] - 674982) does not link to our best block ([...] - 674981)"}

@William8Work
Copy link

mined another orphan block 😢. When does it stop?

021-04-17T19:45:41.038-0700	WARN	sub	sub/incoming.go:104	received block with large delay from miner	{"block": "bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg", "delay": 11, "miner": "f019354"}
2021-04-17T19:45:41.041-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg]
2021-04-17T19:45:41.041-0700	INFO	chain	chain/sync_manager.go:314	worker 77197 syncing in [bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg]
2021-04-17T19:45:41.075-0700	INFO	chain	chain/sync.go:710	block validation	{"took": 0.03254636, "height": "680251", "age": 11.075561639}
2021-04-17T19:45:41.077-0700	INFO	chainstore	store/store.go:582	New heaviest tipset! [bafy2bzaceazsyw4mvg43fpoxcc23fgmw7c3cvovovzosc7dpoyirbk6om6qio bafy2bzacedwpwjo7zkd66wunvb7inwso3bi3dkhtf6e5aulpkpzzialevgfpu bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg bafy2bzacecvaw3edjspmzg47nyhnd5x4b2yy6lqsa2a34cqdtalqahfhxf4q6] (height=680251)
2021-04-17T19:45:41.077-0700	INFO	chain	chain/sync_manager.go:322	worker 77197 done; took 36.375247ms
2021-04-17T19:45:44.071-0700	INFO	messagepool	messagepool/selection.go:109	create message chains done	{"took": 0.179370799}
2021-04-17T19:45:44.073-0700	INFO	messagepool	messagepool/selection.go:222	merge message chains done	{"took": 0.001214184}
2021-04-17T19:45:44.073-0700	WARN	messagepool	messagepool/selection.go:384	optimal selection failed to pack a block; picked 100 messages with random selection
2021-04-17T19:45:44.073-0700	INFO	messagepool	messagepool/selection.go:89	message selection done	{"took": 0.194961226}
2021-04-17T19:45:56.370-0700	INFO	chain	chain/sync_manager.go:232	selected sync target: [bafy2bzaceazsyw4mvg43fpoxcc23fgmw7c3cvovovzosc7dpoyirbk6om6qio bafy2bzacedwpwjo7zkd66wunvb7inwso3bi3dkhtf6e5aulpkpzzialevgfpu bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg bafy2bzacecvaw3edjspmzg47nyhnd5x4b2yy6lqsa2a34cqdtalqahfhxf4q6]
2021-04-17T19:45:56.370-0700	INFO	chain	chain/sync_manager.go:314	worker 77198 syncing in [bafy2bzaceazsyw4mvg43fpoxcc23fgmw7c3cvovovzosc7dpoyirbk6om6qio bafy2bzacedwpwjo7zkd66wunvb7inwso3bi3dkhtf6e5aulpkpzzialevgfpu bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg bafy2bzacecvaw3edjspmzg47nyhnd5x4b2yy6lqsa2a34cqdtalqahfhxf4q6]
2021-04-17T19:45:56.370-0700	INFO	chain	chain/sync_manager.go:322	worker 77198 done; took 9.866µs
2021-04-17T19:46:00.039-0700	WARN	chain	chain/sync.go:1414	(fork detected) synced header chain ([bafy2bzaceclckdsmg6oz4d7q7743fgepyv3kl6a3jumc7ek4eylqxxkfpznc4] - 680252) does not link to our best block ([bafy2bzaceazsyw4mvg43fpoxcc23fgmw7c3cvovovzosc7dpoyirbk6om6qio bafy2bzacedwpwjo7zkd66wunvb7inwso3bi3dkhtf6e5aulpkpzzialevgfpu bafy2bzaceddjt3ycndbtvfdzwwjz7zl3vjocmhdq3hzqwsgecrxf5scspaskg bafy2bzacecvaw3edjspmzg47nyhnd5x4b2yy6lqsa2a34cqdtalqahfhxf4q6] - 680251)

@Storage-Hive
Copy link

I've had two occurrences in the last two weeks, below are the relevant logs, if I scan my lotus log I see many blocks coming in with large delays, considering that the round trip time to pretty much anywhere on the planet is ~500ms I don't understand why some blocks from some miners are coming in so late/slow, all I can think is they have very poor hardware and/or are doing it maliciously to cause block losses for others, either way miners with excessive continuous delays should be penalised/slashed for such behaviour, it's not good for the network.

https://filfox.info/en/tipset/617327
2021-03-27T02:23:36.353-0400 INFO storageminer storage/miner.go:256 Computing WinningPoSt ;[{SealProof:8 SectorNumber:245 SealedCID:bagboea4b5abcbjm4r7g6wbegenhaiihedcsomyxgtbnows3w6wxpb665rodcvura}]; [74 134 153 23 38 10 223 85 17 155 117 235 85 25 141 103 254 180 95 113 74 255 204 4 17 247 10 48 1 121 170 47]
2021-03-27T02:23:42.670-0400 INFO storageminer storage/miner.go:263 GenerateWinningPoSt took 6.316548958s
2021-03-27T02:23:47.020-0400 INFO miner miner/miner.go:447 mined new block {"cid": "bafy2bzaceaaxezgw3rxtpkr4ivtdfmeu5n245rno7tst7f3koh3lvp4mxbupk", "height": "617328", "miner": "f098770", "parents": ["f0127721","f062619","f05316","f01800","f020330","f02520"], "took": 10.678904845}

2021-03-22T11:06:36.815-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzacecjs4lkhirqkjrq7hwpb77t6oh7qlc3g7i5ejd6alkqpelzoikthm", "delay": 6, "miner": "f019074"}
2021-03-23T09:50:36.726-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzacediumbgcfqqoara2lw457tc5bvnwvpphiueqd5mceauknq5uycvny", "delay": 6, "miner": "f019074"}
2021-03-24T04:24:36.607-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzacecdrtwicmgcadxeq6egjoeo7f2m2nalgobmrkoakhhmma7biezrz4", "delay": 6, "miner": "f019074"}
2021-03-25T09:36:49.205-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzaceayekjlz57nm4qkicx6o2jthg7nmkspektyzlkap2u3muanbx74lo", "delay": 19, "miner": "f019074"}
2021-03-26T14:28:56.632-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzaced3vhb25gvbs725dnyrogah6bzdpdalamibvvhnm7dfgm366oczks", "delay": 25556, "miner": "f019074"}
2021-03-26T20:57:36.755-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzacebabvrujm274a5jwkkapqs6jrfxhgmbkhvv3425jd65yoaon6orxy", "delay": 6, "miner": "f019074"}
2021-03-27T02:23:39.241-0400 WARN sub sub/incoming.go:104 received block with large delay from miner {"block": "bafy2bzaceafwrxaxk365ahy4gmauf465sxlgfm37k3e2qp5iojityc7k46uia", "delay": 9, "miner": "f019074"}

@ncgege
Copy link

ncgege commented May 5, 2021

2021-05-05T12:07:06.318+0800 INFO storageminer storage/miner.go:256 Computing WinningPoSt ;[{SealProof:9 SectorNumber:77 Seal
edCID:bagboea4b5abcaft7myysf2s5tbwny6ut7f4siv2ofqibdcwvufaktysww64bgfzm}]; [233 2 249 115 175 220 135 136 131 58 62 173 11 176 124 215 85 224 14
248 150 205 201 108 192 237 182 181 138 136 194 169]
2021-05-05T12:07:06.318 INFO filcrypto::proofs::api > generate_winning_post: start
2021-05-05T12:07:06.337 INFO filecoin_proofs::api::post > generate_winning_post:start
2021-05-05T12:07:06.337 INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[68719476736]
2021-05-05T12:07:06.337 INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[68719476736]
2021-05-05T12:07:06.637 INFO storage_proofs_core::compound_proof > vanilla_proofs:start
2021-05-05T12:07:10.311 INFO storage_proofs_core::compound_proof > vanilla_proofs:finish
2021-05-05T12:07:10.367 INFO storage_proofs_core::compound_proof > snark_proof:start
2021-05-05T12:07:10.367 INFO bellperson::groth16::prover > Bellperson 0.12.5 is being used!
2021-05-05T12:07:10.482 INFO bellperson::groth16::prover > starting proof timer
2021-05-05T12:07:10.492 INFO bellperson::gpu::locks > GPU is available for FFT!
2021-05-05T12:07:10.646 INFO bellperson::gpu::fft > FFT: 1 working device(s) selected.
2021-05-05T12:07:10.646 INFO bellperson::gpu::fft > FFT: Device 0: GeForce RTX 3090
2021-05-05T12:07:10.646 INFO bellperson::domain > GPU FFT kernel instantiated!
2021-05-05T12:07:10.940 INFO bellperson::gpu::locks > GPU is available for Multiexp!
2021-05-05T12:07:11.033 INFO bellperson::gpu::multiexp > Multiexp: 1 working device(s) selected. (CPU utilization: 0)
2021-05-05T12:07:11.033 INFO bellperson::gpu::multiexp > Multiexp: Device 0: GeForce RTX 3090 (Chunk-size: 18061702)
2021-05-05T12:07:11.033 INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
2021-05-05T12:07:12.259 INFO bellperson::groth16::prover > prover time: 1.777228178s
2021-05-05T12:07:12.269 INFO storage_proofs_core::compound_proof > snark_proof:finish
2021-05-05T12:07:12.269 INFO filecoin_proofs::api::post > generate_winning_post:finish
2021-05-05T12:07:12.274 INFO filcrypto::proofs::api > generate_winning_post: finish
2021-05-05T12:07:12.274+0800 INFO storageminer storage/miner.go:263 GenerateWinningPoSt took 5.956045472s
2021-05-05T12:07:12.526+0800 INFO miner miner/miner.go:452 mined new block {"cid": "bafy2bzaceaoym3ftdathlounkynyshzixexarwf
sw34pqwjdwzwtirwxwpwoa", "height": "729375", "miner": "f0523711", "parents": ["f0152337","f0422737","f0154039","f0102670","f084135"], "took": 6.2
19865994}
The miner log show i"ve mined a block ,evevery thing seems ok ,but i didn't win the block. cant find in the FIL explorer.

I found some error message form the lotus daemon log :
https://files.slack.com/files-pri/TEHTVS1L6-F021AT3F4CR/image.png
chain/sync_manager.go:253 error during sync in [bafy2bzacecy5cxi4y73qqurukav2rjbupprmjipvkmgjfu2hivwkpgrvewaiy]: collectChain failed: collectChain syncMessages: message processing failed: validating block bafy2bzacecy5cxi4y73qqurukav2rjbupprmjipvkmgjfu2hivwkpgrvewaiy: block was from the future (now=1620187612, blk=1620187620): temporal error
and i didn't find "Received block with large delay" near the block time.
image

@William8Work
Copy link

My miner had another instance on this. Block is mined but lotus daemon said with large delay.

Are we going to address this?

@Storage-Hive
Copy link

@William8Work we'll probably need to starting working on a FIP proposal and probably introduce some kind of penalty / slashing for miners that causes delays.

@ribasushi
Copy link
Collaborator

This is in the process of being investigated more thoroughly. Expect update EoW-ish

@jennijuju jennijuju added P1 P1: Must be resolved P2 P2: Should be resolved and removed P1 P1: Must be resolved labels Aug 16, 2021
@kikakkz
Copy link

kikakkz commented Aug 16, 2021

something interesting for this issue:
consider about the mining process:
1 lotus gather parents
2 miner wait for mining base with PropagationDelaySecs=6s, that's why your miner log 'Time delta between now and our mining base: 6s'. and if some message's process is a bit long, you may see log like 'Time delta between now and our mining base: 7s'. and if null block happen, you may see log like 'Time delta between now and our mining base: 36s'
3 miner try to mine a block base on current gathered parents
4 if miner is winner, miner submit the block to network
if everything is perfect, we should receive all parents within 6 seconds, but:
1 for some miner, winning post and window post happens at the same time, so its cpu threads will be exhausted by window post, then cannot calculate or broadcast the block in time
2 for some miner, they modify the PropagationDelaySecs to larger value then they can gather as many parents as possible
if any of the above case happens, then the block will be gathered after 6s by miner who is the winner of next round. if the miner use default PropagationDelaySecs=6s, and generate a block already, then its block will be think as orphan block due to the late parent.

so, i suggest we have some mechanism to make sure miner can generate valid block for valid parents. e.g. i generate a block with current parents at 6s, but if i gather a new parent after 6s, i still can generate a new block. for such two blocks from same miner at the same height, due to they have different parents, only the block with all parents will be accepted by the network.

@Fatman13
Copy link
Contributor

Fatman13 commented Sep 30, 2021

2 for some miner, they modify the PropagationDelaySecs to larger value then they can gather as many parents as possible
if any of the above case happens, then the block will be gathered after 6s by miner who is the winner of next round. if the miner use default PropagationDelaySecs=6s, and generate a block already, then its block will be think as orphan block due to the late parent.

This seems to be happening on the network all the time as pointed out by @moliujian in this thread on Slack.

Recap (according to the the claim from the thread):
On height 1151262, 6 miners have mined blocks from parent blocks coming in at 2021-09-28 23:50:30 and 2021-09-28 23:50:31. Then another parent coming in at 2021-09-28 23:50:54 which is 24 seconds late. While the 6 miners have propagation cutoff at 6s have already published their block, the other two miners have cutoff at longer than 24 s pick up the block coming in late, publish their mined block and orphan the blocks by the other 6 miner.

This creates incentive that miners set propagation cut off to a larger value to game the system.

@William8Work
Copy link

Found another orphan block last night (running version v1.13.0-rc2):

2021-10-10T00:38:19.886-0700    INFO    miner   miner/miner.go:569      mined new block {"cid": "bafy2bzacedsq5dhh3ryosynffryntjdvhjwdtui53reymbew7w6fcvxzwc4pg", "height": 1184836, "miner": "f08399", "parents": ["f0500003","f01218989","f0127595","f0724216","f061666","f0152337","f0755327"], "parentTipset": "{bafy2bzacechnbaxbfotrm6w2spqc4lmja5ijfr56cu4duosuiboo5cvub34cs,bafy2bzaceau3r7aa7fsxxmkmslckbpkc4eeinfhxum344bsb7gqd76ybelnrm,bafy2bzaceahxl6oftzbwkpjc2rkyj4kglmjjunbpn5pygbzwcnnw7hofmumk6,bafy2bzacecz6s2gk5b5uzctekb77a3vin5l7jimdkgg525gtevjut7nduye7o,bafy2bzacea6k7mzct2vgmmq5qzj3p5qrvirby2jq3osnp6ajiiqnei3ypz3gs,bafy2bzacebyu7btk3xi5sm2kx63qkafo62sliihgjkoltukiblczj7ibnz52c,bafy2bzaceamm7k52yrbmgxjroakqx2opi63nb7zlnvkrt3i36exumdoipfuma}", "took": 43.876861466}
2021-10-10T00:38:19.886-0700    WARN    miner   miner/miner.go:324      mined block in the past {"block-time": "2021-10-10T00:38:00.000-0700", "time": "2021-10-10T00:38:19.886-0700", "difference": 19.88698674}

@s0nik42
Copy link

s0nik42 commented Apr 19, 2022

Can you guys confirm if you have seen that block late? For now, it appears to be late on every nodes we checked, but still, been added to the tipset. (6 nodes operated by different miners)

grep bafy2bzacec7lzy7w2l3bki4pechede234e2g4xr4wqvhyn5spzkly6so23ywc /var/log/lotus/daemon.log
2022-04-19T07:48:43.246+0200	WARN	sub	sub/incoming.go:95	received block with large delay from miner	{"block": "bafy2bzacec7lzy7w2l3bki4pechede234e2g4xr4wqvhyn5spzkly6so23ywc", "delay": 13, "miner": "f01394448"}

@rjan90
Copy link
Contributor

rjan90 commented Sep 20, 2022

Hey everybody! 👋

Since the beginning of this thread it has been quite clear that one of the biggest reasons for "orphan blocks" has been that a new block from the parent tipset arrives after the storage provider already has started minting the block (after the 6 second propagation cutoff). WinningPoSt used to be a lot slower in the early days of the network (10-15s), and with the need of a good buffer for the tipset compute time (~10s) it was decided before mainnet that the PropagationDelay was to be set at 6 seconds.

Example of an ancient winningPoSt:

2020-07-28T08:48:01.582 INFO filecoin_proofs::api::post > generate_winning_post:start
2020-07-28T08:48:11.298 INFO filecoin_proofs::api::post > generate_winning_post:finish

Since that time we have seen significant improvements in the computation times for winningPoSt, as well as general lower rate of "orphan blocks". But SPs are still experiencing orphan blocks from time to time due to a parent block coming in late. After gathering newer block mining metrics, discussing potential solutions and getting confirmation from the researcher that changing this will be fine, we have decided to raise the default PropagationDelay to 10 seconds with this PR (coming in the v1.17.2 release).

We feel confident that all systems (even when computed on CPU) will still be able to compute winningPoSt comfortably within the required time. We have also added the ability to set the PropagationDelay yourself with the PROPAGATION_DELAY_SECS env variable to fine tune it to your setup. That said, raising this setting high only puts yourself in a position where you might be too slow to compute it.

Clearing up a misunderstanding

I also want to clear up some confusion about what the PropagationDelay actually does. PropagationDelaySecs isn't how long you wait to release the block, it's how long you wait for other blocks to arrive from the network; You'll still release the block exactly at epoch time, so there is no way to game the system by changing this value really high.

TL;DR: A block is released exactly at epoch time.

So all in all, the default PropagationDelay is raised from 6 seconds -> 10 seconds, and SPs can also fine tune this even further. We expect this to fix a lot of the remaining unwanted "orphan blocks" people are seeing, so therefore we are closing this issue. There may be events where there are hiccups in the physical internet network fabric, and a block is able to come in and be accepted right before the epoch ends. These events should be very rare, and unfortunately not something that Lotus can prevent.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/mining Area: Mining need/analysis Hint: Needs Analysis P2 P2: Should be resolved
Projects
None yet
Development

No branches or pull requests