Misleading log entry

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 ?

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.

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 ?

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

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

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