Freezing mid-backup (profiling log level captured)

Tomahawk · December 22, 2018, 11:46pm

I have been trying to troubleshoot a recurring problem where duplicati seems to freeze mid-backup and requires the processes to restart to resume. I finally caught it in the act with Profiling log level enabled.

System:
Windows 10
Single user OS and all files backing up are under C:\users<user_name>
Duplicati - 2.0.4.5_beta_2018-11-28
Backing up via FTP over SSL (a few other clients backup successfully to the same FTP server)
Configuration and usage done via Web UI
Scheduled backups are enabled and set to run daily

There appears to be no backup activity for days. An initial backup has not yet completed yet (i.e. “Last successful run: Never”)

Symptoms:
The timestamp on the destination disk and the contents of the log show no recent activity. The Status was 0% for file DSC_0396.NEF upon my arrival and you can observe that file name in the log below.

Additional details:
Netstat -ano for connections to the destination IP showed only one (IP address redacted):

TCP 192.168.1.145:58396 x.x.x.x:21 ESTABLISHED 6540

Normally a netstat shows both command port 21 and a high data port. I stopped the backup in the UI which locked the database. I quit duplicati from the system tray, restarted the tray process and started the backup. The backup then resumed normally.

Log file below (last 30 lines). Note the last activity before I intervened was 12-20 and the timestamp corresponds with the last activity on the destination FTP disk. You can see today (12-22) when I stopped and tried to resume the backup but the database was locked. Sadly the log file contents don’t seem to indicate (to me) what caused things to freeze up. Thoughts?

2018-12-20 10:25:32 -06 - [Profiling-Duplicati.Library.Main.Operation.Common.BackendHandler-UploadSpeed]: Uploaded 38.25 KB in 00:00:06.1721901, 6.20 KB/s
2018-12-20 10:25:32 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i7b6b563af8364ff7b7f5ccc9c81628eb.dindex.zip.aes (38.25 KB)
2018-12-20 10:25:32 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: Starting - CommitAfterUpload
2018-12-20 10:25:32 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: CommitAfterUpload took 0:00:00:00.234
2018-12-20 10:25:32 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b68b12895e8df45d5ac234f721bcd90d5.dblock.zip.aes"
2018-12-20 10:25:32 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Remotevolume" WHERE "Name" = "duplicati-b68b12895e8df45d5ac234f721bcd90d5.dblock.zip.aes" took 0:00:00:00.000
2018-12-20 10:25:32 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba2297da1209c4d7882047fa69bf45472.dblock.zip.aes (50.00 MB)
2018-12-20 10:25:32 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-b3087a6404e194788a2f5b3d9dab5ae8a.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid();
2018-12-20 10:25:32 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (4, "duplicati-b3087a6404e194788a2f5b3d9dab5ae8a.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.078
2018-12-20 10:25:35 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-NewFile]: New file C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0395.NEF
2018-12-20 10:25:35 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0397.NEF
2018-12-20 10:25:35 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-CheckFileForChanges]: Checking file for changes C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0396.NEF, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 9/15/2018 3:21:52 AM vs 1/1/0001 12:00:00 AM
2018-12-20 10:25:38 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-NewFile]: New file C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0396.JPG
2018-12-20 10:25:38 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0398.JPG
2018-12-20 10:25:38 -06 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-CheckFileForChanges]: Checking file for changes C:\Users\Luke and Debbi\Pictures\2018-09\DSC_0397.JPG, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 9/15/2018 3:22:06 AM vs 1/1/0001 12:00:00 AM
2018-12-20 10:25:41 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: Starting - CommitAddBlockToOutputFlush
2018-12-20 10:25:46 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: CommitAddBlockToOutputFlush took 0:00:00:04.702
2018-12-22 15:37:41 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 3:05:38:22.578
2018-12-22 15:37:45 -06 - [Warning-Duplicati.Library.Main.Controller-DeprecatedOption]: The option log-level is deprecated: Use the log-file-log-level and console-log-level options instead
2018-12-22 15:37:45 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2018-12-22 15:37:45 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunBackup]: Starting - Running Backup
2018-12-22 15:37:45 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("Backup", 1545514665); SELECT last_insert_rowid();
2018-12-22 15:38:15 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("Backup", 1545514665); SELECT last_insert_rowid(); took 0:00:00:30.051
2018-12-22 15:38:15 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:00:30.246
2018-12-22 15:38:17 -06 - [Warning-Duplicati.Library.Main.Controller-DeprecatedOption]: The option log-level is deprecated: Use the log-file-log-level and console-log-level options instead
2018-12-22 15:38:17 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2018-12-22 15:38:17 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunBackup]: Starting - Running Backup
2018-12-22 15:38:17 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("Backup", 1545514697); SELECT last_insert_rowid();
2018-12-22 15:38:47 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("Backup", 1545514697); SELECT last_insert_rowid(); took 0:00:00:30.062
2018-12-22 15:38:47 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:00:30.066

JonMikelV · December 26, 2018, 9:23pm

I’m a little confused how you went from 2018-12-20 10:25:46 CommitAddBlockToOutputFlush took 0:00:00:04.702 to Running Backup took 3:05:38:22.578 days later then right into starting a backup.

The only thing I can think of is you’ve triggered the (known but not fixed) bug where a connectivity loss during a file put seems to cause Duplicati to wait forever for a response from the disconnected server.

I don’t suppose you’ve got access to the Remote job log to see what file transfers were going on around that 2018-12-20 10:25:46 time frame, do you?

(Note that I edited your post by adding > and “~~~” around some of your console and error lines to make them easier to read.)

Tomahawk · December 28, 2018, 3:44am

Where might I find the “Remote job log”? Next time I’m on-site I can try to retrieve it.

In the mean time, I wrote a crude BAT script that checks for 1 row rather than two on the netstat output. If there is only one, then it kills the duplicati process and restarts it. I then set a scheduled task to run it once a day. It does a few other things like first check that the process is even running, and it has some sleep timers in case it’s between file uploads. On my side (the destination) it appears that the backups are stopping at some point but resume some time later. So the script seems to be a work around.

Thanks for editing my post. I was trying to use the WYSIWYG editor to make the log file a code block but without luck.

ts678 · December 28, 2018, 12:55pm

My guess is “Remote job log” meant GUI’s Job --> Show logs --> Remote, but your Profiling log is even better.

2018-12-20 10:25:32 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i7b6b563af8364ff7b7f5ccc9c81628eb.dindex.zip.aes (38.25 KB)
2018-12-20 10:25:32 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba2297da1209c4d7882047fa69bf45472.dblock.zip.aes (50.00 MB)

There it sat for two days until you intervened manually. Any chance you can get the remote FTPS server log?
Server logs is an example for Filezilla Server, but other FTPS programs can probably do some similar logging, and would be easier than trying to decrypt the command stream, or guess situation by data channel watching. Depending on whether you trust the security of your network, debugging using FTP would be a little simpler…

Very crude logging for connectivity issues would be timed loop of dated netstat for the FTPS server address. This could be an addition to the script you already have. Let it run and fill up some disk space for later exam.

Alternatively, this might have nothing to do with communications, but an internal hang will be difficult to chase. Does the problem occur with a similar Profiling view each time? At least it’s good for debug in being recurring. Does a small backup with few options work? If so, you can start looking for a midpoint where the hang begins.

One possibility is that filling of blocks to upload paused because you hit –asynchronous-upload-limit so when manual intervention was done, there were still several uploads queued in your –asynchronous-upload-folder. This is hard to examine due to the random filenames and because Duplicati sometimes cleans up area badly. Looking in the database of the job is more direct, but you have to set --unencrypted-database on the Server, then use something like DB Browser for SQLite to look at RemoteVolume table for uploads that didn’t finish…