Afternoon all, noticed recently that one of my main backup jobs gets stuck at this phase. I’ve tried deleting and re-creating database, which succeeds but the jobs still gets stuck at that point. Looking at the logs, General log doesn’t have any entry created when I try to run the job and the Remote log just shows a single operation “list” with a whole bunch of entries such as:
{“Name”:“duplicati-20180703T051202Z.dlist.zip.aes”,“LastAccess”:“2018-07-03T05:41:14.799Z”,“LastModification”:“2018-07-03T05:41:14.799Z”,“Size”:337117,“IsFolder”:false},
I don’t see any network activity other than 842 B/sec coming from Duplicati.GUI.TrayIcon.exe, which I don’t think is the actual job running?
Another job backing up different things runs fine, so it just seems this one is stuck somehow.
Any ideas to try to troubleshoot other than deleting the job and re-creating?
One way to be sure of your assumption that Duplicati is stuck doing nothing (versus doing background processing that’s just taking a while) is to view the Profiling-level log - i believe you can do this after the apparent “stuck spot” is reached - because even if the normal UI is stuck doing nothing at that point, the profiling log will show whatever activity is happening in the background regardless.
Thank you Drakar2007. It does seem to be doing something, as I see it’s CPU utilization sitting at 22% and varying up/down about 1%. I enabled profiling and the last operation I see is the below. It does not update (atleast so far beyond this point) I’ll leave it running again a few hours and see if it helps
It does earlier show Starting PreBackupVerify and Starting RemoteOperationList and completed those two. I see it Starting - BackupMainOperation and adding a bunch of directories and files, Skipping checking files because timestamp was not updated and then adding the Dropbox directory:
2018-07-11 13:26:42Z - Profiling: Adding directory C:\Users\mganc\OneDrive\Dropbox
2018-07-11 13:26:42Z - Profiling: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ?
2018-07-11 13:26:42Z - Profiling: ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ? took 00:00:00.000
2018-07-11 13:26:42Z - Profiling: Starting - ExecuteScalarInt64: SELECT “A”.“ID” FROM “Metadataset” A, “BlocksetEntry” B, “Block” C WHERE “A”.“BlocksetID” = “B”.“BlocksetID” AND “B”.“BlockID” = “C”.“ID” AND “C”.“Hash” = ? AND “C”.“Size” = ?
2018-07-11 13:26:42Z - Profiling: ExecuteScalarInt64: SELECT “A”.“ID” FROM “Metadataset” A, “BlocksetEntry” B, “Block” C WHERE “A”.“BlocksetID” = “B”.“BlocksetID” AND “B”.“BlockID” = “C”.“ID” AND “C”.“Hash” = ? AND “C”.“Size” = ? took 00:00:00.000
2018-07-11 13:26:42Z - Profiling: Starting - ExecuteScalarInt64: SELECT “ID” FROM “File” WHERE “BlocksetID” = ? AND “MetadataID” = ? AND “Path” = ?
2018-07-11 13:26:42Z - Profiling: ExecuteScalarInt64: SELECT “ID” FROM “File” WHERE “BlocksetID” = ? AND “MetadataID” = ? AND “Path” = ? took 00:00:00.000
10 hours later, profiling log hasn’t updated at all, Duplicati UI hasn’t updated at all, still shows "Counting (678 files found…). CPU usage still at ~22%. Memory use 45,820 K.
I think that’s the culprit somehow. Once I exclude that folder, the backup runs fine. When I was excluding it, Duplicati could also not read the folder structure within it.
Looks like it. I ran ProcessMonitor and it actually looks like there’s still a Duplicati process stuck on that folder.
|High Resolution Date & Time:|2018-07-15 11:18:28.8201837 AM|
|Event Class:|File System|
|Operation:|FileSystemControl|
|Result:|NOT REPARSE POINT|
|Path:|C:\Users\mganc\OneDrive\Dropbox\Private|
|TID:|18492|
|Duration:|0.0000008|
|Control:|FSCTL_GET_REPARSE_POINT|
It generates about 1 million of these events every 10 seconds, or about 100,000 per second.
It looks like it keeps repeating this operation until I terminate the process. If I re-open Duplicati it doesn’t repeat it until I try to choose that folder to be included either as Backup Destination or Source Data. Process is:
Add Backup, Configure New Backup, Enter any name, click Next, under Backup Destination, in Folder path navigate to C:\Users\Username\OneDrive\Dropbox and try to expand it.
The Duplicate interface at that point will just show the spinning loading icon on the folder and will keep repeating the above noted operation. CPU usage by the process shows 10% when it’s running.
Interestingly, if I try to rename that Dropbox folder in File Explorer, it says “Availability status: Sync Pending”
When I tried to delete it, I got a system BSOD!
Stop code: System Service Exception
What failed: Ntfs.sys
After the system reboot from the BSOD, I can now rename it no problem. Duplicati can also open it without problems. I’ll see if it reappears but it looks like this was more of a NTFS or OneDrive weirdness issue rather than Duplicati.
Yes, I did have a Dropbox sync folder inside of a OneDrive sync folder. When I did it originally it did feel like I was ‘crossing the streams’ and the universe might implode, but it worked fine for years. I’ve upgraded to a different computer now and copied things over, but did not reinstall Dropbox, so in theory, the dropbox folder inside there should now just behave as a folder that happens to be named, dropbox.
It also looks like this problem re-appears after my computer is on for a while. Duplicati is now reporting once again Count (680 files found, 4.33 GB) and it’s stuck doing the same thing, this time on the same folder. So it worked fine for about 3 days and now windows or Duplicate are stuck in the same way.
I’m going to try rebooting and then renaming the folder to competely something other than dropbox and see if it re-occurs again.
This is probably NOT what you’re experiencing, but there was an issue reported regarding OneDrive and a Windows update. But just in case it might be related I’ll ask - you didn’t happen to have a Windows update shove itself in your face install just before this issue appeared, did you?
Thank you for the welcome. I am on 1803 of Windows 10, installed on June 25 and I don’t remember this issue cropping up before that update, so that may very well be the culprit.
I do have “files-on demand” enabled in OneDrive also. I’ll monitor and see if it starts happening again with the renamed folder and then I can try toggling the files-on demand off
Yep, happened again with renamed folder. I’ve removed the folder entirely now and moved it’s contents to the local users Documents folder. Duplicati still backs up that folder but this time the files won’t be in the OneDrive folder, so hopefully we can isolate it to something about the files or something about OneDrive.
