Config file mistake causes miner log file to grow to 2GB in 90 min #8399

shotcollin · 2021-11-05T06:59:02Z

shotcollin
Nov 5, 2021

Checklist

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

Lotus component

Lotus Version

Daemon:  1.13.0+mainnet+git.7a55e8e89+api1.2.0
Local: lotus-miner version 1.13.0+mainnet+git.7a55e8e89

Describe the Bug

While changing the miner's config.toml file, I duplicated a line in order to update the variable's value and retain the original value for reference, but I neglected to comment out the original line, i.e. the file looked like this:

...
  # env var: LOTUS_STORAGE_RESOURCEFILTERING
  ResourceFiltering = "disabled"
  ResourceFiltering = "hardware"
...

The miner started as usual and ran normally for over four hours. It then began to generate errors related to the duplicate line at a rate of almost one per microsecond, which seems excessive.

2021-11-05T04:21:01.631Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.632Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.636Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.637Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.639Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.640Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.641Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.642Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.643Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.644Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.645Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}

I had the log file open in a viewer, but it was no longer updating because it had crashed due to the file size, which obviates the log file's purpose. Had I not noticed this fairly quickly, it would have eventually crashed the miner because when allocating space I didn't anticipate multi-gigabyte log files.

This "bug" is admittedly caused in part by operator error, but I'm submitting as a bug since there's probably a more ideal way to deal with such errors.

Also, as a side note, I'm using logrotate to prevent system problems caused by rapidly expanding log files, but it doesn't/can't force applications to release their log files when they're rotated. If they're not released, it can't compress the log files until the subsequent rotation. This means that logrotate will create a new log file for the miner when the current one exceeds some preset limit, but until the miner is restarted it continues to write to the old log file. So in this case, the log files looked like this, and the miner.log-20211105 would have continued to be written to by the miner until a restart.

-rw-rw-r--  1 user user       0 Nov  5 05:45 miner.log
-rw-rw-r--  1 user user   1015K Oct 31 11:38 miner.log-20211031.gz
-rw-rw-r--  1 user user    849K Nov  3 06:01 miner.log-20211103.gz
-rw-rw-r--  1 user user    1.9G Nov  5 05:58 miner.log-20211105

Previously this was a minor annoyance but I realize now it might have more serious consequences if there are other situations that cause the log files to grow rapidly. I don't know if there's anyway to program the miner so that when logrotate or a similar application makes a new log file the miner would immediately begin writing to that file, but if so it would be much appreciated.

Logging Information

2021-11-05T04:01:33.991Z	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 1 queued; 10 open windows
2021-11-05T04:01:34.000Z	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:[]}]
2021-11-05T04:01:34.000Z	DEBUG	advmgr	sector-storage/sched.go:450	SCHED Acceptable win: [[5 7 8 9]]
2021-11-05T04:01:34.000Z	DEBUG	advmgr	sector-storage/sched.go:465	SCHED try assign sqi:0 sector 619 to window 5
2021-11-05T04:01:34.000Z	DEBUG	advmgr	sector-storage/sched.go:472	SCHED ASSIGNED sqi:0 sector 619 task seal/v0/precommit/2 to window 5
2021-11-05T04:01:34.000Z	DEBUG	advmgr	sector-storage/sched_resources.go:71	sched: not scheduling on worker be87292c-489e-4fa6-9995-691728341bc3 for startPreparing; not enough threads, need 44, 44 in use, target 48
2021-11-05T04:01:36.393Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 13, "forRound": 1259284, "baseEpoch": 1259283, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182577518296236032", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:02:06.020Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 13, "forRound": 1259285, "baseEpoch": 1259284, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182577518296236032", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:02:36.197Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 13, "forRound": 1259286, "baseEpoch": 1259285, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182590952953937920", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:03:06.105Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 94, "forRound": 1259287, "baseEpoch": 1259286, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182590952953937920", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:03:36.397Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259288, "baseEpoch": 1259287, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182590952953937920", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:04:06.028Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 21, "forRound": 1259289, "baseEpoch": 1259288, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182590952953937920", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:04:36.093Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 15, "forRound": 1259290, "baseEpoch": 1259289, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182613094236291072", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:05:06.414Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259291, "baseEpoch": 1259290, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182614331186872320", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:05:36.015Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 11, "forRound": 1259292, "baseEpoch": 1259291, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182614331186872320", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:06:06.160Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 19, "forRound": 1259293, "baseEpoch": 1259292, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182614296827133952", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:06:36.405Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 7, "forRound": 1259294, "baseEpoch": 1259293, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182614296827133952", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:07:06.028Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 17, "forRound": 1259295, "baseEpoch": 1259294, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182614296827133952", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:07:36.083Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 15, "forRound": 1259296, "baseEpoch": 1259295, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182692740109828096", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:08:06.024Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259297, "baseEpoch": 1259296, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182694355017531392", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:08:36.118Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 101, "forRound": 1259298, "baseEpoch": 1259297, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182700677209391104", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:09:06.224Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 218, "forRound": 1259299, "baseEpoch": 1259298, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182700677209391104", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:09:36.363Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 12, "forRound": 1259300, "baseEpoch": 1259299, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182723457715929088", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:10:06.588Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 105, "forRound": 1259301, "baseEpoch": 1259300, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182723766953574400", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:10:36.021Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259302, "baseEpoch": 1259301, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182739812951392256", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:11:06.491Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259303, "baseEpoch": 1259302, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182739812951392256", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:11:36.023Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259304, "baseEpoch": 1259303, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182764586322755584", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:12:06.339Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259305, "baseEpoch": 1259304, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182781937990631424", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:12:36.388Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 15, "forRound": 1259306, "baseEpoch": 1259305, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182781937990631424", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:13:06.382Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 376, "forRound": 1259307, "baseEpoch": 1259305, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:13:12.552Z	DEBUG	advmgr	sector-storage/sched_worker.go:278	task done	{"workerid": "71ab7ee7-a36e-466c-b0b3-932f4c86e996"}
2021-11-05T04:13:12.552Z	DEBUG	advmgr	sector-storage/sched.go:354	SCHED 0 queued; 9 open windows
2021-11-05T04:13:36.026Z	WARN	miner	miner/miner.go:477	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259307, "baseEpoch": 1259306, "baseDeltaSeconds": 36, "nullRounds": 0, "lateStart": true, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:13:36.038Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 8, "forRound": 1259308, "baseEpoch": 1259306, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:14:06.028Z	WARN	miner	miner/miner.go:477	completed mineOne	{"tookMilliseconds": 17, "forRound": 1259308, "baseEpoch": 1259307, "baseDeltaSeconds": 36, "nullRounds": 0, "lateStart": true, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:14:06.042Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 8, "forRound": 1259309, "baseEpoch": 1259307, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:14:36.028Z	WARN	miner	miner/miner.go:477	completed mineOne	{"tookMilliseconds": 17, "forRound": 1259309, "baseEpoch": 1259308, "baseDeltaSeconds": 36, "nullRounds": 0, "lateStart": true, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:14:36.044Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 9, "forRound": 1259310, "baseEpoch": 1259308, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:15:06.162Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 107, "forRound": 1259311, "baseEpoch": 1259310, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:15:36.496Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 15, "forRound": 1259312, "baseEpoch": 1259311, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:16:06.202Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259313, "baseEpoch": 1259312, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787744786415616", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:16:36.021Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259314, "baseEpoch": 1259313, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787710426677248", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:17:06.023Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 16, "forRound": 1259315, "baseEpoch": 1259314, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182787710426677248", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:17:36.112Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 105, "forRound": 1259316, "baseEpoch": 1259315, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182790493565485056", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:18:06.424Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 13, "forRound": 1259317, "baseEpoch": 1259316, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182792142832926720", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:18:36.060Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 54, "forRound": 1259318, "baseEpoch": 1259316, "baseDeltaSeconds": 36, "nullRounds": 1, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182792142832926720", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:19:06.082Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 15, "forRound": 1259319, "baseEpoch": 1259318, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182935079344537600", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:19:36.397Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259320, "baseEpoch": 1259319, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182935079344537600", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:20:06.023Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 18, "forRound": 1259321, "baseEpoch": 1259320, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182935044984799232", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:20:36.020Z	INFO	miner	miner/miner.go:479	completed mineOne	{"tookMilliseconds": 14, "forRound": 1259322, "baseEpoch": 1259321, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "15182935354222444544", "minerPowerAtLookback": "446676598784", "isEligible": false, "isWinner": false, "error": null}
2021-11-05T04:21:01.631Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.632Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.636Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.637Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.639Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.640Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.641Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.642Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.643Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.644Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.645Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.646Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.647Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.648Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.650Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.651Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.652Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.653Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.654Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.655Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.656Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.657Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.658Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.659Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.660Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}
2021-11-05T04:21:01.661Z	WARN	sectors	storage-sealing/terminate_batch.go:86	TerminateBatcher getconfig error	{"error": "Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined."}
2021-11-05T04:21:01.662Z	WARN	sectors	storage-sealing/terminate_batch.go:104	TerminateBatcher processBatch error	{"error": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.)", "errorVerbose": "getting sealing config: %!W(toml.parseError=Near line 411 (last key parsed 'Storage.ResourceFiltering'): Key 'Storage.ResourceFiltering' has already been defined.):\n    github.com/filecoin-project/lotus/extern/storage-sealing.(*TerminateBatcher).processBatch\n        /home/user/lotus/extern/storage-sealing/terminate_batch.go:117"}

Repo Steps

Modify the config file to include two lines specifying a value for the same variable.
Run the miner.
When the miner at some point reads the portion of the file with the duplicate variable, it will create a rapidly expanding log file.

shotcollin · 2021-11-05T07:53:02Z

shotcollin
Nov 5, 2021
Author

Attached is the full (compressed) log file.
miner.log-20211105.gz

0 replies

TippyFlitsUK · 2022-03-29T16:16:00Z

TippyFlitsUK
Mar 29, 2022
Maintainer

Hi @shotcollin

Thank you for taking the time to provide detailed information and logs.

As this issue was the result of the config error that you kindly documented, I am moving the this ticket to discussions for better visibilty.

Many thanks!

0 replies

TippyFlitsUK · 2022-03-31T19:57:42Z

TippyFlitsUK
Mar 31, 2022
Maintainer

Also referenced in #8405

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Config file mistake causes miner log file to grow to 2GB in 90 min #8399

Uh oh!

{{title}}

Uh oh!

Replies: 3 comments

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Config file mistake causes miner log file to grow to 2GB in 90 min #8399

Uh oh!

shotcollin Nov 5, 2021

Checklist

Lotus component

Lotus Version

Describe the Bug

Logging Information

Repo Steps

Replies: 3 comments

Uh oh!

shotcollin Nov 5, 2021 Author

Uh oh!

TippyFlitsUK Mar 29, 2022 Maintainer

Uh oh!

TippyFlitsUK Mar 31, 2022 Maintainer

shotcollin
Nov 5, 2021

shotcollin
Nov 5, 2021
Author

TippyFlitsUK
Mar 29, 2022
Maintainer

TippyFlitsUK
Mar 31, 2022
Maintainer