[5.2.4] VPN Stuck at 98% / Connecting-Disconnecting..

[AlexandreL]

Hello everybody.

Lately we got some problem using Forticlient and VPNSSL. Sometimes the connection is stuck at 98% (it will work again few minutes laters) Sometimes the connection goes up&down repeatedly ...

I tried to ran a diagnose debug application vpnssl -1 but we cant see much (the connection was going up&down)

Any idea?

Here is the trace

2016-10-10 17:28:04 [1033:aname:63283]allocSSLConn:245 sconn 0x2a98c5dc00 (7:aname)
2016-10-10 17:28:04 [1033:aname:63283]SSL state:before/accept initialization (ClientIP)
2016-10-10 17:28:04 [1033:aname:63283]SSL_accept returned 0.
2016-10-10 17:28:04 [1033:aname:63283]Destroy sconn 0x2a98c5dc00, connSize=1. (aname)
2016-10-10 17:28:04 [1033:aname:63284]allocSSLConn:245 sconn 0x2a98c5dc00 (7:aname)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:before/accept initialization (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 read client hello A (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 write server hello A (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 write change cipher spec A (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 write finished A (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 flush data (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 read finished A:system lib(ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 read finished A:system lib(ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSLv3 read finished A (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL state:SSL negotiation finished successfully (ClientIP)
2016-10-10 17:28:04 [1033:aname:63284]SSL established: TLSv1.2 ECDHE-RSA-AES256-SHA384
2016-10-10 17:28:04 [1033:aname:63284]req: /remote/login
2016-10-10 17:28:04 [1033:aname:63284]rmt_authutil.c:418 no session id in auth info
2016-10-10 17:28:04 [1033:aname:63284]rmt_authutil.c:701 invalid cache, ret=4103
2016-10-10 17:28:04 [1033:aname:63284]req: /remote/logincheck
2016-10-10 17:28:04 [1033:aname:63284]rmt_authutil.c:418 no session id in auth info
2016-10-10 17:28:04 [1033:aname:63284]rmt_authutil.c:639 access failed, uri=[/remote/logincheck],ret=4103,
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_auth_check_usrgroup:1702 forming user/group list from policy.
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_auth_check_usrgroup:1740 got user (0) group (1:0).
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1384 validating with SSL VPN authentication rules (1), realm ().
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1432 checking rule 1 cipher.
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1440 checking rule 1 realm.
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1451 checking rule 1 source intf.
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1487 checking rule 1 vd source intf.
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1552 rule 1 done, got user (0) group (1:0).
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_validate_user_group_list:1638 got user (0), group (1:0).
2016-10-10 17:28:04 [1033:aname:63284]two factor check for accountname: off
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_authenticate_user:168 authenticate user: [accountname]
2016-10-10 17:28:04 [1033:aname:63284]sslvpn_authenticate_user:175 create fam state
2016-10-10 17:28:04 [1033:aname:63284]fam_auth_send_req:514 with server blacklist:
2016-10-10 17:28:04 [1033:aname:63284]fam_auth_send_req_internal:414 fnbam_auth return: 4
2016-10-10 17:28:04 [1033:aname:63284]Auth successful for group LDAP_VPN
2016-10-10 17:28:04 [1033:aname:63284]fam_do_cb:463 fnbamd return auth success.
2016-10-10 17:28:04 [1033:aname:63284]SSL VPN login matched rule (1).
2016-10-10 17:28:04 [1033:aname:63284]login_succeeded:375 redirect to hostcheck
2016-10-10 17:28:04 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:04 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:04 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63284]req: /
2016-10-10 17:28:05 [1033:aname:63284]mza: 0x1dfe2e0 /rmt_index.html
2016-10-10 17:28:05 [1033:aname:63284]def: 0x1dfe2e0 /rmt_index.html
2016-10-10 17:28:05 [1033:aname:63284]req: /remote/index
2016-10-10 17:28:05 [1033:aname:63284]def: (nil) /remote/index
2016-10-10 17:28:05 [1033:aname:63284]req: /remote/fortisslvpn
2016-10-10 17:28:05 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 33) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 34) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 35) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63284]req: /remote/fortisslvpn_xml
2016-10-10 17:28:05 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63284]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63284]rmt_apsession.c:1022 failed to get dynamic IP
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 33) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 34) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63284]rmt_fortisslvpn.c:1440 Matched policy (id = 35) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63285]allocSSLConn:245 sconn 0x2a98c60c00 (7:aname)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:before/accept initialization (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read client hello A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write server hello A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write certificate A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write key exchange A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write server done A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 flush data (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read client certificate A:system lib(ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read client certificate A:system lib(ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read client key exchange A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read certificate verify A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 read finished A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write session ticket A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write change cipher spec A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 write finished A (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSLv3 flush data (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL state:SSL negotiation finished successfully (ClientIP)
2016-10-10 17:28:05 [1033:aname:63285]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
2016-10-10 17:28:05 [1033:aname:63285]req: /remote/fortisslvpn_xml
2016-10-10 17:28:05 [1033:aname:63285]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63285]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63285]rmt_apsession.c:1022 failed to get dynamic IP
2016-10-10 17:28:05 [1033:aname:63285]rmt_fortisslvpn.c:1440 Matched policy (id = 33) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63285]rmt_fortisslvpn.c:1440 Matched policy (id = 34) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63285]rmt_fortisslvpn.c:1440 Matched policy (id = 35) to add split tunnel routing address
2016-10-10 17:28:05 [1033:aname:63285]req: /remote/sslvpn-tunnel?dns0=172.20.1.31&dns1=172.20.1.32
2016-10-10 17:28:05 [1033:aname:63285]rmt_tunnel.c,sslvpn_tunnel_handler,49, Calling rmt_conn_access_ex.
2016-10-10 17:28:05 [1033:aname:63285]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:05 [1033:aname:63285]rmt_tunnel.c,sslvpn_tunnel_handler,151, Calling tunnel.
2016-10-10 17:28:05 [1033:aname:63285]tunnel_state.c:1266 0x2a98c60c00:0x2a98d72b00 sslvpn user[accountname],type 16,logintime 0 vd 7
2016-10-10 17:28:05 [1033:aname:63285]tunnel_state.c:1278 no more addresses available
2016-10-10 17:28:05 [1033:aname:63285]Destroy sconn 0x2a98c60c00, connSize=2. (aname)
2016-10-10 17:28:05 [1033:aname:63285]tunnel_state.c:tunnelStateCleanup:1565 0x2a98c60c00::(nil)
2016-10-10 17:28:05 [1033:aname:63285]session removed s: 0x2a98c60c00 (aname)
2016-10-10 17:28:05 [1033:aname:63285]rmt_websession.c:342 decode session id ok, user=[accountname],group=[LDAP_VPN],portal=[tunnel-access],host=[ClientIP],realm=[],idx=1,auth=16,login=1476113284
2016-10-10 17:28:09 [1033:aname:63284]rmt_websession.c:1780 delete connection 0x2a98c5dc00 w/ web session 1
2016-10-10 17:28:09 [1033:aname:63284]Destroy sconn 0x2a98c5dc00, connSize=1. (aname)
2016-10-10 17:28:14 [1033:aname:63286]allocSSLConn:245 sconn 0x2a98c5dc00 (7:aname)
2016-10-10 17:28:14 [1033:aname:63286]SSL state:before/accept initialization (ClientIP)

[Filonowst]

98% is the point where the FortiGate is supposed to issue the IP address to the VPN client. At this point, your credentials have already been verified, etcetera. If this is happening to all users, check your IP address settings and make sure they are correct and look at your DHCP monitor to see if IP addresses are hanging after connections should be already terminated. Post them here if you're not sure. If this is for just particular ones users, sometimes when a client is disconnected suddenly and the connection is not properly terminated, something hangs on the client machine and when you try to reconnect you can't get past 98%. An OS reboot fixes it (despite searching, I haven't been able to locate the exact process, service, or device to reset the hung connection without a full reboot).

[AlexandreL]

Hello,

Thanks for the answer, that's usefull information to know. I'll check this next time we will encounter the issue.

I'll let you know if i found something usefull.

[MrSinners]

Is the client using the newest FortiClient?

[canstayn]

Hi everyone,

Did you ever get a resolution to this problem?

As far as i understand the problem is caused by :

tunnel_state.c:1278 no more addresses available Which could be worked around by re-starting vpn deamon. Is there a permanent solution that can be applied so that the ip pool does not exhaust. Best regardsSadik