Keep flooding VPN user log Fortiauthenticator

[mirzaa]

Hi all,

I have strange problem and couldn't figured out. We had a one let say "user_6" than I changed the name "user_10" after that On forti auth. flood every 10 sec to this log:

user authentication error: user not partially authenticated 

After this happens we change user pass, delete user_10, reopen user_6 and delete but nothing stopped this log.

FortiAutjenticator ver: Firmware Version v5.5.0, build0366

Thanks,

Debug log:

2019-02-18T11:13:37.734637+03:00 fortiauth radiusd[7193]: ===>NAS IP:192.168.11.20 
2019-02-18T11:13:37.734862+03:00 fortiauth radiusd[7193]: fac_auth_cache_data_init inited 
2019-02-18T11:13:37.734891+03:00 fortiauth radiusd[7193]: ===>Username:user_6 
2019-02-18T11:13:37.734902+03:00 fortiauth radiusd[7193]: Comparing client IP 192.168.11.20 with collection Fortinet100E (192.168.11.20, 1 IPs) 
2019-02-18T11:13:37.734913+03:00 fortiauth radiusd[7193]: ------> matched! 
2019-02-18T11:13:37.734922+03:00 fortiauth radiusd[7193]: Comparing client IP 192.168.11.20 with collection FortiCloud_Sample (208.91.113.110, 1 IPs) 
2019-02-18T11:13:37.734932+03:00 fortiauth radiusd[7193]: Found NAS from preloaded collections for 192.168.11.20: Fortinet100E (192.168.11.20) 
2019-02-18T11:13:37.736206+03:00 fortiauth radiusd[7193]: Found NAS profile for client, NAS: 192.168.11.20 profile: Fortinet100E 
2019-02-18T11:13:37.736858+03:00 fortiauth radiusd[7193]: Setting 'Auth-Type := FACAUTH'
2019-02-18T11:13:37.736892+03:00 fortiauth radiusd[7193]: ++[facauth] = updated
2019-02-18T11:13:37.736902+03:00 fortiauth radiusd[7193]: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
2019-02-18T11:13:37.736910+03:00 fortiauth radiusd[7193]: ++[pap] = noop
2019-02-18T11:13:37.736916+03:00 fortiauth radiusd[7193]: +} # group authorize = updated
2019-02-18T11:13:37.736923+03:00 fortiauth radiusd[7193]: Found Auth-Type = facauth
2019-02-18T11:13:37.736929+03:00 fortiauth radiusd[7193]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2019-02-18T11:13:37.736936+03:00 fortiauth radiusd[7193]: +group FACAUTH {
2019-02-18T11:13:37.736945+03:00 fortiauth radiusd[7193]: This is a response to Access-Challenge
2019-02-18T11:13:37.736952+03:00 fortiauth radiusd[7193]: ERROR: partial auth user not found
2019-02-18T11:13:37.737985+03:00 fortiauth radiusd[7193]: Updated auth log 'user_6': user authentication error: user not partially authenticated 
2019-02-18T11:13:37.738021+03:00 fortiauth radiusd[7193]: facauth: print reply attributes of request id 175: 
2019-02-18T11:13:37.738033+03:00 fortiauth radiusd[7193]: ++[facauth] = reject
2019-02-18T11:13:37.738044+03:00 fortiauth radiusd[7193]: +} # group FACAUTH = reject
2019-02-18T11:13:37.738054+03:00 fortiauth radiusd[7193]: Failed to authenticate the user.
2019-02-18T11:13:37.738064+03:00 fortiauth radiusd[7193]: Using Post-Auth-Type Reject
2019-02-18T11:13:37.738073+03:00 fortiauth radiusd[7193]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2019-02-18T11:13:37.738204+03:00 fortiauth radiusd[7193]: +group REJECT {
2019-02-18T11:13:37.738220+03:00 fortiauth radiusd[7193]: User-Name: user_6 (from request)
2019-02-18T11:13:37.738231+03:00 fortiauth radiusd[7193]: ++[facauth] = ok
2019-02-18T11:13:37.738242+03:00 fortiauth radiusd[7193]: +} # group REJECT = ok
2019-02-18T11:13:37.738252+03:00 fortiauth radiusd[7193]: Delaying reject of request 246 for 1 seconds
2019-02-18T11:13:37.738262+03:00 fortiauth radiusd[7193]: Going to the next request
2019-02-18T11:13:37.738273+03:00 fortiauth radiusd[7193]: Waking up in 0.9 seconds.
2019-02-18T11:13:38.736408+03:00 fortiauth radiusd[7193]: Sending delayed reject for request 246
2019-02-18T11:13:38.736461+03:00 fortiauth radiusd[7193]: Waking up in 4.9 seconds.
2019-02-18T11:13:42.753600+03:00 fortiauth radiusd[7193]: Sending duplicate reply to client Fortinet100E port 4500 - ID: 175
2019-02-18T11:13:42.753646+03:00 fortiauth radiusd[7193]: Waking up in 0.9 seconds.
2019-02-18T11:13:43.736573+03:00 fortiauth radiusd[7193]: Cleaning up request 246 ID 175 with timestamp +2441
2019-02-18T11:13:43.736607+03:00 fortiauth radiusd[7193]: Ready to process requests.
2019-02-18T11:13:47.773390+03:00 fortiauth radiusd[7193]: # Executing section authorize from file /usr/etc/raddb/sites-enabled/default
2019-02-18T11:13:47.773457+03:00 fortiauth radiusd[7193]: +group authorize {
2019-02-18T11:13:47.773472+03:00 fortiauth radiusd[7193]: ++[preprocess] = ok
2019-02-18T11:13:47.773493+03:00 fortiauth radiusd[7193]: ++[chap] = noop
2019-02-18T11:13:47.773508+03:00 fortiauth radiusd[7193]: ++[mschap] = noop
2019-02-18T11:13:47.773519+03:00 fortiauth radiusd[7193]: [eap] No EAP-Message, not doing EAP
2019-02-18T11:13:47.773530+03:00 fortiauth radiusd[7193]: ++[eap] = noop
2019-02-18T11:13:47.773540+03:00 fortiauth radiusd[7193]: ++[expiration] = noop
2019-02-18T11:13:47.773551+03:00 fortiauth radiusd[7193]: ++[logintime] = noop
2019-02-18T11:13:47.773560+03:00 fortiauth radiusd[7193]: facauth: recv Access-Request from 192.168.11.20 port 4500, id=175, length=123 
2019-02-18T11:13:47.773571+03:00 fortiauth radiusd[7193]: NAS-Identifier = "MEDAS-IDC-HA" 
2019-02-18T11:13:47.773777+03:00 fortiauth radiusd[7193]: State = 0x31 
2019-02-18T11:13:47.773874+03:00 fortiauth radiusd[7193]: User-Name = "user_6" 
2019-02-18T11:13:47.773892+03:00 fortiauth radiusd[7193]: User-Password: ****** 
2019-02-18T11:13:47.773902+03:00 fortiauth radiusd[7193]: NAS-Port = 10 
2019-02-18T11:13:47.773912+03:00 fortiauth radiusd[7193]: NAS-Port-Type = Virtual 
2019-02-18T11:13:47.773923+03:00 fortiauth radiusd[7193]: Calling-Station-Id = "178.183.8.254" 
2019-02-18T11:13:47.773933+03:00 fortiauth radiusd[7193]: Acct-Session-Id = "259d6370" 
2019-02-18T11:13:47.773944+03:00 fortiauth radiusd[7193]: Connect-Info = "vpn-ssl" 
2019-02-18T11:13:47.773956+03:00 fortiauth radiusd[7193]: Fortinet-Vdom-Name = "root" 
2019-02-18T11:13:47.773968+03:00 fortiauth radiusd[7193]: NAS-IP-Address = 192.168.11.20 
2019-02-18T11:13:47.773978+03:00 fortiauth radiusd[7193]: ===>NAS IP:192.168.11.20 
2019-02-18T11:13:47.773989+03:00 fortiauth radiusd[7193]: fac_auth_cache_data_init inited 
2019-02-18T11:13:47.774241+03:00 fortiauth radiusd[7193]: ===>Username:user_6 
2019-02-18T11:13:47.774274+03:00 fortiauth radiusd[7193]: Comparing client IP 192.168.11.20 with collection Fortinet100E (192.168.11.20, 1 IPs) 
2019-02-18T11:13:47.774287+03:00 fortiauth radiusd[7193]: ------> matched! 
2019-02-18T11:13:47.774297+03:00 fortiauth radiusd[7193]: Comparing client IP 192.168.11.20 with collection FortiCloud_Sample (208.91.113.110, 1 IPs) 
2019-02-18T11:13:47.774307+03:00 fortiauth radiusd[7193]: Found NAS from preloaded collections for 192.168.11.20: Fortinet100E (192.168.11.20) 
2019-02-18T11:13:47.776136+03:00 fortiauth radiusd[7193]: Found NAS profile for client, NAS: 192.168.11.20 profile: Fortinet100E 
2019-02-18T11:13:47.777047+03:00 fortiauth radiusd[7193]: Setting 'Auth-Type := FACAUTH'
2019-02-18T11:13:47.777080+03:00 fortiauth radiusd[7193]: ++[facauth] = updated
2019-02-18T11:13:47.777087+03:00 fortiauth radiusd[7193]: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
2019-02-18T11:13:47.777094+03:00 fortiauth radiusd[7193]: ++[pap] = noop
2019-02-18T11:13:47.777100+03:00 fortiauth radiusd[7193]: +} # group authorize = updated
2019-02-18T11:13:47.777107+03:00 fortiauth radiusd[7193]: Found Auth-Type = facauth
2019-02-18T11:13:47.777114+03:00 fortiauth radiusd[7193]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2019-02-18T11:13:47.777120+03:00 fortiauth radiusd[7193]: +group FACAUTH {
2019-02-18T11:13:47.777126+03:00 fortiauth radiusd[7193]: This is a response to Access-Challenge
2019-02-18T11:13:47.777132+03:00 fortiauth radiusd[7193]: ERROR: partial auth user not found
2019-02-18T11:13:47.777369+03:00 fortiauth radiusd[7193]: Updated auth log 'user_6': user authentication error: user not partially authenticated 
2019-02-18T11:13:47.777403+03:00 fortiauth radiusd[7193]: facauth: print reply attributes of request id 175: 
2019-02-18T11:13:47.777415+03:00 fortiauth radiusd[7193]: ++[facauth] = reject
2019-02-18T11:13:47.777435+03:00 fortiauth radiusd[7193]: +} # group FACAUTH = reject
2019-02-18T11:13:47.777446+03:00 fortiauth radiusd[7193]: Failed to authenticate the user.
2019-02-18T11:13:47.777457+03:00 fortiauth radiusd[7193]: Using Post-Auth-Type Reject
2019-02-18T11:13:47.777468+03:00 fortiauth radiusd[7193]: # Executing group from file /usr/etc/raddb/sites-enabled/default
2019-02-18T11:13:47.777481+03:00 fortiauth radiusd[7193]: +group REJECT {
2019-02-18T11:13:47.777494+03:00 fortiauth radiusd[7193]: User-Name: user_6 (from request)
2019-02-18T11:13:47.777504+03:00 fortiauth radiusd[7193]: ++[facauth] = ok
2019-02-18T11:13:47.777519+03:00 fortiauth radiusd[7193]: +} # group REJECT = ok
2019-02-18T11:13:47.778428+03:00 fortiauth radiusd[7193]: Delaying reject of request 247 for 1 seconds
2019-02-18T11:13:47.778475+03:00 fortiauth radiusd[7193]: Going to the next request
2019-02-18T11:13:47.778488+03:00 fortiauth radiusd[7193]: Waking up in 0.9 seconds.
2019-02-18T11:13:48.776289+03:00 fortiauth radiusd[7193]: Sending delayed reject for request 247
2019-02-18T11:13:48.776334+03:00 fortiauth radiusd[7193]: Waking up in 4.9 seconds.
2019-02-18T11:13:52.793491+03:00 fortiauth radiusd[7193]: Sending duplicate reply to client Fortinet100E port 4500 - ID: 175
2019-02-18T11:13:52.793536+03:00 fortiauth radiusd[7193]: Waking up in 0.9 seconds.
2019-02-18T11:13:53.776217+03:00 fortiauth radiusd[7193]: Cleaning up request 247 ID 175 with timestamp +2451
2019-02-18T11:13:53.776268+03:00 fortiauth radiusd[7193]: Ready to process requests

[mirzaa]

Ok solutions is simple for us. Examine the debug log and one of forti procces keep spaming. We restarted forti fw. Problem solved

[jhjeffrey]

Had the same issue with an account logging every 10 seconds. TAC trace the problem to the"Fortigate's Authentication Daemon". There is a command to kill/restart the daemon. Note: running the command will disconnect all users. We are running a HA A/P failover, it was cleaner to promote the secondary unit and reboot the primary unit.