Fwd: failure log from radius debug

[Jim Pazarena]

please diagnose why radius feels that my server has
declined the user/password? both these user attempts
used their correct password, yet the log says it was invalid.

Thanks!

-------- Original Message --------
Subject: failure log from radius debug
Date: Tue, 29 Nov 2011 10:50:29 -0800
From: Charlie Root
To: jim at paz.bz

Tue Nov 29 10:42:30 2011 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 209.53.238.13 port 513, id=118, length=95
	User-Name = "carlmerk"
	User-Password = "mushXX"
	NAS-Port = 15
	NAS-Port-Type = Async
	NAS-Identifier = "ras"
	Called-Station-Id = "unknown"
	Calling-Station-Id = "unknown"
	Service-Type = Framed-User
	Framed-Protocol = PPP
Tue Nov 29 10:44:13 2011 : Info: # Executing section authorize from file 
/usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:13 2011 : Info: +- entering group authorize {...}
Tue Nov 29 10:44:13 2011 : Info: ++[preprocess] returns ok
Tue Nov 29 10:44:13 2011 : Info: ++[chap] returns noop
Tue Nov 29 10:44:13 2011 : Info: ++[mschap] returns noop
Tue Nov 29 10:44:13 2011 : Info: ++[digest] returns noop
Tue Nov 29 10:44:13 2011 : Info: [suffix] No '@' in User-Name = "carlmerk", looking up realm NULL
Tue Nov 29 10:44:13 2011 : Info: [suffix] No such realm "NULL"
Tue Nov 29 10:44:13 2011 : Info: ++[suffix] returns noop
Tue Nov 29 10:44:13 2011 : Info: [eap] No EAP-Message, not doing EAP
Tue Nov 29 10:44:13 2011 : Info: ++[eap] returns noop
Tue Nov 29 10:44:13 2011 : Info: [files] users: Matched entry DEFAULT at line 50
Tue Nov 29 10:44:13 2011 : Info: ++[files] returns ok
Tue Nov 29 10:44:13 2011 : Info: ++[expiration] returns noop
Tue Nov 29 10:44:13 2011 : Info: ++[logintime] returns noop
Tue Nov 29 10:44:13 2011 : Info: [pap] WARNING! No "known good" password found for the user. 
Authentication may fail because of this.
Tue Nov 29 10:44:13 2011 : Info: ++[pap] returns noop
Tue Nov 29 10:44:13 2011 : Info: Found Auth-Type = System
Tue Nov 29 10:44:13 2011 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:13 2011 : Info: +- entering group authenticate {...}
Tue Nov 29 10:44:13 2011 : Auth: [unix] invalid password "carlmerk"
Tue Nov 29 10:44:13 2011 : Info: ++[unix] returns reject
Tue Nov 29 10:44:13 2011 : Info: Failed to authenticate the user.
Tue Nov 29 10:44:13 2011 : Auth: Login incorrect: [carlmerk/mushXX] (from client localhost port 15 
cli unknown)
Tue Nov 29 10:44:13 2011 : Info: Using Post-Auth-Type Reject
Tue Nov 29 10:44:13 2011 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:13 2011 : Info: +- entering group REJECT {...}
Tue Nov 29 10:44:13 2011 : Info: [attr_filter.access_reject] 	expand: %{User-Name} -> carlmerk
Tue Nov 29 10:44:13 2011 : Debug: attr_filter: Matched entry DEFAULT at line 11
Tue Nov 29 10:44:13 2011 : Info: ++[attr_filter.access_reject] returns updated
Tue Nov 29 10:44:13 2011 : Info: Delaying reject of request 0 for 1 seconds
Tue Nov 29 10:44:13 2011 : Debug: Going to the next request
Tue Nov 29 10:44:13 2011 : Debug: Waking up in 0.9 seconds.
Tue Nov 29 10:44:14 2011 : Info: Sending delayed reject for request 0
Sending Access-Reject of id 118 to 209.53.238.13 port 513
Tue Nov 29 10:44:14 2011 : Debug: Waking up in 4.9 seconds.
Tue Nov 29 10:44:19 2011 : Info: Cleaning up request 0 ID 118 with timestamp +103
Tue Nov 29 10:44:19 2011 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 209.53.238.13 port 513, id=119, length=95
	User-Name = "carollyn"
	User-Password = "carolXX"
	NAS-Port = 2
	NAS-Port-Type = Async
	NAS-Identifier = "ras"
	Called-Station-Id = "unknown"
	Calling-Station-Id = "unknown"
	Service-Type = Framed-User
	Framed-Protocol = PPP
Tue Nov 29 10:44:20 2011 : Info: # Executing section authorize from file 
/usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:20 2011 : Info: +- entering group authorize {...}
Tue Nov 29 10:44:20 2011 : Info: ++[preprocess] returns ok
Tue Nov 29 10:44:20 2011 : Info: ++[chap] returns noop
Tue Nov 29 10:44:20 2011 : Info: ++[mschap] returns noop
Tue Nov 29 10:44:20 2011 : Info: ++[digest] returns noop
Tue Nov 29 10:44:20 2011 : Info: [suffix] No '@' in User-Name = "carollyn", looking up realm NULL
Tue Nov 29 10:44:20 2011 : Info: [suffix] No such realm "NULL"
Tue Nov 29 10:44:20 2011 : Info: ++[suffix] returns noop
Tue Nov 29 10:44:20 2011 : Info: [eap] No EAP-Message, not doing EAP
Tue Nov 29 10:44:20 2011 : Info: ++[eap] returns noop
Tue Nov 29 10:44:20 2011 : Info: [files] users: Matched entry DEFAULT at line 50
Tue Nov 29 10:44:20 2011 : Info: ++[files] returns ok
Tue Nov 29 10:44:20 2011 : Info: ++[expiration] returns noop
Tue Nov 29 10:44:20 2011 : Info: ++[logintime] returns noop
Tue Nov 29 10:44:20 2011 : Info: [pap] WARNING! No "known good" password found for the user. 
Authentication may fail because of this.
Tue Nov 29 10:44:20 2011 : Info: ++[pap] returns noop
Tue Nov 29 10:44:20 2011 : Info: Found Auth-Type = System
Tue Nov 29 10:44:20 2011 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:20 2011 : Info: +- entering group authenticate {...}
Tue Nov 29 10:44:20 2011 : Auth: [unix] invalid password "carollyn"
Tue Nov 29 10:44:20 2011 : Info: ++[unix] returns reject
Tue Nov 29 10:44:20 2011 : Info: Failed to authenticate the user.
Tue Nov 29 10:44:20 2011 : Auth: Login incorrect: [carollyn/carolXX] (from client localhost port 2 
cli unknown)
Tue Nov 29 10:44:20 2011 : Info: Using Post-Auth-Type Reject
Tue Nov 29 10:44:20 2011 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Tue Nov 29 10:44:20 2011 : Info: +- entering group REJECT {...}
Tue Nov 29 10:44:20 2011 : Info: [attr_filter.access_reject] 	expand: %{User-Name} -> carollyn
Tue Nov 29 10:44:20 2011 : Debug: attr_filter: Matched entry DEFAULT at line 11
Tue Nov 29 10:44:20 2011 : Info: ++[attr_filter.access_reject] returns updated
Tue Nov 29 10:44:20 2011 : Info: Delaying reject of request 1 for 1 seconds
Tue Nov 29 10:44:20 2011 : Debug: Going to the next request
Tue Nov 29 10:44:20 2011 : Debug: Waking up in 0.9 seconds.
Tue Nov 29 10:44:21 2011 : Info: Sending delayed reject for request 1
Sending Access-Reject of id 119 to 209.53.238.13 port 513
Tue Nov 29 10:44:21 2011 : Debug: Waking up in 4.9 seconds.
Tue Nov 29 10:44:26 2011 : Info: Cleaning up request 1 ID 119 with timestamp +110
Tue Nov 29 10:44:26 2011 : Info: Ready to process requests.
^\Quit
auth# ^Dexit

Script done on Tue Nov 29 10:44:31 2011