Add file or files to a backup. Files or files must be manually added by check-mark or specify one by one in command line.
Run backup.
Set usn policy to Auto.
Run backup.
Check results: old file is deleted in a new snapshot. No file is added, even if file was changed. File is just lost from now (because it only exist in the first backup so if retention policy is short enough…).
5a. Usn policy seems to work when files are added by directories.
Thanks for the steps, but problem is not reproducible with them on 2.0.8.0 Experimental, and I’m not seeing About → Changelog showing USN fixes, so tentatively I will wonder if we’re testing this differently somehow.
I added one file to a new backup using a check mark, ran it, added policy at Auto, ran it, got no new version (which is correct since nothing changed), so Restore menu only shows the first, but there are logs for both.
I’m running as an elevated administrator on Windows 10. Can you spot anything different in our procedure?
Thanks for testing. Hm. One more thing maybe, can you try add a new file while usn is on? Or change a file to see if new version will be processed? I just redone my test and results are the same - Duplicati doesn’t see new files or changed old files. If those files are in selected sub-directories (as oppose to individual selection of files) everything works as it should.
Thanks… Well, I don’t know what is causing this in my system. I do know, that I can replicate this behavior every time when I try usn auto on individual files (source is 0 bytes and no files are added).
Right. “Usn On” cause - [Warning-Duplicati.Library.Main.Operation.BackupHandler-FailedToUseChangeJournal]: Failed to use change journal for volume "C:": Access is denied.
Hm. And this error happens when I selected sub-directories as well. “Usn Required” just throws “access denied”.
After giving administrator rights for Duplicati, those “access is denied” errors vanished, but nothing else changed, Duplicati still not adding files.
What happens if you start fresh with an elevated administrator, which is the way that I tested it?
Maybe what you can do is describe an exact test, including file names, then I can try to repeat it.
Ultimately this might also need logs, so it would be nice to not have sensitive path names in use.
Mine were just A.txt and B.txt in C:\backup source.
An information level log is pretty safe, and USN code sometimes uses that, but some is profiling.
looks like On got a Warning (so got noisy), and Auto might have just logged at Information, unseen.
I don’t know the details of the code. If it can be turned into good steps, perhaps author of it will help.
Thank you for some pointers to check. Running with administrator rights changes nothing (new backup, new database). Fresh backup, usn auto and a two individual files:
How are you doing initial backup of two files without any log showing them? Anyway, I edited config
was the log from backup, exactly as was expected. Restore now has two versions, two files in each.
is also kind of strange for an initial backup. Is there some retention policy that wasn’t talked about yet?
I also checked the pull requests (only checked changelog before), and can’t see any recent changes.
Possibly I would be surprised if I ran the same test on 2.0.7.1, but I still suspect some test difference.
EDIT:
2.0.7.1 runs fine too. I used the same setup, except for reducing the log to information. Here is the log:
2024-05-04 13:55:28 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2024-05-04 13:55:32 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2024-05-04 13:55:32 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: ()
2024-05-04 13:55:32 -04 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume "C:\": Previous backup did not record USN journal info
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5553a8e8b26a4110a03daf3c2e3cb74b.dblock.zip (1.10 KB)
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b5553a8e8b26a4110a03daf3c2e3cb74b.dblock.zip (1.10 KB)
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-if920e4f3634e45abae013119ce3c1d63.dindex.zip (686 bytes)
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-if920e4f3634e45abae013119ce3c1d63.dindex.zip (686 bytes)
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20240504T175532Z.dlist.zip (769 bytes)
2024-05-04 13:55:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20240504T175532Z.dlist.zip (769 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (3 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240504T175532Z.dlist.zip (769 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240504T175532Z.dlist.zip (769 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-if920e4f3634e45abae013119ce3c1d63.dindex.zip (686 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-if920e4f3634e45abae013119ce3c1d63.dindex.zip (686 bytes)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b5553a8e8b26a4110a03daf3c2e3cb74b.dblock.zip (1.10 KB)
2024-05-04 13:55:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b5553a8e8b26a4110a03daf3c2e3cb74b.dblock.zip (1.10 KB)
2024-05-04 13:58:25 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2024-05-04 13:58:25 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2024-05-04 13:58:25 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (3 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b90eacd385f204c1da1070472484a0a53.dblock.zip (687 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b90eacd385f204c1da1070472484a0a53.dblock.zip (687 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i685c12baf1754392961e8c5e854ab837.dindex.zip (607 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i685c12baf1754392961e8c5e854ab837.dindex.zip (607 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20240504T175825Z.dlist.zip (771 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20240504T175825Z.dlist.zip (771 bytes)
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2024-05-04 13:58:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (6 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240504T175825Z.dlist.zip (771 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240504T175825Z.dlist.zip (771 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i685c12baf1754392961e8c5e854ab837.dindex.zip (607 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i685c12baf1754392961e8c5e854ab837.dindex.zip (607 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b90eacd385f204c1da1070472484a0a53.dblock.zip (687 bytes)
2024-05-04 13:58:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b90eacd385f204c1da1070472484a0a53.dblock.zip (687 bytes)
2024-05-04 13:58:58 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2024-05-04 13:58:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2024-05-04 13:58:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2024-05-04 13:59:04 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
Thank you again for thorough troubleshooting. This ensure me, this is something in my individual settings/system. I will look deeper into this. My test backup is just a test one - creating from scratch (delete database etc). Retention policy is set to “smart retention”. So there should be no interference from other factors. But maybe some of my settings gets in a way… Anyway, my test shows just 0 bytes and zero files - when I created backup from scratch with usn auto on. No matter of settings… I have no idea what is wrong here.
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingSourcePath]: Including source path: C:\Users\Xxx.matplotlib\fontlist-v330.json
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx.matplotlib
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-ExcludingPathFromAttributes]: Excluding path due to attribute filter: C:
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingSourcePath]: Including source path: C:\Users\Xxx\aranym\config
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx\aranym
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingSourcePath]: Including source path: C:\Users\Xxx.matplotlib\fontlist-v330.json
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx.matplotlib
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-ExcludingPathFromAttributes]: Excluding path due to attribute filter: C:
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingSourcePath]: Including source path: C:\Users\Xxx\aranym\config
2024-05-05 00:08:33 +02 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Xxx\aranym\
OK. I found culprit! Thanks to @ts678 and suggestion to use a totally fresh profile. With new profile everything works as it should. Previously I used my test profile and “only” deleted database, destination backup files and source files (as well as filters and settings), I thought that’s enough for to be a “clear and new profile”. But that was not a case. So something in empty profile itself create a culprit which confusing usn. Case closed I think. Thanks @ts678 again for help.
For curiosity sake, I exported fault profile and imported back to check if error persist. It did. If you can check this profile? I wonder, where exactly is a problem here. I don’t see anything suspicious in the .json profile file. Source and destination doesn’t matter.
You could find a job that’s not backing up those files, see if that Exclude is set, and if so, try turning it off.
EDIT:
Going the other way, adding Exclude System files and backing up thinks both files were deleted. Log:
2024-05-04 19:46:47 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Maintenance\aranym\.matplotlib\
2024-05-04 19:46:47 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Maintenance\aranym\
2024-05-04 19:46:47 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Maintenance\
2024-05-04 19:46:47 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\
2024-05-04 19:46:47 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-ExcludingPathFromAttributes]: Excluding path due to attribute filter: C:\
and again the worrisome exclude of the drive root, but I can’t get Windows to tell me drive root’s attributes.
Possibly USN and Exclude System files used in combination have a bug that you were the first to see?
Bingo! You are right “Exclude System files” is the culprit. That one, too innocent for me to turn it off… I suppose this is a sort of corner case - use usn auto and manual selection of individual files and “Exclude System files” equals no backup of those files. Also, “Exclude System files” is off when user create a new profile, that why new profile works. Well, I am glad that sorted things out. Phew… Thanks again for help @ts678!
Thanks again for help