One of two nodes on same machine is suspended - don't know why

articulateape · August 24, 2020, 5:55pm

Hi,

I have a Raspberry Pi 4 with two nodes. I am running Raspbian OS.

Node one is okay but node two is now disqualified. Please see attachment.

When I use

docker logs storagenode

I don’t see any issues that crop up. I also have Storj Success rate Master Audit installed and it shows this:

========== AUDIT ==============
Critically failed: 0
Critical Fail Rate: 0.000%
Recoverable failed: 100
Recoverable Fail Rate: 98.039%
Successful: 2
Success Rate: 1.961%
========== DOWNLOAD ===========
Failed: 2628
Fail Rate: 93.423%
Canceled: 17
Cancel Rate: 0.604%
Successful: 168
Success Rate: 5.972%
========== UPLOAD =============
Rejected: 0
Acceptance Rate: 100.000%
---------- accepted -----------
Failed: 3854
Fail Rate: 99.974%
Canceled: 0
Cancel Rate: 0.000%
Successful: 1
Success Rate: 0.026%
========== REPAIR DOWNLOAD ====
Failed: 0
Fail Rate: 0.000%
Canceled: 0
Cancel Rate: 0.000%
Successful: 0
Success Rate: 0.000%
========== REPAIR UPLOAD ======
Failed: 1874
Fail Rate: 100.000%
Canceled: 0
Cancel Rate: 0.000%
Successful: 0
Success Rate: 0.000%
========== DELETE =============
Failed: 42
Fail Rate: 100.000%
Successful: 0
Success Rate: 0.000%

Clearly the auditing is failing, however, another node on the same machine is fine but this is not. What could the issue be?

The only thing that differs is that the failed node uses USB 2.0 external enclosure but the successful one uses USB 3.0, could this be an issue too?

baker · August 24, 2020, 6:34pm

The type of USB version shouldn’t be an issue. It looks like from your screenshot that the node is suspended, not disqualified. You should stop the node immediately to (hopefully) prevent the node from being disqualified. Have you verified that the drive for the suspended node is still mounted? It’s not just audits that are failing, it appears that almost everything is. Can you post the last 20 lines of your log?

docker logs -tail 20 storagenode

articulateape · August 24, 2020, 6:49pm

Thanks for the reply @baker, I’ve also changed the name of the thread as you’re right it’s suspended not DQ.

Disk is mounted and can be seen through df and lsblk

I have also stopped the node as you recommended.

Here is the output of docker log --tail 20 storagenode-eneloop

2020-08-24T18:44:54.583Z        INFO    piecestore      download started        {"Piece ID": "LLMS5FO7NPQUBMWZJ4PSGQTC6LFUVF6DMHTZ6YZC4EASWTM5QEBQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:44:59.343Z        INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      sending {"count": 7}
2020-08-24T18:44:59.343Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      sending {"count": 35}
2020-08-24T18:44:59.346Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      sending {"count": 7}
2020-08-24T18:44:59.348Z        INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       sending {"count": 20}
2020-08-24T18:44:59.343Z        INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      sending {"count": 2}
2020-08-24T18:45:00.057Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      finished
2020-08-24T18:45:00.199Z        INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       finished
2020-08-24T18:45:02.555Z        INFO    piecestore      downloaded      {"Piece ID": "LLMS5FO7NPQUBMWZJ4PSGQTC6LFUVF6DMHTZ6YZC4EASWTM5QEBQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:45:04.521Z        INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      finished
2020-08-24T18:45:04.630Z        INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      finished
2020-08-24T18:45:05.258Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      finished
2020-08-24T18:45:35.800Z        INFO    piecestore      download started        {"Piece ID": "PIR6LS344ANESRCBGD32MCYD36SMATCKVKYJBCUEOVJB2CG6SJ7A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:45:44.022Z        INFO    piecestore      downloaded      {"Piece ID": "PIR6LS344ANESRCBGD32MCYD36SMATCKVKYJBCUEOVJB2CG6SJ7A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:46:20.981Z        INFO    piecestore      download started        {"Piece ID": "FBW3SJMBNIYRTIJUDWYNQ6HUZXLPLTBVQKVBNOEQKX6DQ44UKLTA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:46:21.237Z        INFO    piecestore      download started        {"Piece ID": "3BDJUXYXJ6E2EFWYKZRZ56BTTWM7RBEAGFBMQVJW7CJYIIWDQQGQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:46:21.800Z        INFO    piecestore      downloaded      {"Piece ID": "3BDJUXYXJ6E2EFWYKZRZ56BTTWM7RBEAGFBMQVJW7CJYIIWDQQGQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:46:21.850Z        INFO    piecestore      downloaded      {"Piece ID": "FBW3SJMBNIYRTIJUDWYNQ6HUZXLPLTBVQKVBNOEQKX6DQ44UKLTA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:47:33.480Z        INFO    Got a signal from the OS: "terminated"
Error: debug: http: Server closed

baker · August 24, 2020, 7:01pm

Hmmm. Not much there. Unfortunately the order sending routine took up a bunch of those 20 lines. Lets see the first 80 lines of your log, since downloads seem to be working as of right now.
docker logs storagenode 2>&1 | head -n 80

You can also try searching your logs for the recoverable failed audits.
docker logs storagenode 2>&1 | grep GET_AUDIT | grep failed

articulateape · August 24, 2020, 7:23pm

I tried docker logs storagenode 2>&1 | head -n 80 and I get the following, seems to be a verbose error with rpccompat…so is that connected to apache server?

2020-08-24T17:43:34.764Z        INFO    Configuration loaded    {"Location": "/app/config/config.yaml"}
2020-08-24T17:43:34.767Z        INFO    Operator email  {"Address": "p....s@gmail.com"}
2020-08-24T17:43:34.767Z        INFO    Operator wallet {"Address": "0x3.....359d5"}
2020-08-24T17:43:35.641Z        INFO    Telemetry enabled
2020-08-24T17:43:35.670Z        INFO    db.migration    Database Version        {"version": 43}
2020-08-24T17:43:36.501Z        INFO    preflight:localtime     start checking local system clock with trusted satellites' system clock.
2020-08-24T17:43:42.402Z        INFO    preflight:localtime     local system clock is in sync with trusted satellites' system clock.
2020-08-24T17:43:42.403Z        INFO    trust   Scheduling next refresh {"after": "10h49m9.871571708s"}
2020-08-24T17:43:42.403Z        INFO    Node 12hk........3S7cgw started
2020-08-24T17:43:42.403Z        INFO    Public server started on [::]:28967
2020-08-24T17:43:42.403Z        INFO    Private server started on 127.0.0.1:7778
2020-08-24T17:43:42.410Z        INFO    bandwidth       Performing bandwidth usage rollups
2020-08-24T17:44:07.308Z        INFO    piecestore      download started        {"Piece ID": "7ZVGG35DBFVRP4RCCZ5M5ABGVKWXEOQX5V77XXRA6YLLMU66PXMA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:44:07.540Z        INFO    piecestore      downloaded      {"Piece ID": "7ZVGG35DBFVRP4RCCZ5M5ABGVKWXEOQX5V77XXRA6YLLMU66PXMA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:44:30.777Z        INFO    piecestore      download started        {"Piece ID": "ROZZB4MX3WVOXF7T3UANLUOZM3R5BWUCMSR25CVNX3J5PTAUCA4A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:44:37.518Z        INFO    piecestore      download started        {"Piece ID": "ZGR5SNH2FM6AJAM3UYCIM2ZAUDPNBDDHALRIY5ADSNDXYCGBE6GA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:44:37.952Z        INFO    piecestore      download canceled       {"Piece ID": "ZGR5SNH2FM6AJAM3UYCIM2ZAUDPNBDDHALRIY5ADSNDXYCGBE6GA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:44:38.754Z        INFO    piecestore      downloaded      {"Piece ID": "ROZZB4MX3WVOXF7T3UANLUOZM3R5BWUCMSR25CVNX3J5PTAUCA4A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:45:15.127Z        INFO    piecestore      download started        {"Piece ID": "2LA5VBRQORJN3IG64GJMQCYJESQMIT6PVXFC5MCQJXSJOSER6MDQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:15.811Z        INFO    piecestore      downloaded      {"Piece ID": "2LA5VBRQORJN3IG64GJMQCYJESQMIT6PVXFC5MCQJXSJOSER6MDQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:23.297Z        INFO    piecestore      download started        {"Piece ID": "HHDV5HTI4GO66B5A7CDCOPHTB2Y6E72ZRB2WCKQX52L5UGSCGB4Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:23.585Z        INFO    piecestore      download started        {"Piece ID": "MZZ4QWGTCLQ5FNIDK4WJUT3654FHLJYULHMH5OIJWDSXZBLS2PHQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:24.603Z        INFO    piecestore      downloaded      {"Piece ID": "HHDV5HTI4GO66B5A7CDCOPHTB2Y6E72ZRB2WCKQX52L5UGSCGB4Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:24.677Z        INFO    piecestore      downloaded      {"Piece ID": "MZZ4QWGTCLQ5FNIDK4WJUT3654FHLJYULHMH5OIJWDSXZBLS2PHQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:45:49.097Z        INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      sending {"count": 9}
2020-08-24T17:45:49.097Z        INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       sending {"count": 26}
2020-08-24T17:45:49.097Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      sending {"count": 4}
2020-08-24T17:45:49.097Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      sending {"count": 23}
2020-08-24T17:45:49.640Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      finished
2020-08-24T17:45:49.972Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      finished
2020-08-24T17:45:54.439Z        INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      finished
2020-08-24T17:45:54.996Z        INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       finished
2020-08-24T17:46:35.105Z        INFO    piecestore      download started        {"Piece ID": "2EFXKVQO4KCC5MKUM2KQYDT5GEE6LGHQO6EVD3RJHMOANS43P3JQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:46:40.348Z        INFO    piecestore      downloaded      {"Piece ID": "2EFXKVQO4KCC5MKUM2KQYDT5GEE6LGHQO6EVD3RJHMOANS43P3JQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:48:14.761Z        INFO    piecestore      download started        {"Piece ID": "RF2KC5G23HW6IT36K76UIWRORJCD4PTBQHKINWFS7TFWXSKXWFGQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}
2020-08-24T17:48:14.990Z        INFO    piecestore      downloaded      {"Piece ID": "RF2KC5G23HW6IT36K76UIWRORJCD4PTBQHKINWFS7TFWXSKXWFGQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}
2020-08-24T17:51:06.201Z        INFO    piecestore      download started        {"Piece ID": "LLMS5FO7NPQUBMWZJ4PSGQTC6LFUVF6DMHTZ6YZC4EASWTM5QEBQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:51:14.847Z        INFO    piecestore      downloaded      {"Piece ID": "LLMS5FO7NPQUBMWZJ4PSGQTC6LFUVF6DMHTZ6YZC4EASWTM5QEBQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:52:00.589Z        INFO    piecestore      download started        {"Piece ID": "TFIR2G3TSQBNO5NIMLFRMU3UZUOXXJ23XR6UZKCKAAWSVCK3I6TQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:01.102Z        INFO    piecestore      downloaded      {"Piece ID": "TFIR2G3TSQBNO5NIMLFRMU3UZUOXXJ23XR6UZKCKAAWSVCK3I6TQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:04.808Z        INFO    piecestore      download started        {"Piece ID": "AQHCG6453VDULUTG4D5EB7IA6HZZYI5CSVZTW7ITQQ5RFZTAVJZQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:05.100Z        INFO    piecestore      downloaded      {"Piece ID": "AQHCG6453VDULUTG4D5EB7IA6HZZYI5CSVZTW7ITQQ5RFZTAVJZQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:16.539Z        INFO    piecestore      download started        {"Piece ID": "75O3W3V5X2FTWYMAKNVOHR5DZVILFEL37HNE5ERYQMOP2HPEUZAA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:18.047Z        INFO    piecestore      downloaded      {"Piece ID": "75O3W3V5X2FTWYMAKNVOHR5DZVILFEL37HNE5ERYQMOP2HPEUZAA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:52:40.252Z        INFO    piecestore      download started        {"Piece ID": "REMKEB5XVWJAPJIZ2ZSJ5B6UCN2AAFJ3DFUXM4DZBFFPAI7LRTMQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:52:42.185Z        INFO    piecestore      downloaded      {"Piece ID": "REMKEB5XVWJAPJIZ2ZSJ5B6UCN2AAFJ3DFUXM4DZBFFPAI7LRTMQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:53:14.273Z        INFO    piecestore      download started        {"Piece ID": "REMKEB5XVWJAPJIZ2ZSJ5B6UCN2AAFJ3DFUXM4DZBFFPAI7LRTMQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:53:15.964Z        INFO    piecestore      downloaded      {"Piece ID": "REMKEB5XVWJAPJIZ2ZSJ5B6UCN2AAFJ3DFUXM4DZBFFPAI7LRTMQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:53:43.751Z        INFO    piecestore      download started        {"Piece ID": "SEI2B4FGRNSKZCXPJQKIHUJNK2OQT5GGU6VECCXLR4CALQV2FDBQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2020-08-24T17:53:44.168Z        ERROR   piecestore      download failed {"Piece ID": "SEI2B4FGRNSKZCXPJQKIHUJNK2OQT5GGU6VECCXLR4CALQV2FDBQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET", "error": "trust: rpccompat: context canceled", "errorVerbose": "trust: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:231\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/trust.Dialer.func1:51\n\tstorj.io/storj/storagenode/trust.IdentityResolverFunc.ResolveIdentity:43\n\tstorj.io/storj/storagenode/trust.(*Pool).GetSignee:143\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).VerifyOrderLimitSignature:134\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:62\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:467\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:1004\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:107\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:56\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"}
2020-08-24T17:54:58.309Z        INFO    piecestore      download started        {"Piece ID": "DIGQNGIRL2HFVG3FR5N5AK3SP7I7XBWXLPW66JICOGJEHF7PZ42A", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET_AUDIT"}
2020-08-24T17:54:58.782Z        INFO    piecestore      downloaded      {"Piece ID": "DIGQNGIRL2HFVG3FR5N5AK3SP7I7XBWXLPW66JICOGJEHF7PZ42A", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET_AUDIT"}
2020-08-24T17:54:59.243Z        INFO    piecestore      download started        {"Piece ID": "2B4GUU4WMDC754AGCE3FVJSODHKWFFCU2ULFYAN2CMJTKFQNWZHQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:55:10.846Z        INFO    piecestore      downloaded      {"Piece ID": "2B4GUU4WMDC754AGCE3FVJSODHKWFFCU2ULFYAN2CMJTKFQNWZHQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:56:22.815Z        INFO    piecestore      download started        {"Piece ID": "TVU5KKUDH3ZJMHKJTFKYWIFQCPKWLD5UBUGIVQ3PWHUXSUNTW32A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:56:24.789Z        INFO    piecestore      download started        {"Piece ID": "TVU5KKUDH3ZJMHKJTFKYWIFQCPKWLD5UBUGIVQ3PWHUXSUNTW32A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:56:30.859Z        INFO    piecestore      downloaded      {"Piece ID": "TVU5KKUDH3ZJMHKJTFKYWIFQCPKWLD5UBUGIVQ3PWHUXSUNTW32A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:56:31.737Z        INFO    piecestore      downloaded      {"Piece ID": "TVU5KKUDH3ZJMHKJTFKYWIFQCPKWLD5UBUGIVQ3PWHUXSUNTW32A", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:57:28.298Z        INFO    piecestore      download started        {"Piece ID": "UTG4X2AUYBS5H5N5DRLK45TUKIKEWM35PNATSEM5KHJNHDEDAXKQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:57:28.727Z        INFO    piecestore      download canceled       {"Piece ID": "UTG4X2AUYBS5H5N5DRLK45TUKIKEWM35PNATSEM5KHJNHDEDAXKQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T17:57:39.280Z        INFO    piecestore      download started        {"Piece ID": "HRLLNPPACU2D6ENKZBLP2R3NC4O2WJPWQ7TVEOX4OXCCTCZOGWKQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:57:49.604Z        INFO    piecestore      downloaded      {"Piece ID": "HRLLNPPACU2D6ENKZBLP2R3NC4O2WJPWQ7TVEOX4OXCCTCZOGWKQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:58:00.496Z        INFO    piecestore      download started        {"Piece ID": "WFW4BRUNFOJVWTJ4JI44BPSIT2SBHG5EQ5E7AGYYKPAP6VLBNCRA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:58:00.676Z        INFO    piecestore      downloaded      {"Piece ID": "WFW4BRUNFOJVWTJ4JI44BPSIT2SBHG5EQ5E7AGYYKPAP6VLBNCRA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:58:00.851Z        INFO    piecestore      download started        {"Piece ID": "WFW4BRUNFOJVWTJ4JI44BPSIT2SBHG5EQ5E7AGYYKPAP6VLBNCRA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:58:00.999Z        INFO    piecestore      downloaded      {"Piece ID": "WFW4BRUNFOJVWTJ4JI44BPSIT2SBHG5EQ5E7AGYYKPAP6VLBNCRA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "Action": "GET"}
2020-08-24T17:58:08.771Z        INFO    piecestore      download started        {"Piece ID": "KSH32A6NBTOFHFFQ4BJU3A5PFCQWW65Y4YOUDCGEEZ5YIIA5XXVA", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2020-08-24T17:58:09.484Z        INFO    piecestore      downloaded      {"Piece ID": "KSH32A6NBTOFHFFQ4BJU3A5PFCQWW65Y4YOUDCGEEZ5YIIA5XXVA", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2020-08-24T17:58:19.042Z        INFO    piecestore      download started        {"Piece ID": "HRLLNPPACU2D6ENKZBLP2R3NC4O2WJPWQ7TVEOX4OXCCTCZOGWKQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T17:58:28.193Z        INFO    piecestore      downloaded      {"Piece ID": "HRLLNPPACU2D6ENKZBLP2R3NC4O2WJPWQ7TVEOX4OXCCTCZOGWKQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:00:49.396Z        INFO    piecestore      download started        {"Piece ID": "I2G5I5GSEUILOH7YISGJ3RMCI7KSEK7B77V5TRWZ3JOQUKQJ4VSA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:00:50.050Z        INFO    piecestore      downloaded      {"Piece ID": "I2G5I5GSEUILOH7YISGJ3RMCI7KSEK7B77V5TRWZ3JOQUKQJ4VSA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:01:15.150Z        INFO    piecestore      download started        {"Piece ID": "GFCJI34ZN76GZUBNT2QBVUTESHDAPVTU46D4EKZWOXJVQZCHNSOA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:01:19.615Z        INFO    piecestore      downloaded      {"Piece ID": "GFCJI34ZN76GZUBNT2QBVUTESHDAPVTU46D4EKZWOXJVQZCHNSOA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:03:39.349Z        INFO    piecestore      download started        {"Piece ID": "JZIA7QCTPQRRHK7Y2CYTNMH53ZN57JOYONDO35INXC7FJS3M4BRQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:03:40.073Z        INFO    piecestore      downloaded      {"Piece ID": "JZIA7QCTPQRRHK7Y2CYTNMH53ZN57JOYONDO35INXC7FJS3M4BRQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:04:59.681Z        INFO    piecestore      download started        {"Piece ID": "2B4GUU4WMDC754AGCE3FVJSODHKWFFCU2ULFYAN2CMJTKFQNWZHQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}
2020-08-24T18:05:06.242Z        INFO    piecestore      download started        {"Piece ID": "KGPNARRDZD7LTM5XLVSKCBMR56CSMCBY4D5PS2Z3PIEER4ATY67A", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:05:06.651Z        INFO    piecestore      download canceled       {"Piece ID": "KGPNARRDZD7LTM5XLVSKCBMR56CSMCBY4D5PS2Z3PIEER4ATY67A", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2020-08-24T18:05:10.091Z        INFO    piecestore      downloaded      {"Piece ID": "2B4GUU4WMDC754AGCE3FVJSODHKWFFCU2ULFYAN2CMJTKFQNWZHQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}

Is this the error?

"trust: rpccompat: context canceled", "errorVerbose": "trust: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:231\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/trust.Dialer.func1:51\n\tstorj.io/storj/storagenode/trust.IdentityResolverFunc.ResolveIdentity:43\n\tstorj.io/storj/storagenode/trust.(*Pool).GetSignee:143\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).VerifyOrderLimitSignature:134\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:62\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:467\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:1004\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:107\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:56\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"}

Alexey · August 24, 2020, 7:29pm

No. This is a GET, and not a GET_AUDIT. There is no any apache.
Please, search for GET_AUDIT and failed.

articulateape · August 24, 2020, 7:36pm

This command

docker logs storagenode 2>&1 | grep GET_AUDIT | grep failed

does not return any value for the node, it is blank with a new line, see screenshot

If I check the whole log with docker logs storagenode this is the only error i can see

 ERROR   contact:service ping satellite failed   {"Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB", "attempts": 1, "error": "ping satellite error: rpccompat: context canceled", "errorVerbose": "ping satellite error: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:211\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatelliteOnce:124\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatellite:95\n\tstorj.io/storj/storagenode/contact.(*Chore).updateCycles.func1:87\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"}
2020-08-24T19:32:48.738Z        INFO    contact:service context cancelled       {"Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2020-08-24T19:32:48.737Z        ERROR   contact:service ping satellite failed   {"Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "attempts": 1, "error": "ping satellite error: rpccompat: context canceled", "errorVerbose": "ping satellite error: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:211\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatelliteOnce:124\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatellite:95\n\tstorj.io/storj/storagenode/contact.(*Chore).updateCycles.func1:87\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"}
2020-08-24T19:32:48.738Z        INFO    contact:service context cancelled       {"Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2020-08-24T19:32:48.737Z        ERROR   contact:service ping satellite failed   {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "attempts": 1, "error": "ping satellite error: rpccompat: context canceled", "errorVerbose": "ping satellite error: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:211\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatelliteOnce:124\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatellite:95\n\tstorj.io/storj/storagenode/contact.(*Chore).updateCycles.func1:87\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"}
2020-08-24T19:32:48.739Z        INFO    contact:service context cancelled       {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2020-08-24T19:32:48.739Z        ERROR   nodestats:cache Get pricing-model/join date failed      {"error": "context canceled"}
2020-08-24T19:32:48.738Z        ERROR   contact:service ping satellite failed   {"Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "attempts": 1, "error": "ping satellite error: rpccompat: context canceled", "errorVerbose": "ping satellite error: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:211\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatelliteOnce:124\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatellite:95\n\tstorj.io/storj/storagenode/contact.(*Chore).updateCycles.func1:87\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"}
2020-08-24T19:32:48.737Z        ERROR   piecestore:cache        error getting current space used calculation:   {"error": "context canceled; context canceled; context canceled; context canceled", "errorVerbose": "group:\n--- context canceled\n--- context canceled\n--- context canceled\n--- context canceled"}
2020-08-24T19:32:48.739Z        INFO    contact:service context cancelled       {"Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2020-08-24T19:32:48.739Z        ERROR   contact:service ping satellite failed   {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "attempts": 1, "error": "ping satellite error: rpccompat: context canceled", "errorVerbose": "ping satellite error: rpccompat: context canceled\n\tstorj.io/common/rpc.Dialer.dialTransport:211\n\tstorj.io/common/rpc.Dialer.dial:188\n\tstorj.io/common/rpc.Dialer.DialNodeURL:148\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatelliteOnce:124\n\tstorj.io/storj/storagenode/contact.(*Service).pingSatellite:95\n\tstorj.io/storj/storagenode/contact.(*Chore).updateCycles.func1:87\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"}
2020-08-24T19:32:48.740Z        INFO    contact:service context cancelled       {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
Error: debug: http: Server closed

baker · August 24, 2020, 7:47pm

Are you sure you are running the commands on the correct storagenode container? The success rate script gets those values from the logs, so if it is being counted by the script, they must be in the logs. Or possibly you have removed and recreated the container since you ran it, which wipes the logs if they are not redirected to a file. If you run the success rate script again, I would bet it only shows successful or cancelled counts.

articulateape · August 24, 2020, 8:00pm

I had to check my original setup file and I didn’t save the log to a file, so that’s a bit of a mistake.

When I run the successrate script again it comes out as 100% success.

========== AUDIT ==============
Critically failed:     0
Critical Fail Rate:    0.000%
Recoverable failed:    0
Recoverable Fail Rate: 0.000%
Successful:            2
Success Rate:          100.000%

What should I do next? I think I need to redo the docker container so that it stores the log in a file, that would certainly be helpful for later. I didn’t do it before as I wasn’t aware that is how the logs are kept.

baker · August 24, 2020, 8:12pm

Unfortunately without the logs we probably won’t be able to determine what the problem is (or was). My suggestion would be to run the node for a while when you have time to periodically check the success rates. If everything seems okay, let it run and your node will get out of suspension after enough successful audits. Until that time you won’t see any uploads to your node. Only downloads (GET) and audits (GET_AUDIT).

Instructions for redirecting logs to a file can be found here.
https://documentation.storj.io/resources/faq/redirect-logs
There is no need to recreate the docker container if your want to use the standard log file redirect location, which defaults to the same location as the node storage location. You might want to set up logrotate at some point to prevent your log file from becoming too large.
https://forum.storj.io/search?q=logrotate
https://linux.die.net/man/8/logrotate

articulateape · August 24, 2020, 8:22pm

Thank you @baker for your help, I’ll redirect the log and see what happens over the next few days.

deathlessdd · August 24, 2020, 9:37pm

Are you running the success script with sudo?

articulateape · August 25, 2020, 2:38pm

I have now moved the log to a file and I can still run the script. It doesn’t need sudo unless I’m missing something here?

Here is the output using the log file on disk

========== AUDIT ==============
Critically failed:     0
Critical Fail Rate:    0.000%
Recoverable failed:    0
Recoverable Fail Rate: 0.000%
Successful:            22
Success Rate:          100.000%
========== DOWNLOAD ===========
Failed:                5
Fail Rate:             0.204%
Canceled:              110
Cancel Rate:           4.481%
Successful:            2340
Success Rate:          95.316%
========== UPLOAD =============
Rejected:              0
Acceptance Rate:       100.000%
---------- accepted -----------
Failed:                0
Fail Rate:             0.000%
Canceled:              1
Cancel Rate:           0.061%
Successful:            1636
Success Rate:          99.939%
========== REPAIR DOWNLOAD ====
Failed:                0
Fail Rate:             0.000%
Canceled:              0
Cancel Rate:           0.000%
Successful:            0
Success Rate:          0.000%
========== REPAIR UPLOAD ======
Failed:                0
Fail Rate:             0.000%
Canceled:              0
Cancel Rate:           0.000%
Successful:            19
Success Rate:          100.000%
========== DELETE =============
Failed:                0
Fail Rate:             0.000%
Successful:            57
Success Rate:          100.000%

Also, I think the node is coming back, two of the satellites are no longer suspended and the other three seem to be moving out of the suspended territory.