Force detailed log of all backup files and missing files

Richard_DeVito_Jr · January 30, 2025, 12:41am

Attached is the full log for about 5 minutes of running this backup. Very interesting…

(attachments)

Richard_DeVito_Jr · January 30, 2025, 5:39pm

Ken, A little more data. Not sure why the clocks are off… I have checked and they are really close. Is this a problem with how duplicati handles FOLDER names?

I have the full procmon logs if you want. They are 256MB in size. For some reason, the mail server is NOT letting me attached the zipped version which is 15MB in size.

This from the procmon logs.

“10:21:43.5921400 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CreateFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened”
“10:21:43.5932338 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryNetworkOpenInformationFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“CreationTime: 1/11/2021 11:21:38 AM, LastAccessTime: 1/11/2021 12:00:00 AM, LastWriteTime: 2/17/2021 12:32:50 PM, ChangeTime: 0, AllocationSize: 0, EndOfFile: 0, FileAttributes: D”
“10:21:43.5932818 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CloseFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“”

“10:21:45.5008381 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CreateFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“Desired Access: Read Data/List Directory, Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened”
“10:21:45.5015588 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryDirectory”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“FileInformationClass: FileFullDirectoryInformation, 1: ., 2: …, 3: JOM_Elmofty.pdf, 4: JOM_Thakur.pdf, 5: Thumbs.db”
“10:21:45.5032428 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryDirectory”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“NO MORE FILES”,“FileInformationClass: FileFullDirectoryInformation”
“10:21:45.5032658 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CloseFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“”
“10:21:45.5106874 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CreateFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened”
“10:21:45.5112916 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryNetworkOpenInformationFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“CreationTime: 1/11/2021 11:21:38 AM, LastAccessTime: 1/11/2021 12:00:00 AM, LastWriteTime: 2/17/2021 12:32:50 PM, ChangeTime: 0, AllocationSize: 0, EndOfFile: 0, FileAttributes: D”
“10:21:45.5113683 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CloseFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“”
“10:21:45.5143279 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CreateFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“Desired Access: Read Data/List Directory, Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened”
“10:21:45.5151187 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryDirectory”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“FileInformationClass: FileFullDirectoryInformation, 1: ., 2: …, 3: JOM_Elmofty.pdf, 4: JOM_Thakur.pdf, 5: Thumbs.db”
“10:21:45.5167557 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“QueryDirectory”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“NO MORE FILES”,“FileInformationClass: FileFullDirectoryInformation”
“10:21:45.5167772 AM”,“Duplicati.GUI.TrayIcon.exe”,“11496”,“CloseFile”,“\Pnpc_nw65\production\JOM\Issue 21\01_02\Proofs\Originals with changes”,“SUCCESS”,“”

This from the duplicati logs. Complete log below my signature.

2025-01-30 10:29:00 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: \Pnpc_nw65\production\JEM\Issue 21\01_02\proof\Originals with changes
IOException: The request is not supported. : ‘\?\UNC\Pnpc_nw65\production\JEM\Issue 21\01_02\proof\Originals with changes’

(Attachment 013025a_Duplicati_Logfile.zip is missing)

Richard_DeVito_Jr · January 30, 2025, 5:59pm

Ken, the attachments killed the message below. Is there somewhere you want me to upload them?

Thanks!

kenkendk · February 3, 2025, 9:19am

Hi, thanks for the logs. I have been examining the code base+logs and from what I can see, all the errors are handled as gracefully as possible. The only issue is the setup where the code calls EnumerateFileSystemEntries once, so we get back both files and folders.

I think this is the optimal way to perform the call, but it has the downside that we need to obtain attributes on each entry afterwards to figure out if it is a file or folder. In this situation, the failed attribute call has the effect that we do not traverse the folder as it is misclassified.

I still do not understand why the attributes fail to be read, but perhaps there is no good way to solve that.

I am currently putting the finishing touches on a new feature that allows sources other than local files. With this feature, it will be possible to re-purpose the CIFS backend as a source-provider and read files directly via the CIFS protocol, which has more features than what the file-system driver allows.

Because of the issue with attribute failures, I am also isolating the choice for how the enumeration is done into a single place so we can easily choose which to use.

tl;dr: The missing folders problem should be fixed shortly.

Richard_DeVito_Jr · February 5, 2025, 7:32pm

Hi Ken,

Couple of followups.

See this link which may shed some light on the issue. https://serverfault.com/questions/754135/windows-treats-mapped-drives-differently-based-on-host-server-type-netware-vs-2
Did you make any changes below in the latest stable release?

Thanks!

kenkendk · February 6, 2025, 10:25am

Hi @Richard_DeVito_Jr

For (1) I think it points to the problem, but there are no solutions. From the comments, it seems that Novell needs to update things, but given this was a problem back in 2016 a fix is unlikely to be on the way.

For (2), no the stable releases do not contain any untested code. The fix I am working on will first be rolled into a canary build, and if it does not break any old systems, it will be promoted to a stable build. I still need to finish the update, test it with VSS and USN, and then it can be considered for a stable release later.

Richard_DeVito_Jr · February 6, 2025, 3:29pm

Ken,

The question now becomes how can we resolve this on a netware server? Remember we did the test of //pnpc_nw65/ type access and it still failed. So why would UNC not work either? Netware supports CFIS. The Netware Client is update continually. The lastest release came out in November so that is an active product to support their active product called Open Enterprise Server.

The larger product issue is how to guarantee that you report failed backups when all you show is warnings. Having designed tape drive backups in the late '80s and early '90s, it becomes critical that backups do what they claim and report any non-backed-up file.

I think I will try a backup of my local PC with the NetWare client installed. It should look at the request, determine it is for a local drive, and go around the NetWare client. Let’s see if that works.

Thanks!

Richard_DeVito_Jr · February 7, 2025, 11:08pm

Ken,

A couple of other things to work on.

Once duplicati starts, it does not refresh the list of attached volumes! I learned this because I started duplicati but was not connected/mapped to the network volumes. When I went to edit a backup that was pointing to the k: drive and the network volume, I was unable to add more folders as duplicati did not go back and check from more folders.
IT SEEMS!!! That is I map the network volumes using the WINDOWS map function and NOT the NETWARE (OES) Map Function, I get better tree walking. I am trying to confirm this with a larger backup. I was looking for ways to get away from the netware/OES client and I remembered that windows will remember mapped drives when it boots. It may not connect to them but it remembers them. That reminded me that to get those, you have to use the windows map function. More as I test this.
As I have gone back to look at other backup options, ALL the backup suppliers who supported netware have moved on. BUT OpenText, who now owns OES server still sells and support this package. I guess they must use linux based backup tools because OES now runs on top of linux (SUSE I think) If they do NOT have a backup solution, this is a potential market for you.

Cheers!

Richard_DeVito_Jr · February 25, 2025, 7:09pm

Ken, I have posted this to the netware forums and there are no changes in how netware responds to tree walking when a volume spans physical or logical drives. It is seamless. Based on discussions with experts on the netware forums, I have run tools on the server volumes to make sure there are no issues with the NSS volumes both at a logical level and physical level.

At this point, I am at a loss to figure out where to go from here. You have our logs where the program chokes on status. I guess I need to go back to a bulk copy via xcopy or maybe robocopy. Then again if robocopy works, does it use the same system calls/code you use in duplicati?

Cheers! radjr

kenkendk · February 27, 2025, 9:33pm

I have a PR ready that works around the issue. It does not solve the underlying problem, but it does not rely on filesystem attributes to figure out if an entry is a file or a folder. Instead it makes two calls to the filesystem: list files and list folders.

Entries from these two calls are then treated as files and folders regardless of what their attributes say, which should only matter in the case where the attributes cannot be read.

I will post here once the canary build is out, and if you can then try that version, we will see if you are saved from xcopy

Richard_DeVito_Jr · February 27, 2025, 10:12pm

Thanks Ken!!

It saves me from more than xcopy… I tried Terracopy and when it copies files from one volume to the other, it screws up all the permissions! It is NOT netware aware and worse, assumes only windows style permissions!

FYI, Netware, not Open Enterprise Server version 25.2 is an ongoing product that is fully supported. It seems they have alot of customers. 25.2 is fully retooled to run on Suse Linux.

I look forward to your test version and MANY THANKS!

kenkendk · February 28, 2025, 6:21pm

You are welcome.

The new version is out now:

Richard_DeVito_Jr · February 28, 2025, 7:15pm

Ken, can two different versions live on the same machine?

kenkendk · February 28, 2025, 7:29pm

Yes and no

The MSI will not allow two installs, but you can use the zip version of the canary build:

If they both run at the same time, they will need different data folders, but if you can live with one running at a time, there is no problem (at least until we change the database schema).

For testing, you can simply do:

Download the zip version
Right click, properties, then “unblock”
Unzip
Stop the running instance
Double click Duplicati.GUI.TrayIcon.exe (or Duplicati.Server.exe depending on use)
Test with the new versions
Exit
Start previous version
Delete the extracted folder and zip file (optional cleanup)

Richard_DeVito_Jr · February 28, 2025, 9:39pm

Thanks Ken. I think I will just install the canary and then reinstall the original version.

I presume the canary MSI will install on top of the existing and leave the data in place?

Grazie!

kenkendk · March 5, 2025, 2:05pm

Yes. The MSI only touches files in C:\Program Files\Duplicati 2.

Richard_DeVito_Jr · March 13, 2025, 9:00pm

Hi Ken,

Just a quick update. I have not had the chance to install the canary version… On my list!

I tried a backup of ANOTHER netware volume that was newer. It is a NSS volume and it ran without error!

Properties shows 91319 files. Netware properties showed 134178 “directory entries”…which I know think must be directory table entries and NOT file count!

There were NO errors on the backup. I do NOT know what other differences there are on the volume as they are both NSS. The older volume had compression turned on and again i go back to the delay in decompressing files as causing a problem…but that is conjecture.

I will get to the canary build! Thanks! Rich D.

{
"DeletedFiles": 0,
"DeletedFolders": 0,
"ModifiedFiles": 0,
"ExaminedFiles": 91317,
"OpenedFiles": 91317,
"AddedFiles": 91317,
"SizeOfModifiedFiles": 0,
"SizeOfAddedFiles": 134485084151,
"SizeOfExaminedFiles": 134485084151,
"SizeOfOpenedFiles": 134485084151,
"NotProcessedFiles": 0,
"AddedFolders": 7229,
"TooLargeFiles": 0,
"FilesWithError": 0,
"ModifiedFolders": 0,
"ModifiedSymlinks": 0,
"AddedSymlinks": 0,
"DeletedSymlinks": 0,
"PartialBackup": false,
"Dryrun": false,
"MainOperation": "Backup",
"CompactResults": null,
"VacuumResults": null,
"DeleteResults": null,
"RepairResults": null,
"TestResults": {
"MainOperation": "Test",
"VerificationsActualLength": 9,
"Verifications": [
{
"Key": "duplicati-20250311T224616Z.dlist.zip",
"Value": []
},
{
"Key": "duplicati-ieccb095512ee4a348929e890f98e1dbd.dindex.zip",
"Value": []
},
{
"Key": "duplicati-i785aef42083c4293b8d25af401936de2.dindex.zip",
"Value": []
},
{
"Key": "duplicati-ib6ef799126d54b05bb09901322b5e6e2.dindex.zip",
"Value": []
},
{
"Key": "duplicati-i1d26fcea7f6e4635982ba6c0111995d2.dindex.zip",
"Value": []
},
{
"Key": "duplicati-bdf66b07de9664d4381a0a0b301e0a607.dblock.zip",
"Value": []
},
{
"Key": "duplicati-beb9ef27b99ea4274a416646350180dfb.dblock.zip",
"Value": []
},
{
"Key": "duplicati-baa3279da85d845f690c8b032ff4a2189.dblock.zip",
"Value": []
},
{
"Key": "duplicati-b92abf38b40634e669db71f1ea05b4da1.dblock.zip",
"Value": []
}
],
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.5 (2.1.0.5_stable_2025-03-04)",
"EndTime": "2025-03-12T05:58:21.1179095Z",
"BeginTime": "2025-03-12T05:57:49.9953248Z",
"Duration": "00:00:31.1225847",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null,
"BackendStatistics": {
"RemoteCalls": 3619,
"BytesUploaded": 93160473825,
"BytesDownloaded": 215306310,
"FilesUploaded": 3597,
"FilesDownloaded": 9,
"FilesDeleted": 4,
"FoldersCreated": 0,
"RetryAttempts": 7,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 3601,
"KnownFileSize": 93212122088,
"LastBackupDate": "2025-03-11T18:46:16-04:00",
"BackupListCount": 1,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.5 (2.1.0.5_stable_2025-03-04)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-03-11T22:46:09.5150292Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
},
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.5 (2.1.0.5_stable_2025-03-04)",
"EndTime": "2025-03-12T05:58:31.6485513Z",
"BeginTime": "2025-03-11T22:46:09.515026Z",
"Duration": "07:12:22.1335253",
"MessagesActualLength": 7268,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": [
"2025-03-11 18:46:09 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
"2025-03-11 18:46:16 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-03-11 18:46:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: ()",
"2025-03-11 18:47:28 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b0cbd089199b34273877036fa8fd8f607.dblock.zip (49.42 MB)",
"2025-03-11 18:47:32 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b0cbd089199b34273877036fa8fd8f607.dblock.zip (49.42 MB)",
"2025-03-11 18:47:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4706aee7526d4172bd8a7fc98ea3df03.dindex.zip (17.91 KB)",
"2025-03-11 18:47:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i4706aee7526d4172bd8a7fc98ea3df03.dindex.zip (17.91 KB)",
"2025-03-11 18:47:38 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b7faada54f4c74be5b0eb3d74d8ddd4c7.dblock.zip (49.06 MB)",
"2025-03-11 18:47:38 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b54cb14441e87430589bc6ad5f768aaa4.dblock.zip (49.04 MB)",
"2025-03-11 18:47:45 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b54cb14441e87430589bc6ad5f768aaa4.dblock.zip (49.04 MB)",
"2025-03-11 18:47:45 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i7c38f09d5882442494e0c3ca0f536b6c.dindex.zip (18.95 KB)",
"2025-03-11 18:47:46 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i7c38f09d5882442494e0c3ca0f536b6c.dindex.zip (18.95 KB)",
"2025-03-11 18:47:46 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b51b7ec574eb44c9ba2ece7bcca5721d3.dblock.zip (49.93 MB)",
"2025-03-11 18:47:47 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd51573e74dc647a690a4ed3ed1273280.dblock.zip (49.04 MB)",
"2025-03-11 18:47:50 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b7faada54f4c74be5b0eb3d74d8ddd4c7.dblock.zip (49.06 MB)",
"2025-03-11 18:47:50 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i3e0b8fd88d0941fb8ea84f85475f6d88.dindex.zip (17.70 KB)",
"2025-03-11 18:47:51 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i3e0b8fd88d0941fb8ea84f85475f6d88.dindex.zip (17.70 KB)",
"2025-03-11 18:47:54 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bd51573e74dc647a690a4ed3ed1273280.dblock.zip (49.04 MB)",
"2025-03-11 18:47:54 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i5da4392569ef4fabaeb74f14bd657b92.dindex.zip (18.06 KB)",
"2025-03-11 18:47:54 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i5da4392569ef4fabaeb74f14bd657b92.dindex.zip (18.06 KB)"
],
"Warnings": [],
"Errors": [],
"BackendStatistics": {
"RemoteCalls": 3619,
"BytesUploaded": 93160473825,
"BytesDownloaded": 215306310,
"FilesUploaded": 3597,
"FilesDownloaded": 9,
"FilesDeleted": 4,
"FoldersCreated": 0,
"RetryAttempts": 7,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 3601,
"KnownFileSize": 93212122088,
"LastBackupDate": "2025-03-11T18:46:16-04:00",
"BackupListCount": 1,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.5 (2.1.0.5_stable_2025-03-04)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-03-11T22:46:09.5150292Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
}