4 TB node has been full the past few months, still only 2.17 TBm storage paid

Sorry, I was wrong, it’s retain

Thank you for information. Hope it won’t take too long.

Not to come across like an ass but it sounds like quite a few of us are being short changed by having our payout values reported as less than what they actually are. That’s not so great to find out but at least I’m not the only one it is happening to.

2 Likes

so far 2 retain logs with lazyfilewalker on satellites US1 and EU1:

2023-06-24T21:03:05.631Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-06-20T11:59:59.942Z", "Filter Size": 3006, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:03:05.631Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:03:05.632Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:03:05.857Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "process": "storagenode"}
2023-06-24T21:03:05.857Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "createdBefore": "2023-06-20T11:59:59.942Z", "bloomFilterSize": 3006, "process": "storagenode"}
2023-06-24T21:35:49.324Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "process": "storagenode", "piecesCount": 3258248, "piecesSkippedCount": 0}
2023-06-24T21:35:49.327Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:35:49.327Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-06-27T06:08:26.388Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-06-21T11:59:59.989Z", "Filter Size": 2544, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T06:08:26.388Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T06:08:26.389Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T06:08:26.467Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode"}
2023-06-27T06:08:26.467Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode", "createdBefore": "2023-06-21T11:59:59.989Z", "bloomFilterSize": 2544}
2023-06-27T06:21:01.440Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode", "piecesCount": 10161776, "piecesSkippedCount": 0}
2023-06-27T06:21:01.445Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T06:21:01.445Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}

Still investigating farther.
earnings.py with DEBUG uncommented:

du --si -s :
103G 6r2fgwqz3manwt4aogq343bfkh2n5vvg4ohqqgggrrunaaaaaaaa
373G qstuylguhrn2ozjv4h2c6xpxykd622gtgurhql2k7k75wqaaaaaa
1.6G arej6usf33ki2kukzd5v6xgry2tdr56g45pp3aao6llsaaaaaaaa
1.9T ukfu6bhbboxilvt7jrwlqk7y2tapb5d2r2tsmj2sjxvw5qaaaaaa
119G pmw6tvzmf2jv6giyybmmvl4o2ahqlaldsaeha4yx74n5aaaaaaaa
2.7T v4weeab67sbgvnbwd5z7tweqsqqun7qox2agpbxy44mqqaaaaaaa

so far 5 “retains” in 6 days:

2023-06-24T21:39:38.479Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-06-20T11:59:59.942Z", "Filter Size": 3065, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:39:38.479Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:39:38.480Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:39:38.599Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "process": "storagenode"}
2023-06-24T21:39:38.600Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "createdBefore": "2023-06-20T11:59:59.942Z", "bloomFilterSize": 3065, "process": "storagenode"}
2023-06-24T21:46:18.071Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "process": "storagenode", "piecesCount": 3163488, "piecesSkippedCount": 0}
2023-06-24T21:46:18.077Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2023-06-24T21:46:18.077Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-06-27T05:39:23.445Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-06-21T11:59:59.989Z", "Filter Size": 1781, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T05:39:23.445Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T05:39:23.445Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T05:39:23.542Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode"}
2023-06-27T05:39:23.542Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode", "createdBefore": "2023-06-21T11:59:59.989Z", "bloomFilterSize": 1781}
2023-06-27T05:54:02.191Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "process": "storagenode", "piecesCount": 9183327, "piecesSkippedCount": 0}
2023-06-27T05:54:02.197Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2023-06-27T05:54:02.197Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-06-28T19:12:56.555Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-01-22T20:31:29.101Z", "Filter Size": 152, "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-28T19:12:56.555Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-28T19:12:56.556Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-28T19:12:56.657Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode"}
2023-06-28T19:12:56.657Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode", "createdBefore": "2023-01-22T20:31:29.101Z", "bloomFilterSize": 152}
2023-06-28T19:12:59.374Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode", "piecesCount": 93265, "piecesSkippedCount": 0}
2023-06-28T19:12:59.378Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-28T19:12:59.378Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-06-28T22:09:06.413Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-06-21T14:57:18.932Z", "Filter Size": 7, "Satellite ID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2023-06-28T22:09:06.413Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2023-06-28T22:09:06.413Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2023-06-28T22:09:06.432Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "process": "storagenode"}
2023-06-28T22:09:06.432Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "process": "storagenode", "createdBefore": "2023-06-21T14:57:18.932Z", "bloomFilterSize": 7}
2023-06-28T22:09:07.079Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "piecesSkippedCount": 0, "process": "storagenode", "piecesCount": 14887}
2023-06-28T22:09:07.082Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2023-06-28T22:09:07.082Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-06-29T06:20:03.454Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-01-22T20:31:29.101Z", "Filter Size": 152, "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-29T06:20:03.455Z        INFO    lazyfilewalker.gc-filewalker    starting subprocess     {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-29T06:20:03.455Z        INFO    lazyfilewalker.gc-filewalker    subprocess started      {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-29T06:20:03.509Z        INFO    lazyfilewalker.gc-filewalker.subprocess Database started        {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode"}
2023-06-29T06:20:03.509Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker started   {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode", "createdBefore": "2023-01-22T20:31:29.101Z", "bloomFilterSize": 152}
2023-06-29T06:20:06.287Z        INFO    lazyfilewalker.gc-filewalker.subprocess gc-filewalker completed {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "process": "storagenode", "piecesCount": 93694, "piecesSkippedCount": 0}
2023-06-29T06:20:06.291Z        INFO    lazyfilewalker.gc-filewalker    subprocess finished successfully        {"process": "storagenode", "satelliteID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-06-29T06:20:06.291Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}

Perhaps it need to come through several bloom filters, but the difference is noticeable.

Thanks everyone for the log lines. They really helped in figuring out what might be going on.

So, garbage collection works by the satellite generating a bloom filter and sending it to the nodes. The nodes then walk every piece and delete any that aren’t part of the filter. Bloom filters are nice because they can be much much smaller than the full set of valid pieces but come with the potential for false positives. In order to limit the false positive rate, the filters are sized based on how many entries are expected to be added. If the size is too small, the false positive rate will approach 100% and no pieces will be deleted. Recently, we had a bug where the satellite doesn’t estimate the number of pieces on the node well and so it sizes the bloom filter too small. That bug should be fixed by this change which is not yet deployed, but should be soon.

I’ll try to keep an eye on the deployment and update this thread when it happens.

12 Likes

I found that it will be in 1.83 only.

I don’t really understand how normal customer deletes could have been delegated to garbage collection while this issue has not been resolved. Looking at my nodes, I already have many TB of garbage on my HDDs now and this is only growing since even normal customer delete operations no longer lead to a regular piece deletion on nodes since the recent change.
I encourage you to keep better track of dependencies. I don’t think that change should have gone live prior to resolving this.
That said, I hope to see this fix go live soon.

Edit: Referring to this: Design draft: fixing deletes and server side copy

2 Likes

So, the change to turn off GC went out on 6/26, and we only put together that this problem was happening because of GC on 6/30. Unfortunate!

That said, I didn’t think the piece count problem was very widespread among nodes, but looking at the database it does seem to be a large fraction. I should have done the diligence to check that earlier. Thanks for bringing it up.

We’re current brainstorming some ideas for stop-gap measures before the deploy, and I’ll update if we end up with something.

update: One time update of node piece counts · Issue #6025 · storj/storj · GitHub is tracking the temporary fix before the permanent fix is deployed.

4 Likes

Apologies. I noticed the issue linked in the change you posted was from back in April and thought it was a known issue since then. I understand now that this resulting impact wasn’t known until much later.

Please keep in mind that last time large GC runs were triggered, many nodes had a lot of trouble keeping up due to the high IO load. I fear this time they may be even bigger.

2 Likes

Since the last update it seems it’s starting to correct, no ingress, but the Average disk Space is growing. No thrashing though.
I’ll report if this trend continues.

The last day reported on that graph is unfortunately inaccurate. I haven’t seen any new GC runs yet, so I doubt anything has actually changed.

ill keep track of it the upcoming days

I hit a good GC:

2023-07-07T23:43:22.982Z INFO retain Prepared to run a Retain request. {“process”: “storagenode”, “Created Before”: “2023-07-04T15:00:09.006Z”, “Filter Size”: 597951, “Satellite ID”: “121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6”}
2023-07-07T23:47:38.876Z INFO retain Moved pieces to trash during retain {“process”: “storagenode”, “num deleted”: 243206, “Retain Status”: “enabled”}

Hope i hit a few more of those.

The higher average of yesterday didn’t hold though. As BrightSilence already mentioned.

graph:

I also hit a good GC:

2023-07-06T22:00:42.142Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2021-01-30T02:33:55.130Z", "Filter Size": 597951, "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2023-07-06T22:02:24.695Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-07-07T10:46:16.236Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-07-03T11:59:59.912Z", "Filter Size": 229, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2023-07-07T10:47:35.624Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 0, "Retain Status": "enabled"}
2023-07-07T23:50:59.064Z        INFO    retain  Prepared to run a Retain request.       {"process": "storagenode", "Created Before": "2023-07-04T15:00:09.006Z", "Filter Size": 597951, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2023-07-07T23:56:44.193Z        INFO    retain  Moved pieces to trash during retain     {"process": "storagenode", "num deleted": 368116, "Retain Status": "enabled"}

2nd retain hit:

2023-07-10T15:36:24.994Z INFO retain Prepared to run a Retain request. {“process”: “storagenode”, “Created Before”: “2023-07-06T05:59:59.833Z”, “Filter Size”: 597951, “Satellite ID”: “12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs”}
2023-07-10T15:55:14.437Z INFO retain Moved pieces to trash during retain {“process”: “storagenode”, “num deleted”: 1078438, “Retain Status”: “enabled”}

resulting in:

this is going the right way, hope it helps you Zeebo to confirm this was a good fix. I will report in a month or so to tell the delta between average and total diskspace when enough of those retains have been done.

Same for me. Glad we have a fix.

oh no…

This is only partially because of the bug being resolved. Don’t forget they are also removing data for the 2 test satellites being shut down. Which is now also handled by GC.

1 Like