Troubleshooting Tip: Troubleshoot FSSO for SSL-VPN users (FSSO CA is acting as syslog server)

[tthrilok]

Description

This article explains the basic troubleshooting steps when 'Fortinet Single Sign On (FSSO) for SSL-VPN users' using syslog is not working.

Scope

FortiGate, FSSO.

Solution

• Once the configuration is done, there are chances that the user info will not be visible on the FortiGate from FSSO CA when SSL VPN users are connected.

1.  First, check if the firewall is generating the logs and forwarding them to the FSSO CA which is acting as a Syslog server. it is possible to check using a sniffer on the firewall and connecting the user to SSL VPN:
   
   di sniffer packet any 'host x.x.x.x and port 514' 4 0 a <----- x.x.x.x is the IP address of the FSSO CA server.

     2. If the firewall is not visible forwarding the log on port 514 to FSSO CA server, make sure the log filter is configured correctly:

config log syslogd filter

    config free-style
        edit 1
            set category event
            set filter "((logid 0101039947) or (logid 0101039948) or (logid 0101039949))"
        next
    end
end

• Make sure the logids are the same and the filter is the same.

     3. Once the firewall forwards the logs, make sure to receive the logs on the FSSO CA server, validate using Wireshark.

•  If the logs are not visible in Wireshark on UDP 514 from the firewall IP on the server, make sure that UDP 514 is whitelisted on the firewalls in between.

     4. Once the logs are visible on the CA Wireshark, it means the server is receiving the logs, now it is necessary to validate the collector agent debug logs.

From GUI, go to FSSO Agent -> Logging and set the Log level to Debug. 

• Once the Debug level is set, connect the user to SSL VPN again, and then take 'View Log'.

• Below are some use case logs from lab FSSO CA:

Username field misconfigured:

08/17/2023 10:28:09 [ 5032] Received syslog: <190>date=2023-08-17 time=11:28:18 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692251898176400908 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300470 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established", from:10.14.4.174   <<<<<< this log explains that CA have received the log from the firewall with IP 10.14.4.174.
08/17/2023 10:28:09 [ 5032] Try to parse log message:
<190>date=2023-08-17 time=11:28:18 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692251898176400908 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300470 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established"
08/17/2023 10:28:09 [ 5032] Extracted IP based on 'tunnelip={{:client_ip}} ': 10.212.134.200 <<<<< CA have extracted the tunnel IP of the client from the log
08/17/2023 10:28:09 [ 5032] Failed to extract user based on 'user=?{{:username}}?' <<<<< CA is unable to extract the username from the log, this happens when the "Username Field" wrong configuration done in the FSSO syslog rules.
08/17/2023 10:28:09 [ 5032] Cannot parse log message to get username
08/17/2023 10:28:09 [ 5032] Failed to parse log, error:-5
08/17/2023 10:28:09 [ 1808] check the cache to send logon events
08/17/2023 10:28:09 [ 1808] No new LOGON_EVENT to send
08/17/2023 10:28:09 [ 1808] No new LOGON_EVENT to send

In the FSSO, go to Advanced Settings -> Syslog Source List -> Manage Rule -> Edit -> Username Field: should be user="{{:user}}".

• Validate the above correctly:

LDAP server probe failed from CA to LDAP server for group query:

08/20/2023 12:29:30 [ 5224] Received syslog: <190>date=2023-08-20 time=13:29:39 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692518378892203111 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300476 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established", from:10.14.4.174 <----- This log explains that CA have received the log from the firewall with IP 10.14.4.174.
08/20/2023 12:29:30 [ 5224] Try to parse log message:
<190>date=2023-08-20 time=13:29:39 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692518378892203111 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300476 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established"
08/20/2023 12:29:30 [ 5224] Extracted IP based on 'tunnelip={{:client_ip}} ': 10.212.134.200 <----- CA have extracted the tunnel IP of the client from the log.
08/20/2023 12:29:30 [ 5224] Extracted user based on 'user="{{:user}}"': test  <<<<< CA have extracted the username of the client from the log
08/20/2023 12:29:30 [ 5224] Login from '10.212.134.200' (IPv6=''), user 'test', group ''
08/20/2023 12:29:30 [ 5224] Bytes received from DC agent(87608): 429 dcagent IP: 10.14.4.174, MT=00400000
08/20/2023 12:29:30 [ 5224] dcagent packet: add to queue, called:87608, current:0
08/20/2023 12:29:30 [ 6308] process_dcagent_events called by worker:112
08/20/2023 12:29:30 [ 6308] dcagent packet: removed from queue, called:87608 remain:0
08/20/2023 12:29:30 [ 6308] get dcagent event from processing queue by worker:112
08/20/2023 12:29:30 [ 6308] [D][Comm]W=112, PDE:HDE(000001B8C06DD430, 10.14.4.174, 429) <-----
08/20/2023 12:29:30 [ 6308] dcagent packet: processed:87608
08/20/2023 12:29:30 [ 6308] logon event(87608): len:69 monitorType:4194304 dc_ip:10.14.4.174 time:1692514770 len:26 data:10.212.134.200/SYSLOG/test ip:0.0.0.0 
08/20/2023 12:29:30 [ 6308] resolve_ip_internal: workstation:10.212.134.200 [10.212.134.200:0.0.0.0] time:0 
08/20/2023 12:29:30 [ 6308] ldaplib::ldap_bind_s failed, server:10.14.3.113 error code:0x31. <----- LDAP bind failed from CA to the server.
08/20/2023 12:29:30 [ 6308] ldaplib::search_s(), no connection to server, try reconnect... <----- No connection to server, hence CA is retrying to connect to the server.
08/20/2023 12:29:30 [ 6308] ldaplib::ldap_bind_s failed, server:10.14.3.113 error code:0x31.
08/20/2023 12:29:30 [ 6308] user test not found in the directory. <<<<<<< Collector agent could not fetch the groupinfo.
08/20/2023 12:29:30 [ 6308] ad_user_get_groups_str2_s():<NONE>

• Above error can pop up for couple of reasons:

1. When the CA is not able to reach the LDAP server (this happens when CA is on a different server and AD is a different server):

•  Validate the reachability like ICMP, and then the port 389 or 636 reachability whichever way it is configured.
•  If no reachability or port communication issues, validate if there are any firewalls in between the CA and LDAP server. If so, whitelist the required communication.

     2. There is reachability and port communication, but still, if the error above appears, it could be because of the password mismatch for the admin used for the bind request. It is possible to validate the above using:

Go to FSSO agent -> Advanced Settings -> Syslog Source List -> Manage LDAP Server, select the LDAP server, and validate that the username is correct, if so, reenter the correct password again and test.

     3. Sometimes, it is possible to have called the wrong LDAP server for the FortiGate where the logs have been received from:

From GUI go to FSSO agent -> Advanced Settings -> Syslog Source List, select the firewall -> Edit -> User Type -> Remote User, select the correct LDAP server configured on the CA for this firewall.

• A successful user login and FSSO log look like below:
  
  08/17/2023 10:33:56 [ 7268] Received syslog: <190>date=2023-08-17 time=11:34:05 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692252245503575478 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300472 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established", from:10.14.4.174
  08/17/2023 10:33:56 [ 7268] Try to parse log message:
  <190>date=2023-08-17 time=11:34:05 devname="FortiGate-81E" devid="FGT81E4Q17000242" eventtime=1692252245503575478 tz="+0530" logid="0101039947" type="event" subtype="vpn" level="information" vd="root" logdesc="SSL VPN tunnel up" action="tunnel-up" tunneltype="ssl-tunnel" tunnelid=285300472 remip=10.5.23.138 tunnelip=10.212.134.200 user="test" group="test" dst_host="N/A" reason="tunnel established" msg="SSL tunnel established"
  08/17/2023 10:33:56 [ 7268] Extracted IP based on 'tunnelip={{:client_ip}} ': 10.212.134.200 <----- CA has extracted the tunnel IP of the client from the log.
  08/17/2023 10:33:56 [ 7268] Extracted user based on 'user="{{:user}}"': test  <----- CA have extracted the username of the client from the log.
  08/17/2023 10:33:56 [ 7268] Login from '10.212.134.200' (IPv6=''), user 'test', group ''
  08/17/2023 10:33:56 [ 7268] Bytes received from DC agent(11): 429 dcagent IP: 10.14.4.174, MT=00400000
  08/17/2023 10:33:56 [ 7268] dcagent packet: add to queue, called:11, current:0
  08/17/2023 10:33:56 [ 7608] logon event(11): len:69 monitorType:4194304 dc_ip:10.14.4.174 time:1692248636 len:26 data:10.212.134.200/SYSLOG/test ip:0.0.0.0
  08/17/2023 10:33:56 [ 7608] resolve_ip_internal: workstation:10.212.134.200 [10.212.134.200:0.0.0.0] time:0
  08/17/2023 10:33:56 [ 7608] ldaplib::ldap_bind_s succeeded <----- Connection to LDAP server is successful, and bind request sent.
  08/17/2023 10:33:56 [ 7608] ldaplib::ldap_search_s, the number of entries: 1
  08/17/2023 10:33:56 [ 7608] DN:CN=test,CN=Users,DC=example,DC=com 
  08/17/2023 10:33:56 [ 7608] Found 'test' in LDAP search: CN=test,CN=Users,DC=example,DC=com 
  08/17/2023 10:33:56 [ 7608] primarygroupID:S-1-5-21-1137974602-3057445812-1867554962-513 <----- Primary group query is forwarded to LDAP.
  08/17/2023 10:33:56 [ 7608] ldaplib::ldap_search_s, the number of entries: 1
  08/17/2023 10:33:56 [ 7608] DN:CN=Domain Users,CN=Users,DC=example,DC=com
  08/17/2023 10:33:56 [ 7608] check member for group: CN=Domain Users,CN=Users,DC=example,DC=com <----- User is part of group Domain Users.
  08/17/2023 10:33:56 [ 7608] member:CN=Users,CN=Builtin,DC=example,DC=com  
  08/17/2023 10:33:56 [ 7608] check member for group: CN=Users,CN=Builtin,DC=example,DC=com
  08/17/2023 10:33:56 [ 7608] ad_user_get_groups_str2_s():CN=test,CN=Users,DC=example,DC=com+CN=Users,DC=example,DC=com+CN=Domain Users,CN=Users,DC=example,DC=com+CN=Users,CN=Builtin,DC=example,DC=com
  08/17/2023 10:33:56 [ 7608] [D][LCache]CCandA:cache_find(10.212.134.200)-->
  08/17/2023 10:33:56 [ 7608] ip_table_find, ip:10.212.134.200 name:
  08/17/2023 10:33:56 [ 7608] [D][LCache]CCandA:cache_find(10.212.134.200): r=NULL
  08/17/2023 10:33:56 [ 7608] add_ip_table, name:10.212.134.200 index:10.212.134.200, ip:c886d40a 00000000
  08/17/2023 10:33:56 [ 7608] new logon, workstation:10.212.134.200 ip:10.212.134.200::: added 
  08/17/2023 10:33:56 [ 7608] [D][Comm]W=021, PDE:HDE(000001AE0D0FABB0, 0xB42FF6C0, 429): r=0, e=0
  08/17/2023 10:33:56 [ 7608] process_dcagent_events returned by worker:21, processed:1
  08/17/2023 10:33:56 [ 7156] check the cache to send logon events
  08/17/2023 10:33:56 [ 7156] send LOGON_EVENT, sock:1740 len:164 SN:FGT81E4Q17000242-root <----- FSSO logon event sent to the firewall.
  08/17/2023 10:33:56 [ 7156] send_to_FGT() called:sock:1740 sendbuf:db2ea20 sendlen:164

Note:

If the above is validated and still seeing the issue, open a ticket with TAC.