- Freeradius-Users - lists.freeradius.org

virtual_server and the default server
by Alan Buxey 14 Oct '09

14 Oct '09

hi, this message is regarding the virtual_server definition in the clients section.... this allows you to point a client request directly to a virtual server. handy. okay - been trying to use this partially buried feature with clients in an SQL table if I add the special 'server' column (commented out in the schema by default) to the SQL table and then update the NAS query in dialup.conf (note, the server must be the last argument on the select query!) then add a named entry for a chosen client then its fine but, if I then query the server from a client that doesnt have a 'server' entry then it doesnt work..... this is what i get (all the startup stuff deleted) server { No such virtual server Invalid user: [testuser] (from client bigbox port 0) } # server Using Post-Auth-Type Reject No such virtual server Delaying reject of request 0 for 1 seconds Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 0 Sending Access-Reject of id 155 to 192.168.10.1 port 36684 Waking up in 4.9 seconds. if I go through and add 'default' to the virtual_server entry for all other clients then things still dont work - no such server : server default { No such virtual server default Invalid user: [testuser] (from client bigbox port 0) } # server default Using Post-Auth-Type Reject No such virtual server default Delaying reject of request 0 for 1 seconds Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 0 Sending Access-Reject of id 57 to 192.168.10.1 port 57991 Waking up in 4.9 seconds. but then if i add the 'server' wrapper around the sites-enabled/default ie server default { {rest of default server config } then it all works....this means that 2 presumptions are wrong: i thought that a blank virtual_server entry would be handled by default server i thought that the default server was known as 'default' i've obviously already been corrected by my trial and error...i'd rather not have been burned like this..but hey, we live and learn... but I am a little concerned by the 'no entry' failing - this means I have to edit a few more files to get things working as expected.... alan

1 0

FreeRADIUS Cluster && MySQL Webinar: online!
by Alan DeKok 14 Oct '09

14 Oct '09

The webinar is now recorded, and available online: http://www.mysql.com/news-and-events/on-demand-webinars/display-od-419.html Anyone wanting to know more about cluster performance should check it out. Alan DeKok.

1 0

errors There are no DB handles to use and Discarding conflicting packet from client
by Alisson 14 Oct '09

14 Oct '09

Hi, I have a dedicated server with freeradius 2.05 i'm getting 2 errors Error: Discarding conflicting packet from client net port 25000 - ID: 100 due to recent request 7343. There are no DB handles to use! skipped 0, tried to connect 0 I'm searching on the forums and a lot of people has this problem.. I change sql_num_socks = 30 I increase the max_connections=5000000 I increase everything that what was possible but the problem still happens I see on the forums in alot of web sites and nobody has the solution somebody can help? -- View this message in context: http://www.nabble.com/errors-There-are-no-DB-handles-to-use-and-Discarding-… Sent from the FreeRadius - User mailing list archive at Nabble.com.

6 19

Failed to bind to proxy address (port 1815)
by Stefan Winter 14 Oct '09

14 Oct '09

Hi, I'm facing a rather annoying and mysterious issue here right now (FR 2.1.7) Wed Oct 14 14:20:05 2009 : Error: Failed binding to proxy address * port 1815: Address already in use Wed Oct 14 14:22:50 2009 : Error: Failed binding to proxy address * port 1815: Address already in use Wed Oct 14 14:24:33 2009 : Error: Failed binding to proxy address * port 1815: Address already in use Wed Oct 14 14:25:27 2009 : Error: Failed binding to proxy address * port 1815: Address already in use Kept coming up multiple times per second half an hour ago, and now sporadically (see timestamps above). netstat -tunelup shows that FR bind'ed itself to *:1815 (but still the messages kept coming). Seems like it tried to re-open its own port over and over again. Restarting fixed it, at least momentarily (and it left port 1815 alone after the restart). But I do wonder what this error message means. The instance's dedicated proxy port is 1814. Could the error message mean that it exceeded its 256 packets-in-flight, overflowed to the next source port, and got bind to the source port wrong? About the only thing I can imagine. The error remained undetected for some time - the affected requests got an unjustified reject, that was the only trace that got me looking into it. Any insight would be very much appreciated. Greetings, Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473

2 1

Re: Munin Graphs
by Neville 14 Oct '09

14 Oct '09

> Hi, > >> I've installed the freeradius_auth plugin >> >> added to plugins.conf >> >> [freeradius*] >> user root >> >> But still I get the following error when the plugin is run... >> >> radmin: Failed connecting to /usr/local/var/run/radiusd/radiusd.sock: >> Permission denied > > edit the munin/plugins/freeradius* files and put the correct user into > the RADMIN= part. you really should NEVER be using the root user - > simply use the user that you run radiusd as (once again, should never be > root) - check the radiusd.sock to see who/what owns it (ls -l > /usr/local/var/run/radiusd/radiusd.sock) Thx Alan, the problem is that the radiusd is owned by root, so not quite sure how to ensure at system startup that /etc/init.d/radiusd is actual run by the radiusd user in /etc/passwd. I've done a chown -R radiusd:radiusd on the programme and /usr/local/etc/raddb, but this the radiusd.sock file is owned by root. Thx Nev

4 3

dynamic crl fetching
by console23 14 Oct '09

14 Oct '09

Hello, is or will there be a feature called "dynamic crl fetching" in FreeRADIUS 2.x ? Strongswan for example is able to fetch actual crls via http and ldap. In the wiki i only could get information about defining local stored pem files. regards, Simon

2 1

Odd proxy authentication failures
by Michael Schlies 14 Oct '09

14 Oct '09

Hello all, I seem to be running into an issue with a RADIUS setup I am doing. I am setting up a server that hosts 5 radius instances in 1.x and does realm proxying to 4 of them but uses one realm (realm 'a.com' in this case) as its default. so if requests for 'b.com', 'c.com', etc come in they get relayed on to their radius server and that result is relayed back to the NAS. In 2.0 I want to merge these separate instances into a single instance using virtual servers. The problem I am running into is I can see that accounts are being successfully authenticated on the virtual servers however the home server is returning Access-Reject unless the user authenticated is one of its local users... Here is what I have come up with so far... /etc/freeradius/radiusd.conf: prefix = /usr exec_prefix = /usr sysconfdir = /etc localstatedir = /var sbindir = ${exec_prefix}/sbin logdir = /var/log/freeradius raddbdir = /etc/freeradius radacctdir = ${logdir}/radacct confdir = ${raddbdir} run_dir = ${localstatedir}/run/freeradius db_dir = $(raddbdir) libdir = /usr/lib/freeradius pidfile = ${run_dir}/freeradius.pid user = freerad group = freerad max_request_time = 30 cleanup_delay = 5 max_requests = 1024 listen { type = auth ipaddr = * port = 0 } listen { ipaddr = * port = 0 type = acct } hostname_lookups = no allow_core_dumps = no regular_expressions = yes extended_expressions = yes log { ... } checkrad = ${sbindir}/checkrad security { max_attributes = 200 reject_delay = 1 status_server = yes } proxy_requests = yes $INCLUDE proxy.conf snmp = no thread pool { start_servers = 5 max_servers = 32 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 0 } modules { pap { auto_header = no } chap { authtype = CHAP } $INCLUDE eap.conf realm IPASS { format = prefix delimiter = "/" ignore_default = yes ignore_null = yes } realm suffix { format = suffix delimiter = "@" ignore_default = yes ignore_null = yes } checkval { item-name = Calling-Station-Id check-name = Calling-Station-Id data-type = string } preprocess { hints = ${confdir}/hints with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no } files { usersfile = ${confdir}/users acctusersfile = ${confdir}/acct_users preproxy_usersfile = ${confdir}/preproxy_users compat = no } detail { detailfile = ${radacctdir}/%{Client-IP-Address}/detail-%Y%m%d detailperm = 0600 header = "%t" } detail pre_proxy_log { detailfile = ${radacctdir}/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d } detail post_proxy_log { detailfile = /tmp/post-proxy-detail detailperm = 0600 } acct_unique { key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" } $INCLUDE sql-*.conf radutmp { filename = ${logdir}/radutmp username = %{User-Name} case_sensitive = yes check_with_nas = yes perm = 0600 callerid = "yes" } radutmp sradutmp { filename = ${logdir}/sradutmp perm = 0644 callerid = "no" } attr_filter attr_filter.post-proxy { attrsfile = ${confdir}/attrs } attr_filter attr_filter.pre-proxy { attrsfile = ${confdir}/attrs.pre-proxy } attr_filter attr_filter.access_reject { key = %{User-Name} attrsfile = ${confdir}/attrs.access_reject } attr_filter attr_filter.accounting_response { key = %{User-Name} attrsfile = ${confdir}/attrs.accounting_response } always fail { rcode = fail } always reject { rcode = reject } always noop { rcode = noop } always handled { rcode = handled } always updated { rcode = updated } always notfound { rcode = notfound } always ok { rcode = ok simulcount = 0 mpp = no } expr { } digest { } expiration { reply-message = "Password Has Expired\r\n" } logintime { reply-message = "You are calling outside your allowed timespan\r\n" minimum-timeout = 60 } exec { wait = yes input_pairs = request shell_escape = yes output = none } exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = request output_pairs = reply shell_escape = yes } } instantiate { exec expr expiration logintime } $INCLUDE sites-enabled/ /etc/freeradius/sql-a.conf: sql sql-a{ database = "mysql" driver = "rlm_sql_${database}" server = "192.168.188.3" login = "radius" password = "radiuspass" radius_db = "radius" acct_table1 = "radacct" acct_table2 = "radacct" postauth_table = "radpostauth" authcheck_table = "radcheck" authreply_table = "radreply" groupcheck_table = "radgroupcheck" groupreply_table = "radgroupreply" usergroup_table = "usergroup" deletestalesessions = yes sqltrace = yes sqltracefile = /tmp/sqltrace.sql num_sql_socks = 5 connect_failure_retry_delay = 60 readclients = yes nas_table = "nas" $INCLUDE sql/${database}/dialup.conf } /etc/freeradius/sql-b.conf: sql sql-a{ database = "mysql" driver = "rlm_sql_${database}" server = "192.168.188.3" login = "radius" password = "radiuspass" radius_db = "radius_b" acct_table1 = "radacct" acct_table2 = "radacct" postauth_table = "radpostauth" authcheck_table = "radcheck" authreply_table = "radreply" groupcheck_table = "radgroupcheck" groupreply_table = "radgroupreply" usergroup_table = "usergroup" deletestalesessions = yes sqltrace = yes sqltracefile = /tmp/sqltrace.sql num_sql_socks = 5 connect_failure_retry_delay = 60 readclients = yes nas_table = "nas" $INCLUDE sql/${database}/dialup.conf } ... /etc/freeradius/sql-e.conf: sql sql-a{ database = "mysql" driver = "rlm_sql_${database}" server = "192.168.188.3" login = "radius" password = "radiuspass" radius_db = "radius_e" acct_table1 = "radacct" acct_table2 = "radacct" postauth_table = "radpostauth" authcheck_table = "radcheck" authreply_table = "radreply" groupcheck_table = "radgroupcheck" groupreply_table = "radgroupreply" usergroup_table = "usergroup" deletestalesessions = yes sqltrace = yes sqltracefile = /tmp/sqltrace.sql num_sql_socks = 5 connect_failure_retry_delay = 60 readclients = yes nas_table = "nas" $INCLUDE sql/${database}/dialup.conf } /etc/freeradius/sql/mysql/dialup.conf: sql_user_name = "%{User-Name}" default_user_profile = "DEFAULT" nas_query = "SELECT id, nasname, shortname, type, secret FROM ${nas_table}" authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM ${authcheck_table} WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM ${authreply_table} WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_group_check_query = "SELECT ${groupcheck_table}.id, ${groupcheck_table}.GroupName, ${groupcheck_table}.Attribute, ${groupcheck_table}.Value, ${groupcheck_table}.op FROM ${groupcheck_table}, ${usergroup_table} WHERE ${usergroup_table}.Username = '%{SQL-User-Name}' AND ${usergroup_table}.GroupName = ${groupcheck_table}.GroupName AND ${groupcheck_table}.HuntgroupName = '%{Huntgroup-Name}' ORDER BY ${groupcheck_table}.id" authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM ${groupreply_table} WHERE GroupName = '%{Sql-Group}' ORDER BY id" accounting_onoff_query = "UPDATE ${acct_table1} SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" accounting_update_query = "UPDATE ${acct_table1} \ SET FramedIPAddress = '%{Framed-IP-Address}', \ AcctSessionTime = '%{Acct-Session-Time}', \ AcctInputOctets = '%{Acct-Input-Octets}', \ AcctOutputOctets = '%{Acct-Output-Octets}' \ WHERE AcctSessionId = '%{Acct-Session-Id}' \ AND UserName = '%{SQL-User-Name}' \ AND NASIPAddress= '%{NAS-IP-Address}'" accounting_update_query_alt = "INSERT into ${acct_table1} (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" accounting_start_query = "INSERT into ${acct_table1} (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" accounting_start_query_alt = "UPDATE ${acct_table1} SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" accounting_stop_query = "UPDATE ${acct_table2} SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" accounting_stop_query_alt = "INSERT into ${acct_table2} (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" simul_count_query = "SELECT COUNT(*) FROM ${acct_table1} WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM ${acct_table1} WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" group_membership_query = "SELECT GroupName FROM ${usergroup_table} WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" /etc/freeradius/sites-enabled/virtuals: server a { $INCLUDE ${confdir}/sites-available/a } server b { $INCLUDE ${confdir}/sites-available/b } server c { $INCLUDE ${confdir}/sites-available/c } server d { $INCLUDE ${confdir}/sites-available/d } server e { $INCLUDE ${confdir}/sites-available/e } /etc/freeradius/sites-enabled/a: checkrad = ${raddbdir}/checkrad-a authorize { preprocess update request { Huntgroup-Name := "%{sql-a:SELECT huntgroup FROM nas WHERE nasname=\"%{NAS-IP-Address}\"}" } chap IPASS { updated = return ok = return } suffix { updated = return ok = return } files sql-a } authenticate { Auth-Type PAP { pap } } preacct { preprocess acct_unique suffix files } accounting { sql-a } session { sql-a } post-auth { sql-a } pre-proxy { pre_proxy_log } post-proxy { post_proxy_log # attr_filter.post-proxy } /etc/freeradius/sites-available/b: checkrad = ${raddbdir}/checkrad-b authorize { preprocess update request { Huntgroup-Name := "%{sql-b:SELECT huntgroup FROM allnas WHERE nasname=\"%{NAS-IP-Address}\"}" } chap IPASS { updated = return ok = return } suffix { updated = return ok = return } files sql-b } authenticate { Auth-Type PAP { pap } } preacct { preprocess acct_unique suffix files } accounting { sql-b } session { sql-b } post-auth { sql-b } pre-proxy { pre_proxy_log } post-proxy { } /etc/freeradius/sites-available/c: checkrad = ${raddbdir}/checkrad-c authorize { preprocess update request { Huntgroup-Name := "%{sql-c:SELECT huntgroup FROM allnas WHERE nasname=\"%{NAS-IP-Address}\"}" } chap IPASS { updated = return ok = return } suffix { updated = return ok = return } files sql-c } authenticate { Auth-Type PAP { pap } } preacct { preprocess acct_unique suffix files } accounting { sql-c } session { sql-c } post-auth { sql-c } pre-proxy { pre_proxy_log } post-proxy { } /etc/freeradius/sites-available/d: checkrad = ${raddbdir}/checkrad-d authorize { preprocess update request { Huntgroup-Name := "%{sql-d:SELECT huntgroup FROM allnas WHERE nasname=\"%{NAS-IP-Address}\"}" } chap IPASS { updated = return ok = return } suffix { updated = return ok = return } files sql-d } authenticate { Auth-Type PAP { pap } } preacct { preprocess acct_unique suffix files } accounting { sql-d } session { sql-d } post-auth { sql-d } pre-proxy { pre_proxy_log } post-proxy { } /etc/freeradius/sites-available/e: checkrad = ${raddbdir}/checkrad-e authorize { preprocess update request { Huntgroup-Name := "%{sql-e:SELECT huntgroup FROM allnas WHERE nasname=\"%{NAS-IP-Address}\"}" } chap IPASS { updated = return ok = return } suffix { updated = return ok = return } files sql-e } authenticate { Auth-Type PAP { pap } } preacct { preprocess acct_unique suffix files } accounting { sql-e } session { sql-e } post-auth { sql-e } pre-proxy { pre_proxy_log } post-proxy { } The log messages I am seeing are as follows: Mon Oct 12 13:39:36 2009 : Info: FreeRADIUS Version 2.0.4, for host x86_64-pc-linux-gnu, built on Sep 7 2008 at 17:42:33 Mon Oct 12 13:39:36 2009 : Info: Starting - reading configuration files ... Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/radiusd.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/proxy.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/snmp.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/eap.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql-a.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql-d.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql-b.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql-c.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql-e.conf Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Mon Oct 12 13:39:36 2009 : Debug: including files in directory /etc/freeradius/sites-enabled/ Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-enabled/a Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-enabled/virtuals Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-available/a Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-available/d Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-available/c Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-available/b Mon Oct 12 13:39:36 2009 : Debug: including configuration file /etc/freeradius/sites-available/e Mon Oct 12 13:39:36 2009 : Debug: including dictionary file /etc/freeradius/dictionary Mon Oct 12 13:39:36 2009 : Debug: main { Mon Oct 12 13:39:36 2009 : Debug: prefix = "/usr" Mon Oct 12 13:39:36 2009 : Debug: localstatedir = "/var" Mon Oct 12 13:39:36 2009 : Debug: logdir = "/var/log/freeradius" Mon Oct 12 13:39:36 2009 : Debug: libdir = "/usr/lib/freeradius" Mon Oct 12 13:39:36 2009 : Debug: radacctdir = "/var/log/freeradius/radacct" Mon Oct 12 13:39:36 2009 : Debug: hostname_lookups = no Mon Oct 12 13:39:36 2009 : Debug: max_request_time = 30 Mon Oct 12 13:39:36 2009 : Debug: cleanup_delay = 5 Mon Oct 12 13:39:36 2009 : Debug: max_requests = 1024 Mon Oct 12 13:39:36 2009 : Debug: allow_core_dumps = no Mon Oct 12 13:39:36 2009 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Mon Oct 12 13:39:36 2009 : Debug: user = "freerad" Mon Oct 12 13:39:36 2009 : Debug: group = "freerad" Mon Oct 12 13:39:36 2009 : Debug: checkrad = "/usr/sbin/checkrad" Mon Oct 12 13:39:36 2009 : Debug: debug_level = 0 Mon Oct 12 13:39:36 2009 : Debug: proxy_requests = yes Mon Oct 12 13:39:36 2009 : Debug: security { Mon Oct 12 13:39:36 2009 : Debug: max_attributes = 200 Mon Oct 12 13:39:36 2009 : Debug: reject_delay = 1 Mon Oct 12 13:39:36 2009 : Debug: status_server = yes Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Loading Realms and Home Servers #### Mon Oct 12 13:39:36 2009 : Debug: proxy server { Mon Oct 12 13:39:36 2009 : Debug: retry_delay = 5 Mon Oct 12 13:39:36 2009 : Debug: retry_count = 3 Mon Oct 12 13:39:36 2009 : Debug: default_fallback = no Mon Oct 12 13:39:36 2009 : Debug: dead_time = 120 Mon Oct 12 13:39:36 2009 : Debug: wake_all_if_all_dead = no Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm example.com { Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm NULL { Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm DEFAULT { Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm a.com { Mon Oct 12 13:39:36 2009 : Debug: virtual_server = a Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm b.com { Mon Oct 12 13:39:36 2009 : Debug: virtual_server = b Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm c.com { Mon Oct 12 13:39:36 2009 : Debug: virtual_server = c Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm d.com { Mon Oct 12 13:39:36 2009 : Debug: virtual_server = d Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: realm e.com { Mon Oct 12 13:39:36 2009 : Debug: virtual_server = e Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Instantiating modules #### Mon Oct 12 13:39:36 2009 : Debug: instantiate { Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_exec, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_exec Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating exec Mon Oct 12 13:39:36 2009 : Debug: exec { Mon Oct 12 13:39:36 2009 : Debug: wait = yes Mon Oct 12 13:39:36 2009 : Debug: input_pairs = "request" Mon Oct 12 13:39:36 2009 : Debug: shell_escape = yes Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_expr, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_expr Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating expr Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_expiration, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_expiration Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating expiration Mon Oct 12 13:39:36 2009 : Debug: expiration { Mon Oct 12 13:39:36 2009 : Debug: reply-message = "Password Has Expired " Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_logintime, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_logintime Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating logintime Mon Oct 12 13:39:36 2009 : Debug: logintime { Mon Oct 12 13:39:36 2009 : Debug: reply-message = "You are calling outside your allowed timespan " Mon Oct 12 13:39:36 2009 : Debug: minimum-timeout = 60 Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Loading Virtual Servers #### Mon Oct 12 13:39:36 2009 : Debug: server a { Mon Oct 12 13:39:36 2009 : Debug: modules { Mon Oct 12 13:39:36 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_pap, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_pap Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating pap Mon Oct 12 13:39:36 2009 : Debug: pap { Mon Oct 12 13:39:36 2009 : Debug: encryption_scheme = "auto" Mon Oct 12 13:39:36 2009 : Debug: auto_header = no Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_preprocess, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_preprocess Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating preprocess Mon Oct 12 13:39:36 2009 : Debug: preprocess { Mon Oct 12 13:39:36 2009 : Debug: huntgroups = "/etc/freeradius/huntgroups" Mon Oct 12 13:39:36 2009 : Debug: hints = "/etc/freeradius/hints" Mon Oct 12 13:39:36 2009 : Debug: with_ascend_hack = no Mon Oct 12 13:39:36 2009 : Debug: ascend_channels_per_line = 23 Mon Oct 12 13:39:36 2009 : Debug: with_ntdomain_hack = no Mon Oct 12 13:39:36 2009 : Debug: with_specialix_jetstream_hack = no Mon Oct 12 13:39:36 2009 : Debug: with_cisco_vsa_hack = no Mon Oct 12 13:39:36 2009 : Debug: with_alvarion_vsa_hack = no Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_chap, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_chap Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating chap Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_realm, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_realm Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating IPASS Mon Oct 12 13:39:36 2009 : Debug: realm IPASS { Mon Oct 12 13:39:36 2009 : Debug: format = "prefix" Mon Oct 12 13:39:36 2009 : Debug: delimiter = "/" Mon Oct 12 13:39:36 2009 : Debug: ignore_default = yes Mon Oct 12 13:39:36 2009 : Debug: ignore_null = yes Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating suffix Mon Oct 12 13:39:36 2009 : Debug: realm suffix { Mon Oct 12 13:39:36 2009 : Debug: format = "suffix" Mon Oct 12 13:39:36 2009 : Debug: delimiter = "@" Mon Oct 12 13:39:36 2009 : Debug: ignore_default = yes Mon Oct 12 13:39:36 2009 : Debug: ignore_null = yes Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_files, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_files Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating files Mon Oct 12 13:39:36 2009 : Debug: files { Mon Oct 12 13:39:36 2009 : Debug: acctusersfile = "/etc/freeradius/acct_users" Mon Oct 12 13:39:36 2009 : Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Mon Oct 12 13:39:36 2009 : Debug: compat = "no" Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_sql, checking if it's valid) Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_sql Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating sql-a Mon Oct 12 13:39:36 2009 : Debug: sql sql-a { Mon Oct 12 13:39:36 2009 : Debug: driver = "rlm_sql_mysql" Mon Oct 12 13:39:36 2009 : Debug: server = "192.168.188.3" Mon Oct 12 13:39:36 2009 : Debug: port = "" Mon Oct 12 13:39:36 2009 : Debug: login = "radius" Mon Oct 12 13:39:36 2009 : Debug: password = "radiuspass" Mon Oct 12 13:39:36 2009 : Debug: radius_db = "radius" Mon Oct 12 13:39:36 2009 : Debug: read_groups = yes Mon Oct 12 13:39:36 2009 : Debug: sqltrace = yes Mon Oct 12 13:39:36 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql" Mon Oct 12 13:39:36 2009 : Debug: readclients = yes Mon Oct 12 13:39:36 2009 : Debug: deletestalesessions = yes Mon Oct 12 13:39:36 2009 : Debug: num_sql_socks = 5 Mon Oct 12 13:39:36 2009 : Debug: sql_user_name = "%{User-Name}" Mon Oct 12 13:39:36 2009 : Debug: default_user_profile = "DEFAULT" Mon Oct 12 13:39:36 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Mon Oct 12 13:39:36 2009 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:36 2009 : Debug: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:36 2009 : Debug: authorize_group_check_query = "SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id" Mon Oct 12 13:39:36 2009 : Debug: authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id" Mon Oct 12 13:39:36 2009 : Debug: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" Mon Oct 12 13:39:36 2009 : Debug: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP-Address}'" Mon Oct 12 13:39:36 2009 : Debug: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" Mon Oct 12 13:39:36 2009 : Debug: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" Mon Oct 12 13:39:36 2009 : Debug: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:36 2009 : Debug: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:36 2009 : Debug: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" Mon Oct 12 13:39:36 2009 : Debug: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" Mon Oct 12 13:39:36 2009 : Debug: connect_failure_retry_delay = 60 Mon Oct 12 13:39:36 2009 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:36 2009 : Debug: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:36 2009 : Debug: postauth_query = "" Mon Oct 12 13:39:36 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon Oct 12 13:39:36 2009 : Debug: } Mon Oct 12 13:39:36 2009 : Info: rlm_sql (sql-a): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Oct 12 13:39:36 2009 : Info: rlm_sql (sql-a): Attempting to connect to radius@192.168.188.3:/radius Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): starting 0 Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): Attempting to connect rlm_sql_mysql #0 Mon Oct 12 13:39:36 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): Connected new DB handle, #0 ... Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): starting 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Attempting to connect rlm_sql_mysql #4 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Connected new DB handle, #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Processing generate_sql_clients Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Reserving sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Read entry nasname=127.0.0.1,shortname=Mike Test,secret=secret Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Adding client 127.0.0.1 (Mike Test, server=<none>) to clients list Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Released sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_acct_unique Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating acct_unique Mon Oct 12 13:39:37 2009 : Debug: acct_unique { Mon Oct 12 13:39:37 2009 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_detail, checking if it's valid) Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_detail Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating pre_proxy_log Mon Oct 12 13:39:37 2009 : Debug: detail pre_proxy_log { Mon Oct 12 13:39:37 2009 : Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d" Mon Oct 12 13:39:37 2009 : Debug: header = "%t" Mon Oct 12 13:39:37 2009 : Debug: detailperm = 384 Mon Oct 12 13:39:37 2009 : Debug: dirperm = 493 Mon Oct 12 13:39:37 2009 : Debug: locking = no Mon Oct 12 13:39:37 2009 : Debug: log_packet_header = no Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating post_proxy_log Mon Oct 12 13:39:37 2009 : Debug: detail post_proxy_log { Mon Oct 12 13:39:37 2009 : Debug: detailfile = "/tmp/post-proxy-detail" Mon Oct 12 13:39:37 2009 : Debug: header = "%t" Mon Oct 12 13:39:37 2009 : Debug: detailperm = 384 Mon Oct 12 13:39:37 2009 : Debug: dirperm = 493 Mon Oct 12 13:39:37 2009 : Debug: locking = no Mon Oct 12 13:39:37 2009 : Debug: log_packet_header = no Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_attr_filter Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating attr_filter.post-proxy Mon Oct 12 13:39:37 2009 : Debug: attr_filter attr_filter.post-proxy { Mon Oct 12 13:39:37 2009 : Debug: attrsfile = "/etc/freeradius/attrs" Mon Oct 12 13:39:37 2009 : Debug: key = "%{Realm}" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: server d { Mon Oct 12 13:39:37 2009 : Debug: modules { Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-d Mon Oct 12 13:39:37 2009 : Debug: sql sql-d { Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql" Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3" Mon Oct 12 13:39:37 2009 : Debug: port = "" Mon Oct 12 13:39:37 2009 : Debug: login = "radius" Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass" Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_d" Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql" Mon Oct 12 13:39:37 2009 : Debug: readclients = yes Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5 Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}" Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT" Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_check_query = "SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60 Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: postauth_query = "" Mon Oct 12 13:39:37 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-d): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-d): Attempting to connect to radius@192.168.188.3:/radius_d Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): starting 0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Attempting to connect rlm_sql_mysql #0 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Connected new DB handle, #0 ... Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): starting 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Attempting to connect rlm_sql_mysql #4 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Connected new DB handle, #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Processing generate_sql_clients Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Reserving sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Released sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: server c { Mon Oct 12 13:39:37 2009 : Debug: modules { Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-c Mon Oct 12 13:39:37 2009 : Debug: sql sql-c { Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql" Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3" Mon Oct 12 13:39:37 2009 : Debug: port = "" Mon Oct 12 13:39:37 2009 : Debug: login = "radius" Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass" Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_c" Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql" Mon Oct 12 13:39:37 2009 : Debug: readclients = yes Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5 Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}" Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT" Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_check_query = "SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60 Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: postauth_query = "" Mon Oct 12 13:39:37 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-c): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-c): Attempting to connect to radius@192.168.188.3:/radius_c Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): starting 0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Attempting to connect rlm_sql_mysql #0 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Connected new DB handle, #0 ... Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): starting 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Attempting to connect rlm_sql_mysql #4 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Connected new DB handle, #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Processing generate_sql_clients Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Reserving sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Released sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: server b { Mon Oct 12 13:39:37 2009 : Debug: modules { Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-b Mon Oct 12 13:39:37 2009 : Debug: sql sql-b { Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql" Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3" Mon Oct 12 13:39:37 2009 : Debug: port = "" Mon Oct 12 13:39:37 2009 : Debug: login = "radius" Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass" Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_b" Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql" Mon Oct 12 13:39:37 2009 : Debug: readclients = yes Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5 Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}" Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT" Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_check_query = "SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60 Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: postauth_query = "" Mon Oct 12 13:39:37 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-b): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-b): Attempting to connect to radius@192.168.188.3:/radius_b Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): starting 0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Attempting to connect rlm_sql_mysql #0 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Connected new DB handle, #0 ... Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): starting 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Attempting to connect rlm_sql_mysql #4 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Connected new DB handle, #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Processing generate_sql_clients Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Reserving sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Released sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: server e { Mon Oct 12 13:39:37 2009 : Debug: modules { Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-e Mon Oct 12 13:39:37 2009 : Debug: sql sql-e { Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql" Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3" Mon Oct 12 13:39:37 2009 : Debug: port = "" Mon Oct 12 13:39:37 2009 : Debug: login = "radius" Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass" Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_e" Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql" Mon Oct 12 13:39:37 2009 : Debug: readclients = yes Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5 Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}" Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT" Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_check_query = "SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id" Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query = "SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id" Mon Oct 12 13:39:37 2009 : Debug: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" Mon Oct 12 13:39:37 2009 : Debug: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" Mon Oct 12 13:39:37 2009 : Debug: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}'" Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60 Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0" Mon Oct 12 13:39:37 2009 : Debug: postauth_query = "" Mon Oct 12 13:39:37 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-e): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-e): Attempting to connect to radius@192.168.188.3:/radius_e Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): starting 0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Attempting to connect rlm_sql_mysql #0 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Connected new DB handle, #0 ... Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): starting 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Attempting to connect rlm_sql_mysql #4 Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Connected new DB handle, #4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Processing generate_sql_clients Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Reserving sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id, nasname, shortname, type, secret FROM nas Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Released sql socket id: 4 Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: server { Mon Oct 12 13:39:37 2009 : Debug: modules { Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-proxy {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for more modules to load Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: radiusd: #### Opening IP addresses and Ports #### Mon Oct 12 13:39:37 2009 : Debug: listen { Mon Oct 12 13:39:37 2009 : Debug: type = "auth" Mon Oct 12 13:39:37 2009 : Debug: ipaddr = * Mon Oct 12 13:39:37 2009 : Debug: port = 0 Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: listen { Mon Oct 12 13:39:37 2009 : Debug: type = "acct" Mon Oct 12 13:39:37 2009 : Debug: ipaddr = * Mon Oct 12 13:39:37 2009 : Debug: port = 0 Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: main { Mon Oct 12 13:39:37 2009 : Debug: snmp = no Mon Oct 12 13:39:37 2009 : Debug: smux_password = "" Mon Oct 12 13:39:37 2009 : Debug: snmp_write_access = no Mon Oct 12 13:39:37 2009 : Debug: } Mon Oct 12 13:39:37 2009 : Debug: Listening on authentication address * port 1812 Mon Oct 12 13:39:37 2009 : Debug: Listening on accounting address * port 1813 Mon Oct 12 13:39:37 2009 : Debug: Listening on proxy address * port 1814 Mon Oct 12 13:39:37 2009 : Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 33589, id=193, length=80 User-Name = "test(a)b.com" User-Password = "12345" NAS-IP-Address = 127.0.0.1 NAS-Port = 1 Framed-Protocol = PPP Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat function of module sql-a for string 'SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}"' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test(a)b.com Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped user --> 'test(a)b.com' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM nas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql -> /tmp/sqltrace.sql Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket id: 3 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT huntgroup FROM nas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat finished Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket id: 3 Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-a:SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}"} -> dialup Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 7 MAX 8 Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ::: APPENDING Huntgroup-Name FROM 0 TO 7 Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 7 out 8 Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = SQL-User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: No '/' in User-Name = "test(a)b.com", skipping NULL due to config. Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Looking up realm "b.com" for User-Name = "test(a)b.com" Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Found realm "b.com" Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Adding Stripped-User-Name = "test" Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Adding Realm = "b.com" Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxying request from user test to realm b.com Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Preparing to proxy authentication request to realm "b.com" Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns updated Mon Oct 12 13:39:45 2009 : Debug: +- entering group pre-proxy Mon Oct 12 13:39:45 2009 : Debug: modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 0 Mon Oct 12 13:39:45 2009 : Debug: expand: /var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d -> /var/log/freeradius/radacct/127.0.0.1/pre-proxy-detail-20091012 Mon Oct 12 13:39:45 2009 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/pre-proxy-detail-20091012 Mon Oct 12 13:39:45 2009 : Debug: expand: %t -> Mon Oct 12 13:39:45 2009 Mon Oct 12 13:39:45 2009 : Debug: modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[pre_proxy_log] returns ok Mon Oct 12 13:39:45 2009 : Debug: >>> Sending proxied request internally to virtual server. Mon Oct 12 13:39:45 2009 : Debug: server b { Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat function of module sql-b for string 'SELECT huntgroup FROM allnas WHERE nasname="%{NAS-IP-Address}"' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): - sql_xlat Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped user --> 'test' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM allnas WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM allnas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql -> /tmp/sqltrace.sql Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket id: 3 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT huntgroup FROM allnas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): - sql_xlat finished Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket id: 3 Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-b:SELECT huntgroup FROM allnas WHERE nasname="%{NAS-IP-Address}"} -> dialup Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 12 MAX 13 Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ::: OVERWRITING Huntgroup-Name FROM 0 TO 6 Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 12 out 12 Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Stripped-User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[8] = Realm Mon Oct 12 13:39:45 2009 : Debug: ::: to[9] = Realm Mon Oct 12 13:39:45 2009 : Debug: ::: to[10] = Proxy-State Mon Oct 12 13:39:45 2009 : Debug: ::: to[11] = SQL-User-Name Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Request already proxied. Ignoring. Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Request already proxied. Ignoring. Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[files] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped user --> 'test' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket id: 2 Mon Oct 12 13:39:45 2009 : Debug: 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 = 'test' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): User found in radcheck table Mon Oct 12 13:39:45 2009 : Debug: 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 = 'test' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = 'test' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName = 'test' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT GroupName FROM usergroup WHERE UserName = 'test' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id -> SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = 'test' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = 'test' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): User found in group B UNLIMITED Mon Oct 12 13:39:45 2009 : Debug: 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 = 'B UNLIMITED' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'B UNLIMITED' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket id: 2 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns ok Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Found Auth-Type Accept Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Auth-Type = Accept, accepting the user Mon Oct 12 13:39:45 2009 : Debug: +- entering group session Mon Oct 12 13:39:45 2009 : Debug: modsingle[session]: calling sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped user --> 'test' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0 -> SELECT COUNT(*) FROM radacct WHERE UserName='test' AND AcctStopTime = 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket id: 1 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT COUNT(*) FROM radacct WHERE UserName='test' AND AcctStopTime = 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket id: 1 Mon Oct 12 13:39:45 2009 : Debug: modsingle[session]: returned from sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns ok Mon Oct 12 13:39:45 2009 : Auth: Login OK: [test/12345] (from client Mike Test port 1 via TLS tunnel) Mon Oct 12 13:39:45 2009 : Debug: +- entering group post-auth Mon Oct 12 13:39:45 2009 : Debug: modsingle[post-auth]: calling sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Processing sql_postauth Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped user --> 'test' Mon Oct 12 13:39:45 2009 : Debug: modsingle[post-auth]: returned from sql-b (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns noop Mon Oct 12 13:39:45 2009 : Debug: } # server b Mon Oct 12 13:39:45 2009 : Debug: Going to the next request Mon Oct 12 13:39:45 2009 : Debug: <<< Received proxied response from internal virtual server. Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat function of module sql-a for string 'SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}"' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test(a)b.com Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped user --> 'test(a)b.com' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM nas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql -> /tmp/sqltrace.sql Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket id: 2 Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT huntgroup FROM nas WHERE nasname="127.0.0.1" Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat finished Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket id: 2 Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-a:SELECT huntgroup FROM nas WHERE nasname="%{NAS-IP-Address}"} -> dialup Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 11 MAX 12 Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ::: OVERWRITING Huntgroup-Name FROM 0 TO 6 Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 11 out 11 Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = Huntgroup-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Stripped-User-Name Mon Oct 12 13:39:45 2009 : Debug: ::: to[8] = Realm Mon Oct 12 13:39:45 2009 : Debug: ::: to[9] = Realm Mon Oct 12 13:39:45 2009 : Debug: ::: to[10] = SQL-User-Name Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxy reply, or no User-Name. Ignoring. Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from IPASS (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxy reply, or no User-Name. Ignoring. Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[files] returns noop Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling sql-a (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test(a)b.com Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped user --> 'test(a)b.com' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket id: 1 Mon Oct 12 13:39:45 2009 : Debug: 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 = 'test(a)b.com' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test(a)b.com' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName = 'test(a)b.com' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT GroupName FROM usergroup WHERE UserName = 'test(a)b.com' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Checking profile DEFAULT Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped user --> 'DEFAULT' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName = '%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName = 'DEFAULT' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT GroupName FROM usergroup WHERE UserName = 'DEFAULT' AND HuntGroupName = 'dialup' Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY radgroupcheck.id -> SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = 'DEFAULT' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup WHERE usergroup.Username = 'DEFAULT' AND usergroup.GroupName = radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): User found in group DISABLED Mon Oct 12 13:39:45 2009 : Debug: 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 = 'DISABLED' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'DISABLED' ORDER BY id Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket id: 1 Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from sql-a (rlm_sql) for request 0 Mon Oct 12 13:39:45 2009 : Debug: ++[sql-a] returns ok Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Found Auth-Type Reject Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Auth-Type = Reject, rejecting user Mon Oct 12 13:39:45 2009 : Debug: auth: Failed to validate the user. Mon Oct 12 13:39:45 2009 : Auth: Login incorrect: [test(a)b.com/12345] (from client Mike Test port 1) Mon Oct 12 13:39:45 2009 : Debug: Delaying reject of request 0 for 1 seconds Mon Oct 12 13:39:45 2009 : Debug: Going to the next request Mon Oct 12 13:39:45 2009 : Debug: Waking up in 0.9 seconds. Mon Oct 12 13:39:46 2009 : Debug: Sending delayed reject for request 0 Sending Access-Reject of id 193 to 127.0.0.1 port 33589 Reply-Message := "This account has been disabled" Mon Oct 12 13:39:46 2009 : Debug: Waking up in 4.9 seconds. Mon Oct 12 13:39:51 2009 : Debug: Cleaning up request 0 ID 193 with timestamp +8 Mon Oct 12 13:39:51 2009 : Debug: Ready to process requests. Thanks for any help you can provide... Michael Schlies

2 2

Active Directory/freeradius/enterasys - combination
by T.Robers＠heidelberg.de 14 Oct '09

14 Oct '09

Hello, I know there was a threat with the same subject 3 years ago, but in addition we need mac-authentication (printers,..),too. The Mac-auth is ok: Ready to process requests. rad_recv: Access-Request packet from host 172.16.255.101 port 49169, id=98, length=158 User-Name = "00-13-20-73-D0-45" Service-Type = Framed-User Called-Station-Id = "00-1F-45-19-9C-68" Calling-Station-Id = "00-13-20-73-D0-45" NAS-Identifier = "D2_Zi31_Tom" NAS-IP-Address = 172.16.255.101 NAS-Port = 1 NAS-Port-Type = Ethernet NAS-Port-Id = "ge.1.1" User-Password = "hdpasswd" Message-Authenticator = 0xc2baf30d011d595efa42357331abcc6c +- entering group authorize {...} ++[preprocess] returns ok [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/172.16.255.101/auth-detail-20091013 [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/172.16.255.101/auth-detail-20091013 [auth_log] expand: %t -> Tue Oct 13 11:59:35 2009 ++[auth_log] returns ok ++[chap] returns noop ++[mschap] returns noop [suffix] No '@' in User-Name = "00-13-20-73-D0-45", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [ntdomain] No '\' in User-Name = "00-13-20-73-D0-45", looking up realm NULL [ntdomain] No such realm "NULL" ++[ntdomain] returns noop [eap] No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns notfound [files] users: Matched entry DEFAULT at line 213 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Found Auth-Type = PAP +- entering group PAP {...} [pap] login attempt with password "hdpasswd" [pap] Using clear text password "hdpasswd" [pap] User authenticated successfully ++[pap] returns ok Login OK: [00-13-20-73-D0-45/hdpasswd] (from client 172.16.255.101 port 1 cli 00-13-20-73-D0-45) +- entering group post-auth {...} ++[exec] returns noop Sending Access-Accept of id 98 to 172.16.255.101 port 49169 Framed-Filter-Id = "Enterasys:version=1:policy=Mitarbeiter" Finished request 0. Going to the next request Waking up in 4.9 seconds. Cleaning up request 0 ID 98 with timestamp +31 Ready to process requests. Now I need a username/password auth against AD. Ntlm-auth works very well. If I activate ldap in /etc/raddb/modules: rad_recv: Access-Request packet from host 172.16.255.101 port 49169, id=191, length=167 User-Name = "DNT1\\testtom" Service-Type = Framed-User Called-Station-Id = "00-1F-45-19-9C-68" Calling-Station-Id = "00-13-20-73-D0-45" NAS-Identifier = "D2_Zi31_Tom" NAS-IP-Address = 172.16.255.101 NAS-Port = 1 NAS-Port-Id = "ge.1.1" Framed-MTU = 1500 NAS-Port-Type = Ethernet State = 0x113208ad123411cced08469153aa8038 EAP-Message = 0x020600061900 Message-Authenticator = 0x27fe716e0b83c7d08f295275043550f4 +- entering group authorize {...} ++[preprocess] returns ok [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/172.16.255.101/auth-detail-20091013 [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/172.16.255.101/auth-detail-20091013 [auth_log] expand: %t -> Tue Oct 13 13:16:13 2009 ++[auth_log] returns ok ++[chap] returns noop ++[mschap] returns noop [suffix] No '@' in User-Name = "DNT1\testtom", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [ntdomain] Looking up realm "DNT1" for User-Name = "DNT1\testtom" [ntdomain] Found realm "DNT1" [ntdomain] Adding Stripped-User-Name = "testtom" [ntdomain] Adding Realm = "DNT1" [ntdomain] Authentication realm is LOCAL. ++[ntdomain] returns ok [eap] EAP packet type response id 6 length 6 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] Received TLS ACK [peap] ACK handshake fragment handler [peap] eaptls_verify returned 1 [peap] eaptls_process returned 13 [peap] EAPTLS_HANDLED ++[eap] returns handled Sending Access-Challenge of id 191 to 172.16.255.101 port 49169 EAP-Message = 0x010700b519003082a52b18d9963104cec8ab3f3ddc453b55e1519bcf57d5178ca7fbc8 1d20727b3d75c92c438dbafd9a5544e5443ad544f16869af57ef84883eebc730362387c9 e6357c18fcb15a8e862e2b6c2ea1871b8756414a7ba875ff9416143a5baf78b6a9f7c93d c023f5edd6c8da55e646513482e5a39f9ccb7c480d68b7e965247b4accf8c1fa07b08368 80301de9e7058a5b891fd8f9e8443517e0eb83847723441ae98c447e7416030100040e00 0000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x113208ad153511cced08469153aa8038 Finished request 5. Going to the next request Waking up in 4.9 seconds. Cleaning up request 1 ID 187 with timestamp +63 Cleaning up request 2 ID 188 with timestamp +63 Cleaning up request 3 ID 189 with timestamp +63 Cleaning up request 4 ID 190 with timestamp +63 Cleaning up request 5 ID 191 with timestamp +63 Ready to process requests. The server don't do ldap. What is my mistake ? First the server should do a ntlm-auth and then check an ldap-group in AD. Version 2.1.6-rpm and CentOS 5.3. Thank you Tom

2 1

xsupplicant - freeradius EAP-TTLS PAP Access-Reject
by Nagendra KS 14 Oct '09

14 Oct '09

Hi All, Supplicant tries authentication with EAP-TTLS, TLS tunnel is established properly but Radius sends Access-Reject. Following are the xsupplicant.conf, eap.conf and radius output. radiusd.conf is not changed. It would be great if anyone could help in solving this issue or identify it. Thanks, Nagendra. freeradius version: FreeRADIUS Version 1.0.1 xsupplicant version: 1.2.8 Following is my xsupplicant configuration: eap-ttls { root_cert = /etc/raddb/certs/ca.pem phase2_type = pap pap { username = test123(a)mynet.net password = "test123" } } Following is my eap.conf configuration with freeradius: eap { default_eap_type = ttls timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 2048 md5 { } leap { } gtc { auth_type = PAP } tls { certdir = ${confdir}/certs cadir = ${confdir}/certs private_key_password = nagendra private_key_file = ${certdir}/server.pem certificate_file = ${certdir}/server.pem CA_file = ${cadir}/ca.pem dh_file = ${certdir}/dh random_file = ${certdir}/random fragment_size = 1024 include_length = yes } ttls { default_eap_type = md5 copy_request_to_tunnel = no use_tunneled_reply = no } } Following is the output of freeRadius. rad_recv: Access-Request packet from host 12.12.12.2:52660, id=201, length=300 User-Name = "test123(a)mynet.net" NAS-Port = 68 State = 0x31f6a6d18c0edbbe0a8135be701c9eff EAP-Message = 0x020e00801500170301002003c6f62435902b65dc7748b238fc47a7e5af9cfdbfed7ce3763b8a3830ac25a41703010050bd010059a58d0a9db18cb4df099dca43c1cadebca1672d9fb2b08a9131aa32b657e2d497196c130405e11396402abbcc130558325bc9ef888c19692d6ce7e2d736b463e6bfa09de4cacdc2511be08c20 Message-Authenticator = 0x9b2ba395fe336634039600437f39e5e4 Acct-Session-Id = "8O2.1x81680002" NAS-Port-Id = "ge-0/0/0.0" Calling-Station-Id = "00-30-48-8b-7f-ff" Called-Station-Id = "00-1f-12-3f-89-40" NAS-Identifier = "bng-l24f1-dev" NAS-Port-Type = Virtual Processing the authorize section of radiusd.conf modcall: entering group authorize for request 5 modcall[authorize]: module "preprocess" returns ok for request 5 rlm_eap: EAP packet type response id 14 length 128 rlm_eap: No EAP Start, assuming it's an on-going EAP conversation modcall[authorize]: module "eap" returns updated for request 5 users: Matched DEFAULT at 164 users: Matched test123(a)mynet.net at 235 modcall[authorize]: module "files" returns ok for request 5 modcall: group authorize returns updated for request 5 rad_check_password: Found Auth-Type EAP auth: type "EAP" Processing the authenticate section of radiusd.conf modcall: entering group authenticate for request 5 rlm_eap: Request found, released from the list rlm_eap: EAP/ttls rlm_eap: processing type ttls rlm_eap_ttls: Authenticate rlm_eap_tls: processing TLS eaptls_verify returned 7 rlm_eap_tls: Done initial handshake eaptls_process returned 7 rlm_eap_ttls: Session established. Proceeding to decode tunneled attributes. TTLS: Got tunneled request User-Name = "test123(a)mynet.net" User-Password = "test123" FreeRADIUS-Proxied-To = 127.0.0.1 TTLS: Sending tunneled request User-Name = "test123(a)mynet.net" User-Password = "test123" FreeRADIUS-Proxied-To = 127.0.0.1 Processing the authorize section of radiusd.conf modcall: entering group authorize for request 5 modcall[authorize]: module "preprocess" returns ok for request 5 rlm_eap: No EAP-Message, not doing EAP modcall[authorize]: module "eap" returns noop for request 5 users: Matched DEFAULT at 164 users: Matched test123(a)mynet.net at 235 modcall[authorize]: module "files" returns ok for request 5 modcall: group authorize returns ok for request 5 rad_check_password: Found Auth-Type System auth: type "System" ERROR: Unknown value specified for Auth-Type. Cannot perform requested action. auth: Failed to validate the user. TTLS: Got tunneled reply RADIUS code 3 TTLS: Got tunneled Access-Reject rlm_eap: Handler failed in EAP/ttls rlm_eap: Failed in EAP select modcall[authenticate]: module "eap" returns invalid for request 5 modcall: group authenticate returns invalid for request 5 auth: Failed to validate the user. Delaying request 5 for 1 seconds Finished request 5 Going to the next request Waking up in 6 seconds... rad_recv: Access-Request packet from host 12.12.12.2:52660, id=201, length=300 Sending Access-Reject of id 201 to 12.12.12.2:52660 EAP-Message = 0x040e0004 Message-Authenticator = 0x00000000000000000000000000000000

2 2

Munin Graphs
by Neville 13 Oct '09

13 Oct '09

Hi, I've installed the freeradius_auth plugin added to plugins.conf [freeradius*] user root But still I get the following error when the plugin is run... radmin: Failed connecting to /usr/local/var/run/radiusd/radiusd.sock: Permission denied Any ideas Running direct from root works fine, just [root@vpn1 munin]# radmin -f /usr/local/var/run/radiusd/radiusd.sock -e "stats client auth" requests 273 responses 273 accepts 206 rejects 67 challenges 0 dup 0 invalid 0 malformed 0 bad_signature 0 dropped 0 unknown_types 0 Thx Nev

2 1