EndTime: 0001-01-01T00:00:00, Duration: 00:00:00 after restore with 2.0.4.21 (2.0.4.21_experimental_2019-06-28)

Support
1

Just took a Linux backup to Google Drive, did a restore to my Windows box using 2.0.4.21 (2.0.4.21_experimental_2019-06-28), and spotted this oddity at the end of a successful restore (with 6 warnings about symlinks):

Note the invalid EndTime and Duration values. Is this a known bug? I spotted it in a few google searches already, but nobody brought attention to it yet.

"Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 77,
    "BytesUploaded": 0,
    "BytesDownloaded": 18901306988,
    "FilesUploaded": 0,
    "FilesDownloaded": 76,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 154,
    "KnownFileSize": 18904464930,
    "LastBackupDate": "2019-08-06T17:28:03-07:00",
    "BackupListCount": 2,
    "TotalQuotaSpace": 11195518050471,
    "FreeQuotaSpace": 10995116277760,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Restore",
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2019-08-07T03:40:44.4185807Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
2

Just checked the log for a restore done to the same Linux box, and the bug is present there too.

"Warnings": [],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 77,
    "BytesUploaded": 0,
    "BytesDownloaded": 18901306988,
    "FilesUploaded": 0,
    "FilesDownloaded": 76,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 154,
    "KnownFileSize": 18904464930,
    "LastBackupDate": "2019-08-06T17:28:03-07:00",
    "BackupListCount": 2,
    "TotalQuotaSpace": 11171835604297,
    "FreeQuotaSpace": 10995116277760,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Restore",
    "ParsedResult": "Success",
    "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2019-08-07T00:31:55.390375Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
3

What’s interesting is that I just noticed at the top above the log the values are correct, so it’s just the log values that are incorrect:

 Aug 6, 2019 8:50 PM - Operation: Restore
Time
Start 2019-08-06 20:40:44
End 2019-08-06 20:50:21
Duration 00:09:37
Source Files
Examined 0 (0 bytes)
Opened 0 (0 bytes)
Added 0 (0 bytes)
Modified 0 (0 bytes)
Deleted 0
Restored Files 15545 (21.97 GB)
Restored Folders 2855
Restored Symlinks 0
 Warnings 6 
 Errors 0

 Aug 6, 2019 6:02 PM - Operation: Restore
Time
Start 2019-08-06 17:31:55
End 2019-08-06 18:02:32
Duration 00:30:38
Source Files
Examined 0 (0 bytes)
Opened 0 (0 bytes)
Added 0 (0 bytes)
Modified 0 (0 bytes)
Deleted 0
Restored Files 15545 (21.97 GB)
Restored Folders 2855
Restored Symlinks 0
 Warnings 0
 Errors 0
4

Might be a minor bug that was first visible in Improve UI for backup logs #3510 where log result code was being rearranged. In 2.0.4.5, BackendStatistics had fewer items. I’m not positive new ones are intentional but if they are, then they should be filled out. You could file a GitHub issue if you like. I see no obvious one.

        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
        Messages: [
            2019-08-08 16:31:11 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2019-08-08 16:31:16 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2019-08-08 16:31:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
            2019-08-08 16:31:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5917d9288f00413ea46f82ea83644b82.dblock.zip (675 bytes),
            2019-08-08 16:31:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b5917d9288f00413ea46f82ea83644b82.dblock.zip (675 bytes),
...
        ]
        Warnings: []
        Errors: []

      "Version": "2.0.4.22 (2.0.4.22_canary_2019-06-30)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2019-07-29T17:22:51.3884257Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
5

Done EndTime: 0001-01-01T00:00:00, Duration: 00:00:00 after restore with 2.0.4.21 (2.0.4.21_experimental_2019-06-28) · Issue #3853 · duplicati/duplicati · GitHub.

6

I’m not able to reproduce this. Did a test restore on Windows using 2.0.4.22:

  "Version": "2.0.4.22 (2.0.4.22_canary_2019-06-30)",
  "EndTime": "2019-08-09T02:32:19.6133324Z",
  "BeginTime": "2019-08-09T02:32:13.5794796Z",
  "Duration": "00:00:06.0338528",

do you have to back up on Linux and restore on Windows to see the problem?

7

Just tested “Direct restore from backup files” on a Windows PC to restore Linux backup data - didn’t make a difference. I see EndTime/Duration detail just fine.

EDIT: Also, not seeing any relevant differences between 2.0.4.21 and 2.0.4.22 that would account for this:

8

Not sure how to help you, but at least I know I’m not alone: "EndTime: 0001-01-01T00:00:00" duplicati - Buscar con Google.

9

Oh wait, you see that in the “Backend Statistics” section? I was not looking there, but rather in the main Restore stats.

10

Right, as per the 3rd message.

11

Ok, I see it now - even on backup jobs.

12

Maybe I’m wrong but it looks like the intent is to not actually show BeginTime, EndTime, and Duration for Backend stats:

I see nowhere in the code where EndTime is set for the backend stats. (BeginTime is initialized at creation of BasicResults ancestor class…)

13

I had the same path of seeing BeginTime, possible filtering intent, and no clear idea about EndTime plan.

EndTime: 0001-01-01T00:00:00, Duration: 00:00:00 after restore with 2.0.4.21 (2.0.4.21_experimental_2019-06-28) #3853

It’s not clear to me what BeginTime and EndTime, or the messages entries mean for BackendStatistics. Possibly original author will notice the touches on past pull request, and give some insight into the intent.

14

Did some more testing and it seems the ToString() override isn’t called at all. Maybe it’s a hangover from old code.

Instead I think this is what is used for serializing:

It has a parameter for filtering certain properties but I’m not seeing that it’s actually used… (it’s always null from what I can see)