Technical Tip: How to read and create an fnbamd debug on FortiGate

[tbarua]

Description

This article describes how to read and create an fnbamd debug on FortiGate.

Scope

FortiGate debugging for authentication debugging. fnbamd handles RADIUS, LDAP, TACACS authentication, as well as certificate validation (peer user authentication).

Solution

fnbamd debugging often goes together with SSL VPN, as they can be combined. fnbamd will receive a request from another process to authenticate a user.

To understand more of the context, consider authentication as a packet flow on a higher OSI layer. One node talks to another and expects a response from it and – that is important – only from this node. A RADIUS Access-Request is sent to another node, RADIUS server and a response is expected or a timeout occurs.

The authentication flow may be easiest to understand with the following color coding – note that the green Authenticator does not refer to the FortiAuthenticator, but the node that handles the direct authentication request from the user:

• Colors = End user | Authenticator(s) | User DB and handling | Authenticators reply and consequences

Authentication flow (simple):

Authentication request (User) -> Authenticator -> Reply (to user) (FAIL/OK) -> User accepted or denied.

Example:

FortiClient login with username and password -> FortiGate with local user database -> Reply (OK) -> User logged in.

Authentication flow (usual):

Authentication request (User) -> Authenticator -> Authenticator Backend (remote user database) -> Reply (FAIL/OK + meta info) -> Authenticator filtering against RADIUS meta info -> Reply (OK) -> User logged in.

Example:

FortiClient Login -> FortiGate -> FortiAuthenticator as RADIUS Backend -> Reply OK with RADIUS additional information (AVP/VSA) -> FortiGate filtering against RADIUS information -> Reply (OK) -> User logged in.

Another example:

FortiClient Login -> FortiGate -> Windows AD as LDAP Backend -> Reply OK with the LDAP additional information (Group memberships typically) -> FortiGate filtering against LDAP information -> Reply (OK) -> User logged in.

2FA (Token, certificate):

A second factor to authenticate against can be requested from an Authenticator or Backend, but not from an LDAP backend.

Note:

On whichever user database the second factor is configured, the same database has to be queried against that same user. If the user is bypassed by querying not the user database but another database like in a parallel configured LDAP backend, there may be no second factor requested.

This explains how to run debug and shows the typical output (truncated)

diag debug console timestamp enable

diag debug app fnbamd -1

diag debug enable

The following two commands are used for testing on the CLI:

diag test authserver ldap <ldapserverNAME> username password

diag test authserver radius <radiusserverNAME> pap username password

These test commands are good to create a timed log. Running the CLI output will instantly create debug output in the same command line session.

Example output with RADIUS with a successful authentication:

diag test authserver radius FAC pap user48 fortinet

fnbamd receives its request to check with the following line and sesison ID. Rcvd auth req + number. The number is an authentication session ID, that can be followed through the debug for this user.
2024-05-05 10:48:48 [2227] handle_req-Rcvd auth req 786962683 for user48 in FAC opt=0000001d prot=0

fnbamd sends this towards the configured RADIUS server as user48 is seen as potential member of a user group that references the RADIUS server „FAC“.
2024-05-05 10:48:48 [555] __fnbamd_cfg_get_radius_list_by_server-Loading RADIUS server 'FAC'
2024-05-05 10:48:48 [1352] fnbamd_radius_auth_send-Compose RADIUS request

2024-05-05 10:48:48 [1294] __fnbamd_rad_send-Sent radius req to server 'FAC': fd=15, IP=192.168.38.38(192.168.38.38:1812) code=1 id=0 len=91 user="user48" using PAP
2024-05-05 10:48:48 [284] radius_server_auth-Timer of rad 'FAC' is added
2024-05-05 10:48:48 [1752] fnbamd_radius_auth_validate_pkt-RADIUS resp code 2
2024-05-05 10:48:48 [319] extract_success_vsas-FORTINET attr, type 1, val VPN-users <- Meta data: RADIUS attribute “Fortinet-Group-Name”, value: “VPN-users”.

fnbamd received an Access-Accept from the RADIUS server and extracted a vendor specific attribute. Fortinet-Group-Name with value „VPN-users“.
2024-05-05 10:48:48 [2466] fnbamd_auth_handle_radius_result-->Result for radius svr 'FAC' 192.168.38.38(1) is 0
2024-05-05 10:48:48 [2784] fnbamd_fas_send_push-username:user48, vdom:root, usertype:0, tfc=0, auth_type:2
2024-05-05 10:48:48 [190] fnbamd_comm_send_result-Sending result 0 (error 0, nid 0) for req 786962683, len=2070

fnbamd finished authentication with success and hands it back to the requesting process with collected detail (like group membership, Access-profile for admin authentication).
authenticate 'user48' against 'pap' succeeded, server=primary assigned_rad_session_id=786962683 session_timeout=0 secs idle_timeout=0 secs!
Group membership(s) - VPN-users <- Final output of test app command.

Example output with LDAP:

diag test authserver ldap LDAP user48 fortinet

fnbamd receives its request to check with the following line and session ID. Rcvd auth req + number. The number is an authentication session ID, that can be followed through the debug for this user.

2024-05-05 11:48:48 [2227] handle_req-Rcvd auth req 786962684 for user48 in LDAP opt=0000001b prot=0
2024-05-05 11:48:48 [417] __compose_group_list_from_req-Group 'LDAP', type 1 <- Meta data: Query to server 'LDAP'.
2024-05-05 11:48:48 [1070] __fnbamd_cfg_get_ldap_list_by_server-Loading LDAP server 'LDAP'
2024-05-05 11:48:48 [1714] fnbamd_ldap_init-search filter is: sAMAccountname=user48 <- Search term, LDAP Attribute 'sAMAccountname' with value 'user48'.
2024-05-05 11:48:48 [1723] fnbamd_ldap_init-search base is: DC=forti,DC=lab <- Search path (baseDN).
2024-05-05 11:48:48 [1144] __fnbamd_ldap_dns_cb-Connection starts LDAP:192.168.95.95, addr 192.168.95.95
2024-05-05 11:48:48 [1095] __ldap_connect-tcps_connect(192.168.95.95) is established.
2024-05-05 11:48:48 [973] __ldap_rxtx-state 3(Admin Binding)
2024-05-05 11:48:48 [206] __ldap_build_bind_req-Binding to 'CN=administrator,CN=users,DC=forti,DC=lab' <- Authenticating to LDAP as user with permission to read the search path (baseDN).
2024-05-05 11:48:48 [939] fnbamd_ldap_send-Request is sent. ID 1
2024-05-05 11:48:48 [831] fnbamd_ldap_parse_response-Got one MESSAGE. ID:1, type:bind
2024-05-05 11:48:48 [594] fnbamd_ldap_build_dn_search_req-base:'DC=forti,DC=lab' filter:sAMAccountname=user48 <- Attribute to be searched for, 'CNID=sAMAccountname, value=user48'.
2024-05-05 11:48:48 [939] fnbamd_ldap_send-Request is sent. ID 2
2024-05-05 11:48:48 [831] fnbamd_ldap_parse_response-Got one MESSAGE. ID:2, type:search-entry
2024-05-05 11:48:48 [206] __ldap_build_bind_req-Binding to 'CN=user48,CN=Users,DC=forti,DC=lab' <- Finding user.
2024-05-05 11:48:48 [1040] __ldap_rxtx-Change state to 'Attr query'
2024-05-05 11:48:48 [492] fnbamd_ldap_build_attr_search_req-Adding attr 'memberOf' <- User attribute LDAP server is queried for.
2024-05-05 11:48:48 [504] fnbamd_ldap_build_attr_search_req-base:'CN=user48,CN=Users,DC=forti,DC=lab'
filter:cn=*
2024-05-05 11:48:48 [533] __retrieve_group_values- attr='memberOf', found 5 values <- Meta data: 5 groups were found here.
2024-05-05 11:48:48 [100] ldap_dn_list_add-added CN=GRP-consulting,CN=Users,DC=forti,DC=lab <- Meta data: LDAP attribute 'memberOf', value: 'GRP-consulting' = user is member of that group.
… <- Meta data: can be plenty of output, depending on the memberships.
2024-05-05 11:48:48 [100] ldap_dn_list_add-added CN=VPN-users,CN=Users,DC=forti,DC=lab
2024-05-05 11:48:48 [542] __retrieve_group_values-val[4]='CN=VPN-users,CN=Users,DC=forti,DC=lab' <- Meta data: LDAP attribute 'memberOf', value: 'VPN-users' is actually filtered against this.
2024-05-05 11:48:48 [1418] __fnbamd_ldap_primary_grp_next-Auth accepted <- Authentication accepted.
2024-05-05 11:48:48 [62] ldap_dn_list_del_all-Del CN=user48,CN=Users,DC=forti,DC=lab
2024-05-05 11:48:48 [725] __ldap_stop-Conn with 192.168.95.95 destroyed.
2024-05-05 11:48:48 [3040] fnbamd_ldap_result-Result for ldap svr 192.168.95.95 is SUCCESS <- Process result (returned to ike, sslvpnd).
2024-05-05 11:48:48 [402] ldap_copy_grp_list-copied CN=GRP-consulting,CN=Users,DC=forti,DC=lab
... <- fnbamd is reading all groups (listing).
2024-05-05 11:48:48 [402] ldap_copy_grp_list-copied CN=Domain Users,CN=Users,DC=forti,DC=lab

The following information is then concerning the end user again. Authentication succeeded.

2024-05-05 11:48:48 [190] fnbamd_comm_send_result-Sending result 0 (error 0, nid 0) for req 786962684, len=2338
authenticate 'user48' against 'LDAP' succeeded! <- Final output of the 'diag test app' command.
Group membership(s) - CN=GRP-consulting,CN=Users,DC=forti,DC=lab
CN=GRP-IT-Override,CN=Users,DC=forti,DC=lab
CN=GRP-IT,CN=Users,DC=forti,DC=lab
CN=GRP-IT-Default,CN=Users,DC=forti,DC=lab
CN=VPN-users,CN=Users,DC=forti,DC=lab
CN=Domain Users,CN=Users,DC=forti,DC=lab

The debug can and should be combined with the requesting service, for example SSL VPN for VPN logins, or httpsd for web UI users or authd for captive portal authentication:

diag debug console timestamp enable

diag debug app fnbamd -1

diag debug app sslvpn -1

diag debug enable

Or:

diag debug console timestamp enable

diag debug app fnbamd -1

diag debug app auth -1

diag debug enable

Or:

diag debug console timestamp enable

diag debug app fnbamd -1

diag debug app httpsd -1

diag debug enable

The timestamp information can be crucial to define when something happens. If the environment had 5 authentications processed in 20 seconds, or the randomness of an issue may just show that a user failed authentication, debugging with timestamp information may give more references to check on the other node logs, like the FortiClient diagnostic report.

If the type of issue is unclear in nature, enable the timestamp.

The log may contain 'timeout' messages which will only make sense with a readable timestamp available.