| Solution |
Below is the debug flow derived from the output of the command 'sslvpnd' and 'fnbamd' and the process is as follows,
Note:
Relevant firewall policies and SSL VPN settings should be configured, this article focuses on explaining the debug output seen when an LDAP user authenticates using SSL VPN therefore basic configurations which are understandable are skipped.
Details:
Username: ek13
Usergroup name in FortiGate: ldap user
Ldap server name: ldap testing
Firewall policy as per below,
LDAP server config:
Steps:
- FortiGate receives user credentials.
- FortiGate checks firewall policy for user/usergroup details (Note: even if the user does not belong to any of the groups defined in the policy, FortiGate will still try to validate and check if there is a match).
- It establishes a connection with the LDAP server.
- Check user binding and group membership
- Once it matches the result is passed back to the FortiGate
- FortiGate then matches the user group defined in the firewall policy and authenticates the user.
Commands:
diag debug application sslvpn -1
diag debug application fnbamd -1
diag de enable
Lotus-kvm21 # [2570] peer_user_cn_dns_refresh-
[3391] __peer_user_cn_dns_refresh-Refresh in 1800 secs
[2355:root:c]allocSSLConn:310 sconn 0x7f2a81255800 (0:root)
[2355:root:d]client cert requirement: no
[2355:root:d]SSL state:SSLv3/TLS read client hello (10.47.3.173)
-----Truncated---------------------------------------
[2355:root:d]rmt_web_access_check:793 access failed, uri=[/remote/logincheck],ret=4103,
[2355:root:d]sslvpn_auth_check_usrgroup:3050 forming user/group list from policy.
[2355:root:d]sslvpn_auth_check_usrgroup:3097 got user (0) group (1:0).
[2355:root:d]sslvpn_validate_user_group_list:1940 validating with SSL VPN authentication rules (1), realm ().
[2355:root:d]sslvpn_validate_user_group_list:2034 checking rule 1 cipher.
[2355:root:d]sslvpn_validate_user_group_list:2042 checking rule 1 realm.
[2355:root:d]sslvpn_validate_user_group_list:2053 checking rule 1 source intf.
[2355:root:d]sslvpn_validate_user_group_list:2092 checking rule 1 vd source intf.
[2355:root:d]sslvpn_validate_user_group_list:2591 rule 1 done, got user (0:0) group (1:0) peer group (0).
[2355:root:d]sslvpn_validate_user_group_list:2599 got user (0:0) group (1:0) peer group (0).
[2355:root:d]sslvpn_validate_user_group_list:2946 got user (0:0), group (1:0) peer group (0).
[2355:root:d]sslvpn_update_user_group_list:1834 got user (0:0), group (1:0), peer group (0) after update.
[2355:root:d]two factor check for ek13: off
[2355:root:d]sslvpn_authenticate_user:193 authenticate user: [ek13] -->user
[2355:root:d]sslvpn_authenticate_user:211 create fam state
[2355:root:d][fam_auth_send_req_internal:430] Groups sent to FNBAM:
[2355:root:d]group_desc[0].grpname = ldap user -->This is the only group defined in the firewall policy and as mentioned this group is a remote user (LDAP) group.
Note:
Even if the user does not belong to this group FortiGate will still list out and select the user group as per the firewall policy definition and if there are multiple policies with multiple user groups then everything will be listed here, this part is NOT the Real user group validation.
[2355:root:d][fam_auth_send_req_internal:442] FNBAM opt = 0X200421
[1939] handle_req-Rcvd auth req 2093133332 for ek13 in opt=00200421 prot=11
[489] __compose_group_list_from_req-Group 'ldap user', type 1
[616] fnbamd_pop3_start-ek13
[378] radius_start-Didn't find radius servers (0)
[765] auth_tac_plus_start-Didn't find tac_plus servers (0)
[1009] __fnbamd_cfg_get_ldap_list_by_group-
The connection establishment to the LDAP server starts below:
[1067] __fnbamd_cfg_get_ldap_list_by_group-Loaded LDAP server 'ldap testing' for usergroup 'ldap user' (2)
[1117] fnbamd_cfg_get_ldap_list-Total ldap servers to try: 1
[1718] fnbamd_ldap_init-search filter is: sAMAccountName=ek13
[1728] fnbamd_ldap_init-search base is: dc=klpod1ftnt,dc=local
[1150] __fnbamd_ldap_dns_cb-Resolved ldap testing:10.47.2.174 to 10.47.2.174, cur stack size:1
[925] __fnbamd_ldap_get_next_addr-
[1155] __fnbamd_ldap_dns_cb-Connection starts ldap testing:10.47.2.174, addr 10.47.2.174
[880] __fnbamd_ldap_start_conn-Still connecting 10.47.2.174.
[480] fnbamd_cfg_get_ext_idp_list-
[454] __fnbamd_cfg_get_ext_idp_list_by_group-
[460] __fnbamd_cfg_get_ext_idp_list_by_group-Group 'ldap user'
[490] fnbamd_cfg_get_ext_idp_list-Total external identity provider servers to try: 0
[652] create_auth_session-Total 1 server(s) to try
[1980] handle_req-r=4
[1108] __ldap_connect-tcps_connect(10.47.2.174) is established. <----- LDAP server connection is established.
[986] __ldap_rxtx-state 3(Admin Binding)
[363] __ldap_build_bind_req-Binding to 'klpod1ftnt\ekrishnan'
[1083] fnbamd_ldap_send-sending 43 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 1
[986] __ldap_rxtx-state 4(Admin Bind resp)
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 14
[1306] fnbamd_ldap_recv-Response len: 16, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:1, type:bind
[1023] fnbamd_ldap_parse_response-ret=0
[1053] __ldap_rxtx-Change state to 'DN search'
[986] __ldap_rxtx-state 11(DN search)
[750] fnbamd_ldap_build_dn_search_req-base:'dc=klpod1ftnt,dc=local' filter:sAMAccountName=ek13
[1083] fnbamd_ldap_send-sending 77 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 2
[986] __ldap_rxtx-state 12(DN search resp)
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 57
[1306] fnbamd_ldap_recv-Response len: 59, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:2, type:search-entry
[1023] fnbamd_ldap_parse_response-ret=0
[1226] __fnbamd_ldap_dn_entry-Get DN 'CN=elang k,CN=Users,DC=klpod1ftnt,DC=local'
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 88
[1306] fnbamd_ldap_recv-Response len: 90, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:2, type:search-reference
[1023] fnbamd_ldap_parse_response-ret=0
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
------------Truncated------------------------------
[596] fnbamd_ldap_build_userbind_req-Trying DN 'CN=elang k,CN=Users,DC=klpod1ftnt,DC=local'
[363] __ldap_build_bind_req-Binding to 'CN=elang k,CN=Users,DC=klpod1ftnt,DC=local'
[1083] fnbamd_ldap_send-sending 97 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 3
[986] __ldap_rxtx-state 6(User Bind resp)
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 14
[1306] fnbamd_ldap_recv-Response len: 16, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:3, type:bind
[1023] fnbamd_ldap_parse_response-ret=0
[1053] __ldap_rxtx-Change state to 'Attr query'
[986] __ldap_rxtx-state 7(Attr query)
[649] fnbamd_ldap_build_attr_search_req-Adding attr 'memberOf'
[661] fnbamd_ldap_build_attr_search_req-base:'CN=elang k,CN=Users,DC=klpod1ftnt,DC=local' filter:cn=*
[1083] fnbamd_ldap_send-sending 118 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 4
[986] __ldap_rxtx-state 8(Attr query resp)
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 212
[1306] fnbamd_ldap_recv-Response len: 214, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:4, type:search-entry
[1023] fnbamd_ldap_parse_response-ret=0
[556] __get_member_of_groups-Get the memberOf groups.
[522] __retrieve_group_values-Get the memberOf groups.
[532] __retrieve_group_values- attr='memberOf', found 1 values
[542] __retrieve_group_values-val[0]='CN=test123456,CN=Users,DC=klpod1ftnt,DC=local' <----- The user group binding in the LDAP server.
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 14
[1306] fnbamd_ldap_recv-Response len: 16, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:4, type:search-result
[1023] fnbamd_ldap_parse_response-ret=0
[1306] __fnbamd_ldap_attr_next-Entering CHKPRIMARYGRP state
[1053] __ldap_rxtx-Change state to 'Primary group query'
[986] __ldap_rxtx-state 13(Primary group query)
[685] fnbamd_ldap_build_primary_grp_search_req-starting primary group check...
[689] fnbamd_ldap_build_primary_grp_search_req-number of sub auths 5
[707] fnbamd_ldap_build_primary_grp_search_req-base:'dc=klpod1ftnt,dc=local' filter:(&(objectclass=group)(objectSid=\01\05\00\00\00\00\00\05\15\00\00\00\06\10\85\74\16
\8c\81\24\70\29\fb\da\01\02\00\00))
[1083] fnbamd_ldap_send-sending 126 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 5
[986] __ldap_rxtx-state 14(Primary group query resp)
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 115
[1306] fnbamd_ldap_recv-Response len: 117, svr: 10.47.2.174
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:5, type:search-entry
[1023] fnbamd_ldap_parse_response-ret=0
[472] __get_one_group-group: CN=Domain Users,CN=Users,DC=klpod1ftnt,DC=local
[1127] __fnbamd_ldap_read-Read 8
[1233] fnbamd_ldap_recv-Leftover 2
[1127] __fnbamd_ldap_read-Read 88
[1306] fnbamd_ldap_recv-Response len: 90, svr: 10.47.2.174
------------Truncated-------------------
[987] fnbamd_ldap_parse_response-Got one MESSAGE. ID:5, type:search-result
[1023] fnbamd_ldap_parse_response-ret=0
[1431] __fnbamd_ldap_primary_grp_next-Auth accepted
[1053] __ldap_rxtx-Change state to 'Done'
[986] __ldap_rxtx-state 23(Done)
[1083] fnbamd_ldap_send-sending 7 bytes to 10.47.2.174
[1096] fnbamd_ldap_send-Request is sent. ID 6
[785] __ldap_done-svr 'ldap testing'
[755] __ldap_destroy-
[724] __ldap_stop-Conn with 10.47.2.174 destroyed.
[2855] fnbamd_ldap_result-Result for ldap svr 10.47.2.174(ldap testing) is SUCCESS <----- The user is validated in the LDAP server.
[401] ldap_copy_grp_list-copied CN=test123456,CN=Users,DC=klpod1ftnt,DC=local
[401] ldap_copy_grp_list-copied CN=Domain Users,CN=Users,DC=klpod1ftnt,DC=local
[1623] fnbam_user_auth_group_match-req id: 2093133332, server: ldap testing, local auth: 0, dn match: 1
[1592] __group_match-Group 'ldap user' passed group matching <----- Upon successful validation with the LDAP server FortiGate matches the user group defined in the firewall policy.
[1595] __group_match-Add matched group 'ldap user'(2)
[2867] fnbamd_ldap_result-Passed group matching
[209] fnbamd_comm_send_result-Sending result 0 (nid 0) for req 2093133332, len=2635
[2355:root:d]fam_auth_proc_resp:1371 fnbam_auth_update_result return: 0 (success)
[2355:root:d][fam_auth_proc_resp:1472] Authenticated groups (1) by FNBAM with auth_type (16):
[2355:root:d]Received: auth_rsp_data.grp_list[0] = 2
[2355:root:d]fam_auth_proc_resp:1497 found node ldap user:0:, valid:1, auth:0
[2355:root:d]Validated: auth_rsp_data.grp_list[0] = ldap user
[2355:root:d]Auth successful for user ek13 in group ldap user <----- The user is authenticated.
[2355:root:d][808] destroy_auth_session-delete session 2093133332
|
