Misleading log entry

Node Operators troubleshooting
1

Hi Awesome Alexey,

Please help me understand these lines

2024-08-28T14:00:17Z	WARN	collector	unable to delete piece	{"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Piece ID": "Q3OYAIYASRULOYQ745F7XNW7PFUKSGOUVVCYWWAEUOX6O7NB52IA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storagenode/blobstore/filestore.(*blobStore).Stat:124\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:340\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).DeleteWithStorageFormat:320\n\tstorj.io/storj/storagenode/pieces.(*Store).DeleteSkipV0:359\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:112\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:68\n\tstorj.io/common/sync2.(*Cycle).Run:99\n\tstorj.io/storj/storagenode/collector.(*Service).Run:64\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:51\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:78"}
2024-08-28T14:00:17Z	WARN	collector	unable to delete piece	{"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Piece ID": "DHN3ETASGX3YFLZISG7BF6MJEOHIJ24ONJRSNZ7E4EURAKJZ64EA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storagenode/blobstore/filestore.(*blobStore).Stat:124\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:340\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).DeleteWithStorageFormat:320\n\tstorj.io/storj/storagenode/pieces.(*Store).DeleteSkipV0:359\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:112\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:68\n\tstorj.io/common/sync2.(*Cycle).Run:99\n\tstorj.io/storj/storagenode/collector.(*Service).Run:64\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:51\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:78"}
2024-08-28T14:00:17Z	INFO	collector	no expired pieces to collect	{"Process": "storagenode"}
2024-08-28T14:00:17Z	INFO	collector	expired pieces collection completed	{"Process": "storagenode", "count": 4504}

Unable to delete is fairly common now. I copied them to give you an idea on what was before those “collect” lines.

I want you to look at the last 2 lines about no expired pieces then the next line says ... collection completed "count" : 4504".

This is totally contradicting the 2nd to last line about NO EXPIRED PIECES. If there are no expired pieces then what does 4504 denote ?

2

Hi!
It doesn’t mention for what satellite. I believe these are for different satellites, at least on this log level it’s impossible to connect this line to the satellite.

4

I don’t understand what you meant by having satellite id to identify.
This line :point_down:

2024-08-28T14:00:17Z INFO collector no expired pieces to collect {“Process”: “storagenode”}

suggests there are no expired pieces to collect while the next line shows it collected 4504 pieces.

2024-08-28T14:00:17Z INFO collector expired pieces collection completed {“Process”: “storagenode”, “count”: 4504}

How could it collect 4504 files when it mentions no expired pieces to collect ?

5

…for the some (unknown) satellite.
Not necessarily the same, which reported

The timing doesn’t matter, all these processes could be run in parallel.

6

It supposed to include deletion of multiple satellites.

Ignore this line:

2024-08-28T14:00:17Z	INFO	collector	no expired pieces to collect	{"Process": "storagenode"}

The second line is true.

Will be fixed here: https://review.dev.storj.io/c/storj/storj/+/14379

Also, I agree, the warnings are unnecessary / misleading:

https://review.dev.storj.io/c/storj/storj/+/14378

3 Likes