Bloom dont work or why my trash is empty?

I have one running 1.100.4 for about 6 days now with lazy turned off and that one completed GC successfully. Thus it looks like the issue probably is related to lazy filewalker.

# zgrep retain /var/log/storj.log-20240331.gz 
2024-03-30T03:58:34Z    INFO    retain  Moved pieces to trash during retain     {"Process": "storagenode", "Deleted pieces": 1335072, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 20709305, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Duration": "3h5m41.628286904s", "Retain Status": "enabled"}

# zgrep retain /var/log/storj.log-20240401.gz 
2024-03-31T04:39:25Z    INFO    retain  Prepared to run a Retain request.       {"Process": "storagenode", "Created Before": "2024-03-26T17:59:59Z", "Filter Size": 1853621, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-03-31T05:13:51Z    INFO    retain  Moved pieces to trash during retain     {"Process": "storagenode", "Deleted pieces": 650985, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 3886994, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Duration": "34m25.7063439s", "Retain Status": "enabled"}

# storage/trash/v4weeab67sbgvnbwd5z7tweqsqqun7qox2agpbxy44mqqaaaaaaa # ls -la
total 60
drwx------    4 storj storj  4096 Mar 31 04:39 .
drwxr-xr-x    6 storj storj  4096 Mar 26 13:36 ..
drwxr-xr-x 1026 storj storj 20480 Jan 24 21:29 2024-03-26
drwx------ 1026 storj storj 28672 Mar 31 05:13 2024-03-31

# storagenode version
2024-04-01T12:06:54Z    INFO    Anonymized tracing enabled      {"Process": "storagenode"}
Release build
Version: v1.100.4
Build timestamp: 19 Mar 24 09:37 UTC
Git commit: 8e38bd71fb047b9cb00149fd90bb5f94ff21d9aa
1 Like

I donā€™t have an issue with lazy on 1.100.3, but, I donā€™t see any pieces in the trash:

Apr 01 01:10:00 50 storagenode[49658]: 2024-04-01T01:10:00Z        INFO        lazyfilewalker.used-space-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Apr 01 01:10:00 50 storagenode[49658]: 2024-04-01T01:10:00Z        INFO        lazyfilewalker.used-space-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Apr 01 01:10:00 50 storagenode[49658]: 2024-04-01T01:10:00Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
Apr 01 01:10:00 50 storagenode[49658]: 2024-04-01T01:10:00Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker completed        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode", "piecesTotal": 7665259106304, "piecesContentSize": 7660071269376}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
Apr 01 01:27:55 50 storagenode[49658]: 2024-04-01T01:27:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker completed        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "piecesTotal": 9227589394632, "piecesContentSize": 9197398841544}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
Apr 01 02:05:55 50 storagenode[49658]: 2024-04-01T02:05:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker started        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker completed        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode", "piecesTotal": 2187546420736, "piecesContentSize": 2185497425408}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Process": "storagenode"}
Apr 01 02:10:55 50 storagenode[49658]: 2024-04-01T02:10:55Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker started        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Process": "storagenode"}
Apr 01 02:12:53 50 storagenode[49658]: 2024-04-01T02:12:53Z        INFO        lazyfilewalker.used-space-filewalker.subprocess        used-space-filewalker completed        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "piecesContentSize": 5244915601664, "Process": "storagenode", "piecesTotal": 5246237338880}
Apr 01 02:12:53 50 storagenode[49658]: 2024-04-01T02:12:53Z        INFO        lazyfilewalker.used-space-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}

Same on 1.100.3:

Mar 28 20:22:38 50 storagenode[11975]: 2024-03-28T20:22:38Z        INFO        retain        Prepared to run a Retain request.        {"Process": "storagenode", "Created Before": "2024-02-17T13:02:55Z", "Filter Size": 1542276, "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
Mar 28 20:23:18 50 storagenode[11975]: 2024-03-28T20:23:18Z        INFO        retain        Moved pieces to trash during retain        {"Process": "storagenode", "Deleted pieces": 0, "Failed to delete": 1, "Pieces failed to read": 0, "Pieces count": 0, "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Duration": "40.075522015s", "Retain Status": "enabled"}
Mar 29 10:31:10 50 storagenode[11975]: 2024-03-29T10:31:10Z        INFO        retain        Prepared to run a Retain request.        {"Process": "storagenode", "Created Before": "2024-03-25T17:59:59Z", "Filter Size": 2259125, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
Mar 29 10:33:00 50 storagenode[11975]: 2024-03-29T10:33:00Z        INFO        retain        Moved pieces to trash during retain        {"Process": "storagenode", "Deleted pieces": 0, "Failed to delete": 1, "Pieces failed to read": 0, "Pieces count": 0, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Duration": "1m50.782061415s", "Retain Status": "enabled"}
Mar 30 05:12:07 50 storagenode[11975]: 2024-03-30T05:12:07Z        INFO        retain        Prepared to run a Retain request.        {"Process": "storagenode", "Created Before": "2024-03-20T17:59:59Z", "Filter Size": 4100003, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Mar 30 05:30:27 50 storagenode[11975]: 2024-03-30T05:30:27Z        INFO        retain        Moved pieces to trash during retain        {"Process": "storagenode", "Deleted pieces": 0, "Failed to delete": 1, "Pieces failed to read": 0, "Pieces count": 0, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Duration": "18m20.586486099s", "Retain Status": "enabled"}
Mar 31 04:00:10 50 storagenode[11975]: 2024-03-31T04:00:10Z        INFO        retain        Prepared to run a Retain request.        {"Process": "storagenode", "Created Before": "2024-03-26T17:59:59Z", "Filter Size": 4100003, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Mar 31 04:07:20 50 storagenode[11975]: 2024-03-31T04:07:20Z        INFO        retain        Moved pieces to trash during retain        {"Process": "storagenode", "Deleted pieces": 0, "Failed to delete": 1, "Pieces failed to read": 0, "Pieces count": 0, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Duration": "7m9.71297575s", "Retain Status": "enabled"}

Is that a single IP? You must be in a popular storj location. Iā€™ve been able to get about 25TB on a single IP, and the nodes are as old as this they can be.

Since the latest version iā€™m seeing 1.8TB pending deletion. My Theory is that abandoned free accounts maybe are getting data cleared?

Hi, i have 5 location in Italy with 2 ip on 2 subnet every location. I have 30 nodes. I have nodes from 4 years but 5 nodes are new. I suppose that any free account have deleted its files. I am a client for storj but i donā€™t deleted my 1Tb of backup that itā€™s update every 1 week

2 Likes

Very cool! Nice dedication to the project. I didnā€™t realize we could combine all nodes in a single consolidated graph in the dashboard. Must be something I missed along the way.

I have problem with this node - the amount of garbage is not decreasing at all and is still increasing.
Node from screenshot is about 6 months old, about a month ago trash size increased very fast to over 900GB, I thought ā€˜okay, this will decrease in week or 2ā€™ I was waiting, but nothing happened. Now I can see that other nodes have trash increase, over 1.5TB in one day on 2nd node, and new 300GB to this node trash - that is something else, but how long it takes for trash to empty itself, again, itā€™s old (nearly 1 month) 1TB trash being frozen. With this rate there will be disk full only of trash.

Look like increasing bloom filter size to 410003 is not enough for big old nodes:

Mar 30 05:12:07 50 storagenode[11975]: 2024-03-30T05:12:07Z        INFO        lazyfilewalker.gc-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Mar 30 05:12:07 50 storagenode[11975]: 2024-03-30T05:12:07Z        INFO        lazyfilewalker.gc-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Mar 30 05:12:07 50 storagenode[11975]: 2024-03-30T05:12:07Z        INFO        lazyfilewalker.gc-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
Mar 30 05:12:07 50 storagenode[11975]: 2024-03-30T05:12:07Z        INFO        lazyfilewalker.gc-filewalker.subprocess        gc-filewalker started        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "createdBefore": "2024-03-20T17:59:59Z", "bloomFilterSize": 4100003}
Mar 30 05:30:26 50 storagenode[11975]: 2024-03-30T05:30:26Z        INFO        lazyfilewalker.gc-filewalker.subprocess        gc-filewalker completed        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "piecesCount": 58447240, "piecesSkippedCount": 0}
Mar 30 05:30:27 50 storagenode[11975]: 2024-03-30T05:30:27Z        INFO        lazyfilewalker.gc-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Mar 31 04:00:10 50 storagenode[11975]: 2024-03-31T04:00:10Z        INFO        lazyfilewalker.gc-filewalker        starting subprocess        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Mar 31 04:00:10 50 storagenode[11975]: 2024-03-31T04:00:10Z        INFO        lazyfilewalker.gc-filewalker        subprocess started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
Mar 31 04:00:10 50 storagenode[11975]: 2024-03-31T04:00:10Z        INFO        lazyfilewalker.gc-filewalker.subprocess        Database started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
Mar 31 04:00:10 50 storagenode[11975]: 2024-03-31T04:00:10Z        INFO        lazyfilewalker.gc-filewalker.subprocess        gc-filewalker started        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode", "createdBefore": "2024-03-26T17:59:59Z", "bloomFilterSize": 4100003}
Mar 31 04:07:19 50 storagenode[11975]: 2024-03-31T04:07:19Z        INFO        lazyfilewalker.gc-filewalker.subprocess        gc-filewalker completed        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode", "piecesCount": 10097877, "piecesSkippedCount": 0}
Mar 31 04:07:20 50 storagenode[11975]: 2024-03-31T04:07:20Z        INFO        lazyfilewalker.gc-filewalker        subprocess finished successfully        {"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}

For now delta between paid and unpaid storage only on one node is about 5Tb :face_with_symbols_over_mouth:

Total count of pieces stored on this node:

find /opt/storj/data/storage/blobs/ -type f -name "*.sj1" | wc -l
76451028

1 Like

Itā€™s not perfect, but based on simulation it will help over the time. Bigger bloom filters will be supported, but first all SN should pick up that changeā€¦ (and there are other limitations, itā€™s slow to calculate very big BFs)

2 Likes

For the record. The mechanism is not changed. We have new protocol which is not used. We are waiting until everybody will get the new version. Probably after half year we can start to use itā€¦

3 Likes

Here is one of mine:

The node has online score 99,99%-100%.

And the question is, how can both values be correct?

5 Likes

2nd question is:
why numbers on left is always smaller?

And 3rd question is:
which side is used to calculate SNOs payouts?

1 Like

The left side is information from sat - itā€™s used for payout,
the right side is calculated information (from jour local side), and here is actual disk usage.

2 Likes

Left side - without deleted pieces; right side - with pieces-to-be-deleted aka sent to trash.

2 Likes

To be honest none is correct.
The left side is what they want to pay to you and the right side is what you should be paid for.
I do not care if their software could hickup and they do want to keep the trash because of that.
If they want to keep it then they will have to pay for it.
I also do not care about all the promises about new versions, new bloom filtersā€¦
Every new version did mess it up even more. Now GC will not even be triggered anymore.
And at least i am sitting on 40% garbage in the meantime that is not recognized as it.
On one of my nodes i have 4.35TB used and trash is 0. I am paid for 2.87TB.

I assume we will get this difference paid in full + a bonus for keeping their serving up and of course a big apology!

2 Likes

Thatā€™s not entirely correct. Iā€™ll explain how it works (TLDR; It works as expected):

  1. At the first of the month you check your node and you see that both left and right show 0 bytes used. Nobody uploaded anything to your node.
  2. On the 15th of the month, your node is suddenly popular. It managed to receive 10TB in a single day!
  3. On the 30th of the month you check your dashboard. Right side shows 10TB used, left side shows 5TB used. You now wonder where the other 5TB went.
  4. The left side shows average usage. Your average usage is 10TB/0.5 month = 5TB/m (or 5TBm). The right side shows ā€œcurrentā€ usage. Thatā€™s why the two values will never be equal. Your node is constantly receiving data and data is constantly deleted.
2 Likes

On the jammerdan screen the right side starts at 7.4Tb, the left side at 10.8Tb, in the trash there are 280Gb. Something doesnā€™t add up. It seems to me that 3TB is missing from the count. Why doesnā€™t the right side show 10.8TB after a day has passed? Shouldā€¦

I know how the calculation works.
My node was limited on purpose to 4.35TB and it stayed at 4.35TB used for the whole month. So no excuse there.

On a bigger nodes, due to bloom filter transfer size limitation at the moment, it will take multiple passes to move most of the deleted data to trash. As these are distributed weekly I believe, it will take multiple weeks to clear what needs to be cleared.
Then you might have some issues distributing or calculating these filters, you might have a node update in the middle of the garbage run, you might be running a version that has these cleanups broken, and all these issues are causing these discrepancies to be more obvious.
There are improvements in works for some time now, some were deployed already, so we just have to be patient and it will eventually be all fixed, hopefully :slight_smile:.

4 Likes

Because itā€™s not based on what was the usage yesterday vs what is the use today. As I have explained, it is averaged over the month. The same way it averages up, it also averages down if data is deleted. In order for the two values to be exactly the same or very close to each other, that would mean that all data was uploaded on the first day of the month (assuming an infinite download speed, if it takes a whole day to upload them, that means that itā€™s not ā€œfull for entire monthā€) and nothing would be added or deleted to the node.

Those 3TB could be the weekly average that will be added next month (assuming no other data is deleted, which it will). It should match (edit:where match=close to each other, not exactly the same) if the node is full for a while. For example, see below:

3 Likes