might give a clue. BackendManager upload did verification file, but BackendUploader did earlier files, therefore I’m questioning usefulness of BackendManager data here, but maybe your log results differ.
Goes to show that I don’t know much about upload, I had never even suspected that DoPut was actually duplicated, one private occurrence in Library/Main/BackendManager.cs and another one in Library/Main/Operation/Backup/BackendUploader.cs. Hey for code reuse
A profiling log might still be useful. That’s about as heavy logging as possible, unless you want to instrument a test build for users to run, adding some debug code, maybe at ExplicitOnly log level.
I searched verbose log for files that changed, using regex CheckFileForChanges.*True. Got 10,
however they’re kind of small with total size of maybe 25 MB, so wouldn’t fill even a 50 MB dblock.
Getting file sizes done by filtering of Process Monitor file. That was simpler than asking OP to look.
Small amount of data emphasizes question of whether or not the SpillCollector ran to pack blocks.
Best view of that unfortunately requires the profile-all-database-queries profiling log option.
As a note.
I might be silent, but I am paying attention. If you guys need something needing doing say it, but since the last time, I have not run Duplicati, and I have saved something new in the folder (thats my Documents folder, something would be saved there eventually). Although it should, I dont know if the stall will happen.
a few additional questions: I have seen dropbox in your task list, are dropbox managed files (or any replicated files such as OneDrive or whatever) backed up by Duplicati ? Also, you are backing up to an external disk, is this external disk also backed up to the cloud by some replication software ?
or similar message (but different technical question is why my backup double-enumerates after that).
This may or may not be relevant to the stall, but getting everything back to normal setup seems wise.
Regarding the nature and location of the stall, the new file in Documents might change the result, but intentionally adding something somewhere else at the end of the source list might add a more certain indication of whether steam_autocloud.vdf was the stuck point, or just the last file needing reading. Indications so far point to the latter, but despite the data so far (thank you), there’s still data lacking…
@gpatel-fr Do you think it’s worth going for a profiling log with profile-all-database-queries option on? There’s no guarantee that will reveal the cause, but it seems like it will probably get us a little closer…
No, the Dropbox folder is specifically excluded from the backup. Or should be, I do remember excluding it. If its showing, it might not be. Id have to open the backup to see if it actually is, and can only do that tomorrow. (Im offhome until then)
Duplicati backs up to a different internal drive in my own machine, because it ran once every four hours for versioning reasons. My job has relied one time too many on having X file Y hour available, and Windows File History ended up being too unreliable. I ran into Duplicati when File History broke, and I was recommended to not use it anymore.
The actual backup PC gets a full copy of this backup once a week. I just copy it over the LAN with Explorer. Nothing fancy or ideal.
As long as we manage to figure whats causing this, this entire mess will have been worth it.
I think the reference to “task list” was the Process Explorer or Resource Manager views you posted.
Dropbox was one of the excludes in the Verbose log you shared, and one can see that doubled too.
It sounds like further exploration of the backup configuration will have to wait at least until tomorrow.
That will give us a little more time to decide on whether to go for profilng log now, or try other things.
I looked more at the verbose log to try to spot a pattern behind when the metadata reads stopped.
This was done by using Linux sort and comm commands to compare enumeration with metadata.
There seemed to be 17134 files (not folders) which were enumerated but lacked a metadata read.
Pure comm output was hard to read, as folders and files got interleaved because paths got sorted.
I adjusted by using perl sort based on folder depth, while preserving original order for equal depth:
This found that even in top-level Documents folder, only some of the files there had metadata read.
The pattern was not clear, but the view was sorted, so probably not the original order of processing.
So return to Process Monitor, find last QuerySecurityFile which gets ACL. Look for near oddities.
Ignore unusual events that are common enough to presume are not a problem, but what about this?
10:54:44.5382905 AM Duplicati.GUI.TrayIcon.exe 15624 19096 ReadFile C:\Users\Kobayen\AppData\Local\Duplicati\RLWEXIKJJV.sqlite DEVICE DATA ERROR 2.6175946 10:54:47.1558851 AM
Offset: 273,784,832
Length: 4,096
That looks like an attempted SQLite page read that takes almost 3 seconds then fails. Why would it?
The next few tries didn’t work either. Note all the blue at the top. I turned everything on while fishing:
I haven’t tried investigating what causes a DEVICE DATA ERROR. I assume that it’s not just an EOF,
but perhaps we can get @Kobayen to tell us what size that file is. Maybe also look in event log then.
This may or may not be related, but it sure looks odd. I haven’t looked into what it might do to SQLite.
I dont use Duplicati to make a backup of open Duplicati databases for it generally sounds like a bad idea. I just used Windows Explorer whenever Duplicati wasnt running.
Or having made a DB copy, you could rename the old DB and rename the copy into its place in case an issue such as a weak sector is deep inside the old one, but not so severe that the copy was impossible.
I watched two of my backups with Process Monitor, but saw no DEVICE DATA ERROR on database.
This reinforces the idea that they are abnormal. Meanwhile the double enumeration seems normal.
Duplicati backup appears to start another one in CountFilesHandler.cs. I hope it’s really necessary.
I also wrote the script I thought might do very well to get an original-order study of the enumeration:
# Track relevant lines using hash of array of line numbers.
while (<>) {
if (/(?<=no filters matched: )(.*)/) {
push @{$ref{$1}}, $.;
}
}
# Show ref count and two references in original line order.
for (sort {${$ref{$a}}[0] <=> ${$ref{$b}}[0]} keys %ref) {
@ref = @{$ref{$_}};
printf("%d\t%d\t%d\t%s\n", scalar(@ref), @ref[0,1], $_);
}
and it nicely showed where double enumeration went down to single near DEVICE DATA ERROR.
The Skipped checking file, because no metadata was updated also stopped around then.
Maybe what happened is the unclear-purpose enumeration finished while the critical one stopped?
Anyway, plan to try to examine or chase away that DEVICE DATA ERROR still seems a good plan.
I hate to be a bearer of bad news, but a recent power outage in the region knocked down this computer. I wouldnt doubt one of these mistimed outages caused this entire debacle, somehow.
I have no idea of the state of the hard drive we were examining, the state of the files there, or the backup database inside it. I dont think I can keep diagnosing this problem anymore.
Setting Process Monitor’s filter to look at all the database accesses found the DEVICE DATA ERROR posted earlier to be contiguous. Filter on Details found them to be the only uses at offset 273,784,832, however whatever happened inside Windows and SQLite did permit other database accesses later on.
Possibly an error was given to Duplicati, but it mishandled it. A profiling log might provide more details.
The Windows event log might also show if it saw any sort of disk error when Process Monitor saw that.
Process Monitor could also watch the old database during its copying to see if the bad result shows up.
BUT
now the power outage has left things in an unknown state. Maybe computer will come back, maybe not.
If computer got damaged and you want to try restore from whatever backup there is, please let us know.
If it does come back, then maybe we can continue exploring what fixing DEVICE DATA ERROR can do.
--profile-all-database-queries (Boolean): Activates logging of all database
queries
To improve performance of the backups, frequent database queries are not
logged by default. Enable this option to log all database queries, and
remember to set either --console-log-level=Profiling or
--log-file-log-level=Profiling to report the additional log data
* default value: false
log-file=<path> (maybe use a different one than the verbose log that I’m still referencing was using)
If system comes up (or even if it doesn’t, but drive still works), you can look at drive S.M.A.R.T stats. CrystalDiskInfo is one such tool, but there are many more. Check for errors and reallocated sectors.
