Client disconnected before sending anything - Server 2.0.36 / 2.0.34


#1

Hi Everyone,

First of all, let me praise you guys. i had to evaluate a lot of Backup-Systems over the past 6 Months. UrBackup is piece of platinum and doesn’t have to hide in comparison to big commercial Software. My Boss loved it aswell and gave permission to establish it.

Server: Windows Server 2012 R2, UrBackup-Server 2.0.36, 25TB iSCSI Storage with (2Gbit/s Bandwidth)
Clients: Windows 7 + 10 - UrBackup-Client 2.0.34 (Bandwidth 100Mbit/s to 1Gbit/s)

There’s this Problem i couldn’t solve for over 3 Weeks now. ´
i could track it down to the “temporary files as buffer” Option and could exclude a network and DNS failure.
In the early Eval. Phase i didnt use it and it worked like a charm but the transfer rate was way too slow (between 40 and 110Mbit/s) and it took ages to backup my test-machines. so i decided to create the temp files on a dedicated 250GB partition. The transfer rate exploded (which is insanely awesome) and i had rates up to 400-850 Mbit/s per Client (always max. 4 parallel).
After that i started a field test with 10 Users and the backups randomly failed on random machines. After a while (weeks) i gave up and made a clean install of 2.0.34.

In this Version i could observe how the temp Partition ran out of space once in a while and at the same time the disk was full, some Backups failed with the message mentioned below. A Disk upgrade to a 600GB 15K RPM SAS disk as the temp partition did a huge improvement in stability. Lots of client Partitions are successfully backed up (about 60% are successful, before that almost none of the clients succeeded) but its still not working reliably.

In an act of despair i turned off the temp file option and did some tests. They were working.
Upgrade to 2.0.36 -> its still working. Turn on temp files -> as worse as before the disk upgrade.
Clean 2.0.34 with temp file -> ~60% success rate -> Upgrade 2.0.36 -> as worse as before the disk upgrade
Clean 2.0.36 with temp files off -> running smoothly (current state)

i also noticed that in 2.0.36 the temp partition never used more than 3 or 4 GB (covering the admin manual that states 1GB per Client) where 2.0.34 sometimes used up to 400GB (and worked - most of the time). So i guess something changed there with the update (just an assumption).

But as i mentioned we need the temp file option for Performance reasons.

An example of the Client log should be attached. (with debug enabled)
ClientLog.txt (88.9 KB)
(Clients and Server will be cleanly installed before going live, so clear UrBackup keys/identities are not an issue here)

As i recently did a clean reinstall i lost the Server logs… (my bad sorry) but the following is what the Server sent per Mail. (and which was the essence in the logs, there was nothing more in there except the exponential backoff)
It’s always the same message for and on all Machines - the “Time taken” ranges from 30 seconds to over an Hour.

UrBackup just did a full image backup of "<Machine>".

Report:
( 3 infos, 0 warnings, 2 errors )

2016-11-21 11:51:44(info): Starting full image backup...
2016-11-21 12:21:31(error): Client disconnected before sending anything (Timeout: false).
2016-11-21 12:21:31(info): Transferred 5.00803 MB - Average speed: 41.912 KBit/s
2016-11-21 12:56:58(info): Time taken for backing up client <Machine>: 1h 5m 14s
2016-11-21 12:56:58(error): Backup failed

(i just redid the scenario to create a debug log entry on the Server. It’s not much more than the mail)

2016-11-22 12:08:33: ERROR: Client disconnected before sending anything (Timeout: false).
2016-11-22 12:08:34: ERROR: Backup failed
2016-11-22 12:08:36: WARNING: Exponential backoff: Waiting at least 40m before next image backup

One more thing. i was able to reproduce all this on a VM as Server (i wanted to make sure, its not some kind of a strange Hardware issue). Less Bandwidth but same behaviour (but i only tested 2.0.36 on the VM).

i crawled the web for ages and did some deep research in the admin manual, but didn’t find much.
i really hope you guys have a hint or even a solution for me.
if you need anymore details/infos please let me know.

That error is drives me crazy!

.
Thanks in advance guys


#2

Was it only with image backups and file backups worked always?

One explanation would be that once temporary space is filled up, it has wait at a lot of places till space is free. If that takes too long it runs into timeouts. The server (debug) log file would probably show more details.

The error you postest isn’t that bad actually. At this point it hasn’t done any work yet and it will simply retry the backup later.


#3

Thanks for your reply.

It only appears with image backups (we try to save ALL_NONUSB) - file backups always work just fine.

The Server Debug log file sadly doesn’t show anything more. The second Codeblock from my original Post is everything that was generated when the client failed.

The error is bad because it appears on different stages of the backup. Sometimes right after a few Megabytes, sometimes after several Gigabytes or even shortly before it would finish.
(thats what strange, because “before sending anything” isn’t correct most of the time)
Even if it retries later it’s most likely to fail again.

After the Disk replacement (250GB to 600GB) the temp storage never ran out of space again, but the client failed anyway (2.0.34). 2.0.36 did not change its behaviour even though more space was available (failing most of the time).

i’ll try to produce some more Debug Server-Logs right now.


#4

Please see this thread on where the server debug log file is and how to turn on debug logging: Having problems with UrBackup? Please read before posting


#5

Hello again.
You were right, i forgot to turn the debug on again after my last clean install. My Bad.

So here’s the Debug ServerLog.
ServerDebugLog.txt (41.6 KB)

One Client was offline which fills the Log a bit up, but i renamed the Clients so its easier to read and identify them. (i named the Client “OFFLINECLIENT6”. This one can be ignored, the machine just went offline during the backup)

In the supplied ServerLog 4 Clients failed 5 Times in total. (They’re named FAILEDCLIENT1 to 4)
i attached the DebugLog of the specific clients (of those, which were in debug mode) aswell as it might be helpful to compare concrete Events.

The first Error appeared at: 2016-11-22 17:50:02 (FAILEDCLIENT1)
The second appeared at : 2016-11-22 18:07:32 (FAILEDCLIENT1)
Failedclient1_DebugLog.txt (31.6 KB)

The third: 2016-11-23 09:00:13 (FAILEDCLIENT2)
Failedclient2_DebugLog.txt (43.3 KB)

The fourth: 2016-11-23 09:00:41 (FAILEDCLIENT3) - was not in debug mode
The fifth: 2016-11-23 09:38:27 (FAILEDCLIENT4) - was not in debug mode

.
Thank you for your courtesy :slight_smile:


#6

At this point it has a timeout of 10s on the client. You can probably use something like process monitor to find out what takes so long on the server and confirm this is the problem.

Edit: I had already increased this timeout to 1min with 2.1.x, so you could try installing that on one client to find out if that helps.


#7

Great News!
i’ll try this out and leave some Feedback.
It could take one or two days though, as my workload increased today.

I really hope it works out, as i’m totally in love with your project :smile:


#8

Soooo it took a bit longer as i were loaded with other other work.

But you sir are awesome.

After an initial (and successful) test i rolled out the new 2.1.4 Beta Client to my Beta Testers and everything works like a Charm now! :heart_eyes:

.
Thanks a lot!