Errors when trying to download deleted files

Node Operators troubleshooting
1

Hello,

I have detected some ““file does not exist”” error messages in logs. After a quick grep… it seems it tries to download a previously deleted file. I have seen these errors but long time ago.
I am worried because this could lead in audit failures due to software bug.
Anyone seeing same issue? I have detected it in 3 old nodes

2020-05-04T04:25:10.922Z        INFO    piecestore      download started        {"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T04:25:14.635Z        INFO    piecestore      downloaded      {"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T04:25:29.492Z        INFO    piecestore      deleted {"Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ"}
2020-05-04T04:25:47.723Z        INFO    piecestore      download started        {"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T04:25:47.724Z        ERROR   piecestore      download failed {"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/pb/pbgrpc.init.0.func3:70\n\tstorj.io/common/rpc/rpcstatus.Wrap:77\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:566\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Download:471\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:995\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:107\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:66\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:111\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:62\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:99\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"}
2

This could be caused by a customer trying to download a piece they’ve deleted. If the customer is running multiple servers/processes/threads/async-calls simultaneously, if process A gets the list of nodes for a certain piece from the satellite, process B deletes the file, then process A tries to download it, you would probably see this exact error.

3

It is Stefan’s test data so I doubt it is trying to download a previously deleted file.
Maybe it just needs to wait till next database refresh.
But i’d love that someone confirms that it is a normal behavior for production release.

4

Unless stated otherwise, I assume it is a bug of the production release and any disqualification or suspension due to this cause should be reviewed. I am storing all the logs for further investigation if needed.

5

When was this piece uploaded ?

6

Long time ago (August 2019). I have filtered all the log lines for this piece.

2019-08-19T**:**:**.***Z    INFO	piecestore	upload started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-08-19T**:**:**.***Z	INFO	piecestore	uploaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "SatelliteID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-04-30T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	INFO	piecestore	downloaded	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	INFO	piecestore	deleted	{"Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ"}
2020-05-04T**:**:**.***Z	INFO	piecestore	download started	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET"}
2020-05-04T**:**:**.***Z	ERROR	piecestore	download failed	{"Piece ID": "LVLPDWYR5I6PUAGIMTIVBNLWC3CVSEFS2K2O75RVVS4RZJSTRGPQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "GET", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/pb/pbgrpc.init.0.func3:70\n\tstorj.io/common/rpc/rpcstatus.Wrap:77\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:566\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Download:471\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:995\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:107\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:66\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:111\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:62\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:99\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"}
7

This is the same time around which that issue was raised. This piece does not have a special marker in its signature and does not affect your node’s audit score.

8

Good to know. Thank you very much.
I thought that pieces older than 6 months were being deleted, but of course i am wrong.

1 Like