Forticlient 5.0.9.347 "Failed to acquire an IP address" on Windows 7 Pro SP1 64-bit

[jcyu]

We pushed out new FortiClient (5.0.9.347) and it worked for most clients.  One client reported problem access any website after establishing FortiClient connection.  He has a Windows 7 Pro SP1 64-bit laptop.  It was on his home Wi-FI (we tried also the company Wi-Fi) network.  He restarted the computer, uninstalled-reinstalled the client, but had same result.  Forticlient could connect, bytes sent was > 0, but bytes received was 0.

It has Symantec Endpoint Protection 12.1.4013.4013, but we already disabling it.  Same result.

We checked the Routing and Remote Access service was already disabled.

http://kb.fortinet.com/kb...ateId=0%200%2067580897

It does not have SKYPE installed.  (As mentioned in this post, https://forum.fortinet.com/tm.aspx?m=29444)

(Forticlient log pasted below).  Any suggestion?  Thanks.

2/11/2015 10:32:10 AM    Notice    FortiShield    id=96851 user=DBLOG_SOURCE_SYSTEM msg="FortiShield is enabled" 2/11/2015 10:32:11 AM    Notice    VPN    id=96602 msg="SSLVPN service started successfully." 2/11/2015 10:32:44 AM    Notice    Update    id=96823 msg="Checking for updates." 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=local mode=aggressive stage=1 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #1 (OK)" vpntunnel=YU 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=local mode=aggressive stage=2 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #2 (DONE)" vpntunnel=YU 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 (" vpntunnel=YU 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=remote mode=xauth_client stage=2 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #2 (" vpntunnel=YU 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=local mode=xauth_client stage=0 dir=inbound status=success Initiator: parsed ###.##.##.## xauth_client mode message #0 (O" vpntunnel=YU 2/11/2015 10:33:04 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 (" vpntunnel=YU 2/11/2015 10:33:05 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=local mode=quick stage=1 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #1 (OK)" vpntunnel=YU 2/11/2015 10:33:05 AM    Notice    VPN    id=96571 msg="locip=###.##.###.## locport=500 remip=###.##.##.## remport=500 outif=0 vpntunnel=YU action=install_sa, inspi=0xb2dff5f0 outspi=0x6a236c62 Initiator: tunnel ###.##.###.##/###.##.##.## install ipsec sa" vpntunnel=YU 2/11/2015 10:33:05 AM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.## loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=YU action=negotiate init=local mode=quick stage=2 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #2 (DONE)" vpntunnel=YU 2/11/2015 10:33:05 AM    Notice    VPN    id=96560 msg="VPN tunnel status" vpnstate=connected [style="background-color: #ffff00;"]2/11/2015 10:36:06 AM    Error    VPN    id=96564 msg="locip=###.##.###.## locport=500 remip=###.##.##.## remport=500 outif=0 vpntunnel=YU Failed to acquire an IP address." vpntunnel=YU[/style] 2/11/2015 10:36:06 AM    Notice    VPN    date=2015-02-11 time=10:36:05 type=traffic level=notice sessionid=36554804 hostname=PF01D92 uid=403A51AFCBB64766B8B1028FDF423BCA devid=FCT8000104923729 fgtserial=N/A regip=N/A srcname=ipsec srcip=0.0.0.0 srcport=36554548 direction=outbound remoteip=###.##.##.## remotename=N/A remoteport=36554420 url=N/A user=jorge proto=ike rcvdbyte=0 sentbyte=18128 utmaction=passthough utmevent=vpn threat=connect vd=N/A

[ashukla_FTNT]

For me it looks like nat-t issue.

Most probably the client has private ip address but i see all the negotiation happening on port 500 and it never switched to 4500.

Can you check if nat-t is enabled?

if client has pulic ip then issue can be something else.

[jcyu]

Thanks.  It wouldn't be NAT-T issue because is only him. All clients have NAT-T enabled and is configured on the gateway.

[ashukla_FTNT]

jcyu wrote:

Thanks.  It wouldn't be NAT-T issue because is only him. All clients have NAT-T enabled and is configured on the gateway.

I understand that NAT-T is enabled on gateway but it looks like either NAT-T did not detected nat on client side or some other issue.

As per RFC:

Negotiation of NAT-Traversal in the IKE January 2005


 Initiator Responder
 ------------ ------------
 UDP(500,500) HDR, SA, KE,
 Ni, IDii, VID -->
 <-- UDP(500,X) HDR, SA, KE,
 Nr, IDir, [CERT, ],
 VID, NAT-D, NAT-D,
 SIG_R
 UDP(4500,4500) HDR*#, [CERT, ],
 NAT-D, NAT-D,
 SIG_I -->
 <-- UDP(4500, Y) HDR*#, ...

Second packet from client should be sent with source and destination port 4500, but i see complete negotiation happening on 500.

Also as per the forticlient logs:

2/11/2015 10:33:05 AM    Notice    VPN    id=96560 msg="VPN tunnel status" vpnstate=connected [<font]2/11/2015 10:36:06 AM    Error    VPN    id=96564 msg="locip=###.##.###.## locport=500 remip=###.##.##.## remport=500 outif=0 vpntunnel=YU Failed to acquire an IP address." vpntunnel=YU

Vpn came up and then you got the error.

If nat-t doesn't detect nat then once tunnel is up traffic will go on protocol ESP (which cannot traverse through nat device).

IF nat-t detected nat ESP will be encapsulated inside udp 4500 and traffic can traverse through any nat device.

I also understand that you tested on two connection but it looks strange to me. 

Check the logs of a working pc and compare.

Check if the nat device has any special feature for ipsec like ipsec pass through. If any special handling is enabled on nat device (Client side) disable it and check.

If the client was behind a many to one nat device and nat is not detected by nat-t that will cause this issue. 

[jcyu]

Thank you for the explanation.

I compared it to the log on my office computer.  Ports are always 500, never 4500.  However, after connected for a few moments, the IPSec connection automatically dropped.

~~~

2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=aggressive stage=1 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #1 (OK)" vpntunnel=** 2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=aggressive stage=2 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #2 (DONE)" vpntunnel=** 2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 " vpntunnel=** 2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=2 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #2 " vpntunnel=** 2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=xauth_client stage=0 dir=inbound status=success Initiator: parsed ###.##.##.## xauth_client mode message #0 (" vpntunnel=** 2/13/2015 4:39:02 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 " vpntunnel=** 2/13/2015 4:39:03 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=quick stage=1 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #1 (OK)" vpntunnel=** 2/13/2015 4:39:03 PM    Notice    VPN    id=96571 msg="locip=###.##.###.### locport=500 remip=###.##.##.## remport=500 outif=0 vpntunnel=** action=install_sa, inspi=0xe29cb6da outspi=0x9d4d8823 Initiator: tunnel ###.##.###.###/###.##.##.## install ipsec sa" vpntunnel=** 2/13/2015 4:39:03 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=quick stage=2 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #2 (DONE)" vpntunnel=** 2/13/2015 4:39:03 PM    Notice    VPN    id=96560 msg="VPN tunnel status" vpnstate=connected 2/13/2015 4:39:18 PM    Notice    VPN    date=2015-02-13 time=16:39:17 type=traffic level=notice sessionid=28493876 hostname=******* uid=217FE5F5BEEA4B869410EEC19F90ECE5 devid=FCT8002710651127 fgtserial=N/A regip=N/A srcname=ipsec srcip=10.240.13.13 srcport=28493620 direction=outbound remoteip=###.##.##.## remotename=N/A remoteport=28493492 url=N/A user=****** proto=ike rcvdbyte=23424 sentbyte=57760 utmaction=passthough utmevent=vpn threat=connect vd=N/A 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=aggressive stage=1 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #1 (OK)" vpntunnel=** 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=aggressive stage=2 dir=outbound status=success Initiator: sent ###.##.##.## aggressive mode message #2 (DONE)" vpntunnel=** 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 " vpntunnel=** 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=2 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #2 " vpntunnel=** 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=xauth_client stage=0 dir=inbound status=success Initiator: parsed ###.##.##.## xauth_client mode message #0 (" vpntunnel=** 2/13/2015 4:40:43 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=remote mode=xauth_client stage=0 dir=inbound status=success Responder: parsed ###.##.##.## xauth_client mode message #0 " vpntunnel=** 2/13/2015 4:40:44 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=quick stage=1 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #1 (OK)" vpntunnel=** 2/13/2015 4:40:44 PM    Notice    VPN    id=96571 msg="locip=###.##.###.### locport=500 remip=###.##.##.## remport=500 outif=0 vpntunnel=** action=install_sa, inspi=0x4f9d526c outspi=0x9e4d8823 Initiator: tunnel ###.##.###.###/###.##.##.## install ipsec sa" vpntunnel=** 2/13/2015 4:40:44 PM    Notice    VPN    id=96566 msg="negotionation information, loc_ip=###.##.###.### loc_port=500 rem_ip=###.##.##.## rem_port=500 out_if=0 vpn_tunnel=** action=negotiate init=local mode=quick stage=2 dir=outbound status=success Initiator: sent ###.##.##.## quick mode message #2 (DONE)" vpntunnel=** 2/13/2015 4:40:44 PM    Notice    VPN    id=96560 msg="VPN tunnel status" vpnstate=connected 2/13/2015 4:40:49 PM    Notice    VPN    date=2015-02-13 time=16:40:48 type=traffic level=notice sessionid=28493876 hostname=******* uid=217FE5F5BEEA4B869410EEC19F90ECE5 devid=FCT8002710651127 fgtserial=N/A regip=N/A srcname=ipsec srcip=10.240.13.13 srcport=28493620 direction=outbound remoteip=###.##.##.## remotename=N/A remoteport=28493492 url=N/A user=****** proto=ike rcvdbyte=20800 sentbyte=46352 utmaction=passthough utmevent=vpn threat=connect vd=N/A ~~~

Attached screencaps show the advanced properties of client's NIC.  Can you advise which off them is related to IPSec connection handling and should be turned off please?  Thank you.