|
The FortiAuthenticator debug log:
The same log keeps coming every 10 seconds. The RADIUS authentication requests looping is sent from the FortiGate (RADIUS Client) repeatedly, IP address of 172.20.110.33 is the FortiGate.
2020-09-10T15:45:15.198354+08:00 FortiAuthenticator radiusd[840]: ===>NAS IP:172.20.110.33
2020-09-10T15:45:15.198360+08:00 FortiAuthenticator radiusd[840]: ===>Username:aceraeb
2020-09-10T15:45:15.198365+08:00 FortiAuthenticator radiusd[840]: ===>Timestamp:1599723915.198110, age:0ms
2020-09-10T15:45:15.198372+08:00 FortiAuthenticator radiusd[840]: Found NAS from preloaded collections for 172.20.110.33: FGVM (172.20.110.33)
2020-09-10T15:45:15.199042+08:00 FortiAuthenticator radiusd[840]: Found NAS profile for client, NAS: 172.20.110.33 profile: Default
2020-09-10T15:45:15.199382+08:00 FortiAuthenticator radiusd[840]: Setting 'Auth-Type := FACAUTH'
2020-09-10T15:45:15.199394+08:00 FortiAuthenticator radiusd[840]: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
2020-09-10T15:45:15.199400+08:00 FortiAuthenticator radiusd[840]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2020-09-10T15:45:15.199406+08:00 FortiAuthenticator radiusd[840]: This is a response to Access-Challenge
2020-09-10T15:45:15.199411+08:00 FortiAuthenticator radiusd[840]: ERROR: partial auth user not found
2020-09-10T15:45:15.199424+08:00 FortiAuthenticator radiusd[840]: Updated auth log 'aceraeb': user authentication error: user not partially authenticated
...
2020-09-10T15:45:21.199947+08:00 FortiAuthenticator radiusd[840]: Ready to process requests.
2020-09-10T15:45:25.218347+08:00 FortiAuthenticator radiusd[840]: # Executing section authorize from file /usr/etc/raddb/sites-enabled/default
2020-09-10T15:45:25.218367+08:00 FortiAuthenticator radiusd[840]: ===>NAS IP:172.20.110.33
2020-09-10T15:45:25.218373+08:00 FortiAuthenticator radiusd[840]: ===>Username:aceraeb
2020-09-10T15:45:25.218379+08:00 FortiAuthenticator radiusd[840]: ===>Timestamp:1599723925.218100, age:0ms
2020-09-10T15:45:25.218385+08:00 FortiAuthenticator radiusd[840]: Found NAS from preloaded collections for 172.20.110.33: FGVM (172.20.110.33)
2020-09-10T15:45:25.219135+08:00 FortiAuthenticator radiusd[840]: Found NAS profile for client, NAS: 172.20.110.33 profile: Default
2020-09-10T15:45:25.219489+08:00 FortiAuthenticator radiusd[840]: Setting 'Auth-Type := FACAUTH'
2020-09-10T15:45:25.219501+08:00 FortiAuthenticator radiusd[840]: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
2020-09-10T15:45:25.219507+08:00 FortiAuthenticator radiusd[840]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2020-09-10T15:45:25.219513+08:00 FortiAuthenticator radiusd[840]: This is a response to Access-Challenge
2020-09-10T15:45:25.219518+08:00 FortiAuthenticator radiusd[840]: ERROR: partial auth user not found
2020-09-10T15:45:25.219532+08:00 FortiAuthenticator radiusd[840]: Updated auth log 'aceraeb': user authentication error: user not partially authenticated
The debug log continuously appears on FortiGate/FortiAuthenticator.
FortiGate:
# diag debug application sslvpn -1
# diag debug application fnbamd -1
# diag debug enable
[1280] __fnbamd_rad_send-Sent radius req to server 'FAC': fd=13, IP=172.20.110.34(172.20.110.34:1812) code=1 id=33 len=126 user="aceraeb" using PAP
[62] handle_rad_timeout-Timer of rad 'FAC' is added
[46] handle_rad_timeout-rad 'FAC' 172.20.110.34 timed out, resend request.
[1280] __fnbamd_rad_send-Sent radius req to server 'FAC': fd=13, IP=172.20.110.34(172.20.110.34:1812) code=1 id=33 len=126 user="aceraeb" using PAP
[62] handle_rad_timeout-Timer of rad 'FAC' is added
FortiAuthenticator:
Logging -> Log Access -> Logs -> Debug Report (button).
FortiAuthenticator radiusd[840]: ===>NAS IP:172.20.110.33
FortiAuthenticator radiusd[840]: ===>Username:aceraeb
FortiAuthenticator radiusd[840]: ===>Timestamp:1599723915.198110, age:0ms
FortiAuthenticator radiusd[840]: Found NAS from preloaded collections for 172.20.110.33: FGVM (172.20.110.33)
FortiAuthenticator radiusd[840]: Found NAS profile for client, NAS: 172.20.110.33 profile: Default
FortiAuthenticator radiusd[840]: Setting 'Auth-Type := FACAUTH'
FortiAuthenticator radiusd[840]: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
FortiAuthenticator radiusd[840]: # Executing group from file /usr/etc/raddb/sites-enabled/default
FortiAuthenticator radiusd[840]: This is a response to Access-Challenge
FortiAuthenticator radiusd[840]: ERROR: partial auth user not found
FortiAuthenticator radiusd[840]: Updated auth log 'aceraeb': user authentication error: user not partially authenticated
Running the commands below shows authenticate failed.
#diag test authserver radius FAC_RADUIS pap aceraeb Password
After restarting the fnbamd process, the error messages do not appear anymore.
Verifying the SSL-VPN login is working now.
- The FortiGate V5.6 bug was fixed in 6.0.1 GA with the bugID: 0489409 and it is a FortiGate bug.
- Basically, the SSL-VPN authentication sometimes results in dead sessions in RADIUS authentication process which is fnbamd, that is the reason have to restart the process then the issue is gone.
It occurred when there is more than one firewall policy that matched with the same remote FortiAuthenticator (for the case) when a user tries to login with an invalid password or key in a wrong password.
|
