Restoring all files in failed disk D causes some files in C to be pulled from backup

redshifted · October 26, 2020, 11:17am

Hello all,

Server: 2.4.12 on FreeBSD (TrueNAS)
Client: Windows 10

Urbackup agent is backing up C:\ and D:\ using following Excluded Files setting:
C:\ProgramData\Microsoft\Network\Downloader\*;C:\Windows\system32\LogFiles\WMI\RtBackup\:.:;C:\Users\Dadovi\index.dat;C:\Windows\Minidump\*;:\Pagefile.sys;:\System Volume Information\MountPointManagerRemoteDatabase;C:\Windows\system32\MSDtc\MSDTC.LOG;C:\Windows\netlogon.chg;:\hiberfil.sys;:\System Volume Information\Heat\*.*;C:\Users\Dadovi\AppData\Local\Temp\*;:\System Volume Information\*{3808876B-C176-4e48-B7AE-04046E6CC752};:\System Volume Information\:.{7cc467ef-6865-4831-853f-2a4817fd1bca}ALT;:\System Volume Information\:.{7cc467ef-6865-4831-853f-2a4817fd1bca}DB;C:\ProgramData\Microsoft\Windows\WER\*;C:\Windows\softwaredistribution\*.*;:\System Volume Information\FVE2.{e40ad34d-dae9-4bc7-95bd-b16218c10f72}.:;:\System Volume Information\FVE2.{c9ca54a3-6983-46b7-8684-a7e5e23499e3};:\System Volume Information\FVE2.{24e6f0ae-6a00-4f73-984b-75ce9942852d};:\System Volume Information\FVE2.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08};:\System Volume Information\FVE2.{aff97bac-a69b-45da-aba1-2cfbce434750}.:;:\System Volume Information\FVE2.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08}.:;:\System Volume Information\FVE.{e40ad34d-dae9-4bc7-95bd-b16218c10f72}.:;:\System Volume Information\FVE.{c9ca54a3-6983-46b7-8684-a7e5e23499e3};:\System Volume Information\FVE.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08};C:\Users\:\AppData\Local\Temp;C:\Users\:\AppData\Local\Microsoft\Windows\Temporary Internet Files;C:\Users\:\AppData\Local\Google\Chrome\User Data\Default\Cache;C:\Users\:\AppData\Local\Google\Chrome\User Data\Default\Media Cache;C:\Users\:\AppData\Local\Microsoft\Windows\Explorer\thumbcache*;C:\Users\:\AppData\Local\Mozilla\Firefox\Profiles\:\cache2;C:\Users\:\AppData\Local\Mozilla\Firefox\Profiles\:\cache;C:\Windows\Temp;:\$Recycle.Bin;:\System Volume Information;C:\Windows.old;C:\$Windows.~BT;C:\ProgramData\Microsoft\Windows Defender\Scans\mpcache-*;C:\Windows;C:\$GetCurrent;C:\Program Files;C:\Program Files (x86);C:\ProgramData

A drive had failed on the client which was replaced, formatted and mounted on the same letter D:\

In web UI tried to restore the latest backup first, then i realized it contains mostly empty folders.

Then I went ahead to restore from a backup made ~two weeks ago (201011-1752 - before the drive failed) using the agent on the client.

I am sure i always browsed to D first, then clicked “restore”, but i see some references to files written in C:. There was one exception, where i clicked “restore” from the top level, but i have realized this and answered “No” on the client confirmation window.

Subsequent attempts to trigger a restore of D just caused the web UI to return to the folder list after a few seconds, without triggering a confirmation on the client.

I noticed that i get errors about “C/Program Files/…”, but these are supposed to be excluded and i wonder why UrBackup server thinks it needs to access this location?

Maybe i should look in the sqlite database for hints? Any pointer is appreciated, i am worried if my backup is consistent.

This is the log from the server:
2020-10-25 09:27:29: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Games/Chicken Invaders 2 - The Next Wave [Christmas Edition]/.dir_metadata. Code 0
2020-10-25 09:27:29: ERROR: Error opening metadata file for “dclientdl0/Games/Chicken Invaders 2 - The Next Wave [Christmas Edition]”
2020-10-25 09:27:29: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Games/Heroes of Might and Magic 3 Complete/.dir_metadata. Code 0
2020-10-25 09:27:29: ERROR: Error opening metadata file for “dclientdl0/Games/Heroes of Might and Magic 3 Complete”
2020-10-25 09:27:30: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Games/KOH/packs/.dir_metadata. Code 0
2020-10-25 09:27:30: ERROR: Error opening metadata file for “dclientdl0/Games/KOH/packs”
2020-10-25 09:27:30: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Games/PortableMachinarium1.01/.dir_metadata. Code 0
2020-10-25 09:27:30: ERROR: Error opening metadata file for “dclientdl0/Games/PortableMachinarium1.01”
2020-10-25 09:27:30: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/OLD/8b72670609365a843fda24fa/.dir_metadata. Code 0
2020-10-25 09:27:30: ERROR: Error opening metadata file for “dclientdl0/OLD/8b72670609365a843fda24fa”
2020-10-25 09:27:30: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/OLD/SIERRA/.dir_metadata. Code 0
2020-10-25 09:27:30: ERROR: Error opening metadata file for “dclientdl0/OLD/SIERRA”
2020-10-25 09:28:26: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Snimki/2013/.dir_metadata. No such file or directory (code: 2)
2020-10-25 09:28:26: ERROR: Error opening metadata file for “dclientdl0/Snimki/2013”
2020-10-25 09:28:27: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Snimki/KALENDAR 2017/.dir_metadata. No such file or directory (code: 2)
2020-10-25 09:28:27: ERROR: Error opening metadata file for “dclientdl0/Snimki/KALENDAR 2017”
2020-10-25 09:28:27: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Snimki/gyu/.dir_metadata. No such file or directory (code: 2)
2020-10-25 09:28:27: ERROR: Error opening metadata file for “dclientdl0/Snimki/gyu”
2020-10-25 09:28:27: ERROR: Cannot read from metadata file /mnt/data/DESKTOP-N3KU1HK/201021-2311/.hashes/D/Snimki/kalendar 2018/.dir_metadata. No such file or directory (code: 2)
2020-10-25 09:28:27: ERROR: Error opening metadata file for “dclientdl0/Snimki/kalendar 2018”
2020-10-25 09:45:42: ERROR: Cannot open handle to restore file metadata of file “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{3DA71D5A-20CC-432F-A115-DFE92379E91F}.3.ver0x000000000000027c.db”. The system cannot find the file specified. (code: 2)
2020-10-25 09:45:42: ERROR: Error saving metadata. Could not save OS specific metadata to “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{3DA71D5A-20CC-432F-A115-DFE92379E91F}.3.ver0x000000000000027c.db”
2020-10-25 09:51:41: ERROR: Restore was declined by client
2020-10-25 09:52:31: ERROR: Cannot open “/mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java”: No such file or directory (2)
2020-10-25 09:52:31: ERROR: Cannot read files from folder /mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java. Cannot start restore.
2020-10-25 10:00:02: ERROR: Cannot open “/mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java”: No such file or directory (2)
2020-10-25 10:00:02: ERROR: Cannot read files from folder /mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java. Cannot start restore.
2020-10-25 10:11:25: ERROR: Cannot open “/mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java”: No such file or directory (2)
2020-10-25 10:11:25: ERROR: Cannot read files from folder /mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java. Cannot start restore.
2020-10-25 10:28:51: ERROR: Error opening file “/mnt/data/DESKTOP-N3KU1HK/201011-1752/D/OLD/Users/user/My Documents”
2020-10-25 10:35:21: ERROR: Error opening file “/mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Users/Dadovi/Documents/My Pictures”
2020-10-25 11:47:35: ERROR: Restore was inactive for 5min. Timeout. Stopping restore…

redshifted · October 26, 2020, 11:50am

I just realized that i have the following folders in the backup which i was restoring:

root@urbackup:~ # ls -al /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/Documents\ and\ Settings
lrwxr-xr-x  1 urbackup  urbackup  10 Oct 11 17:55 /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/Documents and Settings -> ../C/Users
root@urbackup:~ #

root@urbackup:~ # ls -al /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/ProgramData
total 83
drwxr-x---  22 urbackup  urbackup  28 Oct 11 17:56 .
drwxr-x---  10 urbackup  urbackup  15 Oct 11 17:56 ..
drwxr-x---   4 urbackup  urbackup   4 Oct 11 17:56 Adobe
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 AMD
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 APN
lrwxr-xr-x   1 urbackup  urbackup  23 Oct 11 17:56 Application Data -> ../../.symlink_void_dir
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 ATI
drwxr-x---   6 urbackup  urbackup   7 Oct 11 17:56 AVAST Software
drwxr-x---   2 urbackup  urbackup   2 Oct 11 17:56 Babylon
drwxr-x---   4 urbackup  urbackup   4 Oct 11 17:56 Canon_Inc_IC
drwxr-x---   2 urbackup  urbackup   2 Oct 11 17:56 CorelDRAW Technical Suite X6
drwxr-x---   2 urbackup  urbackup   4 Oct 11 17:56 DAEMON Tools Lite
lrwxr-xr-x   1 urbackup  urbackup  28 Oct 11 17:56 Desktop -> ../../C/Users/Public/Desktop
lrwxr-xr-x   1 urbackup  urbackup  30 Oct 11 17:56 Documents -> ../../C/Users/Public/Documents
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 Downloaded Installations
lrwxr-xr-x   1 urbackup  urbackup  30 Oct 11 17:56 Favorites -> ../../C/Users/Public/Favorites
drwxr-x---   2 urbackup  urbackup   3 Oct 11 17:56 fltk.org
drwxr-x---   4 urbackup  urbackup   5 Oct 11 17:56 McAfee
drwxr-x---  25 urbackup  urbackup  25 Oct 11 17:56 Microsoft
drwxr-x---   4 urbackup  urbackup   4 Oct 11 17:56 Mozilla
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 Oracle
drwxr-x---  12 urbackup  urbackup  12 Oct 11 17:56 Package Cache
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 PlayFirst
drwxr-x---   8 urbackup  urbackup   9 Oct 11 17:56 Skype
lrwxr-xr-x   1 urbackup  urbackup  48 Oct 11 17:56 Start Menu -> ../../C/ProgramData/Microsoft/Windows/Start Menu
drwxr-x---   3 urbackup  urbackup   3 Oct 11 17:56 Sun
drwxr-x---   2 urbackup  urbackup   2 Oct 11 17:56 TEMP
lrwxr-xr-x   1 urbackup  urbackup  47 Oct 11 17:56 Templates -> ../../C/ProgramData/Microsoft/Windows/Templates

Can this be the reason that Urbackup has tried to restore files in C:?

redshifted · October 26, 2020, 12:31pm

When searching for java in the backup under D, i find following references:

lrwxr-xr-x  1 urbackup  urbackup  82 Oct 11 17:55 javapath -> ../../../../../../C/Program Files/Common Files/Oracle/Java/javapath_target_9421087
lrwxr-xr-x  1 urbackup  urbackup  82 Oct 11 17:55 /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/OLD/Program Files/Common Files/Oracle/Java/javapath -> ../../../../../../C/Program Files/Common Files/Oracle/Java/javapath_target_9421087
lrwxr-xr-x  1 urbackup  urbackup  61 Apr 23  2017 java.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/java.exe
lrwxr-xr-x  1 urbackup  urbackup  62 Apr 23  2017 javaw.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/javaw.exe
lrwxr-xr-x  1 urbackup  urbackup  63 Apr 23  2017 javaws.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/javaws.exe
lrwxr-xr-x  1 urbackup  urbackup  63 Apr 23  2017 /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/ProgramData/Oracle/Java/javapath/javaws.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/javaws.exe
lrwxr-xr-x  1 urbackup  urbackup  61 Apr 23  2017 /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/ProgramData/Oracle/Java/javapath/java.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/java.exe
lrwxr-xr-x  1 urbackup  urbackup  62 Apr 23  2017 /mnt/data/DESKTOP-N3KU1HK/201011-1752/D/ProgramData/Oracle/Java/javapath/javaw.exe -> ../../../../../C/Program Files/Java/jre1.8.0_131/bin/javaw.exe

This explains why i got errors like
2020-10-25 10:11:25: ERROR: Cannot open “/mnt/data/DESKTOP-N3KU1HK/201011-1752/C/Program Files/Common Files/Oracle/Java”: No such file or directory (2)

This is quite unexpected, since this means Urbackup doesn’t restore those as links, but tries resolving the link, which leads to inconsistent backup set.

uroni · October 26, 2020, 12:45pm

No it follows symlinks during restore, but restores them properly. Using the command line one can disable following symlinks during restore (urbackupclientctl restore --no-follow-symlinks /"C:\Program Files\UrBackup\UrBackupClient_cmd.exe" on Windows) .

The question is more why your backups are corrupted?

redshifted · November 1, 2020, 5:35pm

Hi Uroni,

Thank you for taking the time to answer personally on this thread. I am thankful for being able to use Urbackup and this is a great software! I am just trying to figure out what i have done, when initiating a restore on the new D:\ drive.

Here are the logs when i have started restore of D:\

Starting restore of path “D/”. Waiting for client confirmation…
Starting restore…
Loading file list…
Calculating download size…
Downloading necessary file data…
Error deleting file “C:\Users\Dadovi\AppData\Local\Comms\UnistoreDB\tmp.edb”. The process cannot access the file because it is being used by another process. (code: 32)
Error deleting file “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{3DA71D5A-20CC-432F-A115-DFE92379E91F}.3.ver0x0000000000000290.db”. Access is denied. (code: 5)
Error deleting file “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{AFBF9F1A-8EE8-4C77-AF34-C647E37CA0D9}.1.ver0x00000000000001e2.db”. Access is denied. (code: 5)
Applying file metadata…
Cannot open handle to restore file metadata of file “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{3DA71D5A-20CC-432F-A115-DFE92379E91F}.3.ver0x000000000000027c.db”. The system cannot find the file specified. (code: 2)
Error saving metadata. Could not save OS specific metadata to “C:\Users\Dadovi\AppData\Local\Microsoft\Windows\Caches{3DA71D5A-20CC-432F-A115-DFE92379E91F}.3.ver0x000000000000027c.db”
Restore failed.

After this restore, Firefox started complaining locked files, and when i examined the Firefox profile directory, i found files named like this:

C:\Users\Dadovi\AppData\Roaming\Mozilla\Firefox\Profiles\26r3bi6f.default>dir /s urbackup
Volume in drive C has no label.
Volume Serial Number is E636-7635

Directory of C:\Users\Dadovi\AppData\Roaming\Mozilla\Firefox\Profiles\26r3bi6f.default

25.10.2020 г. 11:36 884 736 cert9.db_urbackup_restore_0
25.10.2020 г. 11:36 229 376 content-prefs.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 3 670 016 cookies.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 7 274 496 favicons.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 819 200 formhistory.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 294 912 key4.db_urbackup_restore_0
25.10.2020 г. 11:36 0 parent.lock_urbackup_restore_0
25.10.2020 г. 11:36 393 216 permissions.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 5 242 880 places.sqlite_urbackup_restore_0
25.10.2020 г. 11:36 65 536 protections.sqlite_urbackup_restore_0
25.10.2020 г. 11:40 263 168 storage.sqlite_urbackup_restore_0
25.10.2020 г. 11:40 56 754 176 webappsstore.sqlite_urbackup_restore_0
12 File(s) 75 891 712 bytes
 Total Files Listed:
          12 File(s)     75 891 712 bytes
           0 Dir(s)  35 616 657 408 bytes free
C:\Users\Dadovi\AppData\Roaming\Mozilla\Firefox\Profiles\26r3bi6f.default>

This all means that the restore has overwritten files in C:, which was not what I wanted to do.

The restored D:\ drive currently looks like this:

D:>dir /AL /S
Volume in drive D is Disk1
Volume Serial Number is 962A-BF46

Directory of D:\

14.07.2009 г. 06:53 Documents and Settings [C:\Users]
0 File(s) 0 bytes

Directory of D:\OLD\Users

14.07.2009 г. 06:53 All Users [C:\ProgramData]
14.07.2009 г. 06:53 Default User [C:\Users\Default]
0 File(s) 0 bytes

Directory of D:\OLD\Users\All Users

25.05.2020 г. 16:57 Application Data [C:\ProgramData]
25.05.2020 г. 16:57 Desktop [C:\Users\Public\Desktop]
25.05.2020 г. 16:57 Documents [C:\Users\Public\Documents]
25.05.2020 г. 16:57 Start Menu [C:\ProgramData\Microsoft\Windows\Start Menu]
25.05.2020 г. 16:57 Templates [C:\ProgramData\Microsoft\Windows\Templates]
0 File(s) 0 bytes
 Total Files Listed:
           0 File(s)              0 bytes
           8 Dir(s)  1 987 169 419 264 bytes free
D:>

It has correctly restored the NTFS link/junctions, but unfortunately for me also followed them further and restoring files in into C:\Users, corrupting some Firefox profile files.

I have looked at my backup set and have confirmed that there are a lot of files under

Clients >DESKTOP-N3KU1HK > 10/11/20 20:54 > D > Documents and Settings

which got pulled from C:\Users by following the link.

I have changed this client’s “Default directories to backup” from

C:\;D:\

To

C:\|C/follow_symlinks,symlinks_optional,one_filesystem;D:\|D/follow_symlinks,symlinks_optional,one_filesystem

This will match my expectation for better control when restoring, so I will give it a try.

Thanks again for this great project!