Windows 11 Restore: Error reading Size

mtaylor · October 17, 2023, 9:46pm

Hi,

I am attempting to use the urbackup flash drive utility to restore a Windows 11 image to a new 500 GB SSD. The last successful image was backed up from the now dead 250 GB SSD. The image that I am attempting to restore shows as below on the urbackup server:

Id: [ID]
Backup time: 10/05/23 00:51
Incremental: Yes
Size: 28.68 GB
Volume: C:
Volume size: 231.37 GB
Partition style: GPT
Disk number: 0
Partition number: 4
File system type: NTFS

When I attempt to restore this image, it gets to 95 GB downloaded, then errors out with:

2023-10-17 13:58:19: Imagesize 34404
2023-10-17 13:58:19: Downloading MBR…
2023-10-17 13:58:19: ClientService cmd: #BjQrSyasdfasdfSYD6USeg#1CHANNEL capa=4096&token=209sjSq0u8HWteiQjaJX&restore_version=1&startup=1&virtual_client=
2023-10-17 13:58:19: rc=0 hasError=true state=0
2023-10-17 13:58:19: Downloading MBR done
2023-10-17 13:58:19: Removing running process (1) id 4 server_id 0 token action 9
2023-10-17 13:58:19: Download done -2
2023-10-17 13:58:20: ClientService cmd: DOWNLOAD IMAGE#pw=asd9yYuDJqsjFfWK999V7FUQjAA5XQ&img_id=173988411&time=1695282231&mbr=false
2023-10-17 13:58:20: Downloading image…
2023-10-17 13:58:20: Waiting for pings…
2023-10-17 13:58:20: done. (Waiting for pings)
2023-10-17 13:58:20: In mutex…
2023-10-17 13:58:20: Downloading from channel 0
2023-10-17 13:58:20: ClientService cmd: #BjQrSyasdfasdfSYD6USeg#1CHANNEL capa=4096&token=209sjSq0u8HWteiQjaJX&restore_version=1&startup=1&virtual_client=
2023-10-17 13:58:20: Imagesize -1
2023-10-17 13:58:20: ERROR: Error reading size
2023-10-17 13:58:20: rc=0 hasError=true state=0
2023-10-17 13:58:20: Removing running process (1) id 5 server_id 0 token action 9
2023-10-17 13:58:20: Download done -2
2023-10-17 13:58:21: ClientService cmd: #BjQrSyasdfasdfSYD6USeg#1CHANNEL capa=4096&token=209sjSq0u8HWteiQjaJX&restore_version=1&startup=1&virtual_client=
2023-10-17 13:58:21: New channel: Number of Channels: 1
2023-10-17 13:59:21: ClientService cmd: PONG

I’m at a loss for understanding how to troubleshoot from this point. I’ve tried restoring older images and get the same error.

Thanks for your help!

Marshall

restore_client.log (8 KB)

uroni · October 18, 2023, 7:54pm

Looks like it finishes restoring the C image then continues on to either the ESP or SYSVOL image which fails. I think you can fix up the SYSVOL partition via Windows install disk.
Maybe there is a hint why SYSVOL/ESP fails in the server log?

mtaylor · October 18, 2023, 9:07pm

Great idea to try uroni! Unfortunately booting a Windows 11 ISO to repair the image did not work. The system diagnosis found nothing when scanning the system for repairable issues. Does the list of C:, SYSVOL and ESP backups look reasonable size-wise? I wouldn’t expect them to vary much (?), but they do:

Backup time Volume Incremental Size Archived? Actions
10/05/23 00:51 C: Yes 28.68 GB ☐
10/05/23 00:51 ESP No 3.75 MB ☐
10/05/23 00:51 SYSVOL No 512 bytes ☐
09/28/23 00:47 C: Yes 28.36 GB ☐
09/28/23 00:47 ESP No 512 bytes ☐
09/28/23 00:46 SYSVOL No 512 bytes ☐

I’m running Urbackup Server in a Truenas jail. /var/log/urbackup.log shows the one entry from 10/16/23, which is this:

Oct 16 12:00:11 urbackup newsyslog[85261]: logfile turned over due to size>5120K

The bzipped (rotated) log before it is full of weird SQLite SQL messages like:

2023-10-16 12:00:22: SQLITE_BUSY in CQuery::Execute Stmt: [BEGIN IMMEDIATE;]
2023-10-16 12:00:22: Active query(0): SELECT COUNT(*) AS c FROM files_incoming_stat
2023-10-16 12:00:22: Active query(1): INSERT INTO files_last (fullpath, hashpath, shahash, filesize) SELECT fullpath, hashpath, shahash, filesize FROM files WHERE backupid = ?
2023-10-16 12:00:22: Active query(2): PRAGMA wal_checkpoint(PASSIVE)
2023-10-16 12:00:22: Active query(3): INSERT INTO files_incoming_stat (filesize, clientid, backupid, existing_clients, direction, incremental) VALUES (?, ?, ?, ?, ?, ?)
2023-10-16 12:00:22: Active query(4): INSERT INTO files (backupid, fullpath, hashpath, shahash, filesize, rsize, clientid, incremental, next_entry, prev_entry, pointed_to) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2023-10-16 12:00:22: Active query(5): INSERT INTO files (backupid, fullpath, hashpath, shahash, filesize, rsize, clientid, incremental, next_entry, prev_entry, pointed_to) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2023-10-16 12:00:22: Active query(6): BEGIN IMMEDIATE;
2023-10-16 12:00:22: Active query(7): BEGIN IMMEDIATE;
2023-10-16 12:00:22: Active query(8): INSERT INTO files (backupid, fullpath, hashpath, shahash, filesize, rsize, clientid, incremental, next_entry, prev_entry, pointed_to) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2023-10-16 12:00:22: Active query(9): BEGIN IMMEDIATE;
2023-10-16 12:00:22: Active query(10): UPDATE files SET prev_entry=? WHERE id=?
2023-10-16 12:00:22: Active query(11): BEGIN IMMEDIATE;
2023-10-16 12:00:22: Active query(12): END;

FWIW, the Urbackup server is running right now, but does not appear to be producing any useful server log debug output (?). I appear to not have that configured correctly

uroni · October 18, 2023, 9:29pm

Yeah, it shouldn’t vary since they are mostly unchanging. Seems something went wrong with the backup of those How large are the actual files on disk?

With GPT/UEFI it seems to be harder to to be able to restore this… There are a lot of instructions like How to Repair Windows Boot Manager, BCD and Master Boot Record (MBR) | Windows OS Hub , but idk how much of it is command line cargo cult.

But at least you should be able to see the restored disk when you go to the command line via Windows install disk?

The best log would be the Log => Live log => All Users while it tries to restore SYSVOL/ESP.

mtaylor · October 19, 2023, 8:45pm

The 10/05/23 and 09/28/23 backup sizes do not agree with what is showed in the urbackup interface. As commented before, this is what is show in the GUI interface:

Backup time Volume Incremental Size Archived? Actions

10/05/23 00:51 C: Yes 28.68 GB ☐
10/05/23 00:51 ESP No 3.75 MB ☐
10/05/23 00:51 SYSVOL No 512 bytes ☐
09/28/23 00:47 C: Yes 28.36 GB ☐
09/28/23 00:47 ESP No 512 bytes ☐
09/28/23 00:46 SYSVOL No 512 bytes ☐

This is what is shown from shelling into TrueNAS and running du:

root@truenas[~]# du -h /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/231005-0051_Image_*
29G /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/231005-0051_Image_C
23M /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/231005-0051_Image_ESP
3.2M /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/231005-0051_Image_SYSVOL
root@truenas[~]# du -h /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/230928-004*
28G /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/230928-0047_Image_C
23M /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/230928-0047_Image_ESP
1.4M /mnt/mainpool/iocage/jails/urbackupjail/root/mnt/backups/urbackup/dsp06/230928-0046_Image_SYSVOL

They appear to differ in size ¯_(ツ)_/¯

I’ll boot the repair disk and see how far I get.