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

[shotcollin]

Discussed in #8399

This issue was turned into a discussion, but the discussion was immediately locked and didn't allow any comment, update, further discussion, etc. So I apologize for turning this back into an issue, but that was the only way to add this annotation:

I attempted to make the original issue clear in that it wasn't referring to my specific config error that caused the massive increase in log size, but rather the fact that any config error in general could (presumably) have a similar effect, which is writing a new log file line once every millisecond. In my case the line was a (640-character) warning, which would have caused the log to increase at a rate over 2 GiB per hour, and over 51 GiB per day (if my calculations are correct).

What makes this problematic and not simply an issue of operator error is that the log file increase didn't occur until hours after the config file was changed, meaning a SP could make a config change, assume the miner was running fine since no immediate errors or warnings were reported, then encounter a problem potentially hours later in which, if log files are being written to the OS drive, warning messages could cause significant log file expansion. This growth could be fast enough to fill up a drive before logrotate or some other automatic mitigation kicks in.

That being said, please of course feel free to turn this back into a discussion if more appropriate there.

^{Originally posted by shotcollin November 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 daemon - chain sync
• lotus miner - mining and block production
• lotus miner/worker - sealing
• lotus miner - proving(WindowPoSt)
• lotus miner/market - storage deal
• lotus miner/market - retrieval deal
• lotus miner/market - data transfer
• lotus client
• lotus JSON-RPC API
• lotus message management (mpool)
• Other

Lotus Version

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

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

[rjan90]

Hey @shotcollin!

Thanks for the detailed issue-report. I will try to reproduce it on a newer version as I know some kvlog / error-loops events have been fixed in the upcoming v1.15.1 release, see this PR: #8338.

[f8-ptrk]

#7003

[TippyFlitsUK]

Many apologies @shotcollin , the discussion was locked in error but is now open again for comment.

[shotcollin]

Many apologies @shotcollin , the discussion was locked in error but is now open again for comment.

No worries @TippyFlitsUK , I thought that was probably what happened, but then couldn't find a way to send a dm so figured this was the next best thing...