My node is getting bad suspension score, and I don't know why

Node Operators troubleshooting
, ,
22

So, an update here. I successfully completed the scrub. During the scrub, I had a power failure and had to redo the scrub from scratch after a reboot. Not sure if this will impact my results. The second scrub completed with 0 errors and 0 bytes corrected. My suspension score has started to slowly creep back up to 100%, sitting currently at 71.31% for saltlake.

This is the output of the latency test script. I’m pretty sure audit latency is not a problem judging from these results. However, there seem to be a low amount of audits (sometimes over a 6-hour gap between the audits). Could this indicate a network problem? For other satellites, I have around 1h gaps between audits.

cat /opt/storj/node.log | grep "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE" | grep -E "GET_AUDIT" | jq -R '. | split("\t") | (.[4] | fromjson) as $body | {SatelliteID: $body."Satellite ID", ($body."Piece ID"): {(.[0]): .[3]}}' | jq -s 'reduce .[] as $item ({}; . * $item)'

{
  "SatelliteID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE",
  "OLOJWYTAFUUB2J6UH4UL7Y2Q3563JKSWMXYPQCBHUJTU4SOOUBBA": {
    "2021-10-02T00:37:33.439Z": "download started",
    "2021-10-02T00:37:33.698Z": "downloaded"
  },
  "I4AIN5O7H6PMIUHT4EOQYMY7YJADGB6W4E2C33SQH3Z7H7DX5DDQ": {
    "2021-10-02T01:08:07.127Z": "download started",
    "2021-10-02T01:08:07.391Z": "downloaded"
  },
  "Z6TGTEHVSUCUM7U7GPHQN3AL7FUHR35NWGGSVKVJ3MLGNAHIIUJQ": {
    "2021-10-02T03:56:19.089Z": "download started",
    "2021-10-02T03:56:19.379Z": "downloaded"
  },
  "2Z7OWSQKWZKJ2KHUXHDLMNJPMWJQSZS542KEV3Q4DX2SQP7DV4JQ": {
    "2021-10-02T10:40:33.392Z": "download started",
    "2021-10-02T10:40:33.661Z": "downloaded"
  },
  "UYFIPE4PFHQ7DBKOKMRARUAW5ZL62GMVWUJBTMR2SH6UHZ2BQSIQ": {
    "2021-10-02T11:31:03.923Z": "download started",
    "2021-10-02T11:31:04.224Z": "downloaded"
  },
  "B4OOD2YISTJJXTA74AGLTLEMLVTOL4MUPCEGNCPXRRSL6DAY47EQ": {
    "2021-10-02T12:09:05.727Z": "download started",
    "2021-10-02T12:09:06.159Z": "downloaded"
  },
  "NUVHF2RNVNNJZV6KW2OZ2YLQ2O2U4QTQI3QSY35CHR4MY4TKBWEQ": {
    "2021-10-02T13:10:33.989Z": "download started",
    "2021-10-02T13:10:34.305Z": "downloaded"
  },
  "F5Q2N5JZEEC5MQADGAKDAJXWAYWV7XJHKC5JACTESL4BXS5EIHYA": {
    "2021-10-02T15:23:06.480Z": "download started",
    "2021-10-02T15:23:06.861Z": "downloaded"
  },
  "VCFLDKUEF3YPUQ6PDNOXOIEDKTVC5NWYAKX7PN6GW6WS7MQ2SFAA": {
    "2021-10-02T17:04:28.315Z": "download started",
    "2021-10-02T17:04:28.630Z": "downloaded"
  },
  "TNBUYACROIIOGQ67AUWCYC6CMSHZLFE56GORNN2RDTVA2AZZJWQA": {
    "2021-10-03T06:31:31.692Z": "download started",
    "2021-10-03T06:31:32.049Z": "downloaded"
  },
  "RYM5X5R2TWYAXO57PGMVLZ3TPGLD3NQL6X6P35CQW2XUPRZV5RTQ": {
    "2021-10-03T07:15:36.149Z": "download started",
    "2021-10-03T07:15:36.417Z": "downloaded"
  },
  "QSLYKNG24A7LRUMRL2Z524BB6HWNPK5HL4IRZ2BTIQ6KQHISMYYQ": {
    "2021-10-03T07:47:53.184Z": "download started",
    "2021-10-03T07:47:53.451Z": "downloaded"
  },
  "2SUQFDZPO7EU2PTKZCC72VB7CZ5GP7G4KFKW3DC7L55SIR2DLKTQ": {
    "2021-10-03T18:51:50.421Z": "download started",
    "2021-10-03T18:51:50.687Z": "downloaded",
    "2021-10-07T10:51:05.663Z": "download started",
    "2021-10-07T10:51:05.922Z": "downloaded"
  },
  "7LXM4O547F7JBZRJ45FVB7EONC3BZ36RFPXO7ULI3WQJL5O2QLAA": {
    "2021-10-03T21:21:18.420Z": "download started",
    "2021-10-03T21:21:18.740Z": "downloaded"
  },
  "IXXRSCGRW7ZCILNPLCHS4K3NVTN2GTO6CG5UUE74VSIOQGOF2DDA": {
    "2021-10-03T21:39:08.868Z": "download started",
    "2021-10-03T21:39:09.145Z": "downloaded"
  },
  "PMXKFD7SNEIDWTEUXUBRNYCER64WOIUROWM7ILB2REKJLUXCPNOA": {
    "2021-10-03T22:48:56.649Z": "download started",
    "2021-10-03T22:48:56.923Z": "downloaded"
  },
  "GXXACONEGZXTMWX4DIV4PH3FYJD55PN4EEECJXLBWGZUBWY7UJTQ": {
    "2021-10-04T00:40:01.146Z": "download started",
    "2021-10-04T00:40:01.415Z": "downloaded"
  },
  "MZNUDF4LJOTO5NFGFU5PXQDGZW4SU4CA4GEIHGDWYWSBPVFFKBYQ": {
    "2021-10-04T06:03:50.081Z": "download started",
    "2021-10-04T06:03:50.606Z": "downloaded"
  },
  "DDRY7YAXDHKU5Y2NKE7Q3LMBAX5U553362KTU36WVZ7MSIIA4QHQ": {
    "2021-10-04T07:45:23.972Z": "download started",
    "2021-10-04T07:45:24.246Z": "downloaded"
  },
  "RXGIIFGW7FTGCZNOD2XJ4SCHKELFMZNL73KCLFNL5JGDF5GLWUJQ": {
    "2021-10-04T09:51:24.420Z": "download started",
    "2021-10-04T09:51:24.740Z": "downloaded"
  },
  "MTORZ2PPIJM7A3CEBLYQ6MOXXR4WCOGESJPGMXZF4YX56AG3MYJQ": {
    "2021-10-04T12:40:13.739Z": "download started",
    "2021-10-04T12:40:14.033Z": "downloaded"
  },
  "L2GK5VBCCZLDSBHWKXFYXWTYOGVMXSVDAX77V6QEKZTFQUYHRMGA": {
    "2021-10-04T20:03:44.248Z": "download started",
    "2021-10-04T20:03:44.504Z": "downloaded"
  },
  "5IXJQWWQXJE5EC7V4SGIEOJMQ3ZVWHTGPKDG2R275LGJ2WXVEPDQ": {
    "2021-10-04T20:12:49.305Z": "download started",
    "2021-10-04T20:12:49.551Z": "downloaded"
  },
  "QOHXRU32XYTBQ5CROZOAGHJL4ERLQ2GY2VEXJMHKU6YTTD4LJCUQ": {
    "2021-10-04T23:04:25.397Z": "download started",
    "2021-10-04T23:04:25.676Z": "downloaded"
  },
  "K7K5IJUVWJRB72XJRB6E77AVEZDQS2YP2GNJYMEB2CGKGX72Q6SQ": {
    "2021-10-04T23:17:26.726Z": "download started",
    "2021-10-04T23:17:27.045Z": "downloaded"
  },
  "N2H2IA2WYPPYTKYTVHNSNMJB4T3XPFUQBGOLIAYD27KFNMGGZ44Q": {
    "2021-10-05T10:27:30.451Z": "download started",
    "2021-10-05T10:27:30.747Z": "downloaded"
  },
  "75E5K3BH6IJWBQRHPZ2TXHPCWGADXMZO3FI6VMRHU6L7V47IKPHQ": {
    "2021-10-05T13:50:23.143Z": "download started",
    "2021-10-05T13:50:23.389Z": "downloaded"
  },
  "KHK34C7PGFNNH2BZCVXJKM3SXEE4BDXF4RQEIII32K473SBL5HRQ": {
    "2021-10-05T14:04:51.880Z": "download started",
    "2021-10-05T14:04:52.156Z": "downloaded"
  },
  "4FCMCRAFECXVHDUK4RQ3R3TWQY3AHOWYJQSCRDZQ5L6YBZDGN5YA": {
    "2021-10-05T14:39:15.821Z": "download started",
    "2021-10-05T14:39:16.360Z": "downloaded"
  },
  "CGCAJT45AERJPSLYXD6W2XL72HWSMSAWKBEVPKZNIRMFOKR2FHSA": {
    "2021-10-05T15:53:05.368Z": "download started",
    "2021-10-05T15:53:05.641Z": "downloaded"
  },
  "OUQIGD6YRSTVYLDYMHDNFRZ3HQQCJQEKTRS6ADK3T46HTRKQ3MHA": {
    "2021-10-05T18:25:03.908Z": "download started",
    "2021-10-05T18:25:04.238Z": "downloaded"
  },
  "W27HOATRUAIDCXTLNHBGTJKVC4FTMUW56ASWSB5DFF6HBQ7XXDGA": {
    "2021-10-05T18:56:37.834Z": "download started",
    "2021-10-05T18:56:38.399Z": "downloaded"
  },
  "2T2MCRRLZQYSLKIYNGOJTJKMXBBKMKW5GCIJSQVMJIAYSO7UPGDA": {
    "2021-10-05T19:12:29.220Z": "download started",
    "2021-10-05T19:12:29.568Z": "downloaded"
  },
  "E2HFPWKE24DX32T5ARDVU33K6DLDFK2RDP3364V62TII2CGXAKTA": {
    "2021-10-06T08:01:09.584Z": "download started",
    "2021-10-06T08:01:09.871Z": "downloaded"
  },
  "S4E46PTECA7ZYE72QOLNQAHWKGSE46QQ3R56RHATYYKDY3UVTK5Q": {
    "2021-10-06T19:51:24.813Z": "download started",
    "2021-10-06T19:51:25.284Z": "downloaded"
  },
  "4FPJE76B7732SG2BERF3QQGBKR7E7OFAE662MNKJQ2P37AMOHJJA": {
    "2021-10-06T22:43:31.448Z": "download started",
    "2021-10-06T22:43:31.754Z": "downloaded"
  },
  "WMIHD25JCP3F6UNRREBMEWRBN2JGQ5EKUBUTBLS2ZABSNOOWPROQ": {
    "2021-10-07T06:33:07.659Z": "download started",
    "2021-10-07T06:33:07.965Z": "downloaded"
  },
  "KLQKPIS7HFWEDLSQRF256VQ7IO5UGUE7UKK5LUNIOBWQIFHJZHNA": {
    "2021-10-08T03:08:02.503Z": "download started",
    "2021-10-08T03:08:02.781Z": "downloaded"
  },
  "NIJ76LKXRVCD3FJGEJUVYSFQMUYU3BNBZXYBOW2UGLDNNXK5MNJQ": {
    "2021-10-08T06:59:51.991Z": "download started",
    "2021-10-08T06:59:52.315Z": "downloaded"
  },
  "3DRBBM4WSO7VG3YTXCFP4Q4KQVKJTZK6MONMTNUIV67WPWVX65HA": {
    "2021-10-08T08:55:54.181Z": "download started",
    "2021-10-08T08:55:54.503Z": "downloaded"
  },
  "WSRMJWVYQKFIO36TMOLDOQJ452KKRO2QDP2UYDPXXLX54YJWIAHA": {
    "2021-10-08T10:10:45.867Z": "download started",
    "2021-10-08T10:10:46.334Z": "downloaded"
  },
  "6MY7L3CKLBDYA2IFW5E6NVESP27M22G4IHD53X2LDYSK2TCDJ5PQ": {
    "2021-10-08T12:47:12.113Z": "download started",
    "2021-10-08T12:47:12.499Z": "downloaded"
  },
  "JMUVHTBAL3L5U3SDTRODIPZX3A5ZP7U7NIIPRZNANU5EB4WGM7IQ": {
    "2021-10-08T14:15:12.935Z": "download started",
    "2021-10-08T14:15:13.214Z": "downloaded"
  },
  "NEATMTA3CW5PCU4PYD5TQNIV43NXDGFDOJX75NP7NPOJFY4UOSJQ": {
    "2021-10-08T14:52:49.171Z": "download started",
    "2021-10-08T14:52:49.477Z": "downloaded"
  },
  "4SPSE3XANRJXKDBM6P2SFGYTO3O5N2PTI3UKE2NFOQN7URRYWLFQ": {
    "2021-10-08T19:08:14.951Z": "download started",
    "2021-10-08T19:08:15.279Z": "downloaded"
  },
  "TRV5XLBANPYHOFG2XCD3KSXI6XBPU6LOLP5RFVR7MPLOAOU74GCA": {
    "2021-10-08T19:19:04.719Z": "download started",
    "2021-10-08T19:19:04.988Z": "downloaded"
  },
  "U5UZGLYS4UMEPF6OOYXVJAVXBLNCZMN4YFGTV4WHFZCCBUN2RGEQ": {
    "2021-10-08T21:32:03.307Z": "download started",
    "2021-10-08T21:32:04.395Z": "downloaded"
  },
  "FPPYEJEUCGT2UKFZLXZFDZS3NSG2Q62OIAH6HTMEVTINOAWI3CJQ": {
    "2021-10-08T21:50:04.729Z": "download started",
    "2021-10-08T21:50:05.422Z": "downloaded"
  },
  "ZYL7FYNF3FYNHFQDHK3RBZFNSMEKIDNOI5XKBVO67JR7DXLQGPOQ": {
    "2021-10-08T23:14:40.679Z": "download started",
    "2021-10-08T23:14:41.134Z": "downloaded"
  },
  "EM2V3HMFMYJC54ZDDASQFK7SSSOSHLJDB7MSKVCG6PTMYXG2AJUQ": {
    "2021-10-08T23:38:24.998Z": "download started",
    "2021-10-08T23:38:25.434Z": "downloaded"
  },
  "ADGQMODS6RWXZLNGKL6BHEX4D5VDMJK3XHDQLATQJVYNHYTNMIBA": {
    "2021-10-09T03:59:49.414Z": "download started",
    "2021-10-09T03:59:49.880Z": "downloaded"
  },
  "L3QB5ZJFQNNIVOWGWL7TM5D7DLBWVS526VRMCAYOW7ALQAISHBIA": {
    "2021-10-09T10:07:27.369Z": "download started",
    "2021-10-09T10:07:27.789Z": "downloaded"
  },
  "ZAFTSOH6CPUZTXZNSUUFVK7Q26UKCRQUM4SYYVJV3JRSPIGWEZ6Q": {
    "2021-10-09T22:13:33.348Z": "download started",
    "2021-10-09T22:13:34.103Z": "downloaded"
  },
  "7CIM7PJBELEFRAAE65IBR2KHYWXGDQ4FXJQH2ERATFMQDRY3JGPQ": {
    "2021-10-09T23:00:16.353Z": "download started",
    "2021-10-09T23:00:16.919Z": "downloaded"
  },
  "MK5K5IUHY45JETZDLXKRJMYN6F6JXV6GNGVSBJYABQTHEGTQTHWA": {
    "2021-10-10T05:26:52.165Z": "download started",
    "2021-10-10T05:26:52.650Z": "downloaded"
  }
}
23

No, it just means you have less data from that satellite relative to other nodes.

If your scores are going up now, you may have had a temporary problem though. If you don’t have old logs you’re not going to be able to find the original issue.

24

No, it just means you have less data from that satellite relative to other nodes.

Ok, that is good to hear.

If the scores rises back to normal in the coming week(s), I’ll consider the issue solved. If they drop back down again, I’ll post my updated logs and continue the investigation here.

1 Like
25

Hi again,

The suspension score is jumping up and down. Now for us1, it has decreased from 99.8 to around 90%. I still have 100% audit score for all satellites. All audit requests are answered in less than 1 second, tested as previously mentioned in this thread.

I have a few errors upload and download fails in the logs, with the error message “use of closed network connection”, or “unexpected EOF”, as before. However, I did get a new error message that I don’t think I’ve had before:

2021-10-09T03:59:39.580Z	INFO	piecestore	upload started	{
    "Piece ID": "OSU5XVDS4K7TCNODUA5NNM4LXH3QEOJ54QNDPOUBEBE3YEPBHV5Q",
    "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", 
    "Action": "PUT", 
    "Available Space": 1587579584458
}
2021-10-09T04:29:39.587Z	ERROR	piecestore	upload failed	{
    "Piece ID": "OSU5XVDS4K7TCNODUA5NNM4LXH3QEOJ54QNDPOUBEBE3YEPBHV5Q", 
    "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", 
    "Action": "PUT", 
    "error": "context deadline exceeded", 
    "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", 
    "Size": 0
}

There is 30 seconds minutes between the upload start and fail. I’m not sure if this could be the problem.

26

More like 30 minutes.

2 Likes
27

Yea sorry my bad. What does “context deadline exceeded” mean?

28

The canceled upload/download. The stack trace may vary depending when the other side is canceled the transfer.
In your case this seems was a stuck connection and was finally canceled only after 30 minutes.

It could be a slow disk or slow connection between your node and the customers’ uplink.

29

Ok. It seems I’ve had a few of these in the last day or so.

If I filter out obvious network errors like this, I’ll get the following log: cat /tank/storj-data/config/node.log | grep ERROR | grep -v "use of closed network connection" | grep -v "unexpected EOF" | grep -v "connection timed out"

2021-10-02T09:21:38.700Z	ERROR	piecestore	download failed	{"Piece ID": "ALHSIATS2DDYADEAGI2CDOERZNGBWPCMXTQDH7O6KHO2Q33EUDFQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-02T09:24:21.953Z	ERROR	piecestore	download failed	{"Piece ID": "ALHSIATS2DDYADEAGI2CDOERZNGBWPCMXTQDH7O6KHO2Q33EUDFQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-02T09:25:18.771Z	ERROR	piecestore	download failed	{"Piece ID": "ALHSIATS2DDYADEAGI2CDOERZNGBWPCMXTQDH7O6KHO2Q33EUDFQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-03T09:41:21.173Z	ERROR	piecestore	upload failed	{"Piece ID": "IIBCRZZGODX45KHPNBEOLPBDT6G5AMOGG4CCY4SLQVZAVRFVYPPQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", "Size": 0}
2021-10-04T16:26:09.907Z	ERROR	piecestore	download failed	{"Piece ID": "7FSWYRBCZJTNQLVKSAQ4T2FIYQTPMD6DK5TEU7PYG46SIY64D4EQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-05T12:43:01.924Z	ERROR	piecestore	download failed	{"Piece ID": "6N3HVJORWKLE5UAM5AGLB46YQTUWO22P5WERVCRO7J5LN3YSPU2A", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-05T15:05:39.726Z	ERROR	piecestore	download failed	{"Piece ID": "XH5WFP5XZYVEJLV3XVMNGR6B7DTFNXWWV7IEHL76UZYPZVNH4JJQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-06T08:12:13.703Z	ERROR	piecestore	download failed	{"Piece ID": "HA3CGL4O5Y375X3ISGWQCE5YOFK232HL62UFBBBDRIKJUOFX3EKA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-07T00:21:09.019Z	ERROR	piecestore	download failed	{"Piece ID": "A6XFDJ6LSSHKTYDUYB35S5XBCO5NC36ITZU77LN5IPV7F477UHNQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-08T07:23:25.736Z	ERROR	piecestore	download failed	{"Piece ID": "E2OFGCLCBJYC3X7U6U5N2EM5N2AVRO65LMWLDWKTO7SI7REZI2FA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-08T07:24:05.207Z	ERROR	piecestore	download failed	{"Piece ID": "E2OFGCLCBJYC3X7U6U5N2EM5N2AVRO65LMWLDWKTO7SI7REZI2FA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-08T07:25:04.337Z	ERROR	piecestore	download failed	{"Piece ID": "E2OFGCLCBJYC3X7U6U5N2EM5N2AVRO65LMWLDWKTO7SI7REZI2FA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-08T17:44:02.052Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T17:44:02.063Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T18:56:44.760Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T18:56:44.760Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T18:56:44.819Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T18:56:44.988Z	ERROR	piecestore:cache	error getting current used space: 	{"error": "context canceled; context canceled", "errorVerbose": "group:\n--- context canceled\n--- context canceled"}
2021-10-08T21:26:58.431Z	ERROR	piecestore:cache	error getting current used space: 	{"error": "context canceled; context canceled", "errorVerbose": "group:\n--- context canceled\n--- context canceled"}
2021-10-08T21:26:58.441Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T21:26:58.442Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-08T21:26:58.498Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T04:29:39.587Z	ERROR	piecestore	upload failed	{"Piece ID": "OSU5XVDS4K7TCNODUA5NNM4LXH3QEOJ54QNDPOUBEBE3YEPBHV5Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", "Size": 0}
2021-10-09T04:29:43.808Z	ERROR	piecestore	upload failed	{"Piece ID": "4MIUDF2YN4XISQXA6RMOH7TJHCPPO7DKT74W5KQPE67OH2VOZIUA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", "Size": 0}
2021-10-09T07:03:25.132Z	ERROR	piecestore	upload failed	{"Piece ID": "GMAQTO4JSLSR44BNSVKBUNT3FX6BHRJGRMWY2LEZEEGO5HDJN2CA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", "Size": 0}
2021-10-09T12:36:08.804Z	ERROR	retain	retain pieces failed	{"error": "retain: context canceled", "errorVerbose": "retain: context canceled\n\tstorj.io/storj/storagenode/retain.(*Service).retainPieces:426\n\tstorj.io/storj/storagenode/retain.(*Service).Run.func2:222\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.434Z	ERROR	piecestore:cache	error getting current used space: 	{"error": "context canceled; context canceled; context canceled; context canceled; context canceled; context canceled", "errorVerbose": "group:\n--- context canceled\n--- context canceled\n--- context canceled\n--- context canceled\n--- context canceled\n--- context canceled"}
2021-10-09T13:08:06.501Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.503Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.504Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.504Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.505Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-09T13:08:06.506Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-10T09:39:51.857Z	ERROR	piecestore	download failed	{"Piece ID": "4AZZJJUSMIKTH4KSEGDC7H54MI2C55BETBLQLFVJDV6C6J56SLZA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-10T15:12:36.827Z	ERROR	piecestore	download failed	{"Piece ID": "4AZZJJUSMIKTH4KSEGDC7H54MI2C55BETBLQLFVJDV6C6J56SLZA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download.func6:656\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:674\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}
2021-10-11T15:19:35.204Z	ERROR	piecestore	upload failed	{"Piece ID": "N2WO4GNW4HI3PNEXXE4B6ACI5VJQXGYZLRWKMSJETHA75VQYPW2A", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "error": "context deadline exceeded", "errorVerbose": "context deadline exceeded\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Upload:344\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func1:220\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:104\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:97\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52", "Size": 0}
2021-10-11T20:38:19.958Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-11T20:38:19.958Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-10-11T20:38:20.164Z	ERROR	pieces:trash	emptying trash failed	{"error": "pieces error: filestore error: context canceled", "errorVerbose": "pieces error: filestore error: context canceled\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:154\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:310\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:367\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

The recurring errors seems to indicate the following problems:

  • emptying trash failed → pieces error: filestore error: context canceled
  • download/upload failed → context deadline exceeded
  • error getting current used space → context canceled

Too me, it looks like it could be an IO problem. Especially “error getting current used space”. During 9 Oct around 13:08:06, there are 7 errors at the same time. The same happened again at 20:38.19 today with 4 errors. At those times, the IO might be too busy.

I’ll see if I can do some zfs magic (adjust record size etc.) to reduce io operations, and perhaps move the databases to an ssd storage.

30

Your disk is very slow and cannot keep up.
All other related to the network communication, but perhaps they happened because of waiting for disk too.
If you have some monitoring, at least NetData, you can clearly see it. The last one in additional will warn you about any issues.

31

it was why i said the errors was the issue, because it’s almost always this same old story, hdd can’t keep up and get overloaded.

and eventually a failed download will hit audits and start pulling down suspension score.

32

zfs set xattr=off poolname
zfs set atime=off poolname

that should cut your iops to by 66% to 75% for most stuff.
if you aren’t doing that already, ofc

1 Like
33

Thanks!

What record size are you currently using for zfs? I read your post here Zfs discussions - #383 by SGC but I find it hard to understand what record sizes are appropriate. I’ve always used the default 128k for other applications without any problems. But for storj, it probably worth tweaking.

1 Like
34

i found 256k to be a nice point, it fits well into the max file size of 2. something mb.
generally it’s a balancing act, the higher your recordsize the more your caches and ram will be cleared for incoming data even if it’s nothing near the 256k… like say if something is pushing 1000 files the system might be aware they are coming, and thus will make room for them… so it would need to clear some of whats cached to make room.

1000 x 256k so it would clear 256mb of cache / ram even if the files might be 1kb each… something like that anyways, so thats the issue with high recordsizes.

the advantage are that you will have a bit fewer checksums, because each record is what is checksummed, this gives a minor performance benefit, but nothing i would really switch for.

the true benefit comes from the io, due to having larger recordsize gives you less fragmented data in a sense, and thus data access goes up, by a factor of two…

so long as files are large enough to benefit from this…

a 1 kb file would take up a 1kb record on both 128k and 256k zfs record size, because its sort of just the max size.

the biggest benefit i have directly observed is during migration, the difference between 128k and 256k is substantial close to double the data throughput.

i experimented a fair bit with this early on, 256k is what i ended with… i would say don’t go to far from the default, its chosen for a reason, and that reason is that its generally very good for most things.

most zfs default’s are very very good and requires a lot of trial and error to get better results than straight up defaults, i like that i can migrate faster 256k even if i rarely use it… because if i was migrating it was most likely because i was in trouble.
and i got a sizable server so plenty of caches and ram

2 Likes
35

It could become worse.

36

Just want to say that the errors were from slow disks. I’ve moved over my node to an ext4 disk (was using zfs previously) on a different machine and it cruses on as intended.

2 Likes