Re: VSA attributes sent with Access-Reject response
Date: Thu, 15 May 2014 10:53:06 -0400 From: Alan DeKok <aland@deployingradius.com> To: FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Subject: Re: VSA attributes sent with Access-Reject response Message-ID: <5374D4D2.2070504@deployingradius.com> Content-Type: text/plain; charset=ISO-8859-1
Contact (COEXSI) wrote:
Doing some tests with FreeRADIUS Version 2.2.3, we have noticed that the VSA attributes normally sent with an Access-Accept response were also sent on Access-Reject response. This was also observed with the Access-Challenge response sent by the server when doing EAP exchange.
This doesn't seem normal as per the FAQ : http://wiki.freeradius.org/guide/faq#VSA-in-Access-Reject "According RFC 2865 (section 5.44) Vendor-Specific Attributes aren't allow in Access-Reject packets."
You edited the default configuration, and broke it.
The default configuration has the following:
Post-Auth-Type REJECT { # log failed authentications in SQL, too. # sql attr_filter.access_reject }
Thank you Alan, this solve the problem for the Access-Reject response! The default configuration explanation wasn't that clear for me.
There is a similar line for EAP and Access-Challenge. The debug log shows you've removed the "attr_filter.access_reject" line. Which is why you're getting VSAs in the Access-Reject.
For filtering the Access-Challenge response when doing EAP, I've these lines (commented) in the default configuration: # Auth-Type eap { # eap { # handled = 1 # } # if (handled && (Response-Packet-Type == Access-Challenge)) { # attr_filter.access_challenge.post-auth # handled # override the "updated" code from attr_filter # } # } When uncommenting them, I've a configuration parsing error: Failed to find "handled" in the "modules" section. Failed to parse "handled" entry. Failed to parse "if" subsection. The parsing error seems to be linked to the line "handled # override the "updated" code from attr_filter". I didn't find a definition of the "handled" keyword to understand the error.
Alan DeKok.
Contact (COEXSI) wrote:
For filtering the Access-Challenge response when doing EAP, I've these lines (commented) in the default configuration:
# Auth-Type eap { # eap { # handled = 1 # } # if (handled && (Response-Packet-Type == Access-Challenge)) { # attr_filter.access_challenge.post-auth # handled # override the "updated" code from attr_filter # } # }
When uncommenting them, I've a configuration parsing error:
Failed to find "handled" in the "modules" section.
Because you edited the configuration, and removed "always" from raddb/modules. It has the definition for "handled". Alan DeKok.
Contact (COEXSI) wrote:
For filtering the Access-Challenge response when doing EAP, I've these lines (commented) in the default configuration:
# Auth-Type eap { # eap { # handled = 1 # } # if (handled && (Response-Packet-Type == Access-Challenge)) { # attr_filter.access_challenge.post-auth # handled # override the "updated" code from attr_filter # } # }
When uncommenting them, I've a configuration parsing error:
Failed to find "handled" in the "modules" section.
Because you edited the configuration, and removed "always" from raddb/modules. It has the definition for "handled".
Yes, we had removed the "always" module as we didn't think it was for production purpose. At the beginning of its configuration file, we can read it's used for debugging: # The "always" module is here for debugging purposes. Each # instance simply returns the same result, always, without # doing anything. After adding the "always" module, the configuration is parsed without error. But, the VSA are still sent along with the EAP-MD5 Access-Challenge response!
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Contact (COEXSI) wrote:
Yes, we had removed the "always" module as we didn't think it was for production purpose.
See "man radiusd". It tells you how to make changes, so that you know it works.
At the beginning of its configuration file, we can read it's used for debugging:
# The "always" module is here for debugging purposes. Each # instance simply returns the same result, always, without # doing anything.
Well, it's used.
After adding the "always" module, the configuration is parsed without error. But, the VSA are still sent along with the EAP-MD5 Access-Challenge response!
If only there was some way of seeing what the server was doing. Alan DeKok. .
-----Original Message----- From: freeradius-users-bounces+contact=coexsi.fr@lists.freeradius.org [mailto:freeradius-users-bounces+contact=coexsi.fr@lists.freeradius.org] On Behalf Of Alan DeKok Sent: vendredi 16 mai 2014 22:36 To: FreeRadius users mailing list Subject: Re: VSA attributes sent with Access-Reject response
Contact (COEXSI) wrote:
Yes, we had removed the "always" module as we didn't think it was for production purpose.
See "man radiusd". It tells you how to make changes, so that you know it works.
At the beginning of its configuration file, we can read it's used for debugging:
# The "always" module is here for debugging purposes. Each # instance simply returns the same result, always, without # doing anything.
Well, it's used.
After adding the "always" module, the configuration is parsed without error. But, the VSA are still sent along with the EAP-MD5 Access-Challenge response!
If only there was some way of seeing what the server was doing.
Sorry, I forgot to add the technical information... Here is an cleaned extract of the configuration: ------------------------------------------------ authorize { preprocess chap mschap eap { ok = return } sql pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } eap Auth-Type eap { eap { handled = 1 } if (handled && (Response-Packet-Type == Access-Challenge)) { attr_filter.access_challenge.post-auth handled } } } post-auth { sql Post-Auth-Type REJECT { sql attr_filter.access_reject } } preacct { preprocess acct_unique } accounting { sql attr_filter.accounting_response } Here is the Access-Challenge sent with VSA: ------------------------------------------- rad_recv: Access-Request packet from host X.X.X.X port 32771, id=141, length=152 Acct-Session-Id = "5612ab46" NAS-Port = 0 NAS-Port-Type = Wireless-802.11 User-Name = "test" Calling-Station-Id = "XX-XX-XX-XX-XX-XX" Called-Station-Id = "XX-XX-XX-XX-XX-XX" Framed-IP-Address = X.X.X.X EAP-Message = 0x028d00090174657374 NAS-Identifier = "test" NAS-IP-Address = X.X.X.X Framed-MTU = 1496 Connect-Info = "HTTPS" Service-Type = Administrative-User Message-Authenticator = 0x0be651342e0ab4fbfe8dbd0c99750120 Fri May 16 22:54:28 2014 : Info: server my_server { Fri May 16 22:54:28 2014 : Info: # Executing section authorize from file /etc/raddb/partner.conf Fri May 16 22:54:28 2014 : Info: +group authorize { Fri May 16 22:54:28 2014 : Info: ++[preprocess] = ok Fri May 16 22:54:28 2014 : Info: ++[chap] = noop Fri May 16 22:54:28 2014 : Info: ++[mschap] = noop Fri May 16 22:54:28 2014 : Info: [eap] EAP packet type response id 141 length 9 Fri May 16 22:54:28 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri May 16 22:54:28 2014 : Info: ++[eap] = updated Fri May 16 22:54:28 2014 : Info: [sql] expand: %{User-Name} -> test Fri May 16 22:54:28 2014 : Info: [sql] sql_set_user escaped user --> 'test' Fri May 16 22:54:28 2014 : Debug: Closing socket 99 as its lifetime has been exceeded Fri May 16 22:54:28 2014 : Info: rlm_sql (sql): Trying to (re)connect unconnected handle 99.. Fri May 16 22:54:28 2014 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #99 Fri May 16 22:54:28 2014 : Info: rlm_sql_mysql: Starting connect to MySQL server for #99 Fri May 16 22:54:28 2014 : Info: rlm_sql (sql): Connected new DB handle, #99 Fri May 16 22:54:28 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 99 Fri May 16 22:54:28 2014 : Debug: rlm_sql (sql): got socket 99 after skipping 0 unconnected handles, tried to reconnect 1 though Fri May 16 22:54:28 2014 : Info: [sql] expand: CALL my_stored_procedure ('%{Virtual-Server}','AUTH_REQ' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Sessi on-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{A cct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Ou tput-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Pack et-Type}','%{Acct-Status-Type}') -> CALL my_stored_procedure ('my_server','AUTH_REQ' ,'test','X.X.X.X','XX-XX-XX-XX-XX-XX','5612ab46','test','XX-XX-XX-XX-XX-XX', '','','','','','','','0','') Fri May 16 22:54:28 2014 : Info: [sql] User found in radcheck table Fri May 16 22:54:28 2014 : Info: [sql] expand: CALL my_stored_procedure ('%{Virtual-Server}','AUTH_REPL' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Sessi on-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{A cct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Ou tput-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Pack et-Type}','%{Acct-Status-Type}') -> CALL my_stored_procedure ('my_server','AUTH_REPL' ,'test','X.X.X.X','XX-XX-XX-XX-XX-XX','5612ab46','test','XX-XX-XX-XX-XX-XX', '','','','','','','','0','') Fri May 16 22:54:28 2014 : Debug: rlm_sql (sql): Released sql socket id: 99 Fri May 16 22:54:28 2014 : Info: ++[sql] = ok Fri May 16 22:54:28 2014 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Fri May 16 22:54:28 2014 : Info: ++[pap] = noop Fri May 16 22:54:28 2014 : Info: +} # group authorize = updated Fri May 16 22:54:28 2014 : Info: Found Auth-Type = EAP Fri May 16 22:54:28 2014 : Info: # Executing group from file /etc/raddb/partner.conf Fri May 16 22:54:28 2014 : Info: +group authenticate { Fri May 16 22:54:28 2014 : Info: [eap] EAP Identity Fri May 16 22:54:28 2014 : Info: [eap] processing type md5 Fri May 16 22:54:28 2014 : Debug: rlm_eap_md5: Issuing Challenge Fri May 16 22:54:28 2014 : Info: ++[eap] = handled Fri May 16 22:54:28 2014 : Info: +} # group authenticate = handled Fri May 16 22:54:28 2014 : Info: } # server my_server Sending Access-Challenge of id 141 to X.X.X.X port 32771 Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" Colubris-AVPair += "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" EAP-Message = 0x018e00160410e4221f5be6c61e8cd9c9d5f403e52706 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4a3d8da24ab389bc6e24b0dbbc2bac25 Fri May 16 22:54:28 2014 : Info: Finished request 0. Fri May 16 22:54:28 2014 : Debug: Going to the next request
Alan DeKok. . - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
What you sent is of little help. Output of radiusd -X should be from the server start up through to the failure you are looking at. Alan -- Sent from my Android device with K-9 Mail. Please excuse my brevity.
-----Original Message----- From: Alan Buxey [mailto:A.L.M.Buxey@lboro.ac.uk] Sent: samedi 17 mai 2014 09:33 To: FreeRadius users mailing list; Contact (COEXSI); 'FreeRadius users mailing list' Subject: RE: VSA attributes sent with Access-Reject response
What you sent is of little help. Output of radiusd -X should be from the server start up through to the failure you are looking at.
Here is the cleaned startup log, the request I've sent before is coming right after: Mon May 19 09:14:13 2014 : Info: radiusd: FreeRADIUS Version 2.2.3, for host x86_64-redhat-linux-gnu, built on Jan 23 2014 at 16:59:33 Mon May 19 09:14:13 2014 : Debug: Server was built with: Mon May 19 09:14:13 2014 : Debug: accounting Mon May 19 09:14:13 2014 : Debug: authentication Mon May 19 09:14:13 2014 : Debug: WITH_DHCP Mon May 19 09:14:13 2014 : Debug: WITH_VMPS Mon May 19 09:14:13 2014 : Debug: Server core libs: Mon May 19 09:14:13 2014 : Debug: ssl: OpenSSL 1.0.1e-fips 11 Feb 2013 Mon May 19 09:14:13 2014 : Info: Copyright (C) 1999-2013 The FreeRADIUS server project and contributors. Mon May 19 09:14:13 2014 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Mon May 19 09:14:13 2014 : Info: PARTICULAR PURPOSE. Mon May 19 09:14:13 2014 : Info: You may redistribute copies of FreeRADIUS under the terms of the Mon May 19 09:14:13 2014 : Info: GNU General Public License. Mon May 19 09:14:13 2014 : Info: For more information about these matters, see the file named COPYRIGHT. Mon May 19 09:14:13 2014 : Info: Starting - reading configuration files ... Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/radiusd.conf Mon May 19 09:14:13 2014 : Debug: including files in directory /etc/raddb/modules/ Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/chap Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/expr Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/attr_filter Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/pap Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/acct_unique Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/preprocess Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/always Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/modules/mschap Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/eap.conf Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/sql.conf Mon May 19 09:14:13 2014 : Debug: including files in directory /etc/raddb/sites-enabled/ Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/sites-enabled/partner-1 Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/partner.conf Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/sites-enabled/admin-status Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/sites-enabled/admin-pptpserver Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/partner.conf Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/sites-enabled/partner-2 Mon May 19 09:14:13 2014 : Debug: including configuration file /etc/raddb/partner.conf Mon May 19 09:14:13 2014 : Debug: main { Mon May 19 09:14:13 2014 : Debug: user = "radiusd" Mon May 19 09:14:13 2014 : Debug: group = "radiusd" Mon May 19 09:14:13 2014 : Debug: allow_core_dumps = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: including dictionary file /etc/raddb/dictionary Mon May 19 09:14:13 2014 : Debug: main { Mon May 19 09:14:13 2014 : Debug: name = "radiusd" Mon May 19 09:14:13 2014 : Debug: prefix = "/usr" Mon May 19 09:14:13 2014 : Debug: localstatedir = "/var" Mon May 19 09:14:13 2014 : Debug: sbindir = "/usr/sbin" Mon May 19 09:14:13 2014 : Debug: logdir = "/var/log/radius" Mon May 19 09:14:13 2014 : Debug: run_dir = "/var/run/radiusd" Mon May 19 09:14:13 2014 : Debug: libdir = "/usr/lib64/freeradius" Mon May 19 09:14:13 2014 : Debug: radacctdir = "/var/log/radius/radacct" Mon May 19 09:14:13 2014 : Debug: hostname_lookups = no Mon May 19 09:14:13 2014 : Debug: max_request_time = 15 Mon May 19 09:14:13 2014 : Debug: cleanup_delay = 15 Mon May 19 09:14:13 2014 : Debug: max_requests = 150000 Mon May 19 09:14:13 2014 : Debug: pidfile = "/var/run/radiusd/radiusd.pid" Mon May 19 09:14:13 2014 : Debug: checkrad = "/usr/sbin/checkrad" Mon May 19 09:14:13 2014 : Debug: debug_level = 0 Mon May 19 09:14:13 2014 : Debug: proxy_requests = no Mon May 19 09:14:13 2014 : Debug: log { Mon May 19 09:14:13 2014 : Debug: stripped_names = no Mon May 19 09:14:13 2014 : Debug: auth = no Mon May 19 09:14:13 2014 : Debug: auth_badpass = no Mon May 19 09:14:13 2014 : Debug: auth_goodpass = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: security { Mon May 19 09:14:13 2014 : Debug: max_attributes = 200 Mon May 19 09:14:13 2014 : Debug: reject_delay = 5 Mon May 19 09:14:13 2014 : Debug: status_server = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: radiusd: #### Loading Realms and Home Servers #### Mon May 19 09:14:13 2014 : Debug: radiusd: #### Loading Clients #### Mon May 19 09:14:13 2014 : Debug: radiusd: #### Instantiating modules #### Mon May 19 09:14:13 2014 : Debug: instantiate { Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_expr, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_expr Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "expr" from file /etc/raddb/modules/expr Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: radiusd: #### Loading Virtual Servers #### Mon May 19 09:14:13 2014 : Debug: server { # from file /etc/raddb/radiusd.conf Mon May 19 09:14:13 2014 : Debug: modules { Mon May 19 09:14:13 2014 : Debug: } # modules Mon May 19 09:14:13 2014 : Debug: } # server Mon May 19 09:14:13 2014 : Debug: server Server-1 { # from file /etc/raddb/sites-enabled/partner-1 Mon May 19 09:14:13 2014 : Debug: modules { Mon May 19 09:14:13 2014 : Debug: Module: Creating Post-Auth-Type = REJECT Mon May 19 09:14:13 2014 : Debug: Module: Checking authenticate {...} for more modules to load Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_pap, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_pap Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "pap" from file /etc/raddb/modules/pap Mon May 19 09:14:13 2014 : Debug: pap { Mon May 19 09:14:13 2014 : Debug: encryption_scheme = "auto" Mon May 19 09:14:13 2014 : Debug: auto_header = yes Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_chap, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_chap Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "chap" from file /etc/raddb/modules/chap Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_mschap, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_mschap Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "mschap" from file /etc/raddb/modules/mschap Mon May 19 09:14:13 2014 : Debug: mschap { Mon May 19 09:14:13 2014 : Debug: use_mppe = yes Mon May 19 09:14:13 2014 : Debug: require_encryption = no Mon May 19 09:14:13 2014 : Debug: require_strong = no Mon May 19 09:14:13 2014 : Debug: with_ntdomain_hack = no Mon May 19 09:14:13 2014 : Debug: allow_retry = yes Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_eap, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_eap Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "eap" from file /etc/raddb/eap.conf Mon May 19 09:14:13 2014 : Debug: eap { Mon May 19 09:14:13 2014 : Debug: default_eap_type = "md5" Mon May 19 09:14:13 2014 : Debug: timer_expire = 60 Mon May 19 09:14:13 2014 : Debug: ignore_unknown_eap_types = no Mon May 19 09:14:13 2014 : Debug: cisco_accounting_username_bug = no Mon May 19 09:14:13 2014 : Debug: max_sessions = 4096 Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: Module: Linked to sub-module rlm_eap_md5 Mon May 19 09:14:13 2014 : Debug: Module: Instantiating eap-md5 Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_attr_filter Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "attr_filter.access_challenge" from file /etc/raddb/modules/attr_filter Mon May 19 09:14:13 2014 : Debug: attr_filter attr_filter.access_challenge { Mon May 19 09:14:13 2014 : Debug: attrsfile = "/etc/raddb/attrs.access_challenge" Mon May 19 09:14:13 2014 : Debug: key = "%{User-Name}" Mon May 19 09:14:13 2014 : Debug: relaxed = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: reading pairlist file /etc/raddb/attrs.access_challenge Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_always, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_always Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "handled" from file /etc/raddb/modules/always Mon May 19 09:14:13 2014 : Debug: always handled { Mon May 19 09:14:13 2014 : Debug: rcode = "handled" Mon May 19 09:14:13 2014 : Debug: simulcount = 0 Mon May 19 09:14:13 2014 : Debug: mpp = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: Module: Checking authorize {...} for more modules to load Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_preprocess, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_preprocess Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "preprocess" from file /etc/raddb/modules/preprocess Mon May 19 09:14:13 2014 : Debug: preprocess { Mon May 19 09:14:13 2014 : Debug: with_ascend_hack = no Mon May 19 09:14:13 2014 : Debug: ascend_channels_per_line = 23 Mon May 19 09:14:13 2014 : Debug: with_ntdomain_hack = no Mon May 19 09:14:13 2014 : Debug: with_specialix_jetstream_hack = no Mon May 19 09:14:13 2014 : Debug: with_cisco_vsa_hack = no Mon May 19 09:14:13 2014 : Debug: with_alvarion_vsa_hack = no Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Debug: (Loaded rlm_sql, checking if it's valid) Mon May 19 09:14:13 2014 : Debug: Module: Linked to module rlm_sql Mon May 19 09:14:13 2014 : Debug: Module: Instantiating module "sql" from file /etc/raddb/sql.conf Mon May 19 09:14:13 2014 : Debug: sql { Mon May 19 09:14:13 2014 : Debug: driver = "rlm_sql_mysql" Mon May 19 09:14:13 2014 : Debug: server = "xxxx" Mon May 19 09:14:13 2014 : Debug: port = "3306" Mon May 19 09:14:13 2014 : Debug: login = "xxxx" Mon May 19 09:14:13 2014 : Debug: password = "xxxx" Mon May 19 09:14:13 2014 : Debug: radius_db = "xxxx" Mon May 19 09:14:13 2014 : Debug: read_groups = yes Mon May 19 09:14:13 2014 : Debug: sqltrace = no Mon May 19 09:14:13 2014 : Debug: sqltracefile = "/var/log/radius/sqltrace.sql" Mon May 19 09:14:13 2014 : Debug: readclients = no Mon May 19 09:14:13 2014 : Debug: deletestalesessions = yes Mon May 19 09:14:13 2014 : Debug: num_sql_socks = 100 Mon May 19 09:14:13 2014 : Debug: lifetime = 120 Mon May 19 09:14:13 2014 : Debug: max_queries = 1000 Mon May 19 09:14:13 2014 : Debug: sql_user_name = "%{User-Name}" Mon May 19 09:14:13 2014 : Debug: default_user_profile = "" Mon May 19 09:14:13 2014 : Debug: nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" Mon May 19 09:14:13 2014 : Debug: authorize_check_query = "CALL my_stored_procedure ('%{Virtual-Server}','AUTH_REQ' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: authorize_reply_query = "CALL my_stored_procedure ('%{Virtual-Server}','AUTH_REPL' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: authorize_group_check_query = "" Mon May 19 09:14:13 2014 : Debug: authorize_group_reply_query = "" Mon May 19 09:14:13 2014 : Debug: accounting_onoff_query = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_ONOFF','%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_update_query = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_UPDT' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_update_query_alt = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_UPDT' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_start_query = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_START','%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_start_query_alt = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_START','%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_stop_query = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_STOP' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: accounting_stop_query_alt = "CALL my_stored_procedure ('%{Virtual-Server}','ACCT_STOP' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: connect_failure_retry_delay = 60 Mon May 19 09:14:13 2014 : Debug: simul_count_query = "" Mon May 19 09:14:13 2014 : Debug: simul_verify_query = "" Mon May 19 09:14:13 2014 : Debug: postauth_query = "CALL my_stored_procedure ('%{Virtual-Server}','AUTH_POST' ,'%{User-Name}','%{Client-IP-Address}','%{Calling-Station-Id}','%{Acct-Session-Id}','%{NAS-Identifier}','%{Called-Station-Id}','%{Framed-Protocol}','%{Acct-Delay-Time}','%{Acct-Terminate-Cause}','%{Acct-Session-Time}','%{Acct-Output-Packets}','%{Acct-Input-Packets}','%{Cleartext-Password}','%{reply:Packet-Type}','%{Acct-Status-Type}')" Mon May 19 09:14:13 2014 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon May 19 09:14:13 2014 : Debug: } Mon May 19 09:14:13 2014 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon May 19 09:14:13 2014 : Info: rlm_sql (sql): Attempting to connect to xxxx@xxxx:3306/xxxx Mon May 19 09:14:13 2014 : Debug: rlm_sql (sql): starting 0 Mon May 19 09:14:13 2014 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 Mon May 19 09:14:13 2014 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon May 19 09:14:13 2014 : Info: rlm_sql (sql): Connected new DB handle, #0 ... starting the 100 connections ... Mon May 19 09:14:14 2014 : Debug: rlm_sql (sql): starting 99 Mon May 19 09:14:14 2014 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #99 Mon May 19 09:14:14 2014 : Info: rlm_sql_mysql: Starting connect to MySQL server for #99 Mon May 19 09:14:14 2014 : Info: rlm_sql (sql): Connected new DB handle, #99 Mon May 19 09:14:14 2014 : Debug: Module: Checking preacct {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Mon May 19 09:14:14 2014 : Debug: Module: Linked to module rlm_acct_unique Mon May 19 09:14:14 2014 : Debug: Module: Instantiating module "acct_unique" from file /etc/raddb/modules/acct_unique Mon May 19 09:14:14 2014 : Debug: acct_unique { Mon May 19 09:14:14 2014 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port" Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: Module: Checking accounting {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /etc/raddb/modules/attr_filter Mon May 19 09:14:14 2014 : Debug: attr_filter attr_filter.accounting_response { Mon May 19 09:14:14 2014 : Debug: attrsfile = "/etc/raddb/attrs.accounting_response" Mon May 19 09:14:14 2014 : Debug: key = "%{User-Name}" Mon May 19 09:14:14 2014 : Debug: relaxed = no Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: reading pairlist file /etc/raddb/attrs.accounting_response Mon May 19 09:14:14 2014 : Debug: Module: Checking post-auth {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /etc/raddb/modules/attr_filter Mon May 19 09:14:14 2014 : Debug: attr_filter attr_filter.access_reject { Mon May 19 09:14:14 2014 : Debug: attrsfile = "/etc/raddb/attrs.access_reject" Mon May 19 09:14:14 2014 : Debug: key = "%{User-Name}" Mon May 19 09:14:14 2014 : Debug: relaxed = no Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: reading pairlist file /etc/raddb/attrs.access_reject Mon May 19 09:14:14 2014 : Debug: } # modules Mon May 19 09:14:14 2014 : Debug: } # server Mon May 19 09:14:14 2014 : Debug: server Status-Server { # from file /etc/raddb/sites-enabled/admin-status Mon May 19 09:14:14 2014 : Debug: modules { Mon May 19 09:14:14 2014 : Debug: Module: Creating Autz-Type = Status-Server Mon May 19 09:14:14 2014 : Debug: Module: Checking authorize {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: } # modules Mon May 19 09:14:14 2014 : Debug: } # server Mon May 19 09:14:14 2014 : Debug: server PPTP-Server { # from file /etc/raddb/sites-enabled/admin-pptpserver Mon May 19 09:14:14 2014 : Debug: modules { Mon May 19 09:14:14 2014 : Debug: Module: Checking authenticate {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking authorize {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking preacct {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking accounting {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking post-auth {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: } # modules Mon May 19 09:14:14 2014 : Debug: } # server Mon May 19 09:14:14 2014 : Debug: server Server-2 { # from file /etc/raddb/sites-enabled/partner-2 Mon May 19 09:14:14 2014 : Debug: modules { Mon May 19 09:14:14 2014 : Debug: Module: Checking authenticate {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking authorize {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking preacct {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking accounting {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: Module: Checking post-auth {...} for more modules to load Mon May 19 09:14:14 2014 : Debug: } # modules Mon May 19 09:14:14 2014 : Debug: } # server Mon May 19 09:14:14 2014 : Debug: radiusd: #### Opening IP addresses and Ports #### Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "auth" Mon May 19 09:14:14 2014 : Debug: ipaddr = * Mon May 19 09:14:14 2014 : Debug: port = 1812 Mon May 19 09:14:14 2014 : Debug: client 0.0.0.0/0 { Mon May 19 09:14:14 2014 : Debug: require_message_authenticator = no Mon May 19 09:14:14 2014 : Debug: secret = "xxxx" Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "acct" Mon May 19 09:14:14 2014 : Debug: ipaddr = * Mon May 19 09:14:14 2014 : Debug: port = 1813 Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "status" Mon May 19 09:14:14 2014 : Debug: ipaddr = 127.0.0.1 Mon May 19 09:14:14 2014 : Debug: port = 1801 Mon May 19 09:14:14 2014 : Debug: client 127.0.0.1/32 { Mon May 19 09:14:14 2014 : Debug: require_message_authenticator = no Mon May 19 09:14:14 2014 : Debug: secret = "xxxx" Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "auth" Mon May 19 09:14:14 2014 : Debug: ipaddr = * Mon May 19 09:14:14 2014 : Debug: port = 1802 Mon May 19 09:14:14 2014 : Debug: client X.X.X.X/X { Mon May 19 09:14:14 2014 : Debug: require_message_authenticator = no Mon May 19 09:14:14 2014 : Debug: secret = "xxxx" Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "auth" Mon May 19 09:14:14 2014 : Debug: ipaddr = * Mon May 19 09:14:14 2014 : Debug: port = 1822 Mon May 19 09:14:14 2014 : Debug: client 0.0.0.0/0 { Mon May 19 09:14:14 2014 : Debug: require_message_authenticator = no Mon May 19 09:14:14 2014 : Debug: secret = "xxxx" Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: listen { Mon May 19 09:14:14 2014 : Debug: type = "acct" Mon May 19 09:14:14 2014 : Debug: ipaddr = * Mon May 19 09:14:14 2014 : Debug: port = 1823 Mon May 19 09:14:14 2014 : Debug: } Mon May 19 09:14:14 2014 : Debug: Listening on authentication address * port 1812 as server Server-1 Mon May 19 09:14:14 2014 : Debug: Listening on accounting address * port 1813 as server Server-1 Mon May 19 09:14:14 2014 : Debug: Listening on status address 127.0.0.1 port 1801 as server Status-Server Mon May 19 09:14:14 2014 : Debug: Listening on authentication address * port 1802 as server PPTP-Server Mon May 19 09:14:14 2014 : Debug: Listening on authentication address * port 1822 as server Server-2 Mon May 19 09:14:14 2014 : Debug: Listening on accounting address * port 1823 as server Server-2 Mon May 19 09:14:14 2014 : Info: Ready to process requests.
Alan -- Sent from my Android device with K-9 Mail. Please excuse my brevity.
Hi,
What you sent is of little help. Output of radiusd -X should be from the server start up through to the failure you are looking at. ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
your output stopped at
Mon May 19 09:14:14 2014 : Info: Ready to process requests.
..pointless. just pointless :( alan
-----Original Message----- From: A.L.M.Buxey@lboro.ac.uk [mailto:A.L.M.Buxey@lboro.ac.uk] Sent: lundi 19 mai 2014 10:33 To: Contact (COEXSI) Cc: 'FreeRadius users mailing list' Subject: Re: VSA attributes sent with Access-Reject response
Hi,
What you sent is of little help. Output of radiusd -X should be from the server start up through to the failure you are looking at. ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
your output stopped at
Mon May 19 09:14:14 2014 : Info: Ready to process requests.
..pointless. just pointless :(
Dear Alan, No so pointless... In a previous message in that thread, I've sent the debug output when the query is received (first RADIUS packet of the EAP exchange). There is nothing between these two group of messages (even if there were not captured at the same time). Sebastien.
alan
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan Buxey
-
Alan DeKok -
Contact (COEXSI)