Warning with 2.0.5.109

1

After switching from .108 to .109:

2020-08-07 13:31:56 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: D:\

{

“DeletedFiles”: 75694,
“DeletedFolders”: 2921,
“ModifiedFiles”: 0,
“ExaminedFiles”: 165,
“OpenedFiles”: 0,
“AddedFiles”: 0,
“SizeOfModifiedFiles”: 0,
“SizeOfAddedFiles”: 0,
“SizeOfExaminedFiles”: 451485492,
“SizeOfOpenedFiles”: 0,
“NotProcessedFiles”: 0,
“AddedFolders”: 0,
“TooLargeFiles”: 0,
“FilesWithError”: 0,
“ModifiedFolders”: 0,
“ModifiedSymlinks”: 0,
“AddedSymlinks”: 0,
“DeletedSymlinks”: 0,
“PartialBackup”: false,
“Dryrun”: false,
“MainOperation”: “Backup”,
“CompactResults”: null,
“VacuumResults”: null,
“DeleteResults”: {
“DeletedSetsActualLength”: 0,
“DeletedSets”: ,
“Dryrun”: false,
“MainOperation”: “Delete”,
“CompactResults”: null,
“ParsedResult”: “Success”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “2020-08-07T11:32:06.7408759Z”,
“BeginTime”: “2020-08-07T11:32:02.2384847Z”,
“Duration”: “00:00:04.5023912”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 6,
“BytesUploaded”: 17741,
“BytesDownloaded”: 14885255,
“FilesUploaded”: 1,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 1339,
“KnownFileSize”: 67430658191,
“LastBackupDate”: “2020-08-07T13:31:32+02:00”,
“BackupListCount”: 15,
“TotalQuotaSpace”: 27487790694400,
“FreeQuotaSpace”: 27416063120638,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-08-07T11:31:32.4981309Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“RepairResults”: null,
“TestResults”: {
“MainOperation”: “Test”,
“VerificationsActualLength”: 3,
“Verifications”: [
{
“Key”: “duplicati-20200807T113132Z.dlist.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i09c1af3c340e4e03863cf37322282dfa.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-b9f876692a12c469d9b8644660b8df645.dblock.zip.aes”,
“Value”:
}
],
“ParsedResult”: “Success”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “2020-08-07T11:32:16.4724623Z”,
“BeginTime”: “2020-08-07T11:32:13.0877618Z”,
“Duration”: “00:00:03.3847005”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 6,
“BytesUploaded”: 17741,
“BytesDownloaded”: 14885255,
“FilesUploaded”: 1,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 1339,
“KnownFileSize”: 67430658191,
“LastBackupDate”: “2020-08-07T13:31:32+02:00”,
“BackupListCount”: 15,
“TotalQuotaSpace”: 27487790694400,
“FreeQuotaSpace”: 27416063120638,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-08-07T11:31:32.4981309Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“ParsedResult”: “Warning”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “2020-08-07T11:32:16.5196828Z”,
“BeginTime”: “2020-08-07T11:31:32.4971341Z”,
“Duration”: “00:00:44.0225487”,
“MessagesActualLength”: 19,
“WarningsActualLength”: 2,
“ErrorsActualLength”: 0,
“Messages”: [
“2020-08-07 13:31:32 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet”,
“2020-08-07 13:31:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2020-08-07 13:31:56 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (1,31 KB)”,
“2020-08-07 13:31:59 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20200807T113132Z.dlist.zip.aes (17,33 KB)”,
“2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20200807T113132Z.dlist.zip.aes (17,33 KB)”,
“2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed”,
“2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00”,
“2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 07.08.2020 08:15:07, 06.08.2020 08:15:07, 05.08.2020 08:15:06, 04.08.2020 08:15:06, 03.08.2020 08:15:06, 01.08.2020 08:15:07, 29.07.2020 08:15:06, 21.07.2020 08:18:26, 14.07.2020 08:15:06, 09.06.2020 08:15:03, 04.05.2020 08:15:03, 28.03.2020 08:15:03, 20.02.2020 08:15:08, 12.01.2020 16:40:14”,
"2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
"2020-08-07 13:32:02 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: ",
“2020-08-07 13:32:06 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted”,
“2020-08-07 13:32:06 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2020-08-07 13:32:12 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (1,31 KB)”,
“2020-08-07 13:32:13 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20200807T113132Z.dlist.zip.aes (17,33 KB)”,
“2020-08-07 13:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20200807T113132Z.dlist.zip.aes (17,33 KB)”,
“2020-08-07 13:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i09c1af3c340e4e03863cf37322282dfa.dindex.zip.aes (72,84 KB)”,
“2020-08-07 13:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i09c1af3c340e4e03863cf37322282dfa.dindex.zip.aes (72,84 KB)”,
“2020-08-07 13:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9f876692a12c469d9b8644660b8df645.dblock.zip.aes (14,11 MB)”,
“2020-08-07 13:32:16 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b9f876692a12c469d9b8644660b8df645.dblock.zip.aes (14,11 MB)”
],
“Warnings”: [
“2020-08-07 13:31:36 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: D:\”,
“2020-08-07 13:31:56 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: D:\”
],
“Errors”: ,
“BackendStatistics”: {
“RemoteCalls”: 6,
“BytesUploaded”: 17741,
“BytesDownloaded”: 14885255,
“FilesUploaded”: 1,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 1339,
“KnownFileSize”: 67430658191,
“LastBackupDate”: “2020-08-07T13:31:32+02:00”,
“BackupListCount”: 15,
“TotalQuotaSpace”: 27487790694400,
“FreeQuotaSpace”: 27416063120638,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.109 (2.0.5.109_canary_2020-08-07)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-08-07T11:31:32.4981309Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}

2

Is that the entire D:\ missing from the backup?

Does the problem go away if you downgrade?

3

If problem is still reproducible, use About → Show log → Live → Warning and click warning for details.

This is what was seen. Any patterns to what was seen and what was not seen (possibly Deleted* files)?

Export As Command-line will show the source paths in a form easy to cut-and-paste. Because 2.0.5.109 changed the code for source processing, any new issues may need path information (not the whole line).
Privacy redactions are of course fine, but please leave any punctuation or trailing spaces alone if you can.

4

Two messages every run:

Aug 7, 2020 6:22 PM: Error reported while accessing file: D:
{“ClassName”:“System.IO.IOException”,“Message”:“Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)\r\n bei System.IO.File.GetAttributes(String path)\r\n bei Duplicati.Library.Utility.Utility.d__20.MoveNext()“,“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nWinIOError\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.IO.__Error\nVoid WinIOError(Int32, System.String)”,“HResult”:-2147024773,“Source”:“mscorlib”,“WatsonBuckets”:null}
Aug 7, 2020 6:22 PM: Error reported while accessing file: D:
{“ClassName”:“System.IO.IOException”,“Message”:“Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:” bei System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)\r\n bei System.IO.File.GetAttributes(String path)\r\n bei Duplicati.Library.Utility.Utility.d__20.MoveNext()",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nWinIOError\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.IO.__Error\nVoid WinIOError(Int32, System.String)”,“HResult”:-2147024773,“Source”:“mscorlib”,“WatsonBuckets”:null}

I have not downgraded yet, but the backup works a few hours bevor upgrading. There was only a reboot in between.

Yes, entire D:\ is missing from backup.

Two backup path, >>“ExaminedFiles”: 165,<< - this is drive Z:

Export backup configuration:

“C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe” backup “sharepoint:///Desktop - 2020-01-12/?site-id=oliver.sharepoint.com,##################-47c1-bf2c-0d44c99ebaba” “Z:\Dragon-Backup\” “D:\” --send-mail-url=smtp://#############:25 --send-mail-username=“############” --send-mail-password=“##########” --send-mail-from=“#############” --send-mail-to=“################” --send-mail-subject=“Desktop: Duplicati %OPERATIONNAME% report for %backup-name%” --log-retention=12h --retry-delay=1m --auto-cleanup=true --backup-name=“Daten” --dbpath=“C:\ProgramData\Duplicati\TVRQOSJEIJ.sqlite” --encryption-module=aes --compression-module=zip --dblock-size=100MB --retention-policy=“1W:1D,4W:1W,12M:1M” --snapshot-policy=Required --run-script-before=“C:\ProgramData\Duplicati\scripts\Duplicati_Anfang.cmd” --run-script-after=“C:\ProgramData\Duplicati\scripts\Duplicati_Ende.cmd” --threshold=20 --disable-module=console-password-input --exclude=“{SystemFiles}” --exclude=“{TemporaryFiles}” --exclude=“{CacheFiles}”

5

(edited slightly because I think there were actually two backslashes in original, before the forum ate one)

seem to be the bad combination, at least for my somewhat different error, tested on 109 (broke) and 108.
EDIT: To clarify, if I use subfolder on C:, it works. If I use --snapshot-policy=off, it works. Combo gets odd.

C:\>"C:\ProgramData\Duplicati\duplicati-2.0.5.109_canary_2020-08-07\Duplicati.CommandLine.exe" backup "file://C:\ProgramData\Duplicati\duplicati-2.0.5.109_canary_2020-08-07\RUN\test 1\\" "C:\\" --backup-name="test 1" --dbpath="C:\ProgramData\Duplicati\duplicati-2.0.5.109_canary_2020-08-07\RUN\ELNPJYPRHW.sqlite" --encryption-module= --compression-module=zip --dblock-size=50mb --no-encryption=true --disable-module=console-password-input --console-log-level=verbose --snapshot-policy=required
Backup started at 8/7/2020 1:31:57 PM
The operation Backup has started
Error reported while accessing file: C:\ => The filename, directory name, or volume label syntax is incorrect.

C:\>"C:\ProgramData\Duplicati\duplicati-2.0.5.108_canary_2020-07-09\Duplicati.CommandLine.exe" backup "file://C:\ProgramData\Duplicati\duplicati-2.0.5.109_canary_2020-08-07\RUN\test 1\\" "C:\\" --backup-name="test 1" --dbpath="C:\ProgramData\Duplicati\duplicati-2.0.5.109_canary_2020-08-07\RUN\ELNPJYPRHW.sqlite" --encryption-module= --compression-module=zip --dblock-size=50mb --no-encryption=true --disable-module=console-password-input --console-log-level=verbose --snapshot-policy=required

This one spat path names as expected, and I killed it because I didn’t really want to back up whole drive.

set AUTOUPDATER_Duplicati_SKIP_UPDATE=true

was done in advance to make Duplicati a single process, otherwise Control-C leaves the child running…

6

I’m not sure why my CLI message was less detailed, but after trying a test with two NTFS drives (like I assume you’re on) in the backup, and not seeing yours, I tried GUI C:\ with --snapshot-policy=required

{"ClassName":"System.IO.IOException","Message":"The filename, directory name, or volume label syntax is incorrect.\r\n","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)\r\n at System.IO.File.GetAttributes(String path)\r\n at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__20.MoveNext()","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nWinIOError\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.IO.__Error\nVoid WinIOError(Int32, System.String)","HResult":-2147024773,"Source":"mscorlib","WatsonBuckets":null}

I’ve updated Support problematic Windows paths #4256 with my idea of what “HResult”:-2147024773 is, likely ERROR_INVALID_NAME from the Win32 component. To see what was used may need debugger.

7

That PR sounds like a really good candidate for producing the problem!

8

I’ll investigate this with regard to Support problematic Windows paths #4256 later today.

9

Downgrading / reverting to a lower version should workaround this error.
Database’s version hasn’t changed since 2.0.5.106_canary_2020-05-11

10

I’ve submitted a pull request #4278 that fixes this, Fix snapshots broken by #4256. It undoes a change I made in #4256 that introduced this bug.

2 Likes
11

Thanks a lot, guys. All affected jobs are back on track (2.0.5.110). That was very quick help!

2 Likes