Node System Clock out of sync .. but time is OK?

Node Operators troubleshooting
, ,
1

Hiya. I’m in Germany, it’s a little to 10pm as I type this.

My node cannot start, because it says time is not correct. I don’t understand.

The node think it’s an hour earlier than it is. That’s not correct. What do?

logs:

docker@ubuntu:/mnt/disk01_87152afd/storagenode01$ docker compose up
[+] Running 1/1
 ✔ Container storagenode01  Created                                                                                                               0.0s
Attaching to storagenode01
storagenode01  | 2025-03-07 20:42:59,166 INFO RPC interface 'supervisor' initialized
storagenode01  | 2025-03-07 20:42:59,167 INFO supervisord started with pid 1
storagenode01  | 2025-03-07 20:43:00,168 INFO spawned: 'processes-exit-eventlistener' with pid 25
storagenode01  | 2025-03-07 20:43:00,170 INFO spawned: 'storagenode' with pid 26
storagenode01  | 2025-03-07 20:43:00,173 INFO spawned: 'storagenode-updater' with pid 27
storagenode01  | 2025-03-07T20:43:00Z  INFO    Configuration loaded    {"Process": "storagenode-updater", "Location": "/app/config/config.yaml"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "healthcheck.enabled"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "storage.allocated-disk-space"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "operator.email"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "operator.wallet-features"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "healthcheck.details"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "server.private-address"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "contact.external-address"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "operator.wallet"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "console.address"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Invalid configuration file key  {"Process": "storagenode-updater", "Key": "server.address"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Anonymized tracing enabled      {"Process": "storagenode-updater"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Running on version      {"Process": "storagenode-updater", "Service": "storagenode-updater", "Version": "v1.122.9"}
storagenode01  | 2025-03-07T20:43:00Z  INFO    Downloading versions.   {"Process": "storagenode-updater", "Server Address": "https://version.storj.io"}
storagenode01  | 2025-03-07 20:43:01,210 INFO success: processes-exit-eventlistener entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
storagenode01  | 2025-03-07 20:43:01,211 INFO success: storagenode entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
storagenode01  | 2025-03-07 20:43:01,211 INFO success: storagenode-updater entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
storagenode01  | 2025-03-07T20:43:30Z  ERROR   Error retrieving version info.  {"Process": "storagenode-updater", "error": "version checker client: Get \"https://version.storj.io\": dial tcp 34.173.164.90:443: i/o timeout", "errorVerbose": "version checker client: Get \"https://version.storj.io\": dial tcp 34.173.164.90:443: i/o timeout\n\tstorj.io/storj/private/version/checker.(*Client).All:68\n\tmain.loopFunc:20\n\tstorj.io/common/sync2.(*Cycle).Run:102\n\tmain.cmdRun:139\n\tstorj.io/common/process.cleanup.func1.4:392\n\tstorj.io/common/process.cleanup.func1:410\n\tgithub.com/spf13/cobra.(*Command).execute:985\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1117\n\tgithub.com/spf13/cobra.(*Command).Execute:1041\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tstorj.io/common/process.ExecWithCustomConfigAndLogger:77\n\tmain.main:22\n\truntime.main:272"}
storagenode01  | 2025-03-07T20:43:30Z  ERROR   version failed to get process version info      {"Process": "storagenode", "error": "version checker client: Get \"https://version.storj.io\": dial tcp 34.173.164.90:443: i/o timeout", "errorVerbose": "version checker client: Get \"https://version.storj.io\": dial tcp 34.173.164.90:443: i/o timeout\n\tstorj.io/storj/private/version/checker.(*Client).All:68\n\tstorj.io/storj/private/version/checker.(*Client).Process:89\n\tstorj.io/storj/private/version/checker.(*Service).checkVersion:104\n\tstorj.io/storj/private/version/checker.(*Service).CheckVersion:78\n\tmain.cmdRun:91\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:392\n\tstorj.io/common/process.cleanup.func1:410\n\tgithub.com/spf13/cobra.(*Command).execute:985\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1117\n\tgithub.com/spf13/cobra.(*Command).Execute:1041\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:272"}
storagenode01  | 2025-03-07T20:43:30Z  WARN    trust   Failed to fetch URLs from source; used cache    {"Process": "storagenode", "source": "https://static.storj.io/dcs-satellites", "error": "HTTP source: \"https://static.storj.io/dcs-satellites\": unexpected status code 403: \"\"", "errorVerbose": "HTTP source: \"https://static.storj.io/dcs-satellites\": unexpected status code 403: \"\"\n\tstorj.io/storj/storagenode/trust.(*HTTPSource).FetchEntries:76\n\tstorj.io/storj/storagenode/trust.(*List).fetchEntries:90\n\tstorj.io/storj/storagenode/trust.(*List).FetchURLs:49\n\tstorj.io/storj/storagenode/trust.(*Pool).fetchURLs:326\n\tstorj.io/storj/storagenode/trust.(*Pool).Refresh:209\n\tstorj.io/storj/storagenode.(*Peer).Run:1085\n\tmain.cmdRun:127\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:392\n\tstorj.io/common/process.cleanup.func1:410\n\tgithub.com/spf13/cobra.(*Command).execute:985\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1117\n\tgithub.com/spf13/cobra.(*Command).Execute:1041\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:272"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   preflight:localtime     unable to get satellite system time     {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "error": "rpc: tcp connector failed: rpc: dial tcp 34.159.134.91:7777: connect: connection timed out", "errorVerbose": "rpc: tcp connector failed: rpc: dial tcp 34.159.134.91:7777: connect: connection timed out\n\tstorj.io/common/rpc.HybridConnector.DialContext.func1:190"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   preflight:localtime     unable to get satellite system time     {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "error": "rpc: tcp connector failed: rpc: dial tcp 34.126.92.94:7777: connect: connection timed out", "errorVerbose": "rpc: tcp connector failed: rpc: dial tcp 34.126.92.94:7777: connect: connection timed out\n\tstorj.io/common/rpc.HybridConnector.DialContext.func1:190"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   preflight:localtime     unable to get satellite system time     {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "error": "rpc: tcp connector failed: rpc: dial tcp 34.94.153.46:7777: connect: connection timed out", "errorVerbose": "rpc: tcp connector failed: rpc: dial tcp 34.94.153.46:7777: connect: connection timed out\n\tstorj.io/common/rpc.HybridConnector.DialContext.func1:190"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   preflight:localtime     unable to get satellite system time     {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "error": "rpc: tcp connector failed: rpc: dial tcp 34.150.199.48:7777: connect: connection timed out", "errorVerbose": "rpc: tcp connector failed: rpc: dial tcp 34.150.199.48:7777: connect: connection timed out\n\tstorj.io/common/rpc.HybridConnector.DialContext.func1:190"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   Failed preflight check. {"Process": "storagenode", "error": "system clock is out of sync: system clock is out of sync with all trusted satellites", "errorVerbose": "system clock is out of sync: system clock is out of sync with all trusted satellites\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check:96\n\tstorj.io/storj/storagenode.(*Peer).Run:1089\n\tmain.cmdRun:127\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:392\n\tstorj.io/common/process.cleanup.func1:410\n\tgithub.com/spf13/cobra.(*Command).execute:985\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1117\n\tgithub.com/spf13/cobra.(*Command).Execute:1041\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:272"}
storagenode01  | 2025-03-07T20:45:39Z  ERROR   failure during run      {"Process": "storagenode", "error": "system clock is out of sync: system clock is out of sync with all trusted satellites", "errorVerbose": "system clock is out of sync: system clock is out of sync with all trusted satellites\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check:96\n\tstorj.io/storj/storagenode.(*Peer).Run:1089\n\tmain.cmdRun:127\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:392\n\tstorj.io/common/process.cleanup.func1:410\n\tgithub.com/spf13/cobra.(*Command).execute:985\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1117\n\tgithub.com/spf13/cobra.(*Command).Execute:1041\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:272"}
storagenode01  | Error: system clock is out of sync: system clock is out of sync with all trusted satellites
storagenode01  | 2025-03-07 20:45:40,934 WARN exited: storagenode (exit status 1; not expected)
storagenode01  | 2025-03-07 20:45:41,936 INFO spawned: 'storagenode' with pid 39
storagenode01  | 2025-03-07 20:45:41,937 WARN received SIGQUIT indicating exit request
storagenode01  | 2025-03-07 20:45:41,938 INFO waiting for processes-exit-eventlistener, storagenode, storagenode-updater to die
storagenode01  | 2025-03-07T20:45:41Z  INFO    Got a signal from the OS: "terminated"  {"Process": "storagenode-updater"}
storagenode01  | 2025-03-07 20:45:41,939 INFO stopped: storagenode-updater (exit status 0)
storagenode01  | 2025-03-07 20:45:44,943 INFO waiting for processes-exit-eventlistener, storagenode to die
Gracefully stopping... (press Ctrl+C again to force)
[+] Stopping 1/1
 ✔ Container storagenode01  Stopped                                                                                                                                                                                    5.7s
docker@ubuntu:/mnt/disk01_87152afd/storagenode01

docker@ubuntu:/mnt/disk01_87152afd/storagenode01$ date
Fri  7 Mar 21:47:10 CET 2025

Addded info
I cannot port forward on my internet here at home and my address outside is weird.

Ended making wireguard tunnel with AirVPN, who provide port forward. This has been working for long time. I have ensured my VPN external IP has not changed. Everything is as it has always been, which has always function

2

I usually see that as a general error: when a node can’t connect to any satellite. Something is b0rked with your networking.

1 Like
3

Thank you for quick response. I just don’t understand.

Ubuntu can get updates just fine, I can ping various websites

When I ping address in log, I get answer fine as well

docker@ubuntu:~$ ping 34.173.164.90
PING 34.173.164.90 (34.173.164.90) 56(84) bytes of data.
64 bytes from 34.173.164.90: icmp_seq=1 ttl=52 time=137 ms
64 bytes from 34.173.164.90: icmp_seq=2 ttl=52 time=137 ms
64 bytes from 34.173.164.90: icmp_seq=3 ttl=52 time=137 ms
64 bytes from 34.173.164.90: icmp_seq=4 ttl=52 time=137 ms
64 bytes from 34.173.164.90: icmp_seq=5 ttl=52 time=137 ms
^C
--- 34.173.164.90 ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 4004ms
rtt min/avg/max/mdev = 136.920/136.989/137.086/0.061 ms
docker@ubuntu:~$
4

It’s important; I should add.

I cannot port forward on my internet here at home and my address outside is weird.

Ended making wireguard tunnel with AirVPN, who provide port forward. This has been working for long time. I have ensured my VPN external IP has not changed. Everything is as it has always been, which has always function

5

Are you sure the system clock on your machine is not off by one hour? From your log message time stamps it looks that way.

1 Like
6

Hello mr Heunland. Thank you for your quick response What does “Storjling” mean?

The time on the Ubuntu machine is correct, as seen below. This matches with time on my wristwatch. I can take picutres, but you must trust me on this lol

docker@ubuntu:/$ date
Fri  7 Mar 22:22:27 CET 2025

I agrees, time within storagenode docker is 1 hour behind. I don’t understand how this can happen. Docker should take time from hostmachine.

7

I don’t think it’s a time problem. Your node can’t connect to any of the four satellites: something messed up with wireguard?

1 Like
8

Additional info. American changes winter/summer time I think this Sunday. I Germany it’s the last Sunday in March. Could that be the problem?

9

I guess it’s possible. But every time I’ve seen a “system clock is out of sync with all trusted satellites” error, it was always a general network-connectivity issue. Every. Single. Time. It was never a time problem.

I guess there’s always a first time though… :wink:

1 Like
10

You have two response: I reply to this one.

I am not a master of Wireguard, maybe something is wrong. I don’t understand how. This setup as been working all time, and as you see I ping the address outside of docker fine no problem. It’s good that you have never seen a time problem. I like that the software behavies in similar ffahion over many problems

11

She’s a Ms., I think. And “Storjling” means Storj employee.

3 Likes
12

My apologies. Thank you.

13

I think I have confirmed time drift inside the container.

docker@ubuntu:/mnt/disk01_87152afd/storagenode01$ docker exec -u 0 -it storagenode01 bash
root@5dcbc5105e9e:/app# date
Fri Mar  7 21:46:32 Europe 2025
root@5dcbc5105e9e:/app# exit
exit
docker@ubuntu:/mnt/disk01_87152afd/storagenode01$ date
Fri  7 Mar 22:46:35 CET 2025
docker@ubuntu:/mnt/disk01_87152afd/storagenode01$
14

CET time zone? Mine is showing UTC from inside the container.

15

I still think you’re chasing the wrong issue. The log isn’t saying:

“I contacted the satellites, and the node time differs”

… it’s saying:

“I couldn’t connect to port 7777 on any of the satellites, for any reason. Oh, and BTW, if I could have connected I would have asked about the time”

2 Likes
16

You are probably right. I restarted the container, and now it has right time.
It has still no connection

docker@ubuntu:/mnt/disk01_87152afd/storagenode01 date
Fri  7 Mar 23:10:28 CET 2025
docker@ubuntu:/mnt/disk01_87152afd/storagenode01 docker exec -u 0 -it storagenode01 bash
root@49f7910b3b77:/app# date
Fri Mar  7 23:10:33 CET 2025
root@49f7910b3b77:/app# exit
exit
docker@ubuntu:/mnt/disk01_87152afd/storagenode01

@Mark - I use CET. It should not make big difference

17

Have you tested different VPN servers? I had a similar problem where a server could not connect to https://version.storj.io.

18

I have not done that yet. I have read a bit about VPNs on this forum, and it seems like I am on the edge of what is allowed. I don’t dare hopping IP too many times. I don’t want ban, I want to provide good stabil storage.

This VPN endpoint has always worked - should I be in risk of it suddenly not working?

19

IPs don’t matter, no reason to stick with the same server.

1 Like
20

Confirmed, jumping to another VPN endpoint fixed the issues.

Does anyone have any idea why this happen?