Technical Tip : Debug output of successful Two Factor Authentication with a Token - INTERNAL

[serge_FTNT]

Description

Baseline to debug VPN SSL Two Factor Authentication with a FortiToken.

Username = 'userguy' with local defined.    

Solution

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log =~=~=~=~=~=~=~=~=~=~=~=
diag deb reset
diag deb console timestamp enable
diag deb application fnbamd -1
diag deb application authd -1
diag deb application sslvpn -1
diag deb enable

2016-02-19 18:08:02 [88:root:53]allocSSLConn:245 sconn 0x2bcaa600 (0:root)
2016-02-19 18:08:02 [88:root:53]SSL state:before/accept initialization (10.5.25.109)
2016-02-19 18:08:02 [88:root:53]SSL_accept returned 0.
2016-02-19 18:08:02 [88:root:53]Destroy sconn 0x2bcaa600, connSize=0. (root)
2016-02-19 18:08:03 [88:root:54]allocSSLConn:245 sconn 0x2bcaa600 (0:root)
2016-02-19 18:08:03 [88:root:54]SSL state:before/accept initialization (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 read client hello A (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 write server hello A (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 write change cipher spec A (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 write finished A (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 flush data (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 read finished A:system lib(10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 read finished A:system lib(10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSLv3 read finished A (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL state:SSL negotiation finished successfully (10.5.25.109)
2016-02-19 18:08:03 [88:root:54]SSL established: TLSv1.2 ECDHE-RSA-AES256-SHA
2016-02-19 18:08:03 [88:root:54]req: /remote/login
2016-02-19 18:08:03 [88:root:54]rmt_authutil.c:418 no session id in auth info
2016-02-19 18:08:03 [88:root:54]rmt_authutil.c:701 invalid cache, ret=4103
2016-02-19 18:08:03 [88:root:54]req: /remote/logincheck
2016-02-19 18:08:03 [88:root:54]rmt_authutil.c:418 no session id in auth info
2016-02-19 18:08:03 [88:root:54]rmt_authutil.c:639 access failed, uri=[/remote/logincheck],ret=4103,
2016-02-19 18:08:03 [88:root:54]rmt_logincheck_cb_handler:839 user 'tokenguy' has a matched local entry.
2016-02-19 18:08:03 [88:root:54]sslvpn_auth_check_usrgroup:1702 forming user/group list from policy.
2016-02-19 18:08:03 [88:root:54]sslvpn_auth_check_usrgroup:1740 got user (3) group (0:0).
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1384 validating with SSL VPN authentication rules (2), realm ().
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1432 checking rule 1 cipher.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1440 checking rule 1 realm.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1451 checking rule 1 source intf.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1487 checking rule 1 vd source intf.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1552 rule 1 done, got user (0) group (0:0).
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1432 checking rule 2 cipher.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1440 checking rule 2 realm.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1451 checking rule 2 source intf.
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1552 rule 2 done, got user (0) group (0:0).
2016-02-19 18:08:03 [88:root:54]sslvpn_validate_user_group_list:1638 got user (3), group (0:0).
2016-02-19 18:08:03 [88:root:54]two factor check for tokenguy: off
2016-02-19 18:08:03 [88:root:54]sslvpn_authenticate_user:168 authenticate user: [tokenguy]
2016-02-19 18:08:03 [88:root:54]sslvpn_authenticate_user:175 create fam state
2016-02-19 18:08:03 [88:root:54]fam_auth_send_req:514 with server blacklist:
2016-02-19 18:08:03 fnbamd_fsm.c[1922] handle_req-Rcvd auth_token req 581910806 for tokenguy in tokenguy
2016-02-19 18:08:03 fnbamd_fsm.c[336] __compose_group_list_from_req-Group 'tokenguy'
2016-02-19 18:08:03 fnbamd_fsm.c[553] create_auth_token_session-Created auth token session 581910806
2016-02-19 18:08:03 [88:root:54]fam_auth_send_req_internal:414 fnbam_auth return: 7
2016-02-19 18:08:06 message_loop: checking timeouts
2016-02-19 18:08:16 [88:root:54]req: /remote/logincheck
2016-02-19 18:08:16 [88:root:54]rmt_authutil.c:418 no session id in auth info
2016-02-19 18:08:16 [88:root:54]rmt_authutil.c:639 access failed, uri=[/remote/logincheck],ret=4103,
2016-02-19 18:08:16 [88:root:54]rmt_logincheck_cb_handler:839 user 'tokenguy' has a matched local entry.
2016-02-19 18:08:16 [88:root:54]two factor check for tokenguy: off
2016-02-19 18:08:16 [88:root:54]sslvpn_authenticate_user:168 authenticate user: [tokenguy]
2016-02-19 18:08:16 [88:root:54]sslvpn_authenticate_user:175 create fam state
2016-02-19 18:08:16 [88:root:54]fam_auth_send_req:514 with server blacklist:
2016-02-19 18:08:16 fnbamd_fsm.c[1949] handle_req-Rcvd auth_token rsp for req 581910806
2016-02-19 18:08:16 fnbamd_fsm.c[1964] handle_req-Check token 397574 with user 'tokenguy'
2016-02-19 18:08:16 fnbamd_fsm.c[1991] handle_req-Token check succeeded
2016-02-19 18:08:16 fnbamd_fsm.c[822] find_matched_usr_grps-Skipped group matching
2016-02-19 18:08:16 fnbamd_comm.c[169] fnbamd_comm_send_result-Sending result 0 for req 581910806
2016-02-19 18:08:16 fnbamd_fsm.c[565] destroy_auth_session-delete session 581910806
2016-02-19 18:08:16 [88:root:54]fam_do_cb:463 fnbamd return auth success.
2016-02-19 18:08:16 [88:root:54]SSL VPN login matched rule (0).
2016-02-19 18:08:16 [88:root:54]login_succeeded:375 redirect to hostcheck
2016-02-19 18:08:16 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:16 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:16 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:16 message_loop: checking timeouts
2016-02-19 18:08:16 [88:root:54]req: /
2016-02-19 18:08:16 [88:root:54]mza: 0x947e5c0 /rmt_index.html
2016-02-19 18:08:16 [88:root:54]def: 0x947e5c0 /rmt_index.html
2016-02-19 18:08:16 [88:root:54]req: /remote/index
2016-02-19 18:08:16 [88:root:54]def: (nil) /remote/index
2016-02-19 18:08:16 [88:root:54]req: /remote/fortisslvpn
2016-02-19 18:08:16 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:16 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:54]req: /remote/fortisslvpn_xml
2016-02-19 18:08:17 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:54]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:54]rmt_apsession.c:1052 tunnel vd[root] ip[10.212.134.200]
2016-02-19 18:08:17 [88:root:55]allocSSLConn:245 sconn 0x2bcaac00 (0:root)
2016-02-19 18:08:17 [88:root:55]SSL state:before/accept initialization (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read client hello A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write server hello A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write certificate A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write key exchange A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write server done A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 flush data (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read client certificate A:system lib(10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read client certificate A:system lib(10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read client key exchange A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read certificate verify A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 read finished A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write session ticket A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write change cipher spec A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 write finished A (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSLv3 flush data (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL state:SSL negotiation finished successfully (10.5.25.109)
2016-02-19 18:08:17 [88:root:55]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
2016-02-19 18:08:17 [88:root:55]req: /remote/fortisslvpn_xml
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]req: /remote/licensecheck
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]req: /remote/sslvpn-tunnel?dns0=10.5.31.1
2016-02-19 18:08:17 [88:root:55]rmt_tunnel.c,sslvpn_tunnel_handler,49, Calling rmt_conn_access_ex.
2016-02-19 18:08:17 [88:root:55]rmt_websession.c:342 decode session id ok, user=[tokenguy],group=[],portal=[full-access],host=[10.5.25.109],realm=[],idx=0,auth=1,login=1455901696
2016-02-19 18:08:17 [88:root:55]rmt_tunnel.c,sslvpn_tunnel_handler,151, Calling tunnel.
2016-02-19 18:08:17 [88:root:55]tunnel_state.c:1266 0x2bcaac00:0x2bcaaf00 sslvpn user[tokenguy],type 1,logintime 0 vd 0
2016-02-19 18:08:17 [88:root:55]sconn 0x2bcaac00 (0:root) vfid=0 local=[10.5.17.196] remote=[10.5.25.109] dynamicip=[10.212.134.200]
2016-02-19 18:08:17 [88:root:55]Prepare to launch pppd...
2016-02-19 18:08:17 [88:root:55]tun: ppp 0x2bcd3000 dev (ssl.root) assigned: 0x2bc08400 ref 1
2016-02-19 18:08:17 [88:root:0]Will add auth policy for policy 2 for user tokenguy:
2016-02-19 18:08:17 authd_admin.c:785 authd_admin_read: called
2016-02-19 18:08:17 message_loop: checking timeouts
2016-02-19 18:08:17 [88:root:0]Add auth logon for user tokenguy:, matched group number 1
2016-02-19 18:08:22 lcp_reqci: returning CONFREJ.
2016-02-19 18:08:22 lcp_reqci: returning CONFACK.
2016-02-19 18:08:22 lcp_up: with mtu 1354
2016-02-19 18:08:22 ipcp: returning Configure-REJ
2016-02-19 18:08:22 ipcp: returning Configure-NAK
2016-02-19 18:08:22 ipcp: returning Configure-ACK
2016-02-19 18:08:22 ipcp: up ppp:0x2bcd3000 tun:0x2bc08400 ref 1
2016-02-19 18:08:22 Cannot determine ethernet address for proxy ARP
2016-02-19 18:08:22 local  IP address 10.5.17.196
2016-02-19 18:08:22 remote IP address 10.212.134.200
2016-02-19 18:08:22 [88:root:55]sys-fortik.c:768 associate 10.212.134.200 to tun (ssl.root:34)
2016-02-19 18:08:22 [88:root:54]http_state.c,ap_read_request,515, ret=-1 error=-1, sconn=0x2bcaa600.
2016-02-19 18:08:22 [88:root:54]Destroy sconn 0x2bcaa600, connSize=1. (root)
2016-02-19 18:08:27 message_loop: checking timeouts
2016-02-19 18:08:37 message_loop: checking timeouts