This post is more than 5 years old
11 Posts
0
8994
March 19th, 2014 11:00
Avamar backup from NAT : "Failed initial handshake, trying again"
Hi all,
I backup laptops with Avamar 7.0.1 which is accessed from NATed WAN ip address.
All work well but when My backup is starting, the backup is "waiting" around 5/10 minutes before real start the backup as you can see on the following logs with "Failed initial handshake, trying again" :
2014-03-19 19:01:07 avtar Info <5554>: Connecting to one node in each datacenter
2014-03-19 19:01:07 avtar Info <5993>: - Connect: Connected to XX.XX.XX.XX:29000, Priv=0, SSL Cipher=AES128-SHA
2014-03-19 19:02:23 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:03:40 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:04:56 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:06:13 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:07:30 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:08:47 avtar Info <5694>: - Failed initial handshake, trying again
2014-03-19 19:08:48 avtar Info <5993>: - Datacenter 0: Connected to XX.XX.XX.XX:29000, Priv=0, SSL Cipher=AES128-SHA
2014-03-19 19:08:49 avtar Info <5581>: Logging in on connection 0 with Session Ticket
2014-03-19 19:08:49 avtar Info <5582>: Avamar Server login successful
2014-03-19 19:08:49 avtar Info <5018>: - Session ID: 0
2014-03-19 19:08:49 avtar Info <10632>: Using Client-ID='7c14c2d67c1cccfb98896edc18ff90e5cec01de6'
2014-03-19 19:08:49 avtar Info <5550>: Successfully logged into Avamar Server [7.0.1-61] (Compression enabled)
2014-03-19 19:08:49 avtar Info <7563>: Back up of "/Users/Sebastien/Desktop" on server "XX.XX.XX.XX" for /clients/macbook-air-de-sebastien.local
2014-03-19 19:08:49 avtar Info <5586>: Loading cache files from /usr/local/avamar/var
2014-03-19 19:08:49 avtar Info <8650>: Opening cache file /usr/local/avamar/var/f_cache.dat
2014-03-19 19:08:49 avtar Info <5573>: - Loaded cache file (2,884,128 bytes)
2014-03-19 19:08:49 avtar Info <8650>: Opening cache file /usr/local/avamar/var/p_cache.dat
2014-03-19 19:08:49 avtar Info <5573>: - Loaded cache file (1,573,408 bytes)
2014-03-19 19:08:50 avtar Info <6426>: Done loading cache files
2014-03-19 19:08:51 avtar Info <5163>: Backup complete, wrapping-up session with Server
2014-03-19 19:08:51 avtar Warning <6550>: Could not get group id for current user
2014-03-19 19:08:53 avtar Info <5156>: Backup #7 timestamp 2014-03-19 19:08:53, 3 files, 4 directories, 32.45 MB (1 files, 0 bytes, 0.00% new)
2014-03-19 19:08:53 avtar Info <7539>: Label "daily 19H-Gr_test_mac_sfaure-1395252000037", scheduled to expire after 03/29/14 (2014-03-29 18:00:00 UTC), daily backup
2014-03-19 19:08:53 avtar Info <6083>: Backed-up 32.45 MB in 7.78 minutes: 250 MB/hour (23 files/hour)
2014-03-19 19:08:53 avtar Info <5587>: Updating cache files in /usr/local/avamar/var
2014-03-19 19:08:53 avtar Info <5069>: - Writing cache file "/usr/local/avamar/var/f_cache.dat"
2014-03-19 19:08:53 avtar Info <5546>: Cache update complete /usr/local/avamar/var/f_cache.dat (2.8MB of 511MB max)
2014-03-19 19:08:53 avtar Info <5069>: - Writing cache file "/usr/local/avamar/var/p_cache.dat"
2014-03-19 19:08:53 avtar Info <5546>: Cache update complete /usr/local/avamar/var/p_cache.dat (1.5MB of 255MB max)
2014-03-19 19:08:53 avtar Info <7883>: Finished at 2014-03-19 19:08:53 CET, Elapsed time: 0000h:07m:46s
2014-03-19 19:08:53 avtar Info <8468>: Sending wrapup message to parent
2014-03-19 19:08:53 avtar Info <5314>: Command completed (1 warning, exit code 0: success)
--------------------------------------------------------------------------------------------------------
----- END avtar log 2014-03-19 19:08:53 CET (1 warning, 0 errors, 0 fatal errors)
--------------------------------------------------------------------------------------------------------
Then all work well, but I don't understand why the job is very slow to start.
Thank you in advance for your help !
Sébastien
sfaure
11 Posts
0
March 25th, 2014 10:00
I've updated the probe.xml file and now all works fine.
ionthegeek
2 Intern
•
2K Posts
0
March 19th, 2014 11:00
Is the Avamar server a single node server or a multi-node server? Based on the logs it looks like it's a multi-node system. It looks like the client is failing to connect to a storage node the first time it tries to connect. The client has to be able to reach the utility node and all storage nodes on port 27000 (for unencrypted backups) or port 29000 (for encrypted backups). Firewalls are the usual suspect for issues like this.
Are the IP addresses in the messages below the same or different?
2014-03-19 19:01:07 avtar Info <5993>: - Connect: Connected to XX.XX.XX.XX:29000, Priv=0, SSL Cipher=AES128-SHA
2014-03-19 19:08:48 avtar Info <5993>: - Datacenter 0: Connected to XX.XX.XX.XX:29000, Priv=0, SSL Cipher=AES128-SHA
If you re-run the backup in debug mode, the logs will record more information about what nodes the client is connecting to. It would be helpful if you could leave the last octet of the IP address intact if you post more logs.
sfaure
11 Posts
0
March 19th, 2014 11:00
Thank you for your answer.
No it's a single node...and the 2 ip address you speak are the same (it's the WAN ip which is used to contact my single node).
I will try to launch a backup in debug mode, and I'll let you know !
sfaure
11 Posts
0
March 20th, 2014 11:00
I started a backup in debug mode :
X.X.X.10 is the LAN ip address of the single node
X.X.X.227 is the WAN ip address of the single node
backup.XXX.com is the DNS record for the WAN ip address
Something is strange : in the following logs, sometime the timestamp is offset one hour...
2014-03-20 18:45:45 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:45:45.39280 [avtar] tcpsock::createclient ipaddr:X.X.X.10:29000
2014/03/20-17:45:45.39300 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.10:29000 netbind:, modified_netbind:
2014/03/20-17:47:01.68230 [avtar] sockimpl::init connect returns -1 errno=60 Operation timed out
2014/03/20-17:47:01.68237 [avtar] sslsockimpl::open failure
2014/03/20-17:47:01.68239 [avtar] tcpsockimpl::close shutdown error -1 code 57: Socket is not connected
2014-03-20 18:47:01 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:47:01.68255 [avtar] tcpsock::createclient ipaddr:X.X.X.10:29000
2014/03/20-17:47:01.68264 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.10:29000 netbind:, modified_netbind:
2014/03/20-17:48:17.61369 [avtar] sockimpl::init connect returns -1 errno=60 Operation timed out
2014/03/20-17:48:17.61379 [avtar] sslsockimpl::open failure
2014/03/20-17:48:17.61383 [avtar] tcpsockimpl::close shutdown error -1 code 57: Socket is not connected
2014-03-20 18:48:17 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:48:17.61403 [avtar] tcpsock::createclient ipaddr:X.X.X.10:29000
2014/03/20-17:48:17.61414 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.10:29000 netbind:, modified_netbind:
2014/03/20-17:49:32.83383 [avtar] sockimpl::init connect returns -1 errno=60 Operation timed out
2014/03/20-17:49:32.83389 [avtar] sslsockimpl::open failure
2014/03/20-17:49:32.83391 [avtar] tcpsockimpl::close shutdown error -1 code 57: Socket is not connected
2014-03-20 18:49:32 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:49:32.83408 [avtar] tcpsock::createclient ipaddr:X.X.X.10:29000
2014/03/20-17:49:32.83421 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.10:29000 netbind:, modified_netbind:
2014/03/20-17:50:48.87825 [avtar] sockimpl::init connect returns -1 errno=60 Operation timed out
2014/03/20-17:50:48.87834 [avtar] sslsockimpl::open failure
2014/03/20-17:50:48.87840 [avtar] tcpsockimpl::close shutdown error -1 code 57: Socket is not connected
2014-03-20 18:50:48 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:50:48.87856 [avtar] tcpsock::createclient ipaddr:X.X.X.10:29000
2014/03/20-17:50:48.87864 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.10:29000 netbind:, modified_netbind:
2014/03/20-17:52:04.62392 [avtar] sockimpl::init connect returns -1 errno=60 Operation timed out
2014/03/20-17:52:04.62396 [avtar] sslsockimpl::open failure
2014/03/20-17:52:04.62398 [avtar] tcpsockimpl::close shutdown error -1 code 57: Socket is not connected
2014-03-20 18:52:04 avtar Info <5694>: - Failed initial handshake, trying again
2014/03/20-17:52:04.62412 [avtar] dpnconnect::create hfsaddr=backup.XXX.com
2014/03/20-17:52:04.62420 [avtar] tabfilename = /usr/local/avamar/var/backup.XXX.com-27000.dtb
2014/03/20-17:52:04.62425 [avtar] filedisk::doopen, fdesc == -1 after open attempt
2014/03/20-17:52:04.62480 [avtar] tcpsock::createclient ipaddr:X.X.X.227:29000
2014/03/20-17:52:04.62486 [avtar] sockimpl::initclient connect timeout = 0 ipaddr:X.X.X.227:29000 netbind:, modified_netbind:
2014/03/20-17:52:04.66291 [avtar] sslsockimpl::open initclient success
2014/03/20-17:52:04.76687 [avtar] sslsockimpl::open initclient success, cipher: AES128-SHA
2014/03/20-17:52:04.82496 [avtar] dpnconnect::getserveraddr trying X.X.X.227:29000
2014/03/20-17:52:04.82502 [avtar] dpnconnect::getserveraddr keyaddr=X.X.X.227:29000
2014/03/20-17:52:04.88641 [avtar] dpnconnect::getserveraddr received newaddr=X.X.X.227:29000 srcaddr=X.X.X.227:29000
2014-03-20 18:52:04 avtar Info <5993>: - Datacenter 0: Connected to X.X.X.227:29000, Priv=0, SSL Cipher=AES128-SHA
2014/03/20-17:52:04.93896 [avtar] getdpninfo: servtime=1395337924.9000 clienttime=1395337924.9381 catserver=0 compressed=1 dpmmaxmessage=449
2014/03/20-17:52:04.93908 [avtar] dpnconnect::getdpninfo serverversion=7.0.1-61 hfscreatetime=1125334329496843 maxmessagedatasize=65382 maxatomchunksize=32691 maxcompchunksize=1
2014/03/20-17:52:04.98828 [avtar] checkrightdpn: olddc=0 newdc=1 numnodes=1 oldcreatetime=1358337291 newcreatetime=1358337291
2014/03/20-17:52:04.98844 [avtar] servercontext::connect() - dpninfo string:
Thanks :-)
ionthegeek
2 Intern
•
2K Posts
0
March 20th, 2014 12:00
The difference in timestamps isn't an issue -- standard logging is timestamped in local time but debug messages use UTC.
It seems clear that the client is trying to connect to the WAN IP address instead of the LAN IP address but the logs don't say why. When this client was activated, was it activated using the WAN hostname? There is a "dispatcher table" that is sent to the client by the Avamar server and recorded in a .dtb file in the Avamar var directory. Which IP address (the LAN IP or the WAN IP) is recorded in the dispatcher table that was used for this backup? If the dispatcher table is wrong, there may be an issue with the probe.xml file on the server.
Opening a service request will likely get you the fastest resolution for this issue. If you open an SR, you'll save some time if you attach the debug logs and .dtb files to the SR.
sfaure
11 Posts
1
March 24th, 2014 12:00
I opened a SR.
Thank you for your answers!
ionthegeek
2 Intern
•
2K Posts
0
March 25th, 2014 10:00
Glad to hear you were able to get it resolved!
dileep451
1 Rookie
•
82 Posts
0
May 5th, 2016 03:00
can you share What is to be updated on probe.xml