137 ERROR delete piece failed (consistently)

tachyontec · September 19, 2022, 9:41am

Hello guys,

After being here for couple of months now I have read about some serious issues with SNO’s so mine maybe won’t be that important but i still think i have to mention it.

After a reboot due to power outage, every XX:36:12 on all hours i am receiving on my emails 127 errors, thanks to my script here , which are all the same ERROR collector unable to delete piece.

This issue seems resolved because people from here (@fmoledina ) and here @BrightSilence mentioned a manual solution to delete each piece from blobs folders.

***ps: i don’t blame any of you guys and thanks for your contributions here on the community

But in my case i have 127 different piece ids which actually come from the same 3 satellites as you can see here: (piece is the file i copied errors to)

~$ wc -l piece
137 piece
~$ grep "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S" piece |wc -l
12
~$ grep "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6" piece |wc -l
7
~$ grep "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs" piece |wc -l
118

and we can see the consistency here: (for one of all the pieces)

$ docker logs storagenode --tail 20000 2>&1 |grep 5EV5I6FVZUCPNUBZ4K65ARKFU2G3ZWYZVRBNOI3M3JUITUIQHXFQ
2022-09-19T06:36:12.916Z	ERROR	collector	unable to delete piece	{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "5EV5I6FVZUCPNUBZ4K65ARKFU2G3ZWYZVRBNOI3M3JUITUIQHXFQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:245\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:226\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:160\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2022-09-19T07:36:15.636Z	ERROR	collector	unable to delete piece	{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "5EV5I6FVZUCPNUBZ4K65ARKFU2G3ZWYZVRBNOI3M3JUITUIQHXFQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:245\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:226\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:160\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2022-09-19T08:36:12.705Z	ERROR	collector	unable to delete piece	{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "5EV5I6FVZUCPNUBZ4K65ARKFU2G3ZWYZVRBNOI3M3JUITUIQHXFQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:245\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:226\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:160\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

I am also aware of this post pointing out here in an issue which is marked as completed for some reason but to be honest i don’t even really understand what i am watching there. ( it is actually an infinity loop between one post in forum and one in github where one points to another for the solution)

I could spent an hour of my life deleting manually all the files, or maybe again one hour to create another script which will take all the pieces id’s from the logs and touch the relevant files to satisfy the collector but i wonder if there is any other solution out there which will get us out of this hustle.

Issue seems solved 4 days ago in some other post but my node is fully updated and i don’t see any solution.
My thought: why don’t the collector just stop trying to delete the piece from the first time it tries? Could the old deleted piece be recreated or sth?

donald.m.motsinger · September 19, 2022, 10:27am

In one of the threads you mentioned I posted as bash script which gets the pieces from the log and creates the missing files as empty files

If you prefer a Powershell script, look at the post above.

tachyontec · September 19, 2022, 10:41am

Thanks
This is simmilar to what i have been thinking to do. Sorry i didn’t see it it was just a huge thread and i didn’t look all of it except the marked solution answer and some of the first posts.

I will wait in case i can help the team to create a more general solution to the problem were SNO’S doesn’t have to do anything like that (which is ideal of course), but otherwise i will run this

BrightSilence · September 19, 2022, 11:18am

This usually means there will be a change in the next release. There does seem to be a related change here for v1.64. However, that’s a partial change that won’t fix the underlying issue.

github.com/storj/storj

storagenode/collector: fix error check when file does not exist

committed 12:26PM - 02 Sep 22 UTC

profclems

+2 -2

The collector calls the Delete() method on the pieces which returns an error whi…ch is wrapped by many error classes. Delete() method is using Stat() from https://github.com/storj/storj/blob/1aec831d9898fb23d9dfbfe1ef500568b12aa278/storage/filestore/dir.go#L328 under the hood. os.IsNotExist(errors.Unwrap(err) will always be false unless errors.Unwrap(err) is called multiple times till it gets to the core os.ErrNotExist. Here is a test case to explain better: func TestABC(t *testing.T) { classA := errs.Class("A") classB := errs.Class("B") wrappedError := classB.Wrap(classA.Wrap(os.ErrNotExist)) require.True(t, os.IsNotExist(errs.Unwrap(wrappedError))) require.True(t, os.IsNotExist(errors.Unwrap(wrappedError))) } Using errs.Is() seems to resolve this even without unwrapping the error: func TestABC(t *testing.T) { classA := errs.Class("A") classB := errs.Class("B") wrappedError := classB.Wrap(classA.Wrap(os.ErrNotExist)) require.True(t, errs.Is(wrappedError, os.ErrNotExist)) require.False(t, errs.Is(wrappedError, os.ErrExist)) require.False(t, os.IsNotExist(wrappedError)) } Does not resolve the collector issue here but enhances it: https://github.com/storj/storj/issues/4192 Change-Id: Ifb75dd15b54c1e1a5e23f6eba2d621d64874a5cc

But there’s also a new issue here:

github.com/storj/storj

[storagenode] Investigate why expired piece is deleted before collector tries deleting

opened 12:31PM - 07 Sep 22 UTC

profclems

Bug Needs investigation SNO

In relation to this issue #4192, the collector service tries deleting a piece th…at has already been deleted. We need to find out why/when the piece is deleted before the collector tries deleting the same piece again. References: https://forum.storj.io/t/error-collector-unable-to-delete-piece/12916/17 Logs: ``` == LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ == /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:20:34.618Z INFO piecestore upload started {"Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Available Space": 344865003008} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:20:53.870Z INFO piecestore uploaded {"Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 2319360} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:24:18.513Z INFO piecestore download started {"Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:24:28.203Z INFO piecestore downloaded {"Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:23:25.824Z INFO collector delete expired {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ"} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:39:23.102Z ERROR collector unable to delete piece {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "LQAJGDCIR25R74WQJRONHMEYYHUOYBN3PKP2E4CQ4FVMDUXPAYNQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"} == P4UDM2RZOJKNXSTQ5QV35WTZQHDQ766QN3MQJROUTIG353VU5LFA == /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:10:09.486Z INFO piecestore upload started {"Piece ID": "P4UDM2RZOJKNXSTQ5QV35WTZQHDQ766QN3MQJROUTIG353VU5LFA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Available Space": 344889131008} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:10:09.531Z INFO piecestore uploaded {"Piece ID": "P4UDM2RZOJKNXSTQ5QV35WTZQHDQ766QN3MQJROUTIG353VU5LFA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 512} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:23:25.454Z INFO collector delete expired {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "P4UDM2RZOJKNXSTQ5QV35WTZQHDQ766QN3MQJROUTIG353VU5LFA"} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:39:22.985Z ERROR collector unable to delete piece {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "P4UDM2RZOJKNXSTQ5QV35WTZQHDQ766QN3MQJROUTIG353VU5LFA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"} == ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A == /mnt/log/storj//node.log-20210904.gz:2021-09-03T13:58:06.489Z INFO piecestore upload started {"Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Available Space": 344906312192} /mnt/log/storj//node.log-20210904.gz:2021-09-03T13:58:06.557Z INFO piecestore uploaded {"Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 23552} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:03:50.449Z INFO piecestore download started {"Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"} /mnt/log/storj//node.log-20210904.gz:2021-09-03T14:03:51.956Z INFO piecestore downloaded {"Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:23:25.250Z INFO collector delete expired {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A"} /mnt/log/storj//node.log-20210919.gz:2021-09-18T14:39:22.670Z ERROR collector unable to delete piece {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "ZC5NYYKNWFLWZY34UMUKVUKIRLGJ3GOE25L7S2R7HEBQQV4GJD7A", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"} ```

littleskunk · September 19, 2022, 11:51am

The bug was closed by this commit: storagenode/collector: fix error check when file does not exist · storj/storj@64e5fb7 · GitHub

As you can see in the commit message it will not fix this bug but the link alone makes it so that the bugs get closed by github.

tachyontec · September 20, 2022, 9:25am

Ok so i assume there is still work in progress about this?

@BrightSilence why this storjrobot keep saying the issue is mentioned? Is this another bug

BrightSilence · September 20, 2022, 10:08am

Because it’s been mentioned a few times. Doesn’t sound like a bug to me.