FortiClient VPN stops at 48% with warning -7200

[sidp]

Hi,

Our users keep having problems logging in with Forticlient VPN only.
It happens very often that Forticlient stops at 48% and issues the warning -7200. Sometimes you have to repeat the login process 3-7 times and then the client asks for the Fortitoken and can then log in successfully.

FortiOS v6.4.15

We are using LDAP authentication with Fortitoken.

It doesn't matter whether I set username-sensitivity to disable or leave it at default enable.

Does anyone know the problem and can help?

[326:root:d3a]allocSSLConn:298 sconn 0x7f268edacd00 (0:root)
[326:root:d3a]SSL state:before SSL initialization (77.239.xy.xyx)
[326:root:d3a]SSL state:before SSL initialization:DH lib(77.239.xy.xyx)
[326:root:d3a]SSL_accept failed, 5:(null)
[326:root:d3a]Destroy sconn 0x7f268edacd00, connSize=1. (root)
[327:root:d3c]allocSSLConn:298 sconn 0x7f268edac800 (0:root)
[327:root:d3c]SSL state:before SSL initialization (77.239.xy.xyx)
[327:root:d3c]SSL state:before SSL initialization (77.239.xy.xyx)
[327:root:d3c]got SNI server name: sslvpn.url.com realm (null)
[327:root:d3c]client cert requirement: no
[327:root:d3c]SSL state:SSLv3/TLS read client hello (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write server hello (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write certificate (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write key exchange (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write server done (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write server done:system lib(77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write server done (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS read client key exchange (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS read change cipher spec (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS read finished (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write session ticket (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write change cipher spec (77.239.xy.xyx)
[327:root:d3c]SSL state:SSLv3/TLS write finished (77.239.xy.xyx)
[327:root:d3c]SSL state:SSL negotiation finished successfully (77.239.xy.xyx)
[327:root:d3c]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
[327:root:d3c]req: /remote/info
[327:root:d3c]capability flags: 0xdf
[327:root:d3c]req: /remote/login?realm=mts
[327:root:d3c]rmt_web_auth_info_parser_common:465 no session id in auth info
[327:root:d3c]rmt_web_get_access_cache:808 invalid cache, ret=4103
[327:root:d3c]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
[327:root:d3c]get_cust_page:127 saml_info 0
[327:root:d3c]req: /remote/logincheck
[327:root:d3c]rmt_web_auth_info_parser_common:465 no session id in auth info
[327:root:d3c]rmt_web_access_check:727 access failed, uri=[/remote/logincheck],ret=4103,
[327:root:d3c]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
[327:root:d3c]rmt_logincheck_cb_handler:1255 user 'max' has a matched local entry.
[327:root:d3c]sslvpn_auth_check_usrgroup:2719 forming user/group list from policy.
[327:root:d3c]sslvpn_auth_check_usrgroup:2757 got user (0) group (3:0).
[327:root:d3c]sslvpn_validate_user_group_list:1843 validating with SSL VPN authentication rules (3), realm (mts).
[327:root:d3c]sslvpn_validate_user_group_list:1928 checking rule 2 cipher.
[327:root:d3c]sslvpn_validate_user_group_list:1936 checking rule 2 realm.
[327:root:d3c]sslvpn_validate_user_group_list:1947 checking rule 2 source intf.
[327:root:d3c]sslvpn_validate_user_group_list:1986 checking rule 2 vd source intf.
[327:root:d3c]sslvpn_validate_user_group_list:2267 rule 2 done, got user (0:0) group (1:0) peer group (0).
[327:root:d3c]sslvpn_validate_user_group_list:1928 checking rule 3 cipher.
[327:root:d3c]sslvpn_validate_user_group_list:1936 checking rule 3 realm.
[327:root:d3c]sslvpn_validate_user_group_list:1928 checking rule 4 cipher.
[327:root:d3c]sslvpn_validate_user_group_list:1936 checking rule 4 realm.
[327:root:d3c]sslvpn_validate_user_group_list:2275 got user (0:0) group (1:0) peer group (0).
[327:root:d3c]sslvpn_validate_user_group_list:2618 got user (0:0), group (1:0) peer group (0).
[327:root:d3c]sslvpn_update_user_group_list:1750 got user (0:0), group (1:0), peer group (0) after update.
[327:root:d3c]two factor check for max: off
[327:root:d3c]sslvpn_authenticate_user:167 authenticate user: [max]
[327:root:d3c]sslvpn_authenticate_user:174 create fam state
[327:root:d3c][fam_auth_send_req_internal:425] Groups sent to FNBAM:
[327:root:d3c]group_desc[0].grpname = ldap_dl-fg-sslvpn-realm-mts
[327:root:d3c][fam_auth_send_req_internal:437] FNBAM opt = 0X200420
[327:root:d3c]fam_auth_send_req_internal:513 fnbam_auth return: 4
[327:root:d3c]fam_auth_proc_resp:1287 fnbam_auth_update_result return: 3
[327:root:d3c][fam_auth_proc_resp:1385] Authenticated groups (1) by FNBAM:
[327:root:d3c]Received: auth_rsp_data.grp_list[0] = 3054238368
[327:root:d3c]login_failed:391 user[max],auth_type=1 failed [sslvpn_login_no_matching_policy]

[fricci_FTNT]

Hi @sidp ,

Thank you for those outputs, I have not spotted any anomaly.
Please let us know if you still experience the issue while the LDAP server IP address is set rather than the name.

Best regards,

[sidp]

Hi @fricci_FTNT 

Unfortunately the problem has occurred again... I was able to capture the debug log again.

Spoiler

FW01 # diagnose test application fnbamd 1 
Total fnbam requests in caller side: 253137; EAGAIN errors: 0; other errors: 1
Pending sessions: 0
Max session reached: 0
Res 0: 250051
Res 1: 741
Res 2: 0
Res 3: 1678
Res 4: 0
Res 5: 190
Res 6: 0
Res 7: 4333
Res 8: 2
Res 9: 0
Res 10: 0
Res 11: 0
Res 12: 174
Auth:
requests: 6669
sessions: 6669
released: 6669
Acct:
requests: 1
sessions: 0
released: 0
Cert:
requests: 241962
sessions: 241962
released: 241962
LDAP stats:
total: 5058
conn failures: 342

FW01 # diagnose debug reset FW01 # diag debug console timestamp enable FW01 # diag debug application fnbamd 0x4 
Debug messages will be on for 30 minutes.

FW01 # diag debug app sslvpn 0x10FF 
Debug messages will be on for 30 minutes.

FW01 # diag debug enable 2024-07-08 08:03:59 [26720:root:2a]allocSSLConn:298 sconn 0x7f269001f100 (0:root)
2024-07-08 08:03:59 [26720:root:2a]SSL_accept failed, 5:(null)
2024-07-08 08:03:59 [26720:root:2a]Destroy sconn 0x7f269001f100, connSize=0. (root)
2024-07-08 08:03:59 [26721:root:2a]allocSSLConn:298 sconn 0x7f269001f100 (0:root)
2024-07-08 08:03:59 [26721:root:2a]got SNI server name: sslvpn.url.com realm (null)
2024-07-08 08:03:59 [26721:root:2a]client cert requirement: no
2024-07-08 08:04:00 [26721:root:2a]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
2024-07-08 08:04:00 [26721:root:2a]capability flags: 0xdf
2024-07-08 08:04:00 [26721:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:00 [26721:root:2a]rmt_web_get_access_cache:808 invalid cache, ret=4103
2024-07-08 08:04:00 [26721:root:2a]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
2024-07-08 08:04:00 [26721:root:2a]get_cust_page:127 saml_info 0
2024-07-08 08:04:00 [26721:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:00 [26721:root:2a]rmt_web_access_check:727 access failed, uri=[/remote/logincheck],ret=4103,
2024-07-08 08:04:00 [26721:root:2a]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
2024-07-08 08:04:00 [26721:root:2a]rmt_logincheck_cb_handler:1255 user 'max' has a matched local entry.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_auth_check_usrgroup:2719 forming user/group list from policy.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_auth_check_usrgroup:2757 got user (0) group (4:0).
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1843 validating with SSL VPN authentication rules (4), realm (mts).
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1928 checking rule 2 cipher.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1936 checking rule 2 realm.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1947 checking rule 2 source intf.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1986 checking rule 2 vd source intf.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:2267 rule 2 done, got user (0:0) group (1:0) peer group (0).
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1928 checking rule 3 cipher.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1936 checking rule 3 realm.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1928 checking rule 4 cipher.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1936 checking rule 4 realm.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1928 checking rule 5 cipher.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:1936 checking rule 5 realm.
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:2275 got user (0:0) group (1:0) peer group (0).
2024-07-08 08:04:00 [26721:root:2a]sslvpn_validate_user_group_list:2618 got user (0:0), group (1:0) peer group (0).
2024-07-08 08:04:00 [26721:root:2a]sslvpn_update_user_group_list:1750 got user (0:0), group (1:0), peer group (0) after update.
2024-07-08 08:04:00 [26721:root:2a]two factor check for max: off
2024-07-08 08:04:00 [26721:root:2a]sslvpn_authenticate_user:167 authenticate user: [max]
2024-07-08 08:04:00 [26721:root:2a]sslvpn_authenticate_user:174 create fam state
2024-07-08 08:04:00 [26721:root:2a][fam_auth_send_req_internal:425] Groups sent to FNBAM:
2024-07-08 08:04:00 [26721:root:2a]group_desc[0].grpname = ldap_dl-fg-sslvpn-realm-mts 
2024-07-08 08:04:00 [26721:root:2a][fam_auth_send_req_internal:437] FNBAM opt = 0X200420
2024-07-08 08:04:00 [26721:root:2a]fam_auth_send_req_internal:513 fnbam_auth return: 4
2024-07-08 08:04:00 [1901] handle_req-Rcvd auth req 1376421611 for max in opt=00200420 prot=11
2024-07-08 08:04:00 [617] fnbamd_pop3_start-max
2024-07-08 08:04:00 [380] radius_start-Didn't find radius servers (0)
2024-07-08 08:04:00 [752] auth_tac_plus_start-Didn't find tac_plus servers (0)
2024-07-08 08:04:00 [2151] __match_and_update_auth_user-Found a matching user in CMDB 'max'
2024-07-08 08:04:00 [1053] __fnbamd_cfg_get_ldap_list_by_group-Loaded LDAP server 'mts.local' for user 'max' in rgroup 'ldap_dl-fg-sslvpn-realm-mts' (3)
2024-07-08 08:04:00 [1131] fnbamd_cfg_get_ldap_list-Total ldap servers to try: 1
2024-07-08 08:04:00 [1713] fnbamd_ldap_init-search filter is: sAMAccountName=max
2024-07-08 08:04:00 [1722] fnbamd_ldap_init-search base is: ou=mts,dc=mts,dc=local
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:10.9.9.12 to 10.9.9.12, cur stack size:1
2024-07-08 08:04:00 [1152] __fnbamd_ldap_dns_cb-Connection starts mts.local:10.9.9.12, addr 10.9.9.12 over SSL
2024-07-08 08:04:00 [874] __fnbamd_ldap_start_conn-Still connecting 10.9.9.12.
2024-07-08 08:04:00 [596] create_auth_session-Total 1 server(s) to try
2024-07-08 08:04:00 [907] __ldap_try_next_server-Try next server 'mts-dc03.mts.local' for 'mts.local'.
2024-07-08 08:04:00 [115] fnbamd_dns_resolv_ex-DNS req ipv4 0x1f23 'mts-dc03.mts.local'
2024-07-08 08:04:00 [125] fnbamd_dns_resolv_ex-DNS req ipv6 0x3f23 'mts-dc03.mts.local'
2024-07-08 08:04:00 [137] fnbamd_dns_resolv_ex-DNS maintainer started.
2024-07-08 08:04:00 [246] fnbamd_dns_parse_resp-got IPv6 DNS reply, req-id=0x3f23
2024-07-08 08:04:00 [267] fnbamd_dns_parse_resp-req 0x1f23: wrong dns format, qr=1, opcode=0, qdc=1, ancount=0
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to ::, cur stack size:0
2024-07-08 08:04:00 [1160] __fnbamd_ldap_dns_cb-No valid address is found for mts.local:mts-dc03.mts.local
2024-07-08 08:04:00 [246] fnbamd_dns_parse_resp-got IPv4 DNS reply, req-id=0x1f23
2024-07-08 08:04:00 [267] fnbamd_dns_parse_resp-req 0x1f23: wrong dns format, qr=1, opcode=0, qdc=1, ancount=0
2024-07-08 08:04:00 [36] __fnbamd_dns_req_del-DNS req 0x1f23 (0x14353740) is removed. Current total: 2
2024-07-08 08:04:00 [47] __fnbamd_dns_req_del-DNS maintainer stopped.
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to 0.0.0.0, cur stack size:0
2024-07-08 08:04:00 [1160] __fnbamd_ldap_dns_cb-No valid address is found for mts.local:mts-dc03.mts.local
2024-07-08 08:04:00 [902] __ldap_try_next_server-No more server to try for 'mts.local'.
2024-07-08 08:04:00 [217] fnbamd_comm_send_result-Sending result 3 (nid 0) for req 1376421611, len=2124
2024-07-08 08:04:00 [752] destroy_auth_session-delete session 1376421611
2024-07-08 08:04:00 [26721:root:2a]fam_auth_proc_resp:1287 fnbam_auth_update_result return: 3
2024-07-08 08:04:00 [26721:root:2a][fam_auth_proc_resp:1385] Authenticated groups (1) by FNBAM:
2024-07-08 08:04:00 [26721:root:2a]Received: auth_rsp_data.grp_list[0] = 3054238368 
2024-07-08 08:04:00 [26721:root:2a]login_failed:391 user[max],auth_type=1 failed [sslvpn_login_no_matching_policy]
2024-07-08 08:04:00 [26721:root:0]dump_one_blocklist:85 status=1;host=77.239.xyx.xyx;fails=1;logintime=1720418640
2024-07-08 08:04:07 [26722:root:2a]allocSSLConn:298 sconn 0x7f269001f100 (0:root)
2024-07-08 08:04:07 [26722:root:2a]client cert requirement: no
2024-07-08 08:04:07 [26722:root:2a]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
2024-07-08 08:04:07 [26722:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:07 [26722:root:2a]rmt_web_get_access_cache:808 invalid cache, ret=4103
2024-07-08 08:04:07 [26722:root:2a]User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.5060.53 Safari/537.36 Edg/103.0.1264.37
2024-07-08 08:04:07 [26722:root:2a]get_cust_page:127 saml_info 0
2024-07-08 08:04:07 [26722:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:07 [26722:root:2a]rmt_web_access_check:727 access failed, uri=[/remote/logincheck],ret=4103,
2024-07-08 08:04:07 [26722:root:2a]User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36 Edg/91.0.864.54
2024-07-08 08:04:07 [26722:root:2a]sslvpn_auth_check_usrgroup:2719 forming user/group list from policy.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_auth_check_usrgroup:2757 got user (0) group (4:0).
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1843 validating with SSL VPN authentication rules (4), realm ().
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1928 checking rule 2 cipher.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1936 checking rule 2 realm.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1928 checking rule 3 cipher.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1936 checking rule 3 realm.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1928 checking rule 4 cipher.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1936 checking rule 4 realm.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1928 checking rule 5 cipher.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:1936 checking rule 5 realm.
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:2275 got user (0:0) group (0:0) peer group (0).
2024-07-08 08:04:07 [26722:root:2a]sslvpn_validate_user_group_list:2618 got user (0:0), group (0:0) peer group (0).
2024-07-08 08:04:07 [26722:root:2a]sslvpn_update_user_group_list:1750 got user (0:0), group (0:0), peer group (0) after update.
2024-07-08 08:04:07 [26722:root:2a]no valid user or group candidate found.
2024-07-08 08:04:07 [26722:root:2a]login_failed:391 user[administrator],auth_type=32768 failed [sslvpn_login_unknown_user]
2024-07-08 08:04:07 [26722:root:0]dump_one_blocklist:85 status=1;host=46.8.155.242;fails=1;logintime=1720418647
2024-07-08 08:04:07 [26722:root:2a]sslvpn_read_request_common,663, ret=-1 error=-1, sconn=0x7f269001f100.
2024-07-08 08:04:07 [26722:root:2a]Destroy sconn 0x7f269001f100, connSize=0. (root)
2024-07-08 08:04:14 [26723:root:2a]allocSSLConn:298 sconn 0x7f269001f100 (0:root)
2024-07-08 08:04:14 [26723:root:2a]SSL_accept failed, 5:(null)
2024-07-08 08:04:14 [26723:root:2a]Destroy sconn 0x7f269001f100, connSize=0. (root)
2024-07-08 08:04:14 [26724:root:2a]allocSSLConn:298 sconn 0x7f269001f100 (0:root)
2024-07-08 08:04:14 [26724:root:2a]got SNI server name: sslvpn.url.com realm (null)
2024-07-08 08:04:14 [26724:root:2a]client cert requirement: no
2024-07-08 08:04:14 [26724:root:2a]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
2024-07-08 08:04:15 [26724:root:2a]capability flags: 0xdf
2024-07-08 08:04:15 [26724:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:15 [26724:root:2a]rmt_web_get_access_cache:808 invalid cache, ret=4103
2024-07-08 08:04:15 [26724:root:2a]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
2024-07-08 08:04:15 [26724:root:2a]get_cust_page:127 saml_info 0
2024-07-08 08:04:15 [26724:root:2a]rmt_web_auth_info_parser_common:465 no session id in auth info
2024-07-08 08:04:15 [26724:root:2a]rmt_web_access_check:727 access failed, uri=[/remote/logincheck],ret=4103,
2024-07-08 08:04:15 [26724:root:2a]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}])
2024-07-08 08:04:15 [26724:root:2a]rmt_logincheck_cb_handler:1255 user 'kaeser' has a matched local entry.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_auth_check_usrgroup:2719 forming user/group list from policy.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_auth_check_usrgroup:2757 got user (0) group (4:0).
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1843 validating with SSL VPN authentication rules (4), realm (mts).
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1928 checking rule 2 cipher.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1936 checking rule 2 realm.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1947 checking rule 2 source intf.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1986 checking rule 2 vd source intf.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:2267 rule 2 done, got user (0:0) group (1:0) peer group (0).
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1928 checking rule 3 cipher.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1936 checking rule 3 realm.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1928 checking rule 4 cipher.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1936 checking rule 4 realm.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1928 checking rule 5 cipher.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:1936 checking rule 5 realm.
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:2275 got user (0:0) group (1:0) peer group (0).
2024-07-08 08:04:15 [26724:root:2a]sslvpn_validate_user_group_list:2618 got user (0:0), group (1:0) peer group (0).
2024-07-08 08:04:15 [26724:root:2a]sslvpn_update_user_group_list:1750 got user (0:0), group (1:0), peer group (0) after update.
2024-07-08 08:04:15 [26724:root:2a]two factor check for kaeser: off
2024-07-08 08:04:15 [26724:root:2a]sslvpn_authenticate_user:167 authenticate user: [kaeser]
2024-07-08 08:04:15 [26724:root:2a]sslvpn_authenticate_user:174 create fam state
2024-07-08 08:04:15 [26724:root:2a][fam_auth_send_req_internal:425] Groups sent to FNBAM:
2024-07-08 08:04:15 [26724:root:2a]group_desc[0].grpname = ldap_dl-fg-sslvpn-realm-mts 
2024-07-08 08:04:15 [26724:root:2a][fam_auth_send_req_internal:437] FNBAM opt = 0X200420
2024-07-08 08:04:15 [26724:root:2a]fam_auth_send_req_internal:513 fnbam_auth return: 4
2024-07-08 08:04:15 [1901] handle_req-Rcvd auth req 1376421612 for kaeser in opt=00200420 prot=11
2024-07-08 08:04:15 [617] fnbamd_pop3_start-kaeser
2024-07-08 08:04:15 [380] radius_start-Didn't find radius servers (0)
2024-07-08 08:04:15 [752] auth_tac_plus_start-Didn't find tac_plus servers (0)
2024-07-08 08:04:15 [2151] __match_and_update_auth_user-Found a matching user in CMDB 'kaeser'
2024-07-08 08:04:15 [1053] __fnbamd_cfg_get_ldap_list_by_group-Loaded LDAP server 'mts.local' for user 'kaeser' in rgroup 'ldap_dl-fg-sslvpn-realm-mts' (3)
2024-07-08 08:04:15 [1131] fnbamd_cfg_get_ldap_list-Total ldap servers to try: 1
2024-07-08 08:04:15 [1713] fnbamd_ldap_init-search filter is: sAMAccountName=kaeser
2024-07-08 08:04:15 [1722] fnbamd_ldap_init-search base is: ou=mts,dc=mts,dc=local
2024-07-08 08:04:15 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:10.9.9.12 to 10.9.9.12, cur stack size:1
2024-07-08 08:04:15 [1152] __fnbamd_ldap_dns_cb-Connection starts mts.local:10.9.9.12, addr 10.9.9.12 over SSL
2024-07-08 08:04:15 [874] __fnbamd_ldap_start_conn-Still connecting 10.9.9.12.
2024-07-08 08:04:15 [596] create_auth_session-Total 1 server(s) to try
2024-07-08 08:04:15 [907] __ldap_try_next_server-Try next server 'mts-dc03.mts.local' for 'mts.local'.
2024-07-08 08:04:15 [115] fnbamd_dns_resolv_ex-DNS req ipv4 0x1f24 'mts-dc03.mts.local'
2024-07-08 08:04:15 [125] fnbamd_dns_resolv_ex-DNS req ipv6 0x3f24 'mts-dc03.mts.local'
2024-07-08 08:04:15 [137] fnbamd_dns_resolv_ex-DNS maintainer started.
2024-07-08 08:04:15 [246] fnbamd_dns_parse_resp-got IPv4 DNS reply, req-id=0x1f24
2024-07-08 08:04:15 [305] fnbamd_dns_parse_resp-req 0x1f24: 10.9.9.13
2024-07-08 08:04:15 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to 10.9.9.13, cur stack size:1
2024-07-08 08:04:15 [1152] __fnbamd_ldap_dns_cb-Connection starts mts.local:mts-dc03.mts.local, addr 10.9.9.13 over SSL
2024-07-08 08:04:15 [874] __fnbamd_ldap_start_conn-Still connecting 10.9.9.13.
2024-07-08 08:04:15 [246] fnbamd_dns_parse_resp-got IPv6 DNS reply, req-id=0x3f24
2024-07-08 08:04:15 [267] fnbamd_dns_parse_resp-req 0x1f24: wrong dns format, qr=1, opcode=0, qdc=1, ancount=0
2024-07-08 08:04:15 [36] __fnbamd_dns_req_del-DNS req 0x1f24 (0x14353740) is removed. Current total: 2
2024-07-08 08:04:15 [47] __fnbamd_dns_req_del-DNS maintainer stopped.
2024-07-08 08:04:15 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to ::, cur stack size:0
2024-07-08 08:04:15 [1103] __ldap_connect-tcps_connect(10.9.9.13) is established.
2024-07-08 08:04:15 [363] __ldap_build_bind_req-Binding to 'fg-ldap@mts.local'
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 1
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:1, type:bind
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'DN search'
2024-07-08 08:04:15 [751] fnbamd_ldap_build_dn_search_req-base:'ou=mts,dc=mts,dc=local' filter:sAMAccountName=kaeser
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 2
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:2, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1220] __fnbamd_ldap_dn_entry-Get DN 'CN=Simon,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:2, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'User Binding'
2024-07-08 08:04:15 [596] fnbamd_ldap_build_userbind_req-Trying DN 'CN=Simon,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [363] __ldap_build_bind_req-Binding to 'CN=Simon,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 3
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:3, type:bind
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'Attr query'
2024-07-08 08:04:15 [649] fnbamd_ldap_build_attr_search_req-Adding attr 'memberOf'
2024-07-08 08:04:15 [661] fnbamd_ldap_build_attr_search_req-base:'CN=Simon,OU=mts,DC=mts,DC=local' filter:cn=*
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 4
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:4, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [556] __get_member_of_groups-Get the memberOf groups.
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [533] __retrieve_group_values- attr='memberOf', found 8 values
2024-07-08 08:04:15 [542] __retrieve_group_values-val[0]='CN=g-menschen-be,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[1]='CN=g-projekt,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[2]='CN=G_mts-TeamViewer,CN=Users,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[3]='CN=mts-FS-IT,OU=FilesystemGroups,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[4]='CN=CiscoVPN-IT,OU=CiscoVPNGroups,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[5]='CN=mts-Sig-BE-J,OU=FilesystemGroups,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[6]='CN=mts-FS-ALL,OU=FilesystemGroups,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[7]='CN=mts-FS-Informatik,OU=FilesystemGroups,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:4, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1300] __fnbamd_ldap_attr_next-Entering CHKPRIMARYGRP state
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'Primary group query'
2024-07-08 08:04:15 [685] fnbamd_ldap_build_primary_grp_search_req-starting primary group check...
2024-07-08 08:04:15 [689] fnbamd_ldap_build_primary_grp_search_req-number of sub auths 5 
2024-07-08 08:04:15 [707] fnbamd_ldap_build_primary_grp_search_req-base:'ou=mts,dc=mts,dc=local' filter:(&(objectclass=group)(objectSid=\01\05\00\00\00\00\00\05\15\00\00\00\bc\1c\68\ee\bb\82\17\3e\f0\0c\2a\78\01\02\00\00))
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 5
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:5, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'User recursive group query'
2024-07-08 08:04:15 [894] fnbamd_ldap_build_recursive_grp_search_req-base:'ou=mts,dc=mts,dc=local' filter:(&(objectclass=group)(|(distinguishedName=CN=g-menschen-be,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=g-projekt,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=G_mts-TeamViewer,CN=Users,DC=mts,DC=local)(distinguishedName=CN=mts-FS-IT,OU=FilesystemGroups,DC=mts,DC=local)(distinguishedName=CN=CiscoVPN-IT,OU=CiscoVPNGroups,DC=mts,DC=local)(distinguishedName=CN=mts-Sig-BE-J,OU=FilesystemGroups,DC=mts,DC=local)(distinguishedName=CN=mts-FS-ALL,OU=FilesystemGroups,DC=mts,DC=local)(distinguishedName=CN=mts-FS-Informatik,OU=FilesystemGroups,DC=mts,DC=local)))
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 6
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:6, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [533] __retrieve_group_values- attr='memberOf', found 5 values
2024-07-08 08:04:15 [542] __retrieve_group_values-val[0]='CN=dl-wiki-ns-buero_zuerich-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[1]='CN=dl-bitwarden-projekt-rw,OU=Bitwarden,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[2]='CN=g-projekt-pikett,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[3]='CN=dl-wiki-ns-promos-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[4]='CN=dl-wiki-ns-projekt-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:6, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [533] __retrieve_group_values- attr='memberOf', found 3 values
2024-07-08 08:04:15 [542] __retrieve_group_values-val[0]='CN=dl-mts-be-pr01-Zentrale Belp-default,OU=PrinterGroups,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[1]='CN=dl-mts-be-pr01-Zentrale Belp,OU=PrinterGroups,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[2]='CN=g-menschen,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:6, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [375] __ldap_grp_list_need_more_check-Group 'CN=dl-wiki-ns-buero_zuerich-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local' is not checked
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'User recursive group query'
2024-07-08 08:04:15 [894] fnbamd_ldap_build_recursive_grp_search_req-base:'ou=mts,dc=mts,dc=local' filter:(&(objectclass=group)(|(distinguishedName=CN=dl-wiki-ns-buero_zuerich-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-bitwarden-projekt-rw,OU=Bitwarden,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=g-projekt-pikett,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-wiki-ns-promos-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-wiki-ns-projekt-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-mts-be-pr01-Zentrale Belp-default,OU=PrinterGroups,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-mts-be-pr01-Zentrale Belp,OU=PrinterGroups,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=g-menschen,OU=Groups,OU=mts,DC=mts,DC=local)))
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 7
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [533] __retrieve_group_values- attr='memberOf', found 4 values
2024-07-08 08:04:15 [542] __retrieve_group_values-val[0]='CN=dl-opvizor-viewer,OU=Opvizor,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[1]='CN=dl-fg-sslvpn-realm-mts,OU=SSLVPN,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[2]='CN=dl-bitwarden-menschen-rw,OU=Bitwarden,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [542] __retrieve_group_values-val[3]='CN=dl-wiki-ns-playground-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [533] __retrieve_group_values- attr='memberOf', found 1 values
2024-07-08 08:04:15 [542] __retrieve_group_values-val[0]='CN=dl-wiki-ns-pikett-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local'
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:7, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [375] __ldap_grp_list_need_more_check-Group 'CN=dl-opvizor-viewer,OU=Opvizor,OU=Groups,OU=mts,DC=mts,DC=local' is not checked
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'User recursive group query'
2024-07-08 08:04:15 [894] fnbamd_ldap_build_recursive_grp_search_req-base:'ou=mts,dc=mts,dc=local' filter:(&(objectclass=group)(|(distinguishedName=CN=dl-opvizor-viewer,OU=Opvizor,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-fg-sslvpn-realm-mts,OU=SSLVPN,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-bitwarden-menschen-rw,OU=Bitwarden,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-wiki-ns-playground-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local)(distinguishedName=CN=dl-wiki-ns-pikett-rw,OU=DokuWiki,OU=Groups,OU=mts,DC=mts,DC=local)))
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 8
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-entry
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [522] __retrieve_group_values-Get the memberOf groups.
2024-07-08 08:04:15 [527] __retrieve_group_values-attr='memberOf' - found 0 values
2024-07-08 08:04:15 [988] fnbamd_ldap_parse_response-Got one MESSAGE. ID:8, type:search-result
2024-07-08 08:04:15 [1023] fnbamd_ldap_parse_response-ret=0
2024-07-08 08:04:15 [1462] __fnbamd_ldap_recursive_grp_next-Auth accepted
2024-07-08 08:04:15 [1048] __ldap_rxtx-Change state to 'Done'
2024-07-08 08:04:15 [1096] fnbamd_ldap_send-Request is sent. ID 9
2024-07-08 08:04:15 [2737] fnbamd_ldap_result-Result for ldap svr 10.9.9.12(mts.local) is SUCCESS
2024-07-08 08:04:15 [1636] fnbam_user_auth_group_match-req id: 1376421612, server: mts.local, local auth: 0, dn match: 1
2024-07-08 08:04:15 [1592] __group_match-Group 'ldap_dl-fg-sslvpn-realm-mts' passed group matching
2024-07-08 08:04:15 [1595] __group_match-Add matched group 'ldap_dl-fg-sslvpn-realm-mts'(3)
2024-07-08 08:04:15 [2748] fnbamd_ldap_result-Passed group matching
2024-07-08 08:04:15 [217] fnbamd_comm_send_result-Sending result 7 (nid 0) for req 1376421612, len=3433
2024-07-08 08:04:15 [1059] __destroy_session_if_needed-Save matched user/groups in the session
2024-07-08 08:04:15 [26724:root:2a]fam_auth_proc_resp:1287 fnbam_auth_update_result return: 7
2024-07-08 08:04:15 [26724:root:2a][fam_auth_proc_resp:1385] Authenticated groups (1) by FNBAM:
2024-07-08 08:04:15 [26724:root:2a]Received: auth_rsp_data.grp_list[0] = 3 
2024-07-08 08:04:15 [26724:root:2a]fam_auth_proc_resp:1409 found node ldap_dl-fg-sslvpn-realm-mts:0:, valid:1
2024-07-08 08:04:15 [26724:root:2a]Validated: auth_rsp_data.grp_list[0] = ldap_dl-fg-sslvpn-realm-mts 
2024-07-08 08:04:15 [26724:root:2a]Auth requires token
diag debug disable 
FW01 # diagnose test application fnbamd 1 
2024-07-08 08:05:21 Total fnbam requests in caller side: 253141; EAGAIN errors: 0; other errors: 1
2024-07-08 08:05:21 Pending sessions: 0
2024-07-08 08:05:21 Max session reached: 0
2024-07-08 08:05:21 Res 0: 250054
2024-07-08 08:05:21 Res 1: 741
2024-07-08 08:05:21 Res 2: 0
2024-07-08 08:05:21 Res 3: 1679
2024-07-08 08:05:21 Res 4: 0
2024-07-08 08:05:21 Res 5: 190
2024-07-08 08:05:21 Res 6: 0
2024-07-08 08:05:21 Res 7: 4334
2024-07-08 08:05:21 Res 8: 2
2024-07-08 08:05:21 Res 9: 0
2024-07-08 08:05:21 Res 10: 0
2024-07-08 08:05:21 Res 11: 0
2024-07-08 08:05:21 Res 12: 174
2024-07-08 08:05:21 Auth:
2024-07-08 08:05:21 requests: 6671
2024-07-08 08:05:21 sessions: 6671
2024-07-08 08:05:21 released: 6671
2024-07-08 08:05:21 Acct:
2024-07-08 08:05:21 requests: 1
2024-07-08 08:05:21 sessions: 0
2024-07-08 08:05:21 released: 0
2024-07-08 08:05:21 Cert:
2024-07-08 08:05:21 requests: 241963
2024-07-08 08:05:21 sessions: 241963
2024-07-08 08:05:21 released: 241963
2024-07-08 08:05:21 LDAP stats:
2024-07-08 08:05:21 total: 5061
2024-07-08 08:05:21 conn failures: 344

[fricci_FTNT]

Hi @sidp ,

Thank you for attaching the logs. I had a look at them and I can see that the DNS is now getting resolved. I have also seen that the user "max" had the issue but the user "kaeser" was able to login well.

From the logs I can see the following:

2024-07-08 08:04:00 [2151] __match_and_update_auth_user-Found a matching user in CMDB 'max'
2024-07-08 08:04:00 [1053] __fnbamd_cfg_get_ldap_list_by_group-Loaded LDAP server 'mts.local' for user 'max' in rgroup 'ldap_dl-fg-sslvpn-realm-mts' (3)
2024-07-08 08:04:00 [1131] fnbamd_cfg_get_ldap_list-Total ldap servers to try: 1
2024-07-08 08:04:00 [1713] fnbamd_ldap_init-search filter is: sAMAccountName=max
2024-07-08 08:04:00 [1722] fnbamd_ldap_init-search base is: ou=mts,dc=mts,dc=local
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:10.9.9.12 to 10.9.9.12, cur stack size:1
2024-07-08 08:04:00 [1152] __fnbamd_ldap_dns_cb-Connection starts mts.local:10.9.9.12, addr 10.9.9.12 over SSL <==============
2024-07-08 08:04:00 [874] __fnbamd_ldap_start_conn-Still connecting 10.9.9.12.
2024-07-08 08:04:00 [596] create_auth_session-Total 1 server(s) to try
2024-07-08 08:04:00 [907] __ldap_try_next_server-Try next server 'mts-dc03.mts.local' for 'mts.local'.
2024-07-08 08:04:00 [115] fnbamd_dns_resolv_ex-DNS req ipv4 0x1f23 'mts-dc03.mts.local'
2024-07-08 08:04:00 [125] fnbamd_dns_resolv_ex-DNS req ipv6 0x3f23 'mts-dc03.mts.local'
2024-07-08 08:04:00 [137] fnbamd_dns_resolv_ex-DNS maintainer started.
2024-07-08 08:04:00 [246] fnbamd_dns_parse_resp-got IPv6 DNS reply, req-id=0x3f23
2024-07-08 08:04:00 [267] fnbamd_dns_parse_resp-req 0x1f23: wrong dns format, qr=1, opcode=0, qdc=1, ancount=0
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to ::, cur stack size:0
2024-07-08 08:04:00 [1160] __fnbamd_ldap_dns_cb-No valid address is found for mts.local:mts-dc03.mts.local
2024-07-08 08:04:00 [246] fnbamd_dns_parse_resp-got IPv4 DNS reply, req-id=0x1f23
2024-07-08 08:04:00 [267] fnbamd_dns_parse_resp-req 0x1f23: wrong dns format, qr=1, opcode=0, qdc=1, ancount=0
2024-07-08 08:04:00 [36] __fnbamd_dns_req_del-DNS req 0x1f23 (0x14353740) is removed. Current total: 2
2024-07-08 08:04:00 [47] __fnbamd_dns_req_del-DNS maintainer stopped.
2024-07-08 08:04:00 [1146] __fnbamd_ldap_dns_cb-Resolved mts.local:mts-dc03.mts.local to 0.0.0.0, cur stack size:0
2024-07-08 08:04:00 [1160] __fnbamd_ldap_dns_cb-No valid address is found for mts.local:mts-dc03.mts.local
2024-07-08 08:04:00 [902] __ldap_try_next_server-No more server to try for 'mts.local'.
2024-07-08 08:04:00 [217] fnbamd_comm_send_result-Sending result 3 (nid 0) for req 1376421611, len=2124
2024-07-08 08:04:00 [752] destroy_auth_session-delete session 1376421611
2024-07-08 08:04:00 [26721:root:2a]fam_auth_proc_resp:1287 fnbam_auth_update_result return: 3
2024-07-08 08:04:00 [26721:root:2a][fam_auth_proc_resp:1385] Authenticated groups (1) by FNBAM:
2024-07-08 08:04:00 [26721:root:2a]Received: auth_rsp_data.grp_list[0] = 3054238368
2024-07-08 08:04:00 [26721:root:2a]login_failed:391 user[max],auth_type=1 failed [sslvpn_login_no_matching_policy] <================
2024-07-08 08:04:00 [26721:root:0]dump_one_blocklist:85 status=1;host=77.239.xyx.xyx;fails=1;logintime=1720418640 <================
 

 
Could you check if there is an issue on the LDAP server, a packet capture might help.
I would also suggest you to open a ticket with our support for further troubleshooting (you can mention this post link as well) so the assigned engineer can be aware of what we tried already.

You might also try to test increasing the LDAP response timeout, despite I do not think that would resolve the issue:

config sys global

set remoteauthtimeout 15
set ldapconntimeout 5000
end

Best regards,

[FortiNole]

Following along with this one.  We are having the exact same issue.  

[Pittstate]

We had this exact same error occurring under 7.0.14, but I ended up closing out the ticket as the problem was intermittent and was never able to get a good capture. But I will post what FN support last said to do as troubleshooting steps. Some of which has been mentioned.

But one thing you might try is disabling IPv6 on the client side if it is not necessary for your environment. Some documentation I ran across that I can not find now, mentioned there could be an issue with that and the ssl-vpn client under certain circumstances.

Anyway, below is the next step path that FN support was going to have me follow:

"As part of further debug capture, I'll need commands to also capture as much information for the FMDB (diag de app fndbamd ????), does a -1 flag on the end capture all debug info for that process? Also is a -1 flag sufficient to capture all debug info for the sslvpn application?
To obtain the complete logs, we require both FNABN and SSL debugs. Packet capture can also provide valuable information.

# diagnose debug application fnbamd -1
# diagnose vpn ssl debug-filter src-addr4 x.x.x.x ------------->Public IP of the client
# diagnose debug application sslvpn -1
# diagnose debug console timestamp enable
# diagnose debug enable
# diagnose sniffer packet any "host [radius-srv-ip] and port (1812 or 1813)" 6 0 l
# diagnose sniffer packet any "host x.x.x.x and port 443" 6 0 l ------------->Public IP of the client

We can also enable debug login on the forticleint

https://community.fortinet.com/t5/FortiClient/Technical-Tip-How-to-enable-debug-log-in-FortiClient/t...
https://community.fortinet.com/t5/FortiClient/Technical-Tip-How-to-generate-and-export-Debug-logs-fr...

We need to isolate whether the issue is occurring on the FGT or on the FortiClient. Therefore, could you perform the test on SSL VPN web mode and inform us of the results? If the issue lies with FortiClient, we'll need to troubleshoot it from the FortiClient perspective."