[Solved] Backup client stuck at "Indexing.." with no ETA shown

Urbackup server 2.1.20 running on a Win 10 Pro (1709, x64) box,
Urbackup client 2.1.16 running on a Win 10 Pro (1709, x64) box as well.

For the last week, the client has not been able to perform a file backup. It starts indexing, the activity is shown as running on the Activities page, but it never completes.

While all other clients show a decreasing ETA during the Indexing… phase, this client only shows “Indexing…” with no ETA.

I have enabled debugging on the client, but I I haven’t been able to find any hint:

2018-01-18 07:43:24: Loaded -fileserv- plugin
2018-01-18 07:43:24: Loaded -fsimageplugin- plugin
2018-01-18 07:43:24: Loaded -cryptoplugin- plugin
2018-01-18 07:43:24: SQLite: recovered 11064 frames from WAL file C:\Program Files\UrBackup\urbackup\backup_client.db-wal code: 283
2018-01-18 07:43:24: urbackupserver: Server started up successfully!
2018-01-18 07:43:24: FileSrv: Backup privileges set successfully
2018-01-18 07:43:24: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2018-01-18 07:43:24: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2018-01-18 07:43:24: Started UrBackupClient Backend…
2018-01-18 07:43:24: FileSrv: Binding UDP socket at port 35622…
2018-01-18 07:43:24: Filesystem. Vol="\?\Volume{82817908-601f-11e2-8bac-806e6f6e6963}" Name=“riservato per il sistema” Type=“ntfs” VPaths=0 Size=104853504
2018-01-18 07:43:25: FileSrv: done.
2018-01-18 07:43:25: FileSrv: Disabling new behavior…
2018-01-18 07:43:25: FileSrv: Servername: -PC072-
2018-01-18 07:43:25: Bootable flag set for volume
2018-01-18 07:43:25: Found potential candidate: \?\Volume{82817908-601f-11e2-8bac-806e6f6e6963}\ Score: 5
2018-01-18 07:43:25: FileSrv: UDP Thread startet
2018-01-18 07:43:25: FileSrv: Server started up successfully
2018-01-18 07:43:25: Filesystem. Vol="\?\Volume{82817909-601f-11e2-8bac-806e6f6e6963}" Name="" Type=“ntfs” VPaths=1 Size=237386067968
2018-01-18 07:43:25: Filesystem is System partition. Skipping…
2018-01-18 07:43:25: Filesystem. Vol="\?\Volume{f7a65d87-601f-11e2-bcb7-de0cb7a68e80}" Name="" Type=“ntfs” VPaths=1 Size=262141898752
2018-01-18 07:43:25: Bootable flag not set for volume
2018-01-18 07:43:25: Filesystem. Vol="\?\Volume{dc884791-0000-0000-0000-a04b37000000}" Name="" Type=“ntfs” VPaths=0 Size=471855104
2018-01-18 07:43:25: Bootable flag not set for volume
2018-01-18 07:43:25: Found potential candidate: \?\Volume{dc884791-0000-0000-0000-a04b37000000}\ Score: 1
2018-01-18 07:43:25: Filesystem. Vol="\?\Volume{8281790c-601f-11e2-8bac-806e6f6e6963}" Name="" Type="" VPaths=1 Size=-1
2018-01-18 07:43:25: GetVolumeInformation failed with error code 21. Skipping…
2018-01-18 07:43:25: Selected volume \?\Volume{82817908-601f-11e2-8bac-806e6f6e6963}
2018-01-18 07:43:25: System dir: C:\WINDOWS
2018-01-18 07:43:25: Volpath: \.\C:
2018-01-18 07:43:25: Device is not GPT formatted (0)
2018-01-18 07:43:25: Found no EFI System Partition
2018-01-18 07:43:25: urbackupserver: No available slots… starting new Worker
2018-01-18 07:43:25: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:43:25: Looking for old Sessions… 0 sessions
2018-01-18 07:43:25: Internet mode not enabled
2018-01-18 07:43:26: Final path: C:
2018-01-18 07:43:26: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:43:29: ClientService cmd: #IvoVdInJjBIuJaRP728C7#1CHANNEL capa=65485&token=NOmGJmdWDZgy6zW1CGbj&restore_version=1&virtual_client=
2018-01-18 07:43:29: New channel: Number of Channels: 1
2018-01-18 07:44:18: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:44:25: Client timeout in ClientConnector::Run
2018-01-18 07:44:29: ClientService cmd: PONG
2018-01-18 07:45:10: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:45:29: ClientService cmd: PONG
2018-01-18 07:46:02: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:46:26: Internet mode not enabled
2018-01-18 07:46:29: ClientService cmd: PONG
2018-01-18 07:46:54: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:47:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#3START FULL BACKUP group=0&running_jobs=1&sha=528&with_permissions=1&with_scripts=1&with_orig_path=1&with_sequence=1&with_proper_symlinks=1&status_id=31&async=1#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:00: Async index 832a02a29d66aa9da408471d5618cb94
2018-01-18 07:47:00: Removing VSS log data…
2018-01-18 07:47:00: rc=0 hasError=true state=0
2018-01-18 07:47:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#WAIT FOR INDEX async_id=832a02a29d66aa9da408471d5618cb94#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:00: Wait for async index 832a02a29d66aa9da408471d5618cb94
2018-01-18 07:47:00: Final path: C:
2018-01-18 07:47:00: Script list at “C:\Program Files\UrBackup\backup_scripts\list.bat” does not exist. Skipping.
2018-01-18 07:47:00: Deleting files… doing full index…
2018-01-18 07:47:00: Final path: C:
2018-01-18 07:47:02: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:47:02: WARNING: Limiting number of DC users to 105
2018-01-18 07:47:04: WARNING: Limiting number of DC groups to 100
2018-01-18 07:47:05: Removing deleted directories from index…
2018-01-18 07:47:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:20: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:29: ClientService cmd: PONG
2018-01-18 07:47:30: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:40: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:50: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:47:54: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:48:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:48:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:48:20: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:48:29: ClientService cmd: PONG
2018-01-18 07:48:30: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:48:40: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:48:46: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:48:50: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:20: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:29: ClientService cmd: PONG
2018-01-18 07:49:30: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:38: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:49:40: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:49:50: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:20: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:29: ClientService cmd: PONG
2018-01-18 07:50:30: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:50:30: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:40: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:50:50: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:20: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:22: ClientService cmd: STATUS#pw=giXD8Ukrgf5lGAy6indnpyaGMnmGT8
2018-01-18 07:51:29: ClientService cmd: PONG
2018-01-18 07:51:30: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:40: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:51:50: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:52:00: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj
2018-01-18 07:52:10: ClientService cmd: #IvoVdInJjBIuJaRP728C7#2PING RUNNING pc_done=&status_id=31&speed_bpms=0&total_bytes=-1&done_bytes=0#token=NOmGJmdWDZgy6zW1CGbj

The last lines repeat endlessly

On the server I haven’t enabled debugging (lack of time… :frowning: ), I have only restarted the PC.

I cannot find anything specific in the log, but there are some suspect lines (PC072 is the problematic machine):

2018-01-14 03:07:50: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-15 03:08:30: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-15 03:08:52: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-15 03:09:13: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-15 09:01:24: WARNING: Creating temporary file at “C:\WINDOWS\TEMP\urbackup_tmp\urb8274545a62bd4c9700000001400DC210e.tmp” failed. Creating directory “C:\WINDOWS\TEMP\urbackup_tmp”…
2018-01-15 14:31:51: WARNING: Sever admin stopped backup during indexing
2018-01-15 14:31:56: ERROR: Backup had an early error. Deleting partial backup.
2018-01-15 14:31:57: WARNING: Exponential backoff: Waiting at least 40m before next file backup
2018-01-15 16:43:24: ERROR: Constructing of filelist of “PC072” failed: error - Async indexing process not found
2018-01-15 16:43:33: ERROR: Backup had an early error. Deleting partial backup.
2018-01-15 16:43:34: WARNING: Exponential backoff: Waiting at least 1h 20m before next file backup
2018-01-15 18:37:23: ERROR: Constructing of filelist of “PC072” failed: error - Async indexing process not found
2018-01-15 18:37:34: ERROR: Backup had an early error. Deleting partial backup.
2018-01-15 18:37:35: WARNING: Exponential backoff: Waiting at least 2h 40m before next file backup
2018-01-15 19:02:06: WARNING: Error: Unknown action [progress]
2018-01-15 19:02:36: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-15 19:02:58: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-15 19:03:19: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-15 19:20:53: ERROR: Connecting to ClientService of “PC072” failed - CONNECT error during filelist construction (2)
2018-01-15 19:21:12: ERROR: Backup had an early error. Deleting partial backup.
2018-01-15 19:21:23: WARNING: Connecting to ClientService of “PC072” failed: Sending logdata to client failed
2018-01-16 03:03:41: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-16 03:04:03: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-16 03:04:24: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-16 18:44:26: ERROR: Connecting to ClientService of “PC072” failed - CONNECT error during filelist construction (2)
2018-01-16 18:44:45: ERROR: Backup had an early error. Deleting partial backup.
2018-01-16 18:44:56: WARNING: Connecting to ClientService of “PC072” failed: Sending logdata to client failed
2018-01-17 03:28:50: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-17 03:29:11: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-17 03:29:32: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-17 07:42:22: ERROR: Connecting to ClientService of “PC050” failed: Querying client capabilities failed
2018-01-17 19:21:06: ERROR: Connecting to ClientService of “PC072” failed - CONNECT error during filelist construction (2)
2018-01-17 19:21:18: ERROR: Backup had an early error. Deleting partial backup.
2018-01-17 19:21:46: WARNING: Connecting to ClientService of “PC072” failed: Sending logdata to client failed
2018-01-18 03:45:31: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-18 03:45:53: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-18 03:46:14: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-18 07:36:09: WARNING: Creating temporary file at “C:\WINDOWS\TEMP\urbackup_tmp\urb9eec5c5a04a0495100000001400DC210b.tmp” failed. Creating directory “C:\WINDOWS\TEMP\urbackup_tmp”…
2018-01-18 08:06:46: ERROR: Constructing of filelist of “PC072” failed: error - Async indexing process not found
2018-01-18 08:06:54: ERROR: Backup had an early error. Deleting partial backup.
2018-01-18 08:06:55: WARNING: Exponential backoff: Waiting at least 40m before next file backup
2018-01-18 08:08:28: WARNING: Error: Unknown action [progress]
2018-01-18 08:08:38: WARNING: Error: Unknown action [progress]
2018-01-18 08:09:02: ERROR: Error while downloading version info from version.txt: Couldn’t resolve host name(ec=6), Could not resolve host: version.txt
2018-01-18 08:09:23: ERROR: Error downloading server version information: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out
2018-01-18 08:09:44: ERROR: Error downloading dataplan database: Couldn’t connect to server(ec=7), Failed to connect to update4.urbackup.org port 80: Timed out

The client log available through the server pages while “Indexing…” is:

|01/18/18 08:13 |INFO |Starting unscheduled full file backup…|
|01/18/18 08:13 |DEBUG |PC072: Connecting for filelist…|
|01/18/18 08:13 |DEBUG |PC072: Waiting for filelist|
|01/18/18 08:13 |DEBUG |PC072: Connecting for filelist (async)…|

I have not had time (yet) to reinstall urbackup on the client PC: could this be useful? Is there a way to reset it, instead of reinstalling?

On the client I have not found anything particular in Event Viewer, and VSS seems to be working properly.

Thanks for your help!

The problem has gone away spontaneously, after a client reboot.

Before the reboot, I was investigating the problem and I found that “vssadmin list writers” would never complete, stuck at the message “Waiting for responses. These may be delayed if a shadow copy is being prepared.”

I tried to restart “COM+ Event System” and “Volume Shadow Copy” services, after which “vssadmin list writers” would complete, but listing no writer at all…

So I rebooted the client, and now a full backup is happily going on… Go figure