no valid user or group candidate found

[Stuart_Kendrick]

Would anyone have a mental model to offer for what the SSL VPN feature is doing when it is 'checking rules'?  I'm trying to spin up an SSL VPN service, using the heavy FortiClient, the client sees "Permission denied".  The relevant output of "diagnose debug application sslvpn -1" looks as follows:

[...]

2020-03-30 09:04:15 [22521:root:2]sslvpn_auth_check_usrgroup:2039 forming user/group list from policy. 2020-03-30 09:04:15 [22521:root:2]sslvpn_auth_check_usrgroup:2145 got user (0) group (1:0). 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1642 validating with SSL VPN authentication rules (1), realm (). 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1690 checking rule 1 cipher. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1698 checking rule 1 realm. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1709 checking rule 1 source intf. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1730 checking rule 1 source address. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1963 got user (0:0), group (0:0) peer group (0). 2020-03-30 09:04:15 [22521:root:2]no valid user or group candidate found.

What is the Firewall doing when it is 'checking rule 1 cipher' ... 'checking rule 1 source address'?

The larger 'diag debug' output looks as follows:

2020-03-30 09:04:15 [22521:root:2]SSL state:SSL negotiation finished successfully (96.93.107.34) 2020-03-30 09:04:15 [22521:root:2]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384 2020-03-30 09:04:15 [22521:root:2]req: /remote/info 2020-03-30 09:04:15 [22521:root:2]req: /remote/login 2020-03-30 09:04:15 [22521:root:2]rmt_web_auth_info_parser_common:470 no session id in auth info 2020-03-30 09:04:15 [22521:root:2]rmt_web_get_access_cache:804 invalid cache, ret=4103 2020-03-30 09:04:15 [22521:root:2]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}]) 2020-03-30 09:04:15 [22521:root:2]get_cust_page:130 saml_info 0 2020-03-30 09:04:15 [22521:root:2]req: /remote/logincheck 2020-03-30 09:04:15 [22521:root:2]rmt_web_auth_info_parser_common:470 no session id in auth info 2020-03-30 09:04:15 [22521:root:2]rmt_web_access_check:723 access failed, uri=[/remote/logincheck],ret=4103, 2020-03-30 09:04:15 [22521:root:2]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}]) 2020-03-30 09:04:15 [22521:root:2]sslvpn_auth_check_usrgroup:2039 forming user/group list from policy. 2020-03-30 09:04:15 [22521:root:2]sslvpn_auth_check_usrgroup:2145 got user (0) group (1:0). 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1642 validating with SSL VPN authentication rules (1), realm (). 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1690 checking rule 1 cipher. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1698 checking rule 1 realm. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1709 checking rule 1 source intf. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1730 checking rule 1 source address. 2020-03-30 09:04:15 [22521:root:2]sslvpn_validate_user_group_list:1963 got user (0:0), group (0:0) peer group (0). 2020-03-30 09:04:15 [22521:root:2]no valid user or group candidate found. 2020-03-30 09:04:15 [22521:root:2]req: /FortiClientSslvpnClearCacheUrl/for/Wini 2020-03-30 09:04:15 [22521:root:2]def: (nil) /FortiClientSslvpnClearCacheUrl/for/WininetLibrary/1/2/3/4/5/6/7/8/9/0/a/b/c/d/e/f/g/h/i/j/k/l/m/n/o/p/q/r/s/t

FortiClient 6.2.6 / FortiOS 6.2.3

--sk

[Toshi_Esumi]

What's configured under "config vpn ssl settings", especially under "config authentication-rule"? It doesn't seem to be able to find a group or members of the group.

[Stuart_Kendrick]

config vpn ssl settings

[...]

    config authentication-rule         edit 1             set source-interface "wan1"             set source-address "FortiVPN-Interface"             set groups "Telecommuter VPN Users"             set portal "Full-Tunnel Service"             set auth ldap         next     end

I see ... you are suggesting that this section of 'diag debug' walks through a number of lines ... I'm not sure where to look for cipher or realm ... but in my case, they seem to 'pass' these checks

==> Do know where this work-flow might be documented?  [Or do I need access to source to document that?  :) ]

Then

checking rule 1 source intf ==== set source-interface 'wan1'

checking rule 1 source address ==== set source-address "FortiVPN-Interface"

got user (0:0), group (0:0) peer group (0) ===== set auth ldap

no valid user or group candidate found.

So ... if I'm following your thinking here ... you are suggesting that 'set auth ldap' doesn't behave the way the Firewall wants

==> How might I increase the verbosity of debugging at this point, to dig deeper into what the Fortigate is doing when it logs the 'got user ...' line?

--sk

[Toshi_Esumi · Accepted solution]

I don't think any public doc explaining how SSL VPN is built to work in the FGT.

Then what's in "config user group" and "edit "Telecommuter VPN Users""? Only one LDAP server is in?

Did you test the LDAP server from the FGT? Is it pingable from the FGT? If it's reachable, you can test with a set of valid <username><password> below:

    diag test authserver ldap "Telecommuter VPN Users" "<username>" "<password>"

If you want to see how the test exchange is happening, you can do below:

    diag debug reset

    diag debug console timestamp enable

    diag debug application fnbamd -1

    diag debug enable

I'm guessing the problem is reachability though.

[Toshi_Esumi]

One error in the CLI for the auth test. It was supposed to be:

   diag test authserver ldap "ldap_servername" "<username>" "<password>"

So, you need to enter the server name, instead of the group name.

[Stuart_Kendrick]

Lots of help from TAC on this one ...

Examining the output of 'diag test authserver ldap', we notice that the group list displayed is incomplete.  And ... we restrict VPN access via membership in an AD group, call it "PermitVPN"

- When the output of 'diag test authserver ldap' includes PermitVPN, the user successfully authenticates via FortiClient

- When the output of 'daig test authserver ldap' does not include PermitVPN, the user fails to authenticate, and "diag debug app sslvpn -1" output displays the "no valid user or group membership" found message

Current speculation is the that 'ldap search' which FortiOS employs truncates the return list after some number of elements / characters.  If I get something more specific, I'll post the result here.

--sk

[Stuart_Kendrick]

diag test authserver ldap "Telecommuter VPN Users" "<username>" "<password>"

- That works fine, as does the GUI version (which I suppose i just invokes ' diag test authserver ldap ... '

- There are (3) LDAP servers inside "Telecommuter VPN Users"; each of them passes the 'diag test authserver ldap' test

And when I run 'diag debug application fnband -1', there isn't any additional output .... until after the 'no valid user or group candidate found' ... which suggests to me that FortiOS doesn't even reach the point of consulting the LDAP server(s)

Here in fact is the 'diag debug' output, with the ensuing 'fnband' lines included

[...]

2020-03-30 11:13:40 [22517:root:5]sslvpn_validate_user_group_list:1690 checking rule 1 cipher. 2020-03-30 11:13:40 [22517:root:5]sslvpn_validate_user_group_list:1698 checking rule 1 realm. 2020-03-30 11:13:40 [22517:root:5]sslvpn_validate_user_group_list:1709 checking rule 1 source intf. 2020-03-30 11:13:40 [22517:root:5]sslvpn_validate_user_group_list:1730 checking rule 1 source address. 2020-03-30 11:13:40 [22517:root:5]sslvpn_validate_user_group_list:1963 got user (0:0), group (0:0) peer group (0). 2020-03-30 11:13:40 [22517:root:5]no valid user or group candidate found. 2020-03-30 11:13:40 [22523:root:4]sslvpn_read_request_common,648, ret=-1 error=-1, sconn=0x7f75d2c86600. 2020-03-30 11:13:40 [22523:root:4]Destroy sconn 0x7f75d2c86600, connSize=0. (root) 2020-03-30 11:13:40 [22518:root:5]allocSSLConn:289 sconn 0x7f75d2c86600 (0:root) 2020-03-30 11:13:40 [22518:root:5]SSL state:before SSL initialization (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:before SSL initialization (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]got SNI server name: vpn-new.alleninstitute.org realm (null) 2020-03-30 11:13:40 [22518:root:5]client cert requirement: no 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS read client hello (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write server hello (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write certificate (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write key exchange (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write server done (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write server done:system lib(96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write server done (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS read client key exchange (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS read change cipher spec (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS read finished (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write session ticket (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write change cipher spec (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSLv3/TLS write finished (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL state:SSL negotiation finished successfully (96.93.107.34) 2020-03-30 11:13:40 [22518:root:5]SSL established: TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384 2020-03-30 11:13:40 [22518:root:5]req: /FortiClientSslvpnClearCacheUrl/for/Wini 2020-03-30 11:13:40 [22518:root:5]def: (nil) /FortiClientSslvpnClearCacheUrl/for/WininetLibrary/1/2/3/4/5/6/7/8/9/0/a/b/c/d/e/f/g/h/i/j/k/l/m/n/o/p/q/r/s/t 2020-03-30 11:13:41 [2761] handle_req-Rcvd auth_cert req id=67190, len=1050 2020-03-30 11:13:41 [1213] __fnbamd_load_certs_from_req-4 cert(s) in req. 2020-03-30 11:13:41 [1241] __fnbamd_build_cert_chain-4 cert(s) after re-org. 2020-03-30 11:13:41 [3191] fnbamd_ca_chain_issuer_info-check local CA cache 2020-03-30 11:13:41 [3243] fnbamd_ca_chain_build-check local CA cache 2020-03-30 11:13:41 [1249] __fnbamd_build_cert_chain-5 cert(s) after local cache search. 2020-03-30 11:13:41 [1250] __fnbamd_build_cert_chain-Chain is complete. 2020-03-30 11:13:41 [817] __fnbamd_cert_verify-Following cert chain depth 0 2020-03-30 11:13:41 [817] __fnbamd_cert_verify-Following cert chain depth 1 2020-03-30 11:13:41 [886] __fnbamd_cert_verify-Trusted CA found: Amazon_Root_CA_1 2020-03-30 11:13:41 [817] __fnbamd_cert_verify-Following cert chain depth 2 2020-03-30 11:13:41 [886] __fnbamd_cert_verify-Trusted CA found: Starfield_Services_Root_Certificate_Authority_-_G2 2020-03-30 11:13:41 [817] __fnbamd_cert_verify-Following cert chain depth 3 2020-03-30 11:13:41 [886] __fnbamd_cert_verify-Trusted CA found: Starfield_Class_2_CA 2020-03-30 11:13:41 [817] __fnbamd_cert_verify-Following cert chain depth 4 2020-03-30 11:13:41 [1749] cert_check_group_list-checking group type 6 group name '' 2020-03-30 11:13:41 [1882] fnbamd_auth_cert_check_status-res=4 2020-03-30 11:13:41 [1910] fnbamd_auth_cert_check_status-match any specified, treat as succeed 2020-03-30 11:13:41 [181] fnbamd_comm_send_result-Sending result 0 (error 0, nid 672) for req 67190 2020-03-30 11:13:44 [2761] handle_req-Rcvd auth_cert req id=67860, len=1050 2020-03-30 11:13:44 [1213] __fnbamd_load_certs_from_req-3 cert(s) in req. 2020-03-30 11:13:44 [1241] __fnbamd_build_cert_chain-3 cert(s) after re-org. 2020-03-30 11:13:44 [3191] fnbamd_ca_chain_issuer_info-check local CA cache 2020-03-30 11:13:44 [1243] __fnbamd_build_cert_chain-Chain is complete. 2020-03-30 11:13:44 [817] __fnbamd_cert_verify-Following cert chain depth 0 2020-03-30 11:13:44 [817] __fnbamd_cert_verify-Following cert chain depth 1 2020-03-30 11:13:44 [886] __fnbamd_cert_verify-Trusted CA found: DigiCert_Global_Root_CA 2020-03-30 11:13:44 [817] __fnbamd_cert_verify-Following cert chain depth 2 2020-03-30 11:13:44 [1749] cert_check_group_list-checking group type 6 group name '' 2020-03-30 11:13:44 [1882] fnbamd_auth_cert_check_status-res=4 2020-03-30 11:13:44 [1910] fnbamd_auth_cert_check_status-match any specified, treat as succeed 2020-03-30 11:13:44 [181] fnbamd_comm_send_result-Sending result 0 (error 0, nid 672) for req 67860 diag debug dis

--sk

[Toshi_Esumi]

I think something to do with certificate you're using, but I don't use cert and don't use LDAP, and don't use 6.2 yet so I can't determine what might be causing the auth failure. I'll suggest waiting for somebody else to look into, or open a ticket at TAC.

I would just make sure with a static user configured on the FGT and put it in the same group with those LDAP servers. So that you can verify the rest of SSL VPN config is good and working.

[Stuart_Kendrick]

I started a TAC ticket last week ... :)

Thanx for the idea to experiment with a local user; I had forgotten to do that.

LOCAL USER

ice-a-fw $ diag test authserver local "AD-Telecommuter VPN Users" testvpn secret authenticate user 'testvpn' in group 'AD-Telecommuter VPN Users' succeeded

And in fact, when I authenticate using FortiClient and the local 'testvpn' account, I succeed.

LDAP USER

ice-a-fw$ diagnose test authserver ldap dc1 ldapuser secret authenticate 'ldapuser' against 'dc1' succeeded! Group membership(s) - CN=xxx,OU=Distribution Lists,OU=Groups,DC=ciompany,DC=com

[...]

But when I authenticate using FortiClient, I fail:

2020-04-03 13:24:05 [22522:root:5d]req: /remote/logincheck 2020-04-03 13:24:05 [22522:root:5d]rmt_web_auth_info_parser_common:470 no session id in auth info 2020-04-03 13:24:05 [22522:root:5d]rmt_web_access_check:723 access failed, uri=[/remote/logincheck],ret=4103, 2020-04-03 13:24:05 [22522:root:5d]User Agent: FortiSSLVPN (Windows NT; SV1 [SV{v=02.01; f=07;}]) 2020-04-03 13:24:05 [22522:root:5d]sslvpn_auth_check_usrgroup:2039 forming user/group list from policy. 2020-04-03 13:24:05 [22522:root:5d]sslvpn_auth_check_usrgroup:2145 got user (0) group (1:0). 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1642 validating with SSL VPN authentication rules (1), realm (). 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1690 checking rule 1 cipher. 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1698 checking rule 1 realm. 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1709 checking rule 1 source intf. 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1730 checking rule 1 source address. 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1845 rule 1 done, got user (0:0) group (0:0) peer group (0). 2020-04-03 13:24:05 [22522:root:5d]sslvpn_validate_user_group_list:1963 got user (0:0), group (1:0) peer group (0). 2020-04-03 13:24:05 [22522:root:5d]two factor check for stuartk: off 2020-04-03 13:24:05 [22522:root:5d]sslvpn_authenticate_user:191 authenticate user: [ldapuser] 2020-04-03 13:24:05 [22522:root:5d]sslvpn_authenticate_user:198 create fam state 2020-04-03 13:24:05 [22522:root:5d]fam_auth_send_req:583 with server blacklist: 2020-04-03 13:24:05 [22522:root:5d]fam_auth_send_req:711 task finished with 5 2020-04-03 13:24:05 [22522:root:5d]login_failed:384 user[ldapuser],auth_type=0 failed [sslvpn_login_unknown_user]

CONFIG FILE

config user group     edit "AD-Telecommuter VPN Users"         set member "dc1" "dc2" "dc3" "testvpn"         config match             edit 1                 set server-name "dc1"                 set group-name "CN=RASUsers,OU=Groups,DC=company,DC=com"             next             edit 2                 set server-name "dc2"                 set group-name "CN=RASUsers,OU=Groups,DC=company,DC=com"             next             edit 3                 set server-name "dc3"                 set group-name "CN=RASUsers,OU=Groups,DC=company,DC=com"             next         end     next end

config vpn ssl settings     set ssl-min-proto-ver tls1-1     set servercert "Fancy Verified Cert"     set idle-timeout 3600     set auth-timeout 57600     set tunnel-ip-pools "FortiVPN-Client-Range"     set dns-server1 a.b.c.d     set dns-server2 e.f.g.h     set port 443     set source-interface "port33"     set source-address "all"     set default-portal "Corporate Full-Tunnel Service"     config authentication-rule         edit 1             set source-interface "port33"             set source-address "all"             set groups "AD-Telecommuter VPN Users"             set portal "Corporate Full-Tunnel Service"             set auth ldap         next     end end

I am puzzled by two aspects of this:

(1) diagnose debug application sslvpn -1

I see the failed authentication message (that last line above), using 'diag deb app sslvpn' ... whereas I would have predicted that I would see authentication failure messages in 'diag debug app fnbamd' ... but I don't ... 'diag debug app fnbamd' gives me lots of talk about certificate chains, but nothing that I recognize around authentication -- certainly no mention of 'ldapuser'  But I thought that fnbamd was the daemon handing Remote Authentication ... what am I missing here?

(2) That 'set auth ldap' line puzzles ... I've tried setting it to 'set auth local' as well .. no change in the 'diag debug app sslvpn' output.  Seems to me that the 'set auth ldap|local' line is irrelevant ... what really matters is the 'set groups' line ... that group determines the authentication sources (could be a mix of local & remote auth, as in fact it is for me).  Perhaps 'set auth ldap|local' is only relevant if one is specifying 'set users' as well, inside the 'config authentication-rule' stanza

--sk