Node suspension - possible timezone (DST) issue?

Tonight was a Daylight Saving Time switch. I got a E-Mail about an hour ago that my node got suspended on asia-east-1. Since I just checked the dashboard yesterday I was wondering how so much audits could suddenly be failing.
What caught my eye was that the last contact is reported as being 60 minutes in the future. (Displays -60m ago)
Could my audits be failing due to incorrect time handling by storj?

Audits only seem to be failing on non EU servers - which further indicates that this is a DST issue?

Here is the screenshot that I couldn’t post in the first post due to being a new user:

Hi @robske110 and welcome to the forum!
The first thing to check would be your node’s logs: error entries should give us an idea why scores are dropping.

Could you have a look and report back?
You can use triple backticks to paste your suspicious log entries in here (if any) so they’re readable.
Example:

    ```
    Your logs
    ```

Running docker logs storagenode 2>&1 | grep -E "GET_AUDIT|GET_REPAIR" | grep failed yields ton of these:

2021-10-31T17:22:03.785Z	ERROR	piecestore	download failed	{"Piece ID": "Y63AO6TJVAW7OKTHKOHBJCIS3RYGR67EL4YGMPPN4YQSSN762JGA", "Satellite ID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "Action": "GET_REPAIR", "error": "order created too long ago: OrderCreation 2021-10-31 16:22:03.633145513 +0000 UTC < SystemClock 2021-10-31 17:22:03.78556177 +0000 UTC m=+165445.791976920", "errorVerbose": "order created too long ago: OrderCreation 2021-10-31 16:22:03.633145513 +0000 UTC < SystemClock 2021-10-31 17:22:03.78556177 +0000 UTC m=+165445.791976920\n\tstorj.io/common/rpc/rpcstatus.Errorf:87\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:45\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:490\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-31T17:37:04.006Z	ERROR	piecestore	download failed	{"Piece ID": "H5IFJFOFLYEMIEFMUENWTJKQUYQY6FKKZNITMCI5EGN6QINRBULQ", "Satellite ID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "Action": "GET_REPAIR", "error": "order created too long ago: OrderCreation 2021-10-31 16:37:03.82264757 +0000 UTC < SystemClock 2021-10-31 17:37:04.006868936 +0000 UTC m=+166346.013284087", "errorVerbose": "order created too long ago: OrderCreation 2021-10-31 16:37:03.82264757 +0000 UTC < SystemClock 2021-10-31 17:37:04.006868936 +0000 UTC m=+166346.013284087\n\tstorj.io/common/rpc/rpcstatus.Errorf:87\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:45\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:490\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-31T18:13:16.735Z	ERROR	piecestore	download failed	{"Piece ID": "3YJQDETWGXNYKN63FSQ34XTNIBZOZ4GSALZWT4R3GJHV5WVTN5HA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET_REPAIR", "error": "order created too long ago: OrderCreation 2021-10-31 17:13:15.764550026 +0000 UTC < SystemClock 2021-10-31 18:13:16.735026369 +0000 UTC m=+168518.741441511", "errorVerbose": "order created too long ago: OrderCreation 2021-10-31 17:13:15.764550026 +0000 UTC < SystemClock 2021-10-31 18:13:16.735026369 +0000 UTC m=+168518.741441511\n\tstorj.io/common/rpc/rpcstatus.Errorf:87\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:45\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:490\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-31T18:27:04.034Z	ERROR	piecestore	download failed	{"Piece ID": "WAADBJ7YCZISEALGDLKQRERJUAIOY5JSFRKPMEE47ODYGVIQJKMQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET_REPAIR", "error": "order created too long ago: OrderCreation 2021-10-31 17:27:03.350922039 +0000 UTC < SystemClock 2021-10-31 18:27:04.034182423 +0000 UTC m=+169346.040597572", "errorVerbose": "order created too long ago: OrderCreation 2021-10-31 17:27:03.350922039 +0000 UTC < SystemClock 2021-10-31 18:27:04.034182423 +0000 UTC m=+169346.040597572\n\tstorj.io/common/rpc/rpcstatus.Errorf:87\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:45\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:490\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"}

Since I restarted the server these errors do not pop up anymore. System clock was also correct before the restart though.

the storagenodes run on UTC this is a timezone and summer winter time agnostic, however i suppose it is possible for your local clock to affect your node.

the offset on the webdash board also happens when one sets a computer in standby and wakes it up later, this has nothing to do with the actual node time, but only when the webdash running on your website viewing device last had contact with the node, and some things offsets it.

not sure how fast one can earn a suspension, but its rarely instant if ever…
if your suspension scores are going up again, i would suppose the problem is gone…
what exactly happened is difficult to say…

sure it could be time adjustment from the summer winter switch, but i don’t think that actually changes anything… you will be on DST and then move to the DSTS (summer timezone) or such thus your clock will not be changed, only the modifier which is applied to it for your usages.

i would say the recent solar flare, a bad hdd cable or just random weirdness that computers sometimes have from running 24/7

but i seriously doubt that its related to time, also keep in mind time keeping has been a critical feature since the dawn of computing, so its pretty rock solid.

Is it a docker node? The docker node might not be aware of your timezone and when the host system screws up the clock than docker might get confused by that. Maybe check if there are any docker + timezone issues for your setup.

1 Like

This happened to me today. My QNAP server was set to an ntp server but testing interval was set to 1-day instead of 1-hour. So when DST was reverted today the time on server didn’t get changed automatically soon enough resulting in account suspension. I’ve now corrected the time, restarted the whole server just in case and restarted docker. Half an hour later i’ve got the email from storj that from one of the satellelites i’ve been unsuspended (although it will take some time to imporve my red %s). Yay!

Hello @PrasangaD,
Welcome to the forum!

This is weird. What was a reason of the suspension? The online score or suspension score?

1 Like

Hi Alexey,
Thank you!
It was the suspention score. Woke up to see couple of automated emails from satellites that the node has been suspended due to audit errors. Found this thread, realised the server time is different to PC/mobile time. Now all good, both suspensions were removed about an hour later and my scores are steadily improving!

Just to add, I had the same time issue here in New Zealand…

Daylight Savings changed over the weekend and for some odd reason the server did not automatically update the time. I woke up this morning to a pile of suspension “suspended for returning errors in response to audits” emails . Within 10 minutes of fixing the time, started getting ‘unsuspended’ emails.

MIght I suggest the Storj dashboard pops up a less scary error message if it detect the time is incorrect and can lead to suspension, I can’t imagine it is that difficult for Storj to detect.

One other thing to address is the log file size, over 2.5GB at the moment, and notepad++ can’t open it… probably needs to be truncated on a weekly/ monthly basis

What was the error message in the logs?

You may do so using either logrotate for Windows or using a PowerShell script like this: Native logs rotation in Windows with a simple PowerShell script
However, you may also just stop the service and move the log file to the archive, then start the service.
To check logs you may also use this method: How do I check my logs? - Storj Docs

1 Like

I have been able to split up the log file using a powershell script I found on here somewhere.

I have uploaded a selection of it to DB for you to have a look at,

The original problem has resolved itself - no longer suspended

So the error is

2023-04-03T03:31:34.287+1200	ERROR	piecestore	download failed	{"Piece ID": "77MP7NTLZEIM52RIRK23NJTH2VVMJS3XFBANX6LPV4AVWUS2MGAA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET_AUDIT", "Remote Address": "34.94.0.20:49434", "error": "order created too long ago: OrderCreation 2023-04-02 14:31:32.851329392 +0000 UTC < SystemClock 2023-04-03 03:31:34.2870324 +1200 NZST m=+345543.668706001", "errorVerbose": "order created too long ago: OrderCreation 2023-04-02 14:31:32.851329392 +0000 UTC < SystemClock 2023-04-03 03:31:34.2870324 +1200 NZST m=+345543.668706001\n\tstorj.io/common/rpc/rpcstatus.Errorf:89\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:45\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:599\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:251\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:61\n\tstorj.io/common/experiment.(*Handler).HandleRPC:42\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:124\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:66\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:114\n\tstorj.io/drpc/drpcctx.(*Tracker).track:35"}

You may change the server to use a system time. Since you use Windows it can be changed in BIOS. Windows doesn’t have such a configuration option.

1 Like

On a Linux instance then I always install NTP, set the NTP servers then run timedatectl set-timezone UTC before installing anything.

1 Like