The usecase:
Duplicati GUI-Trayicon on Windows 10, backing up to a different HDD on the same machine. Duplicati is being used as file versioning of project files and savegames; essentially, anything inside the Documents folder.
The problem:
Duplicati simply stalls when meeting a specific, recently modified file; in this case related to the savegames. Most of the help I have seen is about backing up to remote locations and havent helped. The progress bar says [File History - Documents: 28425 files (19.32 GB) to go ] and Current File is at [ Current file:
C:\Users[USER]\Documents[GAME][STEAM ID]\steam_autocloud.vdf ]
The only thing I have tried was to start Duplicati trough the Task Scheduler so I could set the --snapshot-policy to ON in the settings. I thought it could be related to the file being locked for some reason. It stalled anyway.
I will need help to find out how I can diagnose this issue.
The current attempt is new. I have restarted the machine and allowed a new backup to begin as scheduled, and it still stalled. I did not open this game today.
(I know its silly, but I am not interested on having my Steam Id searchable on Google)
In some previous times, Duplicati managed to copy files while the game was open without any trouble. The theory I have is that it tried the same before and failed, but I cant just assume those things I need to diagnose them properly.
One thing I noticed is that the PC fails to go into standby or hibernation if Duplicati is in this stalled state.
It is possible this is just the most recently modified file in this backup, and this would happen no matter what file was modified. Not a fan of that thought.
Sysinternals Procmonitor check
There is alot going on here. I’m not sure of what I am looking for, but between what seems to be Registry accesses and TCP pings to localhost, I found these entries.
I think its just from me poking around the backup configuration though trying to find out what is wrong. I dont know what I am looking for. If what I need to do is to have this open while a backup runs again, first I need to find out how to make Duplicati resume.
About → System info → Server state properties → lastPgEvent
What is modifying files there? What other files are there?
The game was included in the path. I have also played other games this week, Astroneer specifically, but they save to APPDATA, and I dont use Duplicati for that.
Files, mostly art programs. Depending on the situation, I use either Photoshop, Clip Studio Paint, Krita, Blender, Illustrator, InDesign, Aseprite, Unity, the list goes on really. (Duplicati does not handle the Unity projects)
Am I correct in that these files are part of a cloud storage and they are kept in sync by some system driver written by the cloud operator (Steam) ? If this is the case, this would not be the first time that Duplicati has problems accessing this kind of files.
Basically it’s supposed to backup local files to the cloud (or local), not cloud files to local (or another cloud).
So the best work around would be to filter them out.
As I understand, this is the local copy of files that are sent to a cloud, yes. They have been backed up successfully before. I can tell Duplicati to filter them out and see what happens.
Still, I would need to restart the backup service. I assume thats a matter of closing Duplicati and opening it again, or is there anything else specific needing doing?
Process Monitor still is open, so if something changed it should be there. Again, there is so much stuff running there at all times I dont know what to look for.
Duplicati seems stalled on the current state. If I notice a change, Ill report. Until then, Ill give it some time to see if anything changes.
Yes, and even after I filtered out all the TCP stuff for the GUI, there is ALOT. Duplicati just keeps opening and closing threads endlessly and I assume doing nothing with them. Is this expected behavior?
I cant find a way to just copy all of this as text so I can paste it here.
EDIT: After reopening the GUI, it went back to how it was. I can only assume Stop Now didnt work.
It looks as it is waiting for something. When it is waiting after a hanged cloud connection, if there is no timeout setup in the Http connection properties, it is usually for ever. But there is no possibility of setting a timeout for a local drive access. So if you are not seeing more interesting stuff in the process monitor for say 30’, I’d advise for harsher measures - hoping that the database will not be damaged in the event.
Process Monitor output can be toned down by unchecking (removes blue tint) the non-file activities:
It would have been nice to have observed previous interactions with the steam-autocloud.vdf file.
Intermittent problems are difficult to observe… There is evidence that the file got processed (100%).
I think Current file doesn’t update to files that aren’t actually read. There’s scanning for next-to-read.
A log at Verbose shows the decision-making process well, but doesn’t detail the individual file reads probably because there are way too many – I think it reads directly by tiny 100 KiB default blocksize, meaning this small file was a single read, then it at least requests to Windows to close and move on.
so 28425 to go, which is exactly what the status bar says. I wonder if Windows got stuck in file close?
This is where a Process Monitor watching only that file. Original post seemed to say there’s a pattern.
This is weird too.
To test whether this particular file is in some trying-to-close state, possibly you can use Task Manager → Performance → Open Resource Monitor → CPU → Search Handles → ask about steam_autocloud.vdf
I’m going to say this upfront, I cant reboot this computer for testing left and right, I am using it for work, and it takes a while to warm up. If we are fishing for information that needs a system reboot, I can do that but Ill leave the PC rebooting while i go get lunch, and thats a few hours from now.
I can disable Duplicati on the Task Scheduler, so I can set up the Process Monitor and stuff to keep an eye on things before I start Duplicati again, so we can catch this when/if it happens.
To be specific: by failing to hibernate / standby, I mean the PC gets stuck on something, HDDs working for a while, then silently turns itself off. When turning on, it goes trough a normal boot up cycle, not a recover from standby or hibernation. This is certainly a Windows thing, but if its provoked by Duplicati or not, is what we’re trying to find out here.
I believe this is related to Duplicati being stuck because I noticed this happening very recently, and it matches a hole in my available Duplicati backups.
How do I view / set that up?
Also its been 30 minuted with no visible change. I assume i should force-close the process? Anything I should do before I do that? Maybe the log level thing?
Viewing the Duplicati Server Logs About → Show log → Live → Verbose (or some other level) can sometimes see things retroactively, but I’m not sure how far it can go. It’s best used for new things.
log-file=<path> log-file-log-level=verbose is better if live log has nothing but you hope to catch next.
Process Monitor can also be set up to filter heavily, perhaps just on that one file and discard others.
Filter → Drop filtered events. Don’t let it grab too much or it might run system out of virtual memory.
Looking through event log around the times of the failed hibernate / standby or the restart might help.
I was thinking of Find Handle or DLL but that’s basically what Resource Monitor just did. There’s also a Handles view in the bottom half of the screen if you View → Show lower pane, but you’d have read File lines and ignore the ones that are program code (.dll). Sorting by Name (click) makes this a little easier.
There’s also a Threads view, but we’re not Windows wizards. Typically it doesn’t help, but you can look. What would be nice would be to attach a debugger to process, but that’s probably too far to go just now.
EDIT:
These are some sample lines at Verbose level, showing the source file scanning and the changes seen:
2023-12-07 20:04:09 -05 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\PortableApps\Notepad++Portable\App\Notepad++64\backup\webpages.txt@2023-12-03_072112
2023-12-07 20:04:20 -05 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\PortableApps\Notepad++Portable\App\Notepad++64\backup\webpages.txt@2023-12-03_072112
2023-12-07 20:04:20 -05 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-CheckFileForChanges]: Checking file for changes C:\PortableApps\Notepad++Portable\App\Notepad++64\backup\webpages.txt@2023-12-03_072112, new: False, timestamp changed: True, size changed: True, metadatachanged: True, 12/7/2023 9:25:30 PM vs 12/5/2023 8:27:17 PM
2023-12-07 20:04:26 -05 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-ChangedFile]: File has changed C:\PortableApps\Notepad++Portable\App\Notepad++64\backup\webpages.txt@2023-12-03_072112
Yours somehow seems to have stopped scanning after that troublesome file (thinking based on math).
The reason I think it got at least to attempting to close that file was described above. Its code might be:
more Resource Monitor tinkering
Windows’ Resource Monitor doesnt seem to have find menu, just that handle search.
I cant find any references to anything in Documents, much less to the troublesome .vdf file.
I am going to force close Duplicati and restart it, and see what happens from here.
Yes, just closing the tray icon doesnt seem to actually close it when its in this state. Not sure if this is intentional.
— EDIT —
Closed Duplicati, opened it, manually ran the backup operation and… we have a stall I think.
I’m not sure of what to do with the Verbose log, and the Process Monitor result. It didnt stop where we thought it would, and I’m not keen on placing a list of every file in my PC up forever on the Internet. It stalled while enumerating files, but not at the file listed over there. I cant even tell if it enumerated all files properly, because theres THAT many files.
If theres a way to send them to someone specific, Im listening.
How? Task Manager is probably the surest (but note that there is usually a parent and a child process). Generally we don’t recommend ending tasks externally, but sometimes that’s necessary – maybe here.
Tray icon is only loosely connected to the server processing via an HTTP connection similar to the GUI, where closing the browser tab is expected leave Duplicati to do what it has to – without a tab showing it.
Beyond that, I’m not sure what’s intentional. but I think I’ve seen server finish work – likely the best plan except for stuck case. Stopping things in the middle (surprisingly difficult) can sometimes make a mess.
I will tentatively assume that you found the processes and ended them. It’s usually safe, but not always.
and there’s the challenge of tracking these things down. Too bad it didn’t stay put as well as was hoped.
in the earlier case makes me wonder if it had finished counting but not processing. These run in parallel and you wouldn’t want the backup to have to wait for all the files to be identified before reading begin…
Now that you have a verbose log, you can see where the GUI got stuck, and see if enumeration kept on going after that. Things earlier in the file might be less interesting (for now), but where it ends might be.
If the stuck status is no more privacy-invasive than the last time, maybe you could just post similar data, which would allow more people (including the developers) to try to figure out what’s going on with this…
You can click on a user name to Message, but it’s generally best for somebody to ask. You can send me the end (or all, if you prefer) of the verbose log as a .zip file. Any portion I post will try to respect privacy.
Please also check the event logs, as a Google search couldn’t quickly find an explanation for sleep fail. Perhaps you have an unhealthy system somehow, which is causing a number of things to not complete.
EDIT:
The status line talks about counting (but not in your old screenshot), for example my new backup shows
Counting (475 files found, 110.05 MB)
It’s kind of a race between the thread that is looking for work needing to be done and the thread doing it. Commonly you will see the numbers go up awhile, and then drop down as the file processing gets done.
Duplicati wasnt responding. I dont know how to close by the GUI, but since it didnt respond to pause requests, I assumed it woulsnt respond to requests to close. Right-clicking the task icon and telling it to close didnt work either, it remained open in the Task manager (as I could find it in the Details tab), and when I ran it again it just reconnected to the old process.
So yeah, I went to the Task Manager, clicked on each process, and chose End Task.
Sending files
The compressed verbose file is a megabyte in size. The compressed Process Monitor Log file is around a gig.
Can you say where it stopped in GUI? Looking at verbose log for something like sample above got
as below, and that seems to be where file processing stopped, although file enumeration continued
2023-12-11 12:44:18 -03 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-CheckFileForChanges]: Checking file for changes C:\Users\Kobayen\Documents\Marvel’s Avengers[STEAM ID]\steam_autocloud.vdf, new: False, timestamp changed: True, size changed: False, metadatachanged: True, 10/12/2023 22:44:39 vs 09/12/2023 22:49:27
2023-12-11 12:44:19 -03 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-FileMetadataChanged]: File has only metadata changes C:\Users\Kobayen\Documents\Marvel’s Avengers[STEAM ID]\steam_autocloud.vdf
You could filter Process Monitor to that file to see what was going on with accesses around that time. View is probably interpretation of the driver-level traffic, so your guess at it might be as good as mine.
Normal processing would probably have Duplicati store the new metadata and move on, but not here.
So it didnt fail at the VDF file, but it seems to have failed on the next file? Theres alot more information about this on the entry, which makes me understand why this thing is a gigbyte in size.
A little later in the same second there is this.
TIME: 12:44:18.1403706
PROCESS MsMpEng.exe
PID 4240
OPERATION CreateFileMapping
PATH \Device\HarddiskVolumeShadowCopy2\Users\Kobayen\Documents\Marvel’s Avengers[STEAM ID]\savebk_5.dat
RESULT FILE LOCKED WITH ONLY READERS
DETAILS SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE|PAGE_NOCACHE
I havent seen similar RESULTS anywhere near those entries. I’m trying to extract the entire second into a smaller file, maybe that can be sent around.
All the Invalid Device Requests that are related to Duplicati.
These are all files I used over the weekend; mostly the savegame, and a painting I was doing for fun. Theres more somewhere, probably, but thats the ones within Duplicati’s domain.
For the record. All the activity from MSMPENG during the last backup operation within the Documents folder.
I can only assume thats the Antivirus messing with the files while Duplicati was trying to access them. Its weird how this was never a problem until this weekend.
I’m not sure if leaving the antivirus off at all times / whenever a backup automatically runs is the best policy though. I will try disabling it, ending Duplicati’s process and restarting a new backup attempt as soon as I can. Work calls and all.
I also have hit the post limit for the first day in the forums, so.
Final Edit for the Day
Closed Duplicati trough the Task manager by Ending Process.
Turned off Windows Defender.
Re-ran Duplicati and retried the backup.
The only difference is the lack of INVALID DEVICE REQUESTs.
Duplicati still stalled. See you tomorrow I guess.
