9 Replies Latest reply: May 5, 2016 3:39 AM by Dileep M RSS

Avamar backup from NAT : "Failed initial handshake, trying again"

sfaure

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

  • 1. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    Ian Anderson

    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.

  • 2. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    sfaure

    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 !

  • 3. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    sfaure

    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: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>

     

    Thanks :-)

  • 4. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    Ian Anderson

    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.

  • 5. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    sfaure

    I opened a SR.

    Thank you for your answers!

  • 6. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    sfaure

    I've updated the probe.xml file and now all works fine.

  • 7. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    Ian Anderson

    Glad to hear you were able to get it resolved!

  • 8. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    francisco_navarro

    It was usefull if you sai what update in  the probe.xml file. Regards

  • 9. Re: Avamar backup from NAT : "Failed initial handshake, trying again"
    Dileep M

    can you share What is to be updated on probe.xml