Timeout while waiting for server to start backup

AckRite · September 6, 2016, 10:24am

Server UrBackup 2.0.33
Client UrBackup 2.0.32

Recently one of my machines didn’t start its backup. What I know:

Ports are open (verified with nmap)
both server and client see each other (pingable)
I can see client listed in webinterface

If I try to start backup from web interface, it states “queued backup” and does nothing.
If I try to start backup from client, I get “Timeout while waiting for server to start backup”.

Relevant live log on server:

09/06/16 02:02  	INFO  	Starting incremental file backup...
09/06/16 02:02  	DEBUG  	ns: Connecting for filelist...
09/06/16 02:02  	DEBUG  	ns: Waiting for filelist
09/06/16 02:03  	ERROR  	Constructing of filelist of "ns" failed - TIMEOUT(1)
09/06/16 02:03  	ERROR  	Backup had an early error. Deleting partial backup.
09/06/16 02:08  	INFO  	Starting incremental file backup...
09/06/16 02:08  	DEBUG  	ns: Connecting for filelist...
09/06/16 02:08  	ERROR  	Connecting to ClientService of "ns" failed - CONNECT error during filelist construction
09/06/16 02:08  	ERROR  	Backup had an early error. Deleting partial backup.
09/06/16 02:08  	WARNING  	Exponential backoff: Waiting at least 40m before next file backup
09/06/16 12:31  	DEBUG  	Getting client settings...
09/06/16 12:31  	DEBUG  	Sending backup incr interval...
09/06/16 12:32  	DEBUG  	Cannot do image backup because can_backup_images=false
09/06/16 12:32  	DEBUG  	Cannot do image backup because internet_no_images=true
09/06/16 12:32  	DEBUG  	Cannot do image backup because can_backup_images=false
09/06/16 12:32  	DEBUG  	Cannot do image backup because internet_no_images=true

Relevant log on server:

2016-09-06 02:04:15: Socket has error: 111
2016-09-06 02:04:25: Socket has error: 111
2016-09-06 02:04:35: Socket has error: 111
2016-09-06 02:04:45: Socket has error: 111
2016-09-06 02:04:55: Socket has error: 111
2016-09-06 02:05:05: Socket has error: 111
2016-09-06 02:05:15: Socket has error: 111
2016-09-06 02:05:25: Socket has error: 111
2016-09-06 02:05:35: Socket has error: 111
2016-09-06 02:05:45: Socket has error: 111
2016-09-06 02:05:55: Socket has error: 111
2016-09-06 02:06:05: Socket has error: 111
2016-09-06 02:06:15: Socket has error: 111
2016-09-06 02:06:25: Socket has error: 111
2016-09-06 02:06:35: Socket has error: 111
2016-09-06 02:06:45: Socket has error: 111
2016-09-06 02:06:55: Socket has error: 111
2016-09-06 02:07:05: Socket has error: 111
2016-09-06 02:07:15: Socket has error: 111
2016-09-06 02:07:25: Socket has error: 111
2016-09-06 02:07:35: Socket has error: 111
2016-09-06 02:07:45: Socket has error: 111
2016-09-06 02:07:55: Socket has error: 111
2016-09-06 02:08:05: Socket has error: 111
2016-09-06 02:08:15: Socket has error: 111
2016-09-06 02:08:21: Starting incremental file backup…
2016-09-06 02:08:21: Socket has error: 111
2016-09-06 02:08:21: Socket has error: 111
2016-09-06 02:08:21: ERROR: Connecting to ClientService of “ns” failed - CONNECT error during filelist construction
2016-09-06 02:08:25: Socket has error: 111

I keep getting “Getting client settings…” and “Cannot do <…>” lines every time I try to start backup.

Has anyone else had this?

ttrammell · September 7, 2016, 6:51pm

I have not experienced this yet, but lets do this one step at a time.

I just noticed this in your logs, so verify this part before continuing with the rest:

Do you maybe have your file backups turned off, as well as your image backups?

Run a remove_unknown.bat on your server to see if there is any residue that is giving it trouble.
Restart both the Server and Client services on both your Server and Client, respectively.
Try running either a file backup of only your C (or root) volume (and nothing else for right now).

AckRite · September 8, 2016, 11:56am

Hey, thanks for checking this log.

Restarting urbackupsrv proved to be enough.
Wondering what happened but as it stands, this is fixed.

marcos.souza · October 21, 2019, 1:35pm

I have the same problems as AckRite.
Can anyone help us? Log files are not helping to identify the cause.

Client log for file backup. It is a windows server 2012 R2 server

2019-10-21 00:03:04: WARNING: Info not found at ‘e:’ - reindexing
2019-10-21 10:22:48: Loaded -fileserv- plugin
2019-10-21 10:22:48: Loaded -fsimageplugin- plugin
2019-10-21 10:22:48: Loaded -cryptoplugin- plugin
2019-10-21 10:22:48: SQLite: recovered 148 frames from WAL file C:\Program Files\UrBackup\urbackup\backup_client.db-wal code: 283
2019-10-21 10:22:48: urbackupserver: Server started up successfully!
2019-10-21 10:22:48: FileSrv: Backup privileges set successfully
2019-10-21 10:22:48: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2019-10-21 10:22:48: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2019-10-21 10:22:48: Started UrBackupClient Backend…
2019-10-21 10:22:48: FileSrv: Binding UDP socket at port 35622…
2019-10-21 10:22:48: FileSrv: done.
2019-10-21 10:22:48: FileSrv: Disabling new behavior…
2019-10-21 10:22:48: FileSrv: Binding ipv6 UDP socket at port 35622…
2019-10-21 10:22:48: FileSrv: done.
2019-10-21 10:22:48: FileSrv: Disabling new behavior…
2019-10-21 10:22:48: Filesystem. Vol="\?\Volume{bcf267a6-6f7d-11e4-80b4-806e6f6e6963}" Name=“reservado pelo sistema” Type=“ntfs” VPaths=0 Size=366997504
2019-10-21 10:22:48: FileSrv: Servername: -ADVW12ACD01-
2019-10-21 10:22:48: FileSrv: Server started up successfully
2019-10-21 10:22:48: FileSrv: UDP Thread started
2019-10-21 10:22:48: Bootable flag set for volume
2019-10-21 10:22:48: Found potential candidate: \?\Volume{bcf267a6-6f7d-11e4-80b4-806e6f6e6963}\ Score: 3
2019-10-21 10:22:48: Filesystem. Vol="\?\Volume{dc3f6609-7068-11e4-80ba-00090ffe0001}" Name=“dados” Type=“ntfs” VPaths=1 Size=53683941376
2019-10-21 10:22:48: Bootable flag not set for volume
2019-10-21 10:22:48: Filesystem. Vol="\?\Volume{32630790-7115-11e4-80bb-00090ffe0001}" Name=“copia de sombra” Type=“ntfs” VPaths=1 Size=10734268416
2019-10-21 10:22:48: Bootable flag not set for volume
2019-10-21 10:22:48: Filesystem. Vol="\?\Volume{bcf267a7-6f7d-11e4-80b4-806e6f6e6963}" Name="" Type=“ntfs” VPaths=1 Size=42580570112
2019-10-21 10:22:48: Filesystem is System partition. Skipping…
2019-10-21 10:22:48: urbackupserver: No available slots… starting new Worker
2019-10-21 10:22:48: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:22:49: Internet mode not enabled
2019-10-21 10:22:49: Looking for old Sessions… 0 sessions
2019-10-21 10:22:49: Final path: E:\Arquivos
2019-10-21 10:22:49: Final path: E:\Backup_AD
2019-10-21 10:22:49: Filesystem. Vol="\?\Volume{bcf267ae-6f7d-11e4-80b4-806e6f6e6963}" Name="" Type="" VPaths=1 Size=-1
2019-10-21 10:22:49: GetVolumeInformation failed with error code 21. Skipping…
2019-10-21 10:22:49: Filesystem. Vol="\?\Volume{8c4dd971-dd60-11e9-8147-806e6f6e6963}" Name="" Type="" VPaths=1 Size=-1
2019-10-21 10:22:49: GetVolumeInformation failed with error code 21. Skipping…
2019-10-21 10:22:49: Selected volume \?\Volume{bcf267a6-6f7d-11e4-80b4-806e6f6e6963}
2019-10-21 10:22:49: System dir: C:\Windows
2019-10-21 10:22:49: Volpath: \.\C:
2019-10-21 10:22:49: Device is not GPT formatted (0)
2019-10-21 10:22:49: Found no EFI System Partition
2019-10-21 10:22:49: ClientService cmd: #ILTBzjuCKLUHV22DgLfFT#1CHANNEL capa=64&token=cA2XSY0u8YgxZbJAATsR&restore_version=1&virtual_client=
2019-10-21 10:22:49: New channel: Number of Channels: 1
2019-10-21 10:23:40: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:23:50: ClientService cmd: PONG
2019-10-21 10:24:31: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:24:49: ClientService cmd: PONG
2019-10-21 10:25:23: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:25:49: Internet mode not enabled
2019-10-21 10:25:49: ClientService cmd: PONG
2019-10-21 10:26:15: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:26:49: ClientService cmd: PONG
2019-10-21 10:27:07: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:27:50: ClientService cmd: PONG
2019-10-21 10:27:59: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:28:50: ClientService cmd: PONG
2019-10-21 10:28:51: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:29:43: ClientService cmd: STATUS#pw=UYjSSGKJfje2USeLHYeGQtT3qQSnq5
2019-10-21 10:29:50: ClientService cmd: PONG

Backup server log. It is a CentOS 7 server.

2019-10-21 10:25:01: Starting HTTP-Server on port 55414
2019-10-21 10:25:01: ERROR: HTTP: Failed binding socket to port 55414. Another instance of this application may already be active and bound to this port.
2019-10-21 10:25:01: Started UrBackup…
2019-10-21 10:25:01: Removing temporary files…
2019-10-21 10:25:01: Recreating temporary folder…
Backupfolder not set
2019-10-21 10:25:01: Image mounting disabled: Backupfolder not set
2019-10-21 10:25:01: Testing if backup destination can handle subvolumes and snapshots…
Backupfolder not set
2019-10-21 10:25:01: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2019-10-21 10:25:01: Testing if backup destination can handle filesystem transactions…
2019-10-21 10:25:01: Testing for hardlinks in backup destination…
2019-10-21 10:25:01: Could create hardlink at backup destination. Hardlinks enabled.
2019-10-21 10:25:01: Testing for reflinks in backup destination…
2019-10-21 10:25:01: Reflink ioctl failed. errno=95
2019-10-21 10:25:01: Could not create reflink at backup destination. Reflinks disabled. Operation not supported (code: 95)
2019-10-21 10:25:01: Binding to interface ens32 (ipv4) for broadcasting…
2019-10-21 10:25:01: Broadcasting on ipv4 interface ens32 addr 192.168.254.6
2019-10-21 10:25:01: Binding to interface ens32 (ipv6) for broadcasting…
2019-10-21 10:25:01: Broadcasting on ipv6 interface ens32 addr 2804:7f7:a5ad:125d:527f:83f2:7a0c:f4e2
2019-10-21 10:25:01: Binding to interface ens32 (ipv6) for broadcasting…
2019-10-21 10:25:01: Broadcasting on ipv6 interface ens32 addr fe80::7742:4a4a:ee89:5e14
2019-10-21 10:25:01: UrBackup Server start up complete.
2019-10-21 10:25:01: ERROR: Failed binding SOCKET to Port 55413
2019-10-21 10:25:01: ERROR: Error while starting listening to ports. Stopping server.
2019-10-21 10:25:01: Exited Loop
2019-10-21 10:25:01: Deleting at…
2019-10-21 10:25:01: Deleting SelectThreads…
2019-10-21 10:25:01: Deleting lbs…
2019-10-21 10:25:01: Shutting down plugins…
2019-10-21 10:25:01: Deleting server…

![|32x32](data:image/svg+xml;base64,PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHhtbG5zOnhsaW5rPSJodHRwOi8vd3d3LnczLm9yZy8xOTk5L3hsaW5rIiB3aWR0aD0iMzIiIGhlaWdodD0iMzIiIHZpZXdCb3g9IjAgMCAzMiAzMiI+CiAgPGRlZnM+CiAgICA8cG9seWdvbiBpZD0ic21hbGwtdmlzZW1lLXYzLWEiIHBvaW50cz0iMCAwIDMyIDAgMzIgMzIgMCAzMiIvPgogIDwvZGVmcz4KICA8ZyBmaWxsPSJub25lIiBmaWxsLXJ1bGU9ImV2ZW5vZGQiPgogICAgPG1hc2sgaWQ9InNtYWxsLXZpc2VtZS12My1iIiBmaWxsPSIjZmZmIj4KICAgICAgPHVzZSB4bGluazpocmVmPSIjc21hbGwtdmlzZW1lLXYzLWEiLz4KICAgIDwvbWFzaz4KICAgIDx1c2UgZmlsbD0iIzQyODVGNCIgeGxpbms6aHJlZj0iI3NtYWxsLXZpc2VtZS12My1hIi8+CiAgICA8cGF0aCBmaWxsPSIjRDJFM0ZDIiBkPSJNMCwxNS4yMzk3OTYzIEMyLjU0Mzg1NzE0LDE4Ljg3MDUyMDMgNS42NTIsMjIuMDgyMTk0NiA5LjIwMjI4NTcxLDI0Ljc0NDg3NjkgQzEzLjIxMTU3MTQsMjcuNzUxNzA3NyAxOC43ODg0Mjg2LDI3Ljc1MTcwNzcgMjIuNzk3NzE0MywyNC43NDQ4NzY5IEMyNi4zNDgsMjIuMDgyMTk0NiAyOS40NTYxNDI5LDE4Ljg3MDUyMDMgMzIsMTUuMjM5Nzk2MyBMMzIsLTcgTDAsLTcgTDAsMTUuMjM5Nzk2MyBaIiBtYXNrPSJ1cmwoI3NtYWxsLXZpc2VtZS12My1iKSIvPgogICAgPHBhdGggZmlsbD0iIzQyODVGNCIgZmlsbC1vcGFjaXR5PSIuNiIgZD0iTTE2LDIxLjIzMDY0OTIgQzE2LjkyNjA5OTEsMjEuMjMwNjQ5MiAxNy43OTEyNDY3LDIxLjQ5NDMxNTcgMTguNTI3MjEzNSwyMS45NTE1MDE5IEMxOC44MTA0NDEsMjIuMTI3MzMwOSAxOS4xMzYyNzM4LDIxLjc4ODc0ODUgMTguOTQwMzc5OSwyMS41MTY0Njc0IEMxOC4yNzg1NTU2LDIwLjU5NzMyNjMgMTcuMjA4MTEzNiwyMCAxNiwyMCBDMTQuNzkxODg2NCwyMCAxMy43MjE0NDQ0LDIwLjU5NzMyNjMgMTMuMDU5NjIwMSwyMS41MTY0Njc0IEMxMi44NjM3MjYyLDIxLjc4ODc0ODUgMTMuMTg5NTU5LDIyLjEyNzMzMDkgMTMuNDcyNzg2NSwyMS45NTE1MDE5IEMxNC4yMDg3NTMzLDIxLjQ5NDMxNTcgMTUuMDczOTAwOSwyMS4yMzA2NDkyIDE2LDIxLjIzMDY0OTIiIG1hc2s9InVybCgjc21hbGwtdmlzZW1lLXYzLWIpIi8+CiAgICA8cGF0aCBzdHJva2U9IiM0Mjg1RjQiIHN0cm9rZS1saW5lY2FwPSJzcXVhcmUiIGQ9Ik0yNSwxMyBDMjMsMTUuMzMzMzMzMyAyMCwxNi41IDE2LDE2LjUgQzEyLDE2LjUgOSwxNS4zMzMzMzMzIDcsMTMgTDEzLDEwLjUgTDE5LDEwLjUgTDI1LDEzIFoiIG1hc2s9InVybCgjc21hbGwtdmlzZW1lLXYzLWIpIi8+CiAgICA8cG9seWdvbiBmaWxsPSIjNDI4NUY0IiBmaWxsLXJ1bGU9Im5vbnplcm8iIHBvaW50cz0iOCAxNCA3IDEzIDI1IDEzIDI0IDE0IiBtYXNrPSJ1cmwoI3NtYWxsLXZpc2VtZS12My1iKSIvPgogICAgPHBhdGggc3Ryb2tlPSIjNDI4NUY0IiBzdHJva2UtbGluZWNhcD0icm91bmQiIGQ9Ik0yMCwzIEwxNy43Njc4NzUsNS4yNTg5MjYyMiBDMTYuNzkxNSw2LjI0NzAyNDU5IDE1LjIwODUsNi4yNDcwMjQ1OSAxNC4yMzIxMjUsNS4yNTg5MjYyMiBMMTIsMyIgbWFzaz0idXJsKCNzbWFsbC12aXNlbWUtdjMtYikiLz4KICA8L2c+Cjwvc3ZnPgo=) Aprenda a pronunciar

The environment is all local, I don’t need external access. No firewall on the enabled server or client. Already checked the anti-virus and the service is released to any port. All in the same IP range.