Skip to main content
mirzaa
mirzaa
New Member
February 18, 2019
Question

Keep flooding VPN user log Fortiauthenticator

  • February 18, 2019
  • 2 replies
  • 5619 views

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

 

    2 replies

    mirzaa
    mirzaaAuthor
    New Member
    March 5, 2019

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

    jhjeffrey
    jhjeffrey
    New Member
    April 29, 2019

    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.  

    Terms & ConditionsAccessibility statement