Restore fails when creating empty files at the end of restore process

asdfasfadf424 · September 8, 2020, 5:18am

I’m running a restore from a backup (created on osx) stored on a usb-3 connected external drive to another usb-3 connected external drive (this time on windows 10). I’m running the latest canary release, the restore was triggered from the backup and I was using the “–no-local-blocks=true” setting to speed up the process.

After running for 1day and 19 hours the restore fails but only after printing the message “Running Restore took…” to the log.

Sep 7, 2020 5:48 AM: The operation Restore has failed with error: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.
{“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.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)\r\n bei System.IO.FileStream…ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize)\r\n bei Duplicati.Library.Common.IO.SystemIOWindows.FileCreate(String path)\r\n bei Duplicati.Library.Main.Operation.RestoreHandler.DoRun(LocalDatabase dbparent, IFilter filter, RestoreResults result)\r\n bei Duplicati.Library.Main.Operation.RestoreHandler.Run(String paths, IFilter filter)\r\n bei Duplicati.Library.Main.Controller.<>c__DisplayClass15_0.b__0(RestoreResults result)\r\n bei Duplicati.Library.Main.Controller.RunAction[T](T result, String& paths, IFilter& filter, Action`1 method)\r\n bei Duplicati.Library.Main.Controller.Restore(String paths, IFilter filter)\r\n bei Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)",“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}
Sep 7, 2020 5:48 AM: Running Restore took 1:19:04:37.344
Sep 7, 2020 5:48 AM: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
Sep 7, 2020 5:48 AM: Starting - ExecuteNonQuery: PRAGMA optimize
Sep 7, 2020 5:46 AM: ExecuteReader: SELECT “Fileset-3299C4294274164CB93D3FD9CCE4A093”.“ID”, “Fileset-3299C4294274164CB93D3FD9CCE4A093”.“TargetPath”, “Blockset”.“FullHash”, “Blockset”.“Length” FROM “Fileset-3299C4294274164CB93D3FD9CCE4A093”,“Blockset” WHERE “Fileset-3299C4294274164CB93D3FD9CCE4A093”.“BlocksetID” = “Blockset”.“ID” AND “Fileset-3299C4294274164CB93D3FD9CCE4A093”.“DataVerified” <= False took 0:00:00:00.985

When checking the restored files it looks that the timestamps has not been restored correctly but the actual file content seems to be there.

Looking at the code it seems that the timestamps are only restored after the empty files has been created.

Now the question is

how can I identify which file it was not able to restore (maybe due to some naming restrictions with windows) so that I can maybe skip it?

Thank you in advance for your help!

I’ve also opended a ticket with the request to add additional logging: Restore fails when creating empty files at the end of restore process · Issue #4315 · duplicati/duplicati · GitHub

warwickmm · September 12, 2020, 9:32pm

Doesn’t this actually slow down the restore process? I believe using true here forces Duplicati to download blocks from the backend instead of trying to first look for them locally.

ts678 · September 12, 2020, 11:58pm

It should be slower as far as I know (unless source files are not available, so no difference in that case).
The main reason I tell people to set that is when doing restore test, to ensure remote backup gets used.

asdfasfadf424 · September 13, 2020, 5:27am

I’m restoring to a completly new machine (after switching from osx to windows I can’t read the osx volumes anymore). For this use case (for me quite a common use case for a restore) there are no local blocks so setting the flag to true should be faster.

asdfasfadf424 · September 17, 2020, 7:22am

I was able to add some debug logging to the restore and now I can see that the restore fails when restoring empty files name “Icon” - e.g. it fails to restore the following file present in my backup: /Users/xxx/Applications/Chrome Apps.localized/Icon (xxx beeing my username).

I tried to manually create an empty file named “Icon” in the windows explorer and it works. If I manually exclude the Icon file from the restore the process works, but I can’t manually exclude all Icon files during restore - the likeliness that I miss some is high. Also it would be nice to actually fix this issue.

For me two questions arise:

is it possible to configure a filter to not restore Files names “Icon” during restore? I’ve tried that with both CLI and UI but did not succeed (besides manually deselecting the files in the web ui)
I’d love to reproduce this in a unit test but I’m not able to. When I modify RestoreHandlerTests to create an empty file named Icon it can be properly restored. So I guess this is somewhow caused by the fact that those Icon files have some special structure under OSX. Does anybody have an Idea how to reproduce that with a test?

ts678 · September 17, 2020, 3:02pm

Google search for “macos” “icon” “empty file” found Icon? file on OS X desktop. Does that fit your case?

A key point is that It's name is actually Icon\r, with \r being the carriage return 0x0D.
Comparison of filename limitations says that Windows NTFS considers 0x00-0x1F in name to be illegal

Another key point is that the icon image is in a Resource fork, so its ordinary content (data fork) is empty.
“forks can make it difficult to exchange files with other operating systems” might describe the situation…

You could certainly look on your Mac with something like ls --literal | hexdump -C to check name.
You could install Sysinternals Process Monitor on Windows to see if you can see Duplicati try file create.

If this is what’s happening, then the next question is how to stop restore from failing tripping over the files.

EDIT: If you can confirm the name, most shells will let you make file name with a carriage return (Ctrl-M), but you have to type Ctrl-V before the Ctrl-M. Here are two I made with touch, the second with a CR too:

$ touch Icon
$ touch Icon^M
$ ls -1
Icon
Icon?
$ ls -1 --literal | hexdump -C
00000000  49 63 6f 6e 0a 49 63 6f  6e 0d 0a                 |Icon.Icon..|
0000000b
$

Above is Linux, which sends NL (0x0a) as end-of-line. Possibly your Mac will use CR (0x0d) as its EOL.

Make your own empty file with some name and a carriage return, back up on macOS, see if Duplicati on Windows chokes. If it does, it might be because Windows didn’t like a carriage return. Error translates to:

The syntax for the file name, directory name, or volume label is incorrect

asdfasfadf424 · September 18, 2020, 5:28am

Thank you very much for the analysis which is 100% correct. I can’t really test on OSX anymore since the Logicboard of the MacbookPro is broken and I’m switching back to a windows machine now (thats the reason I have to restore the backup ).

I’ve added a try/catch around the restore of empty files in the source code logging the errors as a warning and just continue.

When doing a small test restore the restore run now executes successful till the end and ends up in the following warnings and errors (the “Failed to restore empty file” is the warning I’ve added).

  "Warnings": [
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Failed to restore empty file: \"c:\\m9\\Applications\\Chrome Apps.localized\\Icon\r\", message: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Failed to restore empty file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Failed to restore empty file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Unexpected character encountered while parsing value: o. Path '', line 1, position 102400.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Unexpected character encountered while parsing value: T. Path '', line 1, position 102400.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications\\Chrome Apps.localized\\Icon\r\", message: Unterminated string. Expected delimiter: \". Path '['unix-ext:com.apple.ResourceFork']', line 1, position 102397.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Unterminated string. Expected delimiter: \". Path '['unix-ext:com.apple.ResourceFork']', line 1, position 102397.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Unexpected character encountered while parsing value: U. Path '', line 1, position 204800.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications\\Chrome Apps.localized\\Icon\r\", message: Unexpected character encountered while parsing value: k. Path '', line 1, position 204800.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Unexpected character encountered while parsing value: T. Path '', line 1, position 307200.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Unexpected character encountered while parsing number: v. Path '', line 1, position 307201.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications\\Chrome Apps.localized\\Icon\r\", message: Error parsing NaN value. Path '', line 1, position 307201.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Unexpected character encountered while parsing value: b. Path '', line 1, position 204800.",
    "2020-09-17 07:16:39 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Unterminated string. Expected delimiter: \". Path '['unix-ext:com.apple.ResourceFork']', line 1, position 102397.",
    "2020-09-17 07:16:40 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications\\Chrome Apps.localized\\Icon\r\", message: Unexpected character encountered while parsing value: H. Path '', line 1, position 102400.",
    "2020-09-17 07:16:40 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\Icon\r\", message: Error parsing boolean value. Path '', line 1, position 409601.",
    "2020-09-17 07:16:40 +02 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: \"c:\\m9\\Applications (Parallels)\\{87a8ebe4-2c4e-49c4-8ead-ac3b47a82567} Applications.localized\\Icon\r\", message: Unexpected character encountered while parsing value: O. Path '', line 1, position 409600."
  ],
  "Errors": [
    "2020-09-17 07:16:40 +02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n",
    "2020-09-17 07:16:40 +02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n",
    "2020-09-17 07:16:40 +02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Die Syntax für den Dateinamen, Verzeichnisnamen oder die Datenträgerbezeichnung ist falsch.\r\n"
  ],

I’ll keep my local code as is and now trigger a full restore of all files. I’d expect that I’ll run into a couple of Warnings for the Icons but apart from that everything else will work. Obviously I don’t really need the Icon files to be restored as I don’t have a use for them on Windows.

I guess there is no way to reproduce this in a unit test (unless we create a backup of such a file on linux, check it in and then add a unit test to restore that backup).

I’m not sure If I should

only commit the added debug profiling logging
or also the catch/ignore exception
as part of the GitHub issues I’ve created? Any opinion about that?

ts678 · September 18, 2020, 1:17pm

I stay out of code-level issues, because I don’t do much code. I’ve updated that issue to point back here.

The intent of both changes seems fine to me. Possibly level could be tweaked. Non-empty files look like logging is at verbose level, whether it’s local or remote data blocks that are being used to rebuild the file.

Nicely done change. If you have any interest in doing more, developer volunteers are very much needed.

Thanks!