Hello, I'm having an issue with our radius server authorising users. The initial request is fine, the customer connects and receives an IP address.... rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=5, length=236 Framed-Protocol = PPP User-Name = "michaelr@example.com" CHAP-Password = 0x974cfb5d4d64e91407e0c85a3b1611a584 Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#" Connect-Info = "1000000000" NAS-Port-Type = Virtual NAS-Port = 501 NAS-Port-Id = "Uniq-Sess-ID501" Service-Type = Framed-User NAS-IP-Address = 10.8.13.254 Fri Jun 14 11:44:14 2013 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Jun 14 11:44:14 2013 : Info: +- entering group authorize {...} Fri Jun 14 11:44:14 2013 : Info: ++[preprocess] returns ok Fri Jun 14 11:44:14 2013 : Info: [chap] Setting 'Auth-Type := CHAP' Fri Jun 14 11:44:14 2013 : Info: ++[chap] returns ok Fri Jun 14 11:44:14 2013 : Info: ++[mschap] returns noop Fri Jun 14 11:44:14 2013 : Info: ++[digest] returns noop Fri Jun 14 11:44:14 2013 : Info: [suffix] Looking up realm "example.com" for User-Name = "michaelr@example.com" Fri Jun 14 11:44:14 2013 : Info: [suffix] Found realm "example.com" Fri Jun 14 11:44:14 2013 : Info: [suffix] Adding Stripped-User-Name = "michaelr" Fri Jun 14 11:44:14 2013 : Info: [suffix] Adding Realm = "example.com" Fri Jun 14 11:44:14 2013 : Info: [suffix] Authentication realm is LOCAL. Fri Jun 14 11:44:14 2013 : Info: ++[suffix] returns ok Fri Jun 14 11:44:14 2013 : Info: [eap] No EAP-Message, not doing EAP Fri Jun 14 11:44:14 2013 : Info: ++[eap] returns noop Fri Jun 14 11:44:14 2013 : Info: [files] users: Matched entry DEFAULT at line 172 Fri Jun 14 11:44:14 2013 : Info: ++[files] returns ok Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Stripped-User-Name} -> michaelr Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> michaelr Fri Jun 14 11:44:14 2013 : Info: [sql] sql_set_user escaped user --> 'michaelr' Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 0 Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'michaelr' ORDER BY id Fri Jun 14 11:44:14 2013 : Info: [sql] User found in radcheck table Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'michaelr' ORDER BY id Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'michaelr' ORDER BY priority Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'Layer2-L2TP' ORDER BY id Fri Jun 14 11:44:14 2013 : Info: [sql] User found in group Layer2-L2TP Fri Jun 14 11:44:14 2013 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'Layer2-L2TP' ORDER BY id Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Released sql socket id: 0 Fri Jun 14 11:44:14 2013 : Info: ++[sql] returns ok Fri Jun 14 11:44:14 2013 : Info: ++[expiration] returns noop Fri Jun 14 11:44:14 2013 : Info: ++[logintime] returns noop Fri Jun 14 11:44:14 2013 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Fri Jun 14 11:44:14 2013 : Info: ++[pap] returns noop Fri Jun 14 11:44:14 2013 : Info: Found Auth-Type = Local Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Fri Jun 14 11:44:14 2013 : Info: !!! Replacing User-Password in config items with Cleartext-Password. !!! Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Fri Jun 14 11:44:14 2013 : Info: !!! Please update your configuration so that the "known good" !!! Fri Jun 14 11:44:14 2013 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!! Fri Jun 14 11:44:14 2013 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Fri Jun 14 11:44:14 2013 : Info: WARNING: Please update your configuration, and remove 'Auth-Type = Local' Fri Jun 14 11:44:14 2013 : Info: WARNING: Use the PAP or CHAP modules instead. Fri Jun 14 11:44:14 2013 : Info: CHAP-Password is correct. Fri Jun 14 11:44:14 2013 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/default Fri Jun 14 11:44:14 2013 : Info: +- entering group post-auth {...} Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Stripped-User-Name} -> michaelr Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> michaelr Fri Jun 14 11:44:14 2013 : Info: [sql] sql_set_user escaped user --> 'michaelr' Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{User-Password} -> Fri Jun 14 11:44:14 2013 : Info: [sql] ... expanding second conditional Fri Jun 14 11:44:14 2013 : Info: [sql] expand: %{Chap-Password} -> 0x974cfb5d4d64e91407e0c85a3b1611a584 Fri Jun 14 11:44:14 2013 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' michaelr@example.com', '0x974cfb5d4d64e91407e0c85a3b1611a584', 'Access-Accept', '2013-06-14 11:44:14') Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' michaelr@example.com', '0x974cfb5d4d64e91407e0c85a3b1611a584', 'Access-Accept', '2013-06-14 11:44:14') Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Fri Jun 14 11:44:14 2013 : Debug: rlm_sql (sql): Released sql socket id: 4 Fri Jun 14 11:44:14 2013 : Info: ++[sql] returns ok Fri Jun 14 11:44:14 2013 : Info: ++[exec] returns noop Sending Access-Accept of id 5 to 10.8.13.254 port 1645 Framed-Protocol := PPP Framed-Compression = Van-Jacobson-TCP-IP Framed-IP-Address == 10.8.13.193 Tunnel-Type:0 := L2TP Tunnel-Medium-Type:0 := IPv4 Service-Type := Framed-User Framed-IP-Netmask := 255.255.255.255 Fri Jun 14 11:44:14 2013 : Info: Finished request 20. Fri Jun 14 11:44:14 2013 : Debug: Going to the next request Fri Jun 14 11:44:14 2013 : Debug: Waking up in 4.9 seconds. Fri Jun 14 11:44:19 2013 : Info: Cleaning up request 20 ID 5 with timestamp +734 Fri Jun 14 11:44:19 2013 : Info: Ready to process requests. However then the customer disconnects a 2nd later, and the following comes through, which makes no sense at all to me. rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=6, length=220 User-Name = "example.com" User-Password = "cisco" Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#" Connect-Info = "1000000000" NAS-Port-Type = Virtual NAS-Port = 501 NAS-Port-Id = "Uniq-Sess-ID501" Service-Type = Outbound-User NAS-IP-Address = 10.8.13.254 Fri Jun 14 11:44:23 2013 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Jun 14 11:44:23 2013 : Info: +- entering group authorize {...} Fri Jun 14 11:44:23 2013 : Info: ++[preprocess] returns ok Fri Jun 14 11:44:23 2013 : Info: ++[chap] returns noop Fri Jun 14 11:44:23 2013 : Info: ++[mschap] returns noop Fri Jun 14 11:44:23 2013 : Info: ++[digest] returns noop Fri Jun 14 11:44:23 2013 : Info: [suffix] No '@' in User-Name = "example.com", looking up realm NULL Fri Jun 14 11:44:23 2013 : Info: [suffix] No such realm "NULL" Fri Jun 14 11:44:23 2013 : Info: ++[suffix] returns noop Fri Jun 14 11:44:23 2013 : Info: [eap] No EAP-Message, not doing EAP Fri Jun 14 11:44:23 2013 : Info: ++[eap] returns noop Fri Jun 14 11:44:23 2013 : Info: [files] users: Matched entry DEFAULT at line 204 Fri Jun 14 11:44:23 2013 : Info: ++[files] returns ok Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{Stripped-User-Name} -> Fri Jun 14 11:44:23 2013 : Info: [sql] ... expanding second conditional Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{User-Name} -> example.com Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> example.com Fri Jun 14 11:44:23 2013 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> example.com Fri Jun 14 11:44:23 2013 : Info: [sql] sql_set_user escaped user --> ' example.com' Fri Jun 14 11:44:23 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Fri Jun 14 11:44:23 2013 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'example.com' ORDER BY id Fri Jun 14 11:44:23 2013 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'example.com' ORDER BY priority Fri Jun 14 11:44:23 2013 : Debug: rlm_sql (sql): Released sql socket id: 3 Fri Jun 14 11:44:23 2013 : Info: [sql] User example.com not found Fri Jun 14 11:44:23 2013 : Info: ++[sql] returns notfound Fri Jun 14 11:44:23 2013 : Info: ++[expiration] returns noop Fri Jun 14 11:44:23 2013 : Info: ++[logintime] returns noop Fri Jun 14 11:44:23 2013 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jun 14 11:44:23 2013 : Info: ++[pap] returns noop Fri Jun 14 11:44:23 2013 : Info: Found Auth-Type = Local Fri Jun 14 11:44:23 2013 : Info: WARNING: Please update your configuration, and remove 'Auth-Type = Local' Fri Jun 14 11:44:23 2013 : Info: WARNING: Use the PAP or CHAP modules instead. Fri Jun 14 11:44:23 2013 : Info: No "known good" password was configured for the user. Fri Jun 14 11:44:23 2013 : Info: As a result, we cannot authenticate the user. Fri Jun 14 11:44:23 2013 : Info: Failed to authenticate the user. Fri Jun 14 11:44:23 2013 : Info: Using Post-Auth-Type Reject Fri Jun 14 11:44:23 2013 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Fri Jun 14 11:44:23 2013 : Info: +- entering group REJECT {...} Fri Jun 14 11:44:23 2013 : Info: [attr_filter.access_reject] expand: %{User-Name} -> example.com Fri Jun 14 11:44:23 2013 : Debug: attr_filter: Matched entry DEFAULT at line 11 Fri Jun 14 11:44:23 2013 : Info: ++[attr_filter.access_reject] returns updated Fri Jun 14 11:44:23 2013 : Info: Delaying reject of request 21 for 1 seconds Fri Jun 14 11:44:23 2013 : Debug: Going to the next request Fri Jun 14 11:44:23 2013 : Debug: Waking up in 0.9 seconds. Fri Jun 14 11:44:24 2013 : Info: Sending delayed reject for request 21 Sending Access-Reject of id 6 to 10.8.13.254 port 1645 Fri Jun 14 11:44:24 2013 : Debug: Waking up in 4.9 seconds. Fri Jun 14 11:44:29 2013 : Info: Cleaning up request 21 ID 6 with timestamp +743 Fri Jun 14 11:44:29 2013 : Info: Ready to process requests. Where is this coming from, why does the customer initially connect and then disconnect ? Any assistance would be greatly appreciated thanks.
On 14.06.2013 5:56, geebs wrote:
rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=6, length=220 User-Name = "example.com <http://example.com>" User-Password = "cisco" Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#" Connect-Info = "1000000000" NAS-Port-Type = Virtual NAS-Port = 501 NAS-Port-Id = "Uniq-Sess-ID501" Service-Type = Outbound-User NAS-IP-Address = 10.8.13.254
Looks line Cisco PPPoE service profile request http://www.cisco.com/en/US/docs/ios-xml/ios/bbdsl/configuration/12-4t/bba-sv...
On Fri, Jun 14, 2013 at 3:33 PM, Iliya Peregoudov <iperegudov@cboss.ru>wrote:
On 14.06.2013 5:56, geebs wrote:
rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=6, length=220 User-Name = "example.com <http://example.com>"
User-Password = "cisco" Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#**587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#" Connect-Info = "1000000000" NAS-Port-Type = Virtual NAS-Port = 501 NAS-Port-Id = "Uniq-Sess-ID501" Service-Type = Outbound-User NAS-IP-Address = 10.8.13.254
Looks line Cisco PPPoE service profile request http://www.cisco.com/en/US/**docs/ios-xml/ios/bbdsl/** configuration/12-4t/bba-svc-**callstup.html<http://www.cisco.com/en/US/docs/ios-xml/ios/bbdsl/configuration/12-4t/bba-svc-callstup.html> - List info/subscribe/unsubscribe? See http://www.freeradius.org/** list/users.html <http://www.freeradius.org/list/users.html>
Yes it is, I'm not sure what's going on there, but to be honest this is not the major issue. The problem is that michaelr@example.com does initially connect, but then gets disconnected... If you have a look at the 1st post, they connect fine, but then get booted, and the only thing in the logs is the above. What would cause this ?
On 06/16/2013 01:15 AM, geebs wrote:
On Fri, Jun 14, 2013 at 3:33 PM, Iliya Peregoudov <iperegudov@cboss.ru <mailto:iperegudov@cboss.ru>> wrote:
On 14.06.2013 5:56, geebs wrote:
rad_recv: Access-Request packet from host 10.8.13.254 port 1645, id=6, length=220 User-Name = "example.com <http://example.com> <http://example.com>"
User-Password = "cisco" Calling-Station-Id = "GigabitEthernet 14/0/3.31010096:3101-96#__587204450###pppoe 00:04:ed:d1:78:85#QTNITE4025M atm 1/1/04/27:8.35#" Connect-Info = "1000000000" NAS-Port-Type = Virtual NAS-Port = 501 NAS-Port-Id = "Uniq-Sess-ID501" Service-Type = Outbound-User NAS-IP-Address = 10.8.13.254
Looks line Cisco PPPoE service profile request http://www.cisco.com/en/US/__docs/ios-xml/ios/bbdsl/__configuration/12-4t/bb... <http://www.cisco.com/en/US/docs/ios-xml/ios/bbdsl/configuration/12-4t/bba-svc-callstup.html> - List info/subscribe/unsubscribe? See http://www.freeradius.org/__list/users.html <http://www.freeradius.org/list/users.html>
Yes it is, I'm not sure what's going on there, but to be honest this is not the major issue.
Well, as Illya says - the Cisco is making a request, over RADIUS, for a PPPoE profile. You aren't configured for that, so return a reject. Is it really that hard to imagine that *this is* the cause? Change the config on the Cisco to *not* request PPPoE profiles over RADIUS, or alternatively read up on what you need to return, and start returning it.
The problem is that michaelr@example.com <mailto:michaelr@example.com> does initially connect, but then gets disconnected...
If you have a look at the 1st post, they connect fine, but then get booted, and the only thing in the logs is the above. What would cause this ?
Well... "this". The reject of the PPPoE profile request. All the info you need is at the URL Illya gave.
participants (3)
-
geebs -
Iliya Peregoudov -
Phil Mayers