Snapshot time offset by +4 hours


#1

This may be a system problem, but I can’t tell.

When I do a restic backup from my Cygwin laptop, the date/time in the snapshot list is correct.
When I do a restic backup from my router shell (dd-wrt), the date/time shows four hours later than the actual time.
Both backups are to the same repo, over sftp: (if that matters).

Within the router, the date command returns the correct date and time.

My current time zone is New York, EST5EDT.

Any ideas what would cause this 4 hour offset?

Thanks - Steven


#2

Can you please paste the output of restic cat snapshot <id> for the two snapshots? Maybe we can see what’s going on. I suspect that something in the timezone configuration is wrong…


#3

Snapshot with correct time:

{
  "time": "2018-11-01T20:00:07.539578-04:00",
  "parent": "26f2ae334de61efc99acbdeb5be7180c7da458d707ec8d3d61e3300740613861",
  "tree": "7a9eaa1ef4143cc90881c21645bce0f64c951d574ed2f6c1bcb5e986b9b0533e",
  "paths": [
    "c:\\"
  ],
  "hostname": "STEVENLT5",
  "username": "STEVENLT5\\STEVEN"
}

Snapshot with time +4 hours:

{
  "time": "2018-11-02T01:00:00.93344552Z",
  "parent": "72d5f1c9bb3d396c40c6e9c6c156eef980303db6f3a4079970fe304ccb31db9c",
  "tree": "6ee06392f080e82657d43d930277038edb190ee0e767dad23968a7d820569631",
  "paths": [
    "/jffs"
  ],
  "hostname": "router",
  "excludes": [
    "/jffs/share",
    "/jffs/lost+found"
  ]
}

#4

Oh, interesting, that’s actually a bug in restic: the snapshots command displays the time stamp as it is, without converting it to the local time zone first. The timestamps for your two snapshots have a different timezone: -04:00 (EST?) and Z (UTC).

I’ve written a small program which parses the timestamps:

2018-11-01 20:00:07.539578 -0400 -0400
2018-11-01 20:00:07
2018-11-02 01:00:07.539578 +0100 CET
2018-11-02 01:00:07
---------------
2018-11-02 01:00:00.93344552 +0000 UTC
2018-11-02 01:00:00
2018-11-02 02:00:00.93344552 +0100 CET
2018-11-02 02:00:00

The first line is the timestamp as has been parsed, the second line is the formatting restic applies for the snapshots command. You can see that it’s 8pm for the first snapshot, and 1am for the second snapshot, that’s just the verbatim values from the time stamp. It looks like as if the snapshots have been taken 5 hours apart.

The third line prints the timestamp converted to local time (Central European Time for me). When you then take the values it makes sense, both snapshots are an hour apart, as you can see in the fourth line.

I’ll fix this and make the snapshots command (and the others concerning time stamps) display the local time.


#5

So it sounds like it was just a display bug in the snapshots command, correct?

If so, that’s great! Glad to find something to improve this tool!

By the way, I am really digging this tool.

– Steven


#6

If/when you want me to verify a beta, let me know.


#7

Well, let’s call it “misfeature”: restic did not display timezone information.

It will be addressed in


#8

You know what the difference is between a bug and a feature?
A good documentation writer! :smile:


#9

It’s merged to master now, you can either build the code yourself and try it, or use the binary that will appear in a few minutes here: https://beta.restic.net/restic-v0.9.3-56-ga630d69e/


#10

Verified, the problem is fixed.

$ restic -r sftp:root@svcrpi:/wd/restic/restic-other snapshots
ID        Time                 Host        Tags        Paths
------------------------------------------------------------
cc9ccbc6  2018-10-22 16:14:17  STEVENLT5               c:\
92b2eb7c  2018-10-25 08:10:00  STEVENLT5               c:\
26f2ae33  2018-10-31 02:56:39  STEVENLT5               c:\
ba4c3266  2018-11-01 19:20:00  router                  /jffs
fc161b32  2018-11-01 20:00:07  STEVENLT5               c:\
60e5cdc9  2018-11-01 21:00:00  router                  /jffs
------------------------------------------------------------
6 snapshots

$ restic version
restic 0.9.3 (v0.9.3-56-ga630d69e) compiled with go1.10.2 on windows/amd64

The last 2 lines of the snapshot were the troublesome ones, which now show the correct time.

Thanks!


#11

I spoke too soon.

I installed the same beta on my dd-wrt ARM router, and the snapshots display is off by 4 hours for every snapshot when viewed from the router, but correct when viewed from my Windows laptop.

View from the router:

root@router:/jffs# restic version
restic 0.9.3 (v0.9.3-56-ga630d69e) compiled with go1.10.2 on linux/arm
root@router:/jffs# restic -vv -o sftp.command="ssh svcrpi -i /tmp/root/.ssh/id_rsa.dropbear -s sftp" \
    -r sftp::/wd/restic/restic-other snapshots

repository 3edbcbc1 opened successfully, password is correct
ID        Time                 Host        Tags        Paths
------------------------------------------------------------
cc9ccbc6  2018-10-22 20:14:17  STEVENLT5               c:\
92b2eb7c  2018-10-25 12:10:00  STEVENLT5               c:\
26f2ae33  2018-10-31 06:56:39  STEVENLT5               c:\
ba4c3266  2018-11-01 23:20:00  router                  /jffs
fc161b32  2018-11-02 00:00:07  STEVENLT5               c:\
60e5cdc9  2018-11-02 01:00:00  router                  /jffs
a011b0e2  2018-11-03 01:00:00  router                  /jffs
56aa74f7  2018-11-03 05:47:59  router                  /jffs
29d24198  2018-11-03 05:49:52  STEVENLT5               c:\
------------------------------------------------------------
9 snapshots

View from the Windows 10 laptop:

$ restic version
restic 0.9.3 (v0.9.3-56-ga630d69e) compiled with go1.10.2 on windows/amd64

$ restic -r sftp:root@svcrpi:/wd/restic/restic-other snapshots
ID        Time                 Host        Tags        Paths
------------------------------------------------------------
cc9ccbc6  2018-10-22 16:14:17  STEVENLT5               c:\
92b2eb7c  2018-10-25 08:10:00  STEVENLT5               c:\
26f2ae33  2018-10-31 02:56:39  STEVENLT5               c:\
ba4c3266  2018-11-01 19:20:00  router                  /jffs
fc161b32  2018-11-01 20:00:07  STEVENLT5               c:\
60e5cdc9  2018-11-01 21:00:00  router                  /jffs
a011b0e2  2018-11-02 21:00:00  router                  /jffs
56aa74f7  2018-11-03 01:47:59  router                  /jffs
29d24198  2018-11-03 01:49:52  STEVENLT5               c:\
------------------------------------------------------------
9 snapshots


#12

It sounds like, then, that the router’s time zone config is wonky – at least the snapshot times are consistent, so I think restic is doing its job correctly there. I can’t explain why date shows the correct timezone though.


#13

It is strange. But then this is a dd-wrt router based on busybox.
Like you mentioned, the date shows correctly:

root@router:~# date
Sat Nov  3 14:13:15 EDT 2018
root@router:~# echo $TZ
EST5EDT,M3.2.0,M11.1.0

I’m not too concerned - I don’t use the router to do anything with restic, except for a backup.
It’s not a show-stopper that all reported snapshot times are 4 hours off…


#14

I suspect the Go runtime is unable to extract the local timezone from the dd-wrt system, which may be different from what Linux systems normally do. I’d leave it at that (at least for now).