search

filecoin-project / lotus

Reference implementation of the Filecoin protocol, written in Go
https://lotus.filecoin.io/
Other
2.84k stars 1.26k forks source link

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

Open shotcollin opened 2 years ago

shotcollin commented 2 years ago

Discussed in https://github.com/filecoin-project/lotus/discussions/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 - [X] This is **not** a security-related bug/issue. If it is, please follow please follow the [security policy](https://github.com/filecoin-project/lotus/security/policy). - [X] This is **not** a question or a support request. If you have any lotus related questions, please ask in the [lotus forum](https://github.com/filecoin-project/lotus/discussions). - [X] This is **not** a new feature request. If it is, please file a [feature request](https://github.com/filecoin-project/lotus/issues/new?assignees=&labels=need%2Ftriage%2Ckind%2Ffeature&template=feature_request.yml) instead. - [X] This is **not** an enhancement request. If it is, please file a [improvement suggestion](https://github.com/filecoin-project/lotus/issues/new?assignees=&labels=need%2Ftriage%2Ckind%2Fenhancement&template=enhancement.yml) instead. - [X] I **have** searched on the [issue tracker](https://github.com/filecoin-project/lotus/issues) and the [lotus forum](https://github.com/filecoin-project/lotus/discussions), and there is no existing related issue or discussion. - [X] I am running the [`Latest release`](https://github.com/filecoin-project/lotus/releases), 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. - [X] I did not make any code changes to lotus. ### Lotus component - [ ] lotus daemon - chain sync - [ ] lotus miner - mining and block production - [X] 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 ```text 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 ```text 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:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} 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 commented 2 years ago

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 commented 2 years ago

https://github.com/filecoin-project/lotus/issues/7003

TippyFlitsUK commented 2 years ago

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

shotcollin commented 2 years ago

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...