So i’ve been all over the forum and I see some similar issues, but everything is so old I don’t think they apply any more. Many of them are fixed by upgrading… I’m all the way upgraded. I’ve been trouble shooting this the last couple of weeks and I’ve gotten no where. I have several servers being backed up to a single Urbackup box running on Ubuntu 20.04 using ZFS. I only have issues with one client. The client is Server 2016 (its not the only server 2016 I’m backing up either). I have wiped all previous backups out of the Urbackup server and reinstalled the client several times… all to the same result. So I thought I would try you guys out for a fix. Here is the Debug log from the client:
Client
2021-08-10 08:18:10: Started connection to SERVICE_FILESRV
2021-08-10 08:18:10: FileSrv: Received data…
2021-08-10 08:18:10: FileSrv: Received a Packet.
2021-08-10 08:18:10: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-10 08:18:10: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-10 08:18:10: FileSrv: Reading last file part
2021-08-10 08:18:10: FileSrv: Info: File End
2021-08-10 08:18:10: FileSrv: Closed file.
2021-08-10 08:18:10: FileSrv: Received data…
2021-08-10 08:18:10: FileSrv: Received a Packet.
2021-08-10 08:18:10: Received flush.
2021-08-10 08:18:10: FileSrv: Recv Error in RecvMessage
2021-08-10 08:18:10: FileSrv: Deleting Memory…
2021-08-10 08:18:10: FileSrv: done.
2021-08-10 08:18:10: SERVICE_FILESRV finished
2021-08-10 08:18:16: ClientService cmd: STATUS#pw=xxxxxx
2021-08-10 08:18:26: ClientService cmd: PONG
2021-08-10 08:18:26: rc=0 hasError=true state=3
2021-08-10 08:18:26: SERVICE_COMMANDS finished
2021-08-10 08:18:26: Started connection to SERVICE_COMMANDS
2021-08-10 08:18:26: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#1CHANNEL capa=11520&token=FCsWEFDrdjkvACPAkcJU&restore_version=1&virtual_client=
2021-08-10 08:18:26: New channel: Number of Channels: 1
2021-08-10 08:18:33: ClientService cmd: GET BACKUP DIRS#pw=xxxx
2021-08-10 08:18:33: rc=0 hasError=true state=0
2021-08-10 08:18:45: ClientService cmd: STATUS DETAIL#pw=xxxx
2021-08-10 08:18:45: rc=0 hasError=true state=0
2021-08-10 08:19:07: ClientService cmd: STATUS#pw=xxxx
2021-08-10 08:19:26: ClientService cmd: PONG
2021-08-10 08:19:46: Started connection to SERVICE_FILESRV
2021-08-10 08:19:46: FileSrv: Received data…
2021-08-10 08:19:46: FileSrv: Received a Packet.
2021-08-10 08:19:46: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-10 08:19:46: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-10 08:19:46: FileSrv: Reading last file part
2021-08-10 08:19:46: FileSrv: Info: File End
2021-08-10 08:19:46: FileSrv: Closed file.
2021-08-10 08:19:46: FileSrv: Received data…
2021-08-10 08:19:46: FileSrv: Received a Packet.
2021-08-10 08:19:46: Received flush.
2021-08-10 08:19:46: FileSrv: Recv Error in RecvMessage
2021-08-10 08:19:46: FileSrv: Deleting Memory…
2021-08-10 08:19:46: FileSrv: done.
2021-08-10 08:19:46: SERVICE_FILESRV finished
2021-08-10 08:19:46: Started connection to SERVICE_COMMANDS
2021-08-10 08:19:56: Client timeout in ClientConnector::Run
2021-08-10 08:19:56: SERVICE_COMMANDS finished
2021-08-10 08:19:56: Started connection to SERVICE_COMMANDS
2021-08-10 08:19:56: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#MBR driveletter=SYSVOL&disk_path=SYSVOL&image_full=1&running_jobs=1&token=FCsWEFDrdjkvACPAkcJU
2021-08-10 08:19:56: rc=0 hasError=true state=0
2021-08-10 08:19:56: SERVICE_COMMANDS finished
2021-08-10 08:19:56: Started connection to SERVICE_COMMANDS
2021-08-10 08:19:56: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#2PING RUNNING pc_done=0&status_id=334&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=FCsWEFDrdjkvACPAkcJU
2021-08-10 08:19:56: Started connection to SERVICE_COMMANDS
2021-08-10 08:19:56: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#FULL IMAGE letter=SYSVOL&token=FCsWEFDrdjkvACPAkcJU&bitmap=1&status_id=334&running_jobs=1&zero_skipped=1
2021-08-10 08:19:56: Filesystem type is ntfs (\?\Volume{34600f9d-1923-11e9-815d-806e6f6e6963})
2021-08-10 08:19:56: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216
2021-08-10 08:19:56: FSINFO: blocksize=4096 size=366997504 has_error=false used_space=126865408
2021-08-10 08:19:57: ClientService cmd: STATUS#pw=xxxx
2021-08-10 08:20:06: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#2PING RUNNING pc_done=0&status_id=334&speed_bpms=0&total_bytes=126865408&done_bytes=0&paused_fb=1#token=FCsWEFDrdjkvACPAkcJU
2021-08-10 08:20:15: rc=0 hasError=true state=4
2021-08-10 08:20:15: Sending failed. Last error: 10054
2021-08-10 08:20:15: ERROR: Pipe broken -2
2021-08-10 08:20:15: ERROR: Pipe broken -4
2021-08-10 08:20:15: Sending full image done
2021-08-10 08:20:15: Removing running process (1) id 1 server_id 334 token FCsWEFDrdjkvACPAkcJU action 3
2021-08-10 08:20:15: Service finished. Transferred 3.00231 MB
2021-08-10 08:20:15: Encryption overhead: 654 bytes
2021-08-10 08:20:15: Transferred uncompressed: 39.2202 MB (ratio: 13.0661)
2021-08-10 08:20:15: Average sent paket size: 13.0733 MB
2021-08-10 08:20:15: SERVICE_COMMANDS finished
2021-08-10 08:20:16: rc=0 hasError=true state=0
2021-08-10 08:20:16: SERVICE_COMMANDS finished
2021-08-10 08:20:16: Started connection to SERVICE_FILESRV
2021-08-10 08:20:16: FileSrv: Received data…
2021-08-10 08:20:16: FileSrv: Received a Packet.
2021-08-10 08:20:16: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-10 08:20:16: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-10 08:20:16: FileSrv: Reading last file part
2021-08-10 08:20:16: FileSrv: Info: File End
2021-08-10 08:20:16: FileSrv: Closed file.
2021-08-10 08:20:17: FileSrv: Received data…
2021-08-10 08:20:17: FileSrv: Received a Packet.
2021-08-10 08:20:17: Received flush.
2021-08-10 08:20:17: FileSrv: Recv Error in RecvMessage
2021-08-10 08:20:17: FileSrv: Deleting Memory…
2021-08-10 08:20:17: FileSrv: done.
2021-08-10 08:20:17: SERVICE_FILESRV finished
2021-08-10 08:20:17: Started connection to SERVICE_COMMANDS
2021-08-10 08:20:17: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#2LOGDATA 1628598016 0-1628597996-Starting unscheduled full image backup of volume “C:”…
2-1628598016-Backing up System Reserved (SYSVOL) partition failed. Image backup failed
0-1628598016-Time taken for backing up client xxx-Server: 20s
2-1628598016-Backup failed
Server
On the server side i dont see a whole lot other than that the backup failed:
2021-08-10 08:18:10: Getting client settings…
2021-08-10 08:18:10: Connecting to target service…
2021-08-10 08:18:10: Established internet connection. Service=1
2021-08-10 08:18:10: Flushing FileClient…
2021-08-10 08:18:10: Authed+capa for client ‘ICS-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:18:26: Settings changed. Capabilities may have changed. Reconnecting channel…
2021-08-10 08:18:26: Connecting to target service…
2021-08-10 08:18:26: Established internet connection. Service=0
2021-08-10 08:18:26: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:26: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:46: msg=START IMAGE FULL
2021-08-10 08:19:46: Getting client settings…
2021-08-10 08:19:46: Connecting to target service…
2021-08-10 08:19:46: Established internet connection. Service=1
2021-08-10 08:19:46: Flushing FileClient…
2021-08-10 08:19:46: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:46: Connecting to target service…
2021-08-10 08:19:46: Established internet connection. Service=0
2021-08-10 08:19:46: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:56: ERROR: Connection broken: Sending settings to client failed
2021-08-10 08:19:56: Starting unscheduled full image backup of volume “C:”…
2021-08-10 08:19:56: Backing up SYSVOL…
2021-08-10 08:19:56: Starting unscheduled full image backup of volume “SYSVOL”…
2021-08-10 08:19:56: Connecting to target service…
2021-08-10 08:19:56: Established internet connection. Service=0
2021-08-10 08:19:56: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:56: Connecting to target service…
2021-08-10 08:19:56: Established internet connection. Service=0
2021-08-10 08:19:56: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:19:56: Connecting to target service…
2021-08-10 08:19:56: Established internet connection. Service=0
2021-08-10 08:19:56: Authed+capa for client ‘xxx-Server’ (encrypted-v2, compressed-v2, token auth) - 1 spare connections
2021-08-10 08:20:15: ERROR: Client disconnected before sending anything (Timeout: false).
2021-08-10 08:20:15: Transferred 1.39062 KB - Average speed: 600 Bit/s
2021-08-10 08:20:15: Script does not exist urbackup/post_full_imagebackup
2021-08-10 08:20:15: Updating statistics…
2021-08-10 08:20:15: Updating image stats…
2021-08-10 08:20:15: Updating file statistics…
2021-08-10 08:20:15: Done updating statistics.
2021-08-10 08:20:16: ERROR: Backing up System Reserved (SYSVOL) partition failed. Image backup failed
2021-08-10 08:20:16: Time taken for backing up client xxx-Server: 20s
2021-08-10 08:20:16: ERROR: Backup failed
This is an internet client… but its the exact same setup as four other clients. So i know its not a firewall issue, and it shows connected. And other than a backup… the logs are clean for it. Has anyone had this happen? I tried to pull the client software and wipe all registry entries and reinstall to the same messages. I’ve wiped all the existing client backups in the server to make sure I didn’t have a mismatch that was screwing this up. I’ve checked ports and firewalls. I have 7 other machines backing up to this server (1 Server 2019, 3 Server 2016, 1 Server 2012, 2 Windows 10) I have no issues with any of them backing up correctly (only the Server 2019 and the Windows 10 machines are local to the server btw). I have a local backup that runs on this server (it doesnt run at the same time) that has no issues. Sysvol backs up without issue. The other weird part is that this used to work… unfortunately i dont watch this server that closely as its just my fail safe backup… so I’m not exactly sure when the backup started failing and I havent gone back in the syslog far enough to find it… but it used to work fine. I’ve done the usually checks on the windows file system and don’t see any glaring issues. Any help would be appreciated. Also I tried to clean up passwords and names… if i missed something let me know so I can edit.
It seems to get a WSAECONNRESET relativly fast, probably while sending from the client. I’d narrow it down by disabling compression and perhaps encryption.
Would this have anything to do with holding libcrypto++6 to version 6_5.6.4-8? I had to hold this previously because encryption wouldn’t work if I upgraded it. I thought holding it was still required because my other servers are still working correctly. Also no changes in the log… I disabled both ecryption and compression and I still have the same result. Are there any other logs you want to see or that might help? I’m lost as to whats happening with this system.
Client
2021-08-11 10:22:39: ClientService cmd: PONG
2021-08-11 10:22:39: FileSrv: Recv Error in RecvMessage
2021-08-11 10:22:39: FileSrv: Deleting Memory…
2021-08-11 10:22:39: FileSrv: done.
2021-08-11 10:22:39: SERVICE_FILESRV finished
2021-08-11 10:22:39: Started connection to SERVICE_FILESRV
2021-08-11 10:22:39: FileSrv: Received data…
2021-08-11 10:22:39: FileSrv: Received a Packet.
2021-08-11 10:22:39: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:22:39: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:22:39: FileSrv: Reading last file part
2021-08-11 10:22:39: FileSrv: Info: File End
2021-08-11 10:22:39: FileSrv: Closed file.
2021-08-11 10:22:40: FileSrv: Received data…
2021-08-11 10:22:40: FileSrv: Received a Packet.
2021-08-11 10:22:40: Received flush.
2021-08-11 10:22:59: FileSrv: Recv Error in RecvMessage
2021-08-11 10:22:59: FileSrv: Deleting Memory…
2021-08-11 10:22:59: FileSrv: done.
2021-08-11 10:22:59: SERVICE_FILESRV finished
2021-08-11 10:22:59: Started connection to SERVICE_FILESRV
2021-08-11 10:22:59: FileSrv: Received data…
2021-08-11 10:22:59: FileSrv: Received a Packet.
2021-08-11 10:22:59: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:22:59: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:22:59: FileSrv: Reading last file part
2021-08-11 10:22:59: FileSrv: Info: File End
2021-08-11 10:22:59: FileSrv: Closed file.
2021-08-11 10:22:59: FileSrv: Received data…
2021-08-11 10:22:59: FileSrv: Received a Packet.
2021-08-11 10:22:59: Received flush.
2021-08-11 10:23:01: ClientService cmd: STATUS#pw=xxx
2021-08-11 10:23:18: FileSrv: Recv Error in RecvMessage
2021-08-11 10:23:18: FileSrv: Deleting Memory…
2021-08-11 10:23:18: FileSrv: done.
2021-08-11 10:23:18: SERVICE_FILESRV finished
2021-08-11 10:23:18: Started connection to SERVICE_FILESRV
2021-08-11 10:23:18: FileSrv: Received data…
2021-08-11 10:23:18: FileSrv: Received a Packet.
2021-08-11 10:23:18: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:23:18: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:23:18: FileSrv: Reading last file part
2021-08-11 10:23:18: FileSrv: Info: File End
2021-08-11 10:23:18: FileSrv: Closed file.
2021-08-11 10:23:18: FileSrv: Received data…
2021-08-11 10:23:18: FileSrv: Received a Packet.
2021-08-11 10:23:18: Received flush.
2021-08-11 10:23:37: FileSrv: Recv Error in RecvMessage
2021-08-11 10:23:37: FileSrv: Deleting Memory…
2021-08-11 10:23:37: FileSrv: done.
2021-08-11 10:23:37: SERVICE_FILESRV finished
2021-08-11 10:23:37: Started connection to SERVICE_FILESRV
2021-08-11 10:23:37: FileSrv: Received data…
2021-08-11 10:23:37: FileSrv: Received a Packet.
2021-08-11 10:23:37: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:23:37: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:23:37: FileSrv: Reading last file part
2021-08-11 10:23:37: FileSrv: Info: File End
2021-08-11 10:23:37: FileSrv: Closed file.
2021-08-11 10:23:37: FileSrv: Received data…
2021-08-11 10:23:37: FileSrv: Received a Packet.
2021-08-11 10:23:37: Received flush.
2021-08-11 10:23:39: ClientService cmd: PONG
2021-08-11 10:23:52: ClientService cmd: STATUS#pw=xxx
2021-08-11 10:23:56: FileSrv: Recv Error in RecvMessage
2021-08-11 10:23:56: FileSrv: Deleting Memory…
2021-08-11 10:23:56: FileSrv: done.
2021-08-11 10:23:56: SERVICE_FILESRV finished
2021-08-11 10:23:56: Started connection to SERVICE_FILESRV
2021-08-11 10:23:56: FileSrv: Received data…
2021-08-11 10:23:56: FileSrv: Received a Packet.
2021-08-11 10:23:56: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:23:56: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:23:56: FileSrv: Reading last file part
2021-08-11 10:23:56: FileSrv: Info: File End
2021-08-11 10:23:56: FileSrv: Closed file.
2021-08-11 10:23:56: FileSrv: Received data…
2021-08-11 10:23:56: FileSrv: Received a Packet.
2021-08-11 10:23:56: Received flush.
2021-08-11 10:23:58: Started connection to SERVICE_COMMANDS
2021-08-11 10:23:58: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#MBR driveletter=SYSVOL&disk_path=SYSVOL&image_full=1&running_jobs=1&token=FCsWEFDrdjkvACPAkcJU
2021-08-11 10:23:58: rc=0 hasError=true state=0
2021-08-11 10:23:58: SERVICE_COMMANDS finished
2021-08-11 10:23:58: Started connection to SERVICE_COMMANDS
2021-08-11 10:23:58: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#2PING RUNNING pc_done=0&status_id=363&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=FCsWEFDrdjkvACPAkcJU
2021-08-11 10:23:59: Started connection to SERVICE_COMMANDS
2021-08-11 10:23:59: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#FULL IMAGE letter=SYSVOL&token=FCsWEFDrdjkvACPAkcJU&bitmap=1&status_id=363&running_jobs=1&zero_skipped=1
2021-08-11 10:23:59: Filesystem type is ntfs (\?\Volume{34600f9d-1923-11e9-815d-806e6f6e6963})
2021-08-11 10:23:59: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216
2021-08-11 10:23:59: FSINFO: blocksize=4096 size=366997504 has_error=false used_space=126865408
2021-08-11 10:24:00: ClientService cmd: STATUS#pw=xxx
2021-08-11 10:24:08: ClientService cmd: #IKw3dEgva8IW40ohw1wWD#2PING RUNNING pc_done=0&status_id=363&speed_bpms=0&total_bytes=126865408&done_bytes=0&paused_fb=1#token=FCsWEFDrdjkvACPAkcJU
2021-08-11 10:24:15: FileSrv: Recv Error in RecvMessage
2021-08-11 10:24:15: FileSrv: Deleting Memory…
2021-08-11 10:24:15: FileSrv: done.
2021-08-11 10:24:15: SERVICE_FILESRV finished
2021-08-11 10:24:16: Started connection to SERVICE_FILESRV
2021-08-11 10:24:16: FileSrv: Received data…
2021-08-11 10:24:16: FileSrv: Received a Packet.
2021-08-11 10:24:16: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:24:16: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:24:16: FileSrv: Reading last file part
2021-08-11 10:24:16: FileSrv: Info: File End
2021-08-11 10:24:16: FileSrv: Closed file.
2021-08-11 10:24:16: FileSrv: Received data…
2021-08-11 10:24:16: FileSrv: Received a Packet.
2021-08-11 10:24:16: Received flush.
2021-08-11 10:24:18: rc=0 hasError=true state=4
2021-08-11 10:24:18: Sending failed. Last error: 10054
2021-08-11 10:24:18: ERROR: Pipe broken -2
2021-08-11 10:24:18: ERROR: Pipe broken -4
2021-08-11 10:24:18: Sending full image done
2021-08-11 10:24:18: Removing running process (1) id 6 server_id 363 token FCsWEFDrdjkvACPAkcJU action 3
2021-08-11 10:24:18: Service finished. Transferred 3.00161 MB
2021-08-11 10:24:18: SERVICE_COMMANDS finished
2021-08-11 10:24:18: rc=0 hasError=true state=0
2021-08-11 10:24:18: SERVICE_COMMANDS finished
2021-08-11 10:24:35: FileSrv: Recv Error in RecvMessage
2021-08-11 10:24:35: FileSrv: Deleting Memory…
2021-08-11 10:24:35: FileSrv: done.
2021-08-11 10:24:35: SERVICE_FILESRV finished
2021-08-11 10:24:35: Started connection to SERVICE_FILESRV
2021-08-11 10:24:35: FileSrv: Received data…
2021-08-11 10:24:35: FileSrv: Received a Packet.
2021-08-11 10:24:35: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:24:35: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:24:35: FileSrv: Reading last file part
2021-08-11 10:24:35: FileSrv: Info: File End
2021-08-11 10:24:35: FileSrv: Closed file.
2021-08-11 10:24:35: FileSrv: Received data…
2021-08-11 10:24:35: FileSrv: Received a Packet.
2021-08-11 10:24:35: Received flush.
2021-08-11 10:24:39: ClientService cmd: PONG
2021-08-11 10:24:52: ClientService cmd: STATUS#pw=xxxx
2021-08-11 10:24:54: FileSrv: Recv Error in RecvMessage
2021-08-11 10:24:54: FileSrv: Deleting Memory…
2021-08-11 10:24:54: FileSrv: done.
2021-08-11 10:24:54: SERVICE_FILESRV finished
2021-08-11 10:24:54: Started connection to SERVICE_FILESRV
2021-08-11 10:24:54: FileSrv: Received data…
2021-08-11 10:24:54: FileSrv: Received a Packet.
2021-08-11 10:24:54: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2021-08-11 10:24:54: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2021-08-11 10:24:54: FileSrv: Reading last file part
2021-08-11 10:24:54: FileSrv: Info: File End
2021-08-11 10:24:54: FileSrv: Closed file.
2021-08-11 10:24:54: FileSrv: Received data…
2021-08-11 10:24:54: FileSrv: Received a Packet.
2021-08-11 10:24:54: Received flush.
Server
2021-08-11 10:22:38: Ping timeout in InternetServiceConnector::Run
2021-08-11 10:22:39: Server timeout (2) in FileClient
2021-08-11 10:22:39: Connecting to target service…
2021-08-11 10:22:39: Established internet connection. Service=1
2021-08-11 10:22:39: Reconnected successfully,
2021-08-11 10:22:39: Flushing FileClient…
2021-08-11 10:22:40: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:22:59: Server timeout (2) in FileClient
2021-08-11 10:22:59: Connecting to target service…
2021-08-11 10:22:59: Established internet connection. Service=1
2021-08-11 10:22:59: Reconnected successfully,
2021-08-11 10:22:59: Loading “urbackup/settings.cfg”. 0% finished 0 bytes/2.42871 KB at 264 Bit/s
2021-08-11 10:22:59: Flushing FileClient…
2021-08-11 10:22:59: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:18: Server timeout (2) in FileClient
2021-08-11 10:23:18: Connecting to target service…
2021-08-11 10:23:18: Established internet connection. Service=1
2021-08-11 10:23:18: Reconnected successfully,
2021-08-11 10:23:18: Flushing FileClient…
2021-08-11 10:23:18: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:37: Server timeout (2) in FileClient
2021-08-11 10:23:37: Connecting to target service…
2021-08-11 10:23:37: Established internet connection. Service=1
2021-08-11 10:23:37: Reconnected successfully,
2021-08-11 10:23:37: Flushing FileClient…
2021-08-11 10:23:37: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:56: Server timeout (2) in FileClient
2021-08-11 10:23:56: FileClient: Reconnect tries exhausted (1)
2021-08-11 10:23:56: FileClient: ERR_TIMEOUT
2021-08-11 10:23:56: ERROR: Error getting Client settings of xxx-Server. Errorcode: TIMEOUT (2)
2021-08-11 10:23:56: ERROR: Getting client settings failed -2
2021-08-11 10:23:56: Cannot do image backup because internet_no_images=true
2021-08-11 10:23:56: msg=START IMAGE FULL
2021-08-11 10:23:56: Getting client settings…
2021-08-11 10:23:56: Starting unscheduled full image backup of volume “C:”…
2021-08-11 10:23:56: Backing up SYSVOL…
2021-08-11 10:23:56: Starting unscheduled full image backup of volume “SYSVOL”…
2021-08-11 10:23:56: Connecting to target service…
2021-08-11 10:23:56: Established internet connection. Service=1
2021-08-11 10:23:56: Flushing FileClient…
2021-08-11 10:23:58: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:58: Connecting to target service…
2021-08-11 10:23:58: Established internet connection. Service=0
2021-08-11 10:23:58: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:58: Connecting to target service…
2021-08-11 10:23:58: Established internet connection. Service=0
2021-08-11 10:23:58: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:23:59: Connecting to target service…
2021-08-11 10:23:59: Established internet connection. Service=0
2021-08-11 10:23:59: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:24:15: Server timeout (2) in FileClient
2021-08-11 10:24:16: Connecting to target service…
2021-08-11 10:24:16: Established internet connection. Service=1
2021-08-11 10:24:16: Reconnected successfully,
2021-08-11 10:24:16: Flushing FileClient…
2021-08-11 10:24:16: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:24:18: ERROR: Client disconnected before sending anything (Timeout: false).
2021-08-11 10:24:18: Transferred 720 bytes - Average speed: 296 Bit/s
2021-08-11 10:24:18: Script does not exist urbackup/post_full_imagebackup
2021-08-11 10:24:18: Updating statistics…
2021-08-11 10:24:18: Updating image stats…
2021-08-11 10:24:18: Updating file statistics…
2021-08-11 10:24:18: Done updating statistics.
2021-08-11 10:24:18: ERROR: Backing up System Reserved (SYSVOL) partition failed. Image backup failed
2021-08-11 10:24:18: Time taken for backing up client xxx-Server: 22s
2021-08-11 10:24:18: ERROR: Backup failed
2021-08-11 10:24:35: Server timeout (2) in FileClient
2021-08-11 10:24:35: Connecting to target service…
2021-08-11 10:24:35: Established internet connection. Service=1
2021-08-11 10:24:35: Reconnected successfully,
2021-08-11 10:24:35: Flushing FileClient…
2021-08-11 10:24:35: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
2021-08-11 10:24:54: Server timeout (2) in FileClient
2021-08-11 10:24:54: Connecting to target service…
2021-08-11 10:24:54: Established internet connection. Service=1
2021-08-11 10:24:54: Reconnected successfully,
2021-08-11 10:24:54: Flushing FileClient…
2021-08-11 10:24:54: Authed+capa for client ‘xxx-Server’ (token auth) - 1 spare connections
I do see a lot of errors but not sure what to make of them…
So it doesn’t help… If you want to further investigate. Try and watch the TCP connection via WireShark. Then the (client) software side via ProcessMonitor.
If you have any drivers that hook into the network stack (such as firewall software), try to disable them
Well, I don’t know what to say… I’ve rebooted this server (the client) about 10 times during all this, and got the same result. I had to reboot (the client) for windows updates last night… and it started working. I mean as soon as it came back up it autostarted a backup! I’m wondering if something got broke by an update and another update solved the problem, which would be like finding a unicorn! In any case its fixed! and I’m sorry for wasting your time, but thank you for trying to help me!
