System clock is out of sync: system clock is out of sync with all trusted satellites

Node Operators troubleshooting
1

I’m getting this error on my storage node despite the system clock being in sync with ntp.org. Any suggestions from the group on what I can do to try and resolve this issue?

2020-04-07T04:19:50.276Z ERROR preflight:localtime unable to get satellite system time {"Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "error": "rpccompat: context deadline exceeded", "errorVerbose": "rpccompat: context deadline exceeded\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

Thanks

2

Welcome to the forum @Archness!

Have you tried this ? http://www.timesynctool.com/

3

Considering that the system is sync’d using NTP (as mentioned in the first post) and is *nix based (Synology) I don’t think I need that tool but thanks for the suggestion.

4

I am not familiar with synology but is it possible that the time is syncing rather than synced? I would suggest “ntpq -p” or “timedatectl” on a linux box, is there anything like that available to you?

5

Does it show your node to be online ?

6

Time on the *nix host is in sync as many other things that rely on time (ssl certs, backup timing, user auth, and more) would break. I’m wondering if the docker instance is losing its time.

The node is in a continuous reboot due to the time issue.

7

Below is the output from ntpq -p.

user@storj:~$ ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 time-b-wwv.nist .INIT.          16 u    - 1024    0    0.000    0.000   0.000

Looking in the docker terminal, the time on the docker terminal is accurate as well.

8

as i remember, synology time is not very good. so need to sync it every 1h.

9

The time is up to date and auto syncs. Believe me, a lot would break in my environment if time went out of sync.

10

“16” for the state is bad

11

for reference, this is on my system:

     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 0.ubuntu.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.000
 1.ubuntu.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.000
 2.ubuntu.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.000
 3.ubuntu.pool.n .POOL.          16 p    -   64    0    0.000    0.000   0.000
 ntp.ubuntu.com  .POOL.          16 p    -   64    0    0.000    0.000   0.000
 ts1.sct.de      192.53.103.104   2 u    1   64    1   38.480    7.834   0.000
 web.nozel.org   89.38.99.207     3 u    -   64    1   29.538    3.456   2.854
 mail.klausen.dk 193.79.237.14    2 u    1   64    1   55.012   13.619   7.978
 app01.arbeidsde 193.79.237.14    2 u    -   64    1   30.188    4.068   2.214
 vmhost-external 129.69.1.153     2 u    1   64    1   40.022    7.259   0.000
 dock-4.deployin 131.188.3.222    2 u    1   64    1   41.520    6.356   0.000
 pugot.canonical 145.238.203.14   2 u    1   64    1   35.467    3.171   0.000
12

In testing I tried to swap to NIST but it appears to be broken, (to be clear, I made the change to NIST a few minutes before testing that.) My system clock on the NAS has been in sync. I swapped back to ntp.org pool and here is the result. The system clock on the box shows it is close enough to not be causing this error.

remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 pool.ntp.org    .POOL.          16 p    -   64    0    0.000    0.000   0.000
 srcf-ntp.stanfo 171.64.7.73      2 u    1   64    1   62.082    2.898   1.371
 static-72-87-88 129.6.15.29      2 u    2   64    1   34.768   -1.937   0.011
 linode227395.st 45.15.168.198    3 u    1   64    1   28.516    1.145   1.385
13

What about the clock inside the docker container?

14

I had to run the test using a different container as the storagenode container won’t stop restarting. Using the ubuntu_bash container and running uptime shows that the time is accurate and that container is using the host time, not container time.

15

I tried removing all containers and reinstalling. I also reinstalled docker. Still getting the same error.

16

Can you show last 20 lines of the log ?

17 
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.442Z e[31mFATALe[0m failed preflight check {"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:648\n\tmain.cmdRun:208\n\tstorj.io/storj/pkg/process.cleanup.func1.2:312\n\tstorj.io/storj/pkg/process.cleanup.func1:330\n\tgithub.com/spf13/cobra.(*Command).execute:826\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:914\n\tgithub.com/spf13/cobra.(*Command).Execute:864\n\tstorj.io/storj/pkg/process.ExecWithCustomConfig:84\n\tstorj.io/storj/pkg/process.ExecCustomDebug:66\n\tmain.main:328\n\truntime.main:203"}|
| --- | --- | --- |
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.442Z e[31mERRORe[0m preflight:localtime unable to get satellite system time {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "error": "rpccompat: context deadline exceeded", "errorVerbose": "rpccompat: context deadline exceeded\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}|
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.418Z e[31mERRORe[0m preflight:localtime unable to get satellite system time {"Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "error": "rpccompat: context deadline exceeded", "errorVerbose": "rpccompat: context deadline exceeded\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}|
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.418Z e[31mERRORe[0m preflight:localtime unable to get satellite system time {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "error": "rpccompat: context deadline exceeded", "errorVerbose": "rpccompat: context deadline exceeded\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}|
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.419Z e[31mERRORe[0m preflight:localtime unable to get satellite system time {"Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "error": "rpccompat: context deadline exceeded", "errorVerbose": "rpccompat: context deadline exceeded\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}|
|2020-04-07 06:12:29|stderr|2020-04-07T06:12:29.419Z e[31mERRORe[0m preflight:localtime unable to get satellite system time {"Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "error": "rpccompat: dial tcp 34.80.94.151:7777: i/o timeout", "errorVerbose": "rpccompat: dial tcp 34.80.94.151:7777: i/o timeout\n\tstorj.io/common/rpc.Dialer.dialTransport:256\n\tstorj.io/common/rpc.Dialer.dial:233\n\tstorj.io/common/rpc.Dialer.DialAddressID:152\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).getSatelliteTime:110\n\tstorj.io/storj/storagenode/preflight.(*LocalTime).Check.func1:67\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}|
|2020-04-07 06:12:09|stderr|2020-04-07T06:12:09.395Z e[34mINFOe[0m preflight:localtime start checking local system clock with trusted satellites' system clock.|
|2020-04-07 06:12:06|stderr|2020-04-07T06:12:06.271Z e[34mINFOe[0m db.migration Database Version {"version": 33}|
|2020-04-07 06:12:02|stderr|2020-04-07T06:12:02.955Z e[34mINFOe[0m version running on version v1.0.1|
|2020-04-07 06:12:02|stderr|2020-04-07T06:12:02.265Z e[34mINFOe[0m operator wallet: |
|2020-04-07 06:12:02|stderr|2020-04-07T06:12:02.265Z e[34mINFOe[0m Operator email: mail@domain.com|
|2020-04-07 06:12:02|stderr|2020-04-07T06:12:02.255Z e[34mINFOe[0m Configuration loaded from: /app/config/config.yaml|
18

Can you confirm if your port is open ?

19

Is that how it works?!

Here is an idea: does the time that storagenode is logging match the time when it is happening? i.e. in docker logs -f storagenode is the time correct in those logs?
It looks like it logs in UTC or Zulu so mine is logging 2020-04-07T10:35:48.148Z at 11:35 (UTC+1)

20

That indicates you have a problem with your network and not with your system clock. If your system clock would be wrong you would see the offset here. Instead you get an error message that you couldn’t reach the satellite.

1 Like