June 2010 - Freeradius-Users - lists.freeradius.org

Calling-Station-ID not sent by pam_radius_auth.
by Christiaan Ehlers 25 May '11

25 May '11

Hi I currently running the following system: Server: FreeRadius, MySQL Client: pam_radius_auth, libnss_mysql.so I use the freeradius to auth and account ssh logins, here is my pam.d/sshd file on the client. #%PAM-1.0 auth sufficient /lib/security/pam_radius_auth.so debug auth required /lib/security/pam_stack.so service=system-auth auth required /lib/security/pam_nologin.so account sufficient /lib/security/pam_radius_auth.so debug account required /lib/security/pam_stack.so service=system-auth password required /lib/security/pam_stack.so service=system-auth session required /lib/security/pam_mkhomedir.so skel=/etc/skel/ umask=0022 session sufficient /lib/security/pam_radius_auth.so debug conf=/etc/radiusclient/servers session required /lib/security/pam_stack.so service=system-auth session required /lib/security/pam_limits.so session optional /lib/security/pam_console.so Now when I authenticate I can see that the Calling-Station-ID gets passed, but when I do authentication that field seems to be missing. Here is the output of radiusd -X Ready to process requests. rad_recv: Access-Request packet from host 10.0.0.1:3698, id=220, length=89 User-Name = "test" User-Password = "123pass" NAS-IP-Address = 10.0.0.1 NAS-Identifier = "sshd" NAS-Port = 2673 NAS-Port-Type = Virtual Service-Type = Authenticate-Only Calling-Station-Id = "10.1.1.1" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 0 modcall[authorize]: module "preprocess" returns ok for request 0 modcall[authorize]: module "chap" returns noop for request 0 modcall[authorize]: module "mschap" returns noop for request 0 rlm_realm: No '@' in User-Name = "test", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "suffix" returns noop for request 0 rlm_eap: No EAP-Message, not doing EAP modcall[authorize]: module "eap" returns noop for request 0 users: Matched entry DEFAULT at line 153 modcall[authorize]: module "files" returns ok for request 0 radius_xlat: 'test' rlm_sql (sql): sql_set_user escaped user --> 'test' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'test' ORDER BY id' rlm_sql (sql): Reserving sql socket id: 7 radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'test' ORDER BY id' radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'test' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' rlm_sql (sql): Released sql socket id: 7 modcall[authorize]: module "sql" returns ok for request 0 modcall: group authorize returns ok for request 0 rad_check_password: Found Auth-Type pap auth: type "PAP" Processing the authenticate section of radiusd.conf modcall: entering group Auth-Type for request 0 rlm_pap: login attempt by "test" with password 123pass rlm_pap: Using password "$1$n/uxpq.r$FBKqAEC8KvsK13QVHRwAf/" for user test authentication. rlm_pap: Using CRYPT encryption. rlm_pap: User authenticated succesfully modcall[authenticate]: module "pap" returns ok for request 0 modcall: group Auth-Type returns ok for request 0 Sending Access-Accept of id 220 to 10.0.0.1:3698 Framed-IP-Address := 10.1.1.1 Framed-Protocol := PPP Service-Type := Framed-User Framed-Compression := Van-Jacobson-TCP-IP Finished request 0 Going to the next request --- Walking the entire request list --- Waking up in 6 seconds... rad_recv: Accounting-Request packet from host 10.0.0.1:3698, id=66, length=72 User-Name = "test" NAS-IP-Address = 10.0.0.1 NAS-Identifier = "sshd" NAS-Port = 2673 NAS-Port-Type = Virtual Acct-Status-Type = Start Acct-Session-Id = "00002673" Acct-Authentic = RADIUS Processing the preacct section of radiusd.conf modcall: entering group preacct for request 1 modcall[preacct]: module "preprocess" returns noop for request 1 rlm_acct_unique: Hashing 'NAS-Port = 2673,Client-IP-Address = 10.0.0.1,NAS-IP-Address = 10.0.0.1,Acct-Session-Id = "00002673",User-Name = "test"' rlm_acct_unique: Acct-Unique-Session-ID = "a0ec8ab13c262f56". modcall[preacct]: module "acct_unique" returns ok for request 1 rlm_realm: No '@' in User-Name = "test", looking up realm NULL rlm_realm: No such realm "NULL" modcall[preacct]: module "suffix" returns noop for request 1 modcall[preacct]: module "files" returns noop for request 1 modcall: group preacct returns ok for request 1 Processing the accounting section of radiusd.conf modcall: entering group accounting for request 1 radius_xlat: '/usr/local/var/log/radius/radacct/10.0.0.1/detail-20050603' rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.0.0.1/detail-20050603 modcall[accounting]: module "detail" returns ok for request 1 modcall[accounting]: module "unix" returns ok for request 1 radius_xlat: '/usr/local/var/log/radius/radutmp' radius_xlat: 'test' modcall[accounting]: module "radutmp" returns ok for request 1 radius_xlat: 'test' rlm_sql (sql): sql_set_user escaped user --> 'test' radius_xlat: '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('00002673', 'a0ec8ab13c262f56', 'test', '', '10.0.0.1', '2673', 'Virtual', '2005-06-03 14:20:01', '0', '0', 'RADIUS', '', '', '0', '0', '', '', '', '', '', '', '', '0')' rlm_sql (sql): Reserving sql socket id: 6 rlm_sql (sql): Released sql socket id: 6 modcall[accounting]: module "sql" returns ok for request 1 modcall: group accounting returns ok for request 1 Sending Accounting-Response of id 66 to 10.0.0.1:3698 Finished request 1 Going to the next request Cleaning up request 1 ID 66 with timestamp 42a05901 Waking up in 6 seconds... --- Walking the entire request list --- Cleaning up request 0 ID 220 with timestamp 42a05901 Nothing to do. Sleeping until we see a request. As you can see the CallingStationId is empty, also there is no mention of it in the Accounting request packet. If this is not supported by the accounting, is there a way to get it from the authentication section? Would also like to say that I know this is more related to the PAM module and I assume this makes this mail a bit out of context in this mail group, but any help would be most appreciated. Kind Regards Christiaan Ehlers

4 3

FR 2.1.0 (ubuntu) proxying to NPS/IAS.
by Ville Leinonen 02 Feb '11

02 Feb '11

Hi, I try to use FR to forwarding access-request to NPS servers, but some reason FR/NPS gives "User password is incorrect" message. I have tripple check that password is correct. When i test IAS to NPS proxy it works. I have enable in NPS side MS-CHAP-v2, MS-CHAP, CHAP and PAP/SPAP methods. Any clue what is wrong? Here is some logs: rad_recv: Access-Request packet from host 192.168.21.150 port 1025, id=57, length=154 User-Name = "vle" User-Password = "\2063\261m\301\344J\216sCÑ \035\003\2328" NAS-Port = 626688 Called-Station-Id = "192.168.21.150" Calling-Station-Id = "192.168.1.114" NAS-Port-Type = Virtual Tunnel-Client-Endpoint:0 = "192.168.1.114" NAS-IP-Address = 192.168.21.150 Cisco-AVPair = "ip:source-ip=192.168.1.114" +- entering group authorize {...} ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop [suffix] No '@' in User-Name = "vle", looking up realm NULL [suffix] Found realm "NULL" [suffix] Adding Stripped-User-Name = "vle" [suffix] Adding Realm = "NULL" [suffix] Proxying request from user vle to realm NULL [suffix] Preparing to proxy authentication request to realm "NULL" ++[suffix] returns updated [eap] No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns notfound ++[files] returns noop ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns noop +- entering group pre-proxy {...} ++[files] returns noop Sending Access-Request of id 118 to 192.168.21.200 port 1812 User-Name = "vle" User-Password = "\2063\261m\301\344J\216sCÑ \035\003\2328" NAS-Port = 626688 Called-Station-Id = "192.168.21.150" Calling-Station-Id = "192.168.1.114" NAS-Port-Type = Virtual Tunnel-Client-Endpoint:0 = "192.168.1.114" NAS-IP-Address = 192.168.21.150 Cisco-AVPair = "ip:source-ip=192.168.1.114" Proxy-State = 0x3537 Proxying request 0 to home server 192.168.21.200 port 1812 Sending Access-Request of id 118 to 192.168.21.200 port 1812 User-Name = "vle" User-Password = "\2063\261m\301\344J\216sCÑ \035\003\2328" NAS-Port = 626688 Called-Station-Id = "192.168.21.150" Calling-Station-Id = "192.168.1.114" NAS-Port-Type = Virtual Tunnel-Client-Endpoint:0 = "192.168.1.114" NAS-IP-Address = 192.168.21.150 Cisco-AVPair = "ip:source-ip=192.168.1.114" Proxy-State = 0x3537 Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Reject packet from host 192.168.21.200 port 1812, id=118, length=52 Proxy-State = 0x3537 Reply-Message = "User password is incorrect" Br, Ville

6 11

rlm_python and dynload problem
by Aurélien Geron 07 Jan '11

07 Jan '11

Hi, I came across a bug when rlm_python executes python code that tries to load a dynamic (shared) module. This bug seems to have been discussed 2 or 3 times on this list, but no really satisfying solution appears to have been found so far (as far as I know), so I thought I might raise the subject again and perhaps try to contribute in finding a solution. In short, I think the solution to this problem is explained here, but I don't know how to implement it in freeRADIUS : http://docs.python.org/release/2.5.2/ext/link-reqs.html Here is my setup : - running a perfectly standard Debian Lenny (2.6.26-2-amd64) - installed the latest freeradius package from the lenny-backports (2.1.8+dfsg-1~bpo50+1) - the python debian package is the one installed with Debian Lenny (2.5.2-3) Here is my config: ---------------------------------------------- ####### # /etc/freeradius/modules/python ####### python python_test { mod_instantiate = radiusd_test func_instantiate = instantiate } ####### # /etc/freeradius/radiusd.conf ####### ... instantiate { python_test } ... ####### # /usr/lib/python2.5/site-packages/radiusd_test.py ####### def instantiate(p): radiusd.radlog(radiusd.L_DBG, "THIS WORKS") import random # this crashes radiusd.radlog(radiusd.L_DBG, "THIS IS NEVER REACHED !") ---------------------------------------------- Here is the output of "freeradius -X" : ---------------------------------------------- FreeRADIUS Version 2.1.8, for host x86_64-pc-linux-gnu, built on Apr 26 2010 at 21:49:28 Copyright (C) 1999-2009 The FreeRADIUS server project and contributors. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License v2. Starting - reading configuration files ... including configuration file /etc/freeradius/radiusd.conf ... Module: Linked to module rlm_python Module: Instantiating python_test python_init done python python_test { mod_instantiate = "radiusd_test" func_instantiate = "instantiate" } THIS WORKS rlm_python:EXCEPT:<type 'exceptions.ImportError'>: /usr/lib/python2.5/lib-dynload/math.so: undefined symbol: PyExc_ValueError /etc/freeradius/modules/python[24]: Instantiation failed for module "python_test" ---------------------------------------------- The module is properly loaded, the "instantiate" function gets called, and the first log message is output. In fact, any 100% pure python code works fine. The bug happens when a python module gets loaded dynamically : importing any module located in /usr/lib/python2.5/lib-dynload/*.so will crash. >From what I understand, here's what happens: 1) rlm_python was built against libpython2.5.a, but for optimization purposes, the linker stripped out all the symbols that were not used by rlm_python itself (including, for example, PyExc_ValueError). This behavior is platform-dependent, which probably explains why everything works fine on centos, for example. 2) when the radiusd_test module runs, it tries to import the "random" module, which itself tries to import the "math" module, which is in lib-dynload, and gets loaded dynamically. 3) unfortunately, python fails to load that module because it uses the PyExc_ValueError symbol and it does not know where it is defined (it is located in /usr/lib/libpython2.5.so.1, but unfortunately, the "math" module does not know that. As I said, I believe that the solution to this problem is clearly explained here: http://docs.python.org/release/2.5.2/ext/link-reqs.html As it's just a few paragraphs, I'll quote it here, for your convenience: ---------------------------------------------- While the configure script shipped with the Python sources will correctly build Python to export the symbols needed by dynamically linked extensions, this is not automatically inherited by applications which embed the Python library statically, at least on Unix. This is an issue when the application is linked to the static runtime library (libpython.a) and needs to load dynamic extensions (implemented as.so files). The problem is that some entry points are defined by the Python runtime solely for extension modules to use. If the embedding application does not use any of these entry points, some linkers will not include those entries in the symbol table of the finished executable. Some additional options are needed to inform the linker not to remove these symbols. Determining the right options to use for any given platform can be quite difficult, but fortunately the Python configuration already has those values. To retrieve them from an installed Python interpreter, start an interactive interpreter and have a short session like this: >>> import distutils.sysconfig >>> distutils.sysconfig.get_config_var('LINKFORSHARED') '-Xlinker -export-dynamic' The contents of the string presented will be the options that should be used. If the string is empty, there's no need to add any additional options. The LINKFORSHARED definition corresponds to the variable of the same name in Python's top-level Makefile. ---------------------------------------------- I think the short-term solution to this bug is to modify "src/modules/rlm_python/configure.in" and make it use the LINKFORSHARED linker options when linking rlm_python against libpython2.5.a., This could be done by adding a line such as: PY_OTHER_LDFLAGS=`sed -n -e 's/^LINKFORSHARED=$.*$/\1/p' $PY_MAKEFILE` just under this one: PY_OTHER_LIBS=`sed -n -e 's/^LIBS=$.*$/\1/p' $PY_MAKEFILE` and then using $PY_OTHER_LDFLAGS somewhere... the thing is, I have no idea where, because I am new to all these dynamic modules and embedded interpreters . I tried this though: python_ldflags="$PY_LIB_LOC $PY_EXTRA_LIBS $PY_OTHER_LDFLAGS -lpython${PY_VERSION} -lm" and recompiled the debian package (dpkg-buildpackage), but the problem was not fixed. Can someone tell me where to add those options exactly ? I can try recompiling as many times as necessary. Apparently, at least one person complains about the fact that you have to link against the static python runtime library (libpython2.5.a) even when you plan to use dynamic modules, and he has opened a bug report here: http://bugs.python.org/issue4434 Basically, if I understand correctly, his idea is to have the python fellows declare the proper dependencies in every *.so file, so that the libpython2.5.so.1 file gets loaded automatically when the "math" module (or any other dynamic module) gets loaded. Maybe that's the ideal solution, I really don't know. But it seems to me that we should try to fix freeRADIUS so that it works around this bug before python dependencies are fixed (it make take a while or even never happen). So I thing the only short-medium-term solution is to use LINKFORSHARED linker options. Thanks for reading this huge message. I hope we can beat this bug. Aurelien Geron

3 8

Certificate-based client side authentication towards a website with freeradius
by Martin Schneider 01 Dec '10

01 Dec '10

Hello all, we're trying to setup a freeradius / apache installation that allows us to authenticate and authorize users with *certificates* towards a website. Is there a good tutorial out there somewhere? We did only finde partial information that seems to be quite old unfortunately. Or could somebody who is deep into this matter please give some advice or ideas how we can solve our task? Best regards M

5 10

Adding Multiple Cisco-AVPairs using rlm_perl
by James Nedila 29 Aug '10

29 Aug '10

I have a rlm_perl script where i'd like to return multiple Cisco-AVPair attributes in an Access-Accept response. Since rlm_perl is passed hashes for RAD_REQUEST, RAD_CHECK, and RAD_REPLY, is there a way to pass an array as the value for the Cisco-AVPair hash key? If not, is there another way to do this? Thanks, James

5 8

Restricting certain users access to certain NAS devices
by Whitmarsh Mark (Leeds Teaching Hospitals NHS Trust) 07 Jul '10

07 Jul '10

Hi All, We are using Freeradius to authenticate network administrators when they login to their switches and routers. The setup is working fine as follows: User telnets to switch and enters username and password. Switch passes authentication request to Freeradius. Freeradius authenticates user against AD. The users are all defined in the users file - the lines I've added or changed from default are below: superuser1 Auth-Type = ntlm_auth superuser2 Auth-Type = ntlm_auth loweruser1 Auth-Type = ntlm_auth loweruser2 Auth-Type = ntlm_auth DEFAULT Group == "disabled", Auth-Type := Reject Reply-Message = "You are not permitted to access this system" The idea is that superusers are allowed to login to any of the 200 network devices whilst users are only allowed to login to a subset of say 50 devices. It's straightforward enough for the superusers and works fine but I'm stumped on how to handle the others. I have tested the following OK in sites-enabled/default: if ("%{User-Name}" == loweruser1) { update reply { Reply-Message := "Mark Whitmarsh not allowed here" } reject } If I login as loweruser1 it rejects me as expected. I think I need to put my users and network devices into groups so I can test for variables but I'm stuck on how to do that. After reading lots of man pages and getting nowhere I've hit one of those annoying mental blocks and need some help. Thanks, Mark Whitmarsh. ******************************************************************************************************************** This message may contain confidential information. If you are not the intended recipient please inform the sender that you have received the message in error before deleting it. Please do not disclose, copy or distribute information in this e-mail or take any action in reliance on its contents: to do so is strictly prohibited and may be unlawful. Thank you for your co-operation. NHSmail is the secure email and directory service available for all NHS staff in England and Scotland NHSmail is approved for exchanging patient data and other sensitive information with NHSmail and GSI recipients NHSmail provides an email address for your career in the NHS and can be accessed anywhere For more information and to find out how you can switch, visit www.connectingforhealth.nhs.uk/nhsmail ********************************************************************************************************************

2 8

Failed disabling Core Dumps on RHEL - SELinux Updates
by Ben Wiechman 02 Jul '10

02 Jul '10

A note for those that may run into this as well. When updating FR to 2.1.9 on RHEL/CentOS with SELinux enabled FreeRADIUS would log the following when it was started: Wed Jun 2 16:19:57 2010 : Error: Failed disabling core dumps: Permission denied To resolve I had to install the following modifications to the default SELinux policy # cat freeradius2.te module freeradius2 1.0; require { type radiusd_t; class process setrlimit; } #============= radiusd_t ============== allow radiusd_t self:process setrlimit; This allowed the daemon to properly disable core dumps. Ben Wiechman Wisper High Speed Internet

4 7

Detail accounting by REalm
by BELLIERE Eric 30 Jun '10

30 Jun '10

Dears, I have a Proxy radius which send authentication and accounting to other radius. I would like to have a copy of these accounting data locally. This is already working in the detail file. Now I am trying to make a file by realm proxyied. I have try this and works but I need to specify the exact realm. Is it a way to configure a expression here? I would like to make an expression to replace abc.be and abcnet.be so only one line is nacessary (like realm == "~abc$") ? accounting { detail if ((realm == "abc.be")||(realm == "abcnet.be")) { WriteABCAccounting WriteLOCALAccounting } if (realm == "xyz.be") { WriteXYZaccounting WriteLOCALAccounting } <http://k-village/team_members/who_s_who/kpeople01.asp?login=ebellier> Eric Bellière Operation & Integration Expert ITNO/ISO/ISIO/LSS Mobistar NV/SA Avenue Jean Mermoz 32 6041 Gosselies cid:image003.jpg@01C961E5.77656AB0 Tel: +32 (0)2 745 7997 GSM: +32(0)495 55 1343

3 2

Newbee question
by Maria Sanchez 30 Jun '10

30 Jun '10

Hi, I am getting familiar with FreeRadius since it is being proposed in the designs as our Authentication/Authorization server. I have successfully installed and started the server and I have done some calls using the radtest client script. I am currently only using the users file to create new users since my goal at this time is validating concepts.... I am currently trying to assign a Role to one of my users and get that value returned to the client. I am still using the radtest client. The only information I found related to configuring roles indicated that I had to enter a new attribute in the dictionary file, add the attribute in the users file with the value I needed and add the dictionary file as a parameter to the radtest (-d directory) to be able to see the attribute in the returned message... Well this is not working as described... Any idea or reference document I can use to have this configured? Thanks for your help! Maria

4 5

originate-coa virtual server
by Ben Wiechman 30 Jun '10

30 Jun '10

The originate-coa virtual server includes a switch condition using the Response-Packet-Type attribute in the post-proxy section. However this attribute is not populated for responses to coa or disconnect requests. The Packet-Type attribute is populated in the proxy-reply list (which is perhaps to be inferred from the comments in the originate-coa file). Is the lack of information in the Response-Packet-Type attribute expected in a response to a coa or disconnect request and the switch should be updated to use %{proxy-reply:Packet-Type} (this does work) or should the Response-Packet-Type attribute be populated for a response to a coa or disconnect request? This is using 2.1.10 up to git 288647f (to pull in the coa correlation fixes) Snippet: Tue Jun 29 15:27:09 2010 : Info: +- entering group post-proxy {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Packet-Type} -> Disconnect-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Packet-Type} -> Accounting-Response Tue Jun 29 15:27:09 2010 : Info: expand: %{Packet-Type} -> Accounting-Request Full Debug: [root@radius-dev sites-enabled]# radiusd -Xx Tue Jun 29 15:26:26 2010 : Info: FreeRADIUS Version 2.1.10, for host x86_64-redhat-linux-gnu, built on Jun 14 2010 at 15:41:02 Tue Jun 29 15:26:26 2010 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors. Tue Jun 29 15:26:26 2010 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Jun 29 15:26:26 2010 : Info: PARTICULAR PURPOSE. Tue Jun 29 15:26:26 2010 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Jun 29 15:26:26 2010 : Info: GNU General Public License v2. Tue Jun 29 15:26:26 2010 : Info: Starting - reading configuration files ... Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/radiusd.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/proxy.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/clients.conf Tue Jun 29 15:26:26 2010 : Debug: including files in directory /etc/raddb/modules/ Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/otp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/realm Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/checkval Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.example.com Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/policy Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/smsotp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sql_log Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/passwd Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/preprocess Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/perl Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/attr_rewrite Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.wisper Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/always Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/counter Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/linelog Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/ippool Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/digest Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/etc_group Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/ntlm_auth Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/exec Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/chap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/files Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/pap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mac2ip Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/smbpasswd Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sqlcounter_expire_on_login Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/inner-eap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mschap Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/unix Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/pam Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/mac2vlan Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/echo Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/expr Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/attr_filter Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/expiration Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/cui Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/acct_unique Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/logintime Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/radutmp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/detail.log Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/modules/sradutmp Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/eap.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql-wisper.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/dialup.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/dialup.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sql/mysql/wimax.conf Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/policy.conf Tue Jun 29 15:26:26 2010 : Debug: including files in directory /etc/raddb/sites-enabled/ Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/buffered-sql-wisper Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/wimax-asn Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/default Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/eap-stress-test Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/status Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/originate-coa-wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/control-socket Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/buffered-sql-wimax Tue Jun 29 15:26:26 2010 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel Tue Jun 29 15:26:26 2010 : Debug: main { Tue Jun 29 15:26:26 2010 : Debug: user = "radiusd" Tue Jun 29 15:26:26 2010 : Debug: group = "radiusd" Tue Jun 29 15:26:26 2010 : Debug: allow_core_dumps = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: including dictionary file /etc/raddb/dictionary Tue Jun 29 15:26:26 2010 : Debug: main { Tue Jun 29 15:26:26 2010 : Debug: prefix = "/usr" Tue Jun 29 15:26:26 2010 : Debug: localstatedir = "/var" Tue Jun 29 15:26:26 2010 : Debug: logdir = "/var/log/radius" Tue Jun 29 15:26:26 2010 : Debug: libdir = "/usr/lib64/freeradius" Tue Jun 29 15:26:26 2010 : Debug: radacctdir = "/var/log/radius/radacct" Tue Jun 29 15:26:26 2010 : Debug: hostname_lookups = no Tue Jun 29 15:26:26 2010 : Debug: max_request_time = 30 Tue Jun 29 15:26:26 2010 : Debug: cleanup_delay = 3 Tue Jun 29 15:26:26 2010 : Debug: max_requests = 25000 Tue Jun 29 15:26:26 2010 : Debug: pidfile = "/var/run/radiusd/radiusd.pid" Tue Jun 29 15:26:26 2010 : Debug: checkrad = "/usr/sbin/checkrad" Tue Jun 29 15:26:26 2010 : Debug: debug_level = 0 Tue Jun 29 15:26:26 2010 : Debug: proxy_requests = yes Tue Jun 29 15:26:26 2010 : Debug: log { Tue Jun 29 15:26:26 2010 : Debug: stripped_names = no Tue Jun 29 15:26:26 2010 : Debug: auth = yes Tue Jun 29 15:26:26 2010 : Debug: auth_badpass = no Tue Jun 29 15:26:26 2010 : Debug: auth_goodpass = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: security { Tue Jun 29 15:26:26 2010 : Debug: max_attributes = 200 Tue Jun 29 15:26:26 2010 : Debug: reject_delay = 1 Tue Jun 29 15:26:26 2010 : Debug: status_server = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Jun 29 15:26:26 2010 : Debug: proxy server { Tue Jun 29 15:26:26 2010 : Debug: retry_delay = 5 Tue Jun 29 15:26:26 2010 : Debug: retry_count = 3 Tue Jun 29 15:26:26 2010 : Debug: default_fallback = no Tue Jun 29 15:26:26 2010 : Debug: dead_time = 120 Tue Jun 29 15:26:26 2010 : Debug: wake_all_if_all_dead = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server localhost { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 127.0.0.1 Tue Jun 29 15:26:26 2010 : Debug: port = 1812 Tue Jun 29 15:26:26 2010 : Debug: type = "auth" Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: response_window = 20 Tue Jun 29 15:26:26 2010 : Debug: max_outstanding = 65536 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: zombie_period = 40 Tue Jun 29 15:26:26 2010 : Debug: status_check = "status-server" Tue Jun 29 15:26:26 2010 : Debug: ping_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: check_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: num_answers_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: num_pings_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: revive_interval = 120 Tue Jun 29 15:26:26 2010 : Debug: status_check_timeout = 4 Tue Jun 29 15:26:26 2010 : Debug: irt = 2 Tue Jun 29 15:26:26 2010 : Debug: mrt = 16 Tue Jun 29 15:26:26 2010 : Debug: mrc = 5 Tue Jun 29 15:26:26 2010 : Debug: mrd = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server_pool my_auth_failover { Tue Jun 29 15:26:26 2010 : Debug: type = fail-over Tue Jun 29 15:26:26 2010 : Debug: home_server = localhost Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: realm example.com { Tue Jun 29 15:26:26 2010 : Debug: auth_pool = my_auth_failover Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: realm LOCAL { Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server wichorus-coa { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 172.17.2.20 Tue Jun 29 15:26:26 2010 : Debug: port = 3799 Tue Jun 29 15:26:26 2010 : Debug: type = "coa" Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: response_window = 30 Tue Jun 29 15:26:26 2010 : Debug: max_outstanding = 65536 Tue Jun 29 15:26:26 2010 : Debug: zombie_period = 40 Tue Jun 29 15:26:26 2010 : Debug: status_check = "none" Tue Jun 29 15:26:26 2010 : Debug: ping_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: check_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: num_answers_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: num_pings_to_alive = 3 Tue Jun 29 15:26:26 2010 : Debug: revive_interval = 300 Tue Jun 29 15:26:26 2010 : Debug: status_check_timeout = 4 Tue Jun 29 15:26:26 2010 : Debug: irt = 2 Tue Jun 29 15:26:26 2010 : Debug: mrt = 16 Tue Jun 29 15:26:26 2010 : Debug: mrc = 5 Tue Jun 29 15:26:26 2010 : Debug: mrd = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: home_server_pool coa { Tue Jun 29 15:26:26 2010 : Debug: type = fail-over Tue Jun 29 15:26:26 2010 : Debug: virtual_server = originate-coa-wimax Tue Jun 29 15:26:26 2010 : Debug: home_server = wichorus-coa Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Clients #### Tue Jun 29 15:26:26 2010 : Debug: client 172.17.2.20 { Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "secret" Tue Jun 29 15:26:26 2010 : Debug: shortname = "wichorus-asn" Tue Jun 29 15:26:26 2010 : Debug: nastype = "other" Tue Jun 29 15:26:26 2010 : Debug: virtual_server = "wimax-asn" Tue Jun 29 15:26:26 2010 : Debug: coa_server = "coa" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Instantiating modules #### Tue Jun 29 15:26:26 2010 : Debug: instantiate { Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_exec, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_exec Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating exec Tue Jun 29 15:26:26 2010 : Debug: exec { Tue Jun 29 15:26:26 2010 : Debug: wait = no Tue Jun 29 15:26:26 2010 : Debug: input_pairs = "request" Tue Jun 29 15:26:26 2010 : Debug: shell_escape = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_expr, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_expr Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating expr Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_expiration, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_expiration Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating expiration Tue Jun 29 15:26:26 2010 : Debug: expiration { Tue Jun 29 15:26:26 2010 : Debug: reply-message = "Password Has Expired " Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_logintime, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_logintime Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating logintime Tue Jun 29 15:26:26 2010 : Debug: logintime { Tue Jun 29 15:26:26 2010 : Debug: reply-message = "You are calling outside your allowed timespan " Tue Jun 29 15:26:26 2010 : Debug: minimum-timeout = 60 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Loading Virtual Servers #### Tue Jun 29 15:26:26 2010 : Debug: server buffered-sql-wisper { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_preprocess, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_preprocess Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating preprocess Tue Jun 29 15:26:26 2010 : Debug: preprocess { Tue Jun 29 15:26:26 2010 : Debug: huntgroups = "/etc/raddb/huntgroups" Tue Jun 29 15:26:26 2010 : Debug: hints = "/etc/raddb/hints" Tue Jun 29 15:26:26 2010 : Debug: with_ascend_hack = no Tue Jun 29 15:26:26 2010 : Debug: ascend_channels_per_line = 23 Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_specialix_jetstream_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_cisco_vsa_hack = no Tue Jun 29 15:26:26 2010 : Debug: with_alvarion_vsa_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_acct_unique Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating acct_unique Tue Jun 29 15:26:26 2010 : Debug: acct_unique { Tue Jun 29 15:26:26 2010 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_sql, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_sql Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating sqlmain Tue Jun 29 15:26:26 2010 : Debug: sql sqlmain { Tue Jun 29 15:26:26 2010 : Debug: driver = "rlm_sql_mysql" Tue Jun 29 15:26:26 2010 : Debug: server = "172.17.0.150" Tue Jun 29 15:26:26 2010 : Debug: port = "" Tue Jun 29 15:26:26 2010 : Debug: login = "radius" Tue Jun 29 15:26:26 2010 : Debug: password = "blah" Tue Jun 29 15:26:26 2010 : Debug: radius_db = "radius2" Tue Jun 29 15:26:26 2010 : Debug: read_groups = yes Tue Jun 29 15:26:26 2010 : Debug: sqltrace = no Tue Jun 29 15:26:26 2010 : Debug: sqltracefile = "/var/log/radius/sqltrace.sql" Tue Jun 29 15:26:26 2010 : Debug: readclients = yes Tue Jun 29 15:26:26 2010 : Debug: deletestalesessions = yes Tue Jun 29 15:26:26 2010 : Debug: num_sql_socks = 15 Tue Jun 29 15:26:26 2010 : Debug: lifetime = 0 Tue Jun 29 15:26:26 2010 : Debug: max_queries = 0 Tue Jun 29 15:26:26 2010 : Debug: sql_user_name = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: default_user_profile = "" Tue Jun 29 15:26:26 2010 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Tue Jun 29 15:26:26 2010 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Jun 29 15:26:26 2010 : Debug: accounting_onoff_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = unix_timestamp('%S') - unix_timestamp(acctstarttime), acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = %{%{Acct-Delay-Time}:-0} WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= '%S'" Tue Jun 29 15:26:26 2010 : Debug: accounting_update_query = " UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Tue Jun 29 15:26:26 2010 : 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, xascendsessionsvrkey) 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-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{X-Ascend-Session-Svr-Key}')" Tue Jun 29 15:26:26 2010 : 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, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')" Tue Jun 29 15:26:26 2010 : Debug: accounting_start_query_alt = " UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Tue Jun 29 15:26:26 2010 : Debug: accounting_stop_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Tue Jun 29 15:26:26 2010 : 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-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{%{Acct-Delay-Time}:-0}')" Tue Jun 29 15:26:26 2010 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = BINARY '%{SQL-User-Name}' ORDER BY priority" Tue Jun 29 15:26:26 2010 : Debug: connect_failure_retry_delay = 60 Tue Jun 29 15:26:26 2010 : Debug: simul_count_query = "" Tue Jun 29 15:26:26 2010 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Tue Jun 29 15:26:26 2010 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Tue Jun 29 15:26:26 2010 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /{}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect to radius@172.17.0.150:/radius2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #0 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #1 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #3 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #4 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #5 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #6 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #7 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #8 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #9 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #10 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #11 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #12 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #13 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): starting 14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Attempting to connect rlm_sql_mysql #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlmain): Connected new DB handle, #14 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Processing generate_sql_clients Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Reserving sql socket id: 14 ...snip... Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlmain): Released sql socket id: 14 Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server wimax-asn { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_eap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_eap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap Tue Jun 29 15:26:26 2010 : Debug: eap { Tue Jun 29 15:26:26 2010 : Debug: default_eap_type = "ttls" Tue Jun 29 15:26:26 2010 : Debug: timer_expire = 60 Tue Jun 29 15:26:26 2010 : Debug: ignore_unknown_eap_types = yes Tue Jun 29 15:26:26 2010 : Debug: cisco_accounting_username_bug = no Tue Jun 29 15:26:26 2010 : Debug: max_sessions = 2048 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_tls Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-tls Tue Jun 29 15:26:26 2010 : Debug: tls { Tue Jun 29 15:26:26 2010 : Debug: rsa_key_exchange = no Tue Jun 29 15:26:26 2010 : Debug: dh_key_exchange = yes Tue Jun 29 15:26:26 2010 : Debug: rsa_key_length = 512 Tue Jun 29 15:26:26 2010 : Debug: dh_key_length = 512 Tue Jun 29 15:26:26 2010 : Debug: verify_depth = 0 Tue Jun 29 15:26:26 2010 : Debug: pem_file_type = yes Tue Jun 29 15:26:26 2010 : Debug: private_key_file = "/etc/raddb/certs/radius-dev_key.pem" Tue Jun 29 15:26:26 2010 : Debug: certificate_file = "/etc/raddb/certs/radius-dev_chain.pem" Tue Jun 29 15:26:26 2010 : Debug: CA_file = "/etc/raddb/certs/ca.pem" Tue Jun 29 15:26:26 2010 : Debug: private_key_password = "blah" Tue Jun 29 15:26:26 2010 : Debug: dh_file = "/etc/raddb/certs/dh" Tue Jun 29 15:26:26 2010 : Debug: random_file = "/etc/raddb/certs/random" Tue Jun 29 15:26:26 2010 : Debug: fragment_size = 1024 Tue Jun 29 15:26:26 2010 : Debug: include_length = yes Tue Jun 29 15:26:26 2010 : Debug: check_crl = no Tue Jun 29 15:26:26 2010 : Debug: cipher_list = "DEFAULT" Tue Jun 29 15:26:26 2010 : Debug: cache { Tue Jun 29 15:26:26 2010 : Debug: enable = yes Tue Jun 29 15:26:26 2010 : Debug: lifetime = 24 Tue Jun 29 15:26:26 2010 : Debug: max_entries = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_ttls Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-ttls Tue Jun 29 15:26:26 2010 : Debug: ttls { Tue Jun 29 15:26:26 2010 : Debug: default_eap_type = "mschapv2" Tue Jun 29 15:26:26 2010 : Debug: copy_request_to_tunnel = no Tue Jun 29 15:26:26 2010 : Debug: use_tunneled_reply = yes Tue Jun 29 15:26:26 2010 : Debug: virtual_server = "inner-tunnel" Tue Jun 29 15:26:26 2010 : Debug: include_length = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating eap-mschapv2 Tue Jun 29 15:26:26 2010 : Debug: mschapv2 { Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module init_wimax Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module verify_wimax_asn Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_always, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_always Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating reject Tue Jun 29 15:26:26 2010 : Debug: always reject { Tue Jun 29 15:26:26 2010 : Debug: rcode = "reject" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating noop Tue Jun 29 15:26:26 2010 : Debug: always noop { Tue Jun 29 15:26:26 2010 : Debug: rcode = "noop" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_wimax, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_wimax Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating wimax Tue Jun 29 15:26:26 2010 : Debug: wimax { Tue Jun 29 15:26:26 2010 : Debug: delete_mppe_keys = yes Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_realm, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_realm Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating suffix Tue Jun 29 15:26:26 2010 : Debug: realm suffix { Tue Jun 29 15:26:26 2010 : Debug: format = "suffix" Tue Jun 29 15:26:26 2010 : Debug: delimiter = "@" Tue Jun 29 15:26:26 2010 : Debug: ignore_default = no Tue Jun 29 15:26:26 2010 : Debug: ignore_null = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_detail, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_detail Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating detail_wimax Tue Jun 29 15:26:26 2010 : Debug: detail detail_wimax { Tue Jun 29 15:26:26 2010 : Debug: detailfile = "/var/log/radius/radacct/wimax/detail-%Y%m%d" Tue Jun 29 15:26:26 2010 : Debug: header = "%t" Tue Jun 29 15:26:26 2010 : Debug: detailperm = 432 Tue Jun 29 15:26:26 2010 : Debug: dirperm = 493 Tue Jun 29 15:26:26 2010 : Debug: locking = no Tue Jun 29 15:26:26 2010 : Debug: log_packet_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating sqlsession Tue Jun 29 15:26:26 2010 : Debug: sql sqlsession { Tue Jun 29 15:26:26 2010 : Debug: driver = "rlm_sql_mysql" Tue Jun 29 15:26:26 2010 : Debug: server = "172.17.0.150" Tue Jun 29 15:26:26 2010 : Debug: port = "" Tue Jun 29 15:26:26 2010 : Debug: login = "radius" Tue Jun 29 15:26:26 2010 : Debug: password = "blah" Tue Jun 29 15:26:26 2010 : Debug: radius_db = "radius2" Tue Jun 29 15:26:26 2010 : Debug: read_groups = no Tue Jun 29 15:26:26 2010 : Debug: sqltrace = no Tue Jun 29 15:26:26 2010 : Debug: sqltracefile = "/var/log/radius/sqltrace.sql" Tue Jun 29 15:26:26 2010 : Debug: readclients = no Tue Jun 29 15:26:26 2010 : Debug: deletestalesessions = no Tue Jun 29 15:26:26 2010 : Debug: num_sql_socks = 15 Tue Jun 29 15:26:26 2010 : Debug: lifetime = 0 Tue Jun 29 15:26:26 2010 : Debug: max_queries = 0 Tue Jun 29 15:26:26 2010 : Debug: sql_user_name = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: default_user_profile = "" Tue Jun 29 15:26:26 2010 : Debug: nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" Tue Jun 29 15:26:26 2010 : Debug: authorize_check_query = "SELECT id, username, 'WiMAX-hHA-IP-MIP4' as attribute, `hha-ip-address` as value, '==' as op FROM wimax WHERE username = BINARY '%{SQL-User-Name}'" Tue Jun 29 15:26:26 2010 : Debug: authorize_reply_query = "select id, username, 'WiMAX-MN-hHA-MIP4-Key' as attribute, `mn-ha-key` as value, ':=' as op FROM wimax WHERE username = BINARY '%{SQL-User-Name}' AND `mn-ha-key-spi` = %{WiMAX-MN-hHA-MIP4-SPI}" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_check_query = "" Tue Jun 29 15:26:26 2010 : Debug: authorize_group_reply_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_onoff_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_update_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_update_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_start_query = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_start_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: accounting_stop_query = " DELETE FROM wimax WHERE `username` = BINARY '%{SQL-User-Name}' AND `wimax-session-id` = '%{Acct-Multi-Session-Id}'" Tue Jun 29 15:26:26 2010 : Debug: accounting_stop_query_alt = "" Tue Jun 29 15:26:26 2010 : Debug: connect_failure_retry_delay = 60 Tue Jun 29 15:26:26 2010 : Debug: simul_count_query = "" Tue Jun 29 15:26:26 2010 : Debug: simul_verify_query = "" Tue Jun 29 15:26:26 2010 : Debug: postauth_query = "INSERT INTO wimax (`username`, `wimax-session-id`, `calling-station-id`, `nas-id`, `nas-ip-address`, `framed-ip-address`, `mip-rk`, `fa-rk`, `fa-rk-spi`, `mn-ha-key`, `mn-ha-spi`, `hha-ip-address`, `vha-ip-address`, `authdate`, `lifetime` ) VALUES ( '%{SQL-User-Name}', %{reply:WiMAX-AAA-Session-Id}, '%{Calling-Station-Id}', '%{NAS-Identifier}', '%{NAS-IP-Address}', '%{reply:Framed-IP-Address}', NULL, %{%{reply:WiMAX-FA-RK-Key}:-NULL}, %{%{reply:WiMAX-FA-RK-SPI}:-NULL}, %{%{reply:WiMAX-MN-hHA-MIP4-Key}:-%{%{reply:WiMAX-MN-hHA-MIP6-Key}:-NULL}}, %{%{reply:WiMAX-MN-hHA-MIP4-SPI}:-%{%{reply:WiMAX-MN-hHA-MIP6-SPI}:-NULL}}, '%{%{reply:WiMAX-hHA-IP-MIP4}:-%{reply:WiMAX-hHA-IP-MIP6}}', '%{%{reply:WiMAX-vHA-IP-MIP4}:-%{reply:WiMAX-vHA-IP-MIP6}}', '%S', '%{%{reply:Session-Timeout}:-86400}' )" Tue Jun 29 15:26:26 2010 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect to radius@172.17.0.150:/radius2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #0 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #1 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #2 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #3 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #4 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #5 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #6 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #7 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #8 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #9 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #10 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #11 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #12 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #13 Tue Jun 29 15:26:26 2010 : Debug: rlm_sql (sqlsession): starting 14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Attempting to connect rlm_sql_mysql #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Tue Jun 29 15:26:26 2010 : Info: rlm_sql (sqlsession): Connected new DB handle, #14 Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_attr_filter Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating attr_filter.accounting_response Tue Jun 29 15:26:26 2010 : Debug: attr_filter attr_filter.accounting_response { Tue Jun 29 15:26:26 2010 : Debug: attrsfile = "/etc/raddb/attrs.accounting_response" Tue Jun 29 15:26:26 2010 : Debug: key = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking session {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Loading virtual module negotiate_ip_technology Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating handled Tue Jun 29 15:26:26 2010 : Debug: always handled { Tue Jun 29 15:26:26 2010 : Debug: rcode = "handled" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating attr_filter.access_reject Tue Jun 29 15:26:26 2010 : Debug: attr_filter attr_filter.access_reject { Tue Jun 29 15:26:26 2010 : Debug: attrsfile = "/etc/raddb/attrs.access_reject" Tue Jun 29 15:26:26 2010 : Debug: key = "%{User-Name}" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server stress { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server status { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating ok Tue Jun 29 15:26:26 2010 : Debug: always ok { Tue Jun 29 15:26:26 2010 : Debug: rcode = "ok" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server originate-coa-wimax { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating fail Tue Jun 29 15:26:26 2010 : Debug: always fail { Tue Jun 29 15:26:26 2010 : Debug: rcode = "fail" Tue Jun 29 15:26:26 2010 : Debug: simulcount = 0 Tue Jun 29 15:26:26 2010 : Debug: mpp = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server buffered-sql-wimax { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server inner-tunnel { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_pap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_pap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating pap Tue Jun 29 15:26:26 2010 : Debug: pap { Tue Jun 29 15:26:26 2010 : Debug: encryption_scheme = "auto" Tue Jun 29 15:26:26 2010 : Debug: auto_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_chap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_chap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating chap Tue Jun 29 15:26:26 2010 : Debug: (Loaded rlm_mschap, checking if it's valid) Tue Jun 29 15:26:26 2010 : Debug: Module: Linked to module rlm_mschap Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating mschap Tue Jun 29 15:26:26 2010 : Debug: mschap { Tue Jun 29 15:26:26 2010 : Debug: use_mppe = yes Tue Jun 29 15:26:26 2010 : Debug: require_encryption = no Tue Jun 29 15:26:26 2010 : Debug: require_strong = no Tue Jun 29 15:26:26 2010 : Debug: with_ntdomain_hack = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking session {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: server { Tue Jun 29 15:26:26 2010 : Debug: modules { Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authenticate {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking authorize {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking preacct {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking accounting {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Instantiating detail_wisper Tue Jun 29 15:26:26 2010 : Debug: detail detail_wisper { Tue Jun 29 15:26:26 2010 : Debug: detailfile = "/var/log/radius/radacct/wisper/detail-%Y%m%d" Tue Jun 29 15:26:26 2010 : Debug: header = "%t" Tue Jun 29 15:26:26 2010 : Debug: detailperm = 432 Tue Jun 29 15:26:26 2010 : Debug: dirperm = 493 Tue Jun 29 15:26:26 2010 : Debug: locking = no Tue Jun 29 15:26:26 2010 : Debug: log_packet_header = no Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: Module: Checking post-auth {...} for more modules to load Tue Jun 29 15:26:26 2010 : Debug: } # modules Tue Jun 29 15:26:26 2010 : Debug: } # server Tue Jun 29 15:26:26 2010 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "auth" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "acct" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 0 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "control" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: socket = "/var/run/radiusd/radiusd.sock" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "detail" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: filename = "/var/log/radius/radacct/wisper/detail-*" Tue Jun 29 15:26:26 2010 : Debug: load_factor = 10 Tue Jun 29 15:26:26 2010 : Debug: poll_interval = 10 Tue Jun 29 15:26:26 2010 : Debug: retry_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "status" Tue Jun 29 15:26:26 2010 : Debug: ipaddr = * Tue Jun 29 15:26:26 2010 : Debug: port = 18120 Tue Jun 29 15:26:26 2010 : Debug: client admin { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 127.0.0.1 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "blah" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: client cacti { Tue Jun 29 15:26:26 2010 : Debug: ipaddr = 172.17.0.138 Tue Jun 29 15:26:26 2010 : Debug: require_message_authenticator = no Tue Jun 29 15:26:26 2010 : Debug: secret = "blah" Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: type = "detail" Tue Jun 29 15:26:26 2010 : Debug: listen { Tue Jun 29 15:26:26 2010 : Debug: filename = "/var/log/radius/radacct/wimax/detail-*" Tue Jun 29 15:26:26 2010 : Debug: load_factor = 10 Tue Jun 29 15:26:26 2010 : Debug: poll_interval = 20 Tue Jun 29 15:26:26 2010 : Debug: retry_interval = 30 Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: } Tue Jun 29 15:26:26 2010 : Debug: Listening on authentication address * port 1812 Tue Jun 29 15:26:26 2010 : Debug: Listening on accounting address * port 1813 Tue Jun 29 15:26:26 2010 : Debug: Listening on command file /var/run/radiusd/radiusd.sock Tue Jun 29 15:26:26 2010 : Debug: Listening on detail file /var/log/radius/radacct/wisper/detail-* as server buffered-sql-wisper Tue Jun 29 15:26:26 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 10.000000 sec Tue Jun 29 15:26:26 2010 : Debug: Listening on status address * port 18120 as server status Tue Jun 29 15:26:26 2010 : Debug: Listening on detail file /var/log/radius/radacct/wimax/detail-* as server buffered-sql-wimax Tue Jun 29 15:26:26 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 20.000000 sec Tue Jun 29 15:26:26 2010 : Debug: Listening on proxy address * port 1814 Tue Jun 29 15:26:26 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:36 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:36 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 10.176255 sec Tue Jun 29 15:26:36 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:46 2010 : Debug: Polling for detail file /var/log/radius/radacct/wimax/detail-* Tue Jun 29 15:26:46 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 19.786953 sec Tue Jun 29 15:26:46 2010 : Debug: Waking up in 0.1 seconds. Tue Jun 29 15:26:46 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:46 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.933326 sec Tue Jun 29 15:26:46 2010 : Debug: Waking up in 9.9 seconds. Tue Jun 29 15:26:56 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:26:56 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.832270 sec Tue Jun 29 15:26:56 2010 : Debug: Waking up in 9.6 seconds. Tue Jun 29 15:27:06 2010 : Debug: Polling for detail file /var/log/radius/radacct/wimax/detail-* Tue Jun 29 15:27:06 2010 : Debug: Detail listener /var/log/radius/radacct/wimax/detail-* state unopened signalled 0 waiting 20.068690 sec Tue Jun 29 15:27:06 2010 : Debug: Waking up in 0.1 seconds. Tue Jun 29 15:27:06 2010 : Debug: Polling for detail file /var/log/radius/radacct/wisper/detail-* Tue Jun 29 15:27:06 2010 : Debug: Detail listener /var/log/radius/radacct/wisper/detail-* state unopened signalled 0 waiting 9.778881 sec Tue Jun 29 15:27:06 2010 : Debug: Waking up in 9.7 seconds. rad_recv: Accounting-Request packet from host 172.17.2.20 port 6154, id=18, length=293 Acct-Status-Type = Interim-Update User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6(a)test.wisper-wireless.com" NAS-IP-Address = 172.17.2.20 NAS-Port-Type = Wireless-802.16 NAS-Port = 5 NAS-Identifier = "melrose.asn-gw.wisper-wireless.com" WiMAX-NAP-Id = 0x575753 WiMAX-GMT-Timezone-offset = -18000 Calling-Station-Id = "\000&\202O\342\326" WiMAX-BS-Id = 0x000039fefe01 Event-Timestamp = "Aug 19 2009 22:33:29 CDT" Acct-Session-Id = "1A" Acct-Multi-Session-Id = "97be68067743d815f4ddd6d2c18b353a" Framed-IP-Address = 209.237.120.249 WiMAX-hHA-IP-MIP4 = 0.0.0.0 Acct-Session-Time = 240 WiMAX-Active-Time-Duration = 240 Acct-Input-Octets = 0 Acct-Output-Octets = 0 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Tue Jun 29 15:27:09 2010 : Info: server wimax-asn { Tue Jun 29 15:27:09 2010 : Info: +- entering group preacct {...} Tue Jun 29 15:27:09 2010 : Info: ++[preprocess] returns ok Tue Jun 29 15:27:09 2010 : Info: [acct_unique] Hashing 'NAS-Port = 5,Client-IP-Address = 172.17.2.20,NAS-IP-Address = 172.17.2.20,Acct-Session-Id = "1A",User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6(a)test.wisper-wireless.com"' Tue Jun 29 15:27:09 2010 : Info: [acct_unique] Acct-Unique-Session-ID = "deb71f7ac9251cc9". Tue Jun 29 15:27:09 2010 : Info: ++[acct_unique] returns ok Tue Jun 29 15:27:09 2010 : Debug: rlm_wimax: Fixing WiMAX binary Calling-Station-Id to 00-26-82-4f-e2-d6 Tue Jun 29 15:27:09 2010 : Info: ++[wimax] returns ok Tue Jun 29 15:27:09 2010 : Info: +- entering group accounting {...} Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] expand: /var/log/radius/radacct/wimax/detail-%Y%m%d -> /var/log/radius/radacct/wimax/detail-20100629 Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] /var/log/radius/radacct/wimax/detail-%Y%m%d expands to /var/log/radius/radacct/wimax/detail-20100629 Tue Jun 29 15:27:09 2010 : Info: [detail_wimax] expand: %t -> Tue Jun 29 15:27:09 2010 Tue Jun 29 15:27:09 2010 : Info: ++[detail_wimax] returns ok Tue Jun 29 15:27:09 2010 : Info: ++? if (Acct-Status-Type == Interim-Update) Tue Jun 29 15:27:09 2010 : Info: ? Evaluating (Acct-Status-Type == Interim-Update) -> TRUE Tue Jun 29 15:27:09 2010 : Info: ++? if (Acct-Status-Type == Interim-Update) -> TRUE Tue Jun 29 15:27:09 2010 : Info: ++- entering if (Acct-Status-Type == Interim-Update) {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{User-Name} -> 90E6A2CE0489B3FC32EBF73572CC92E6(a)test.wisper-wireless.com Tue Jun 29 15:27:09 2010 : Info: expand: %{Calling-Station-Id} -> 00-26-82-4f-e2-d6 Tue Jun 29 15:27:09 2010 : Info: +++[disconnect] returns ok Tue Jun 29 15:27:09 2010 : Info: ++- if (Acct-Status-Type == Interim-Update) returns ok Tue Jun 29 15:27:09 2010 : Info: ++? if ((Acct-Status-Type == Stop) && (WiMAX-Session-Continue == False)) Tue Jun 29 15:27:09 2010 : Info: ?? Evaluating (Acct-Status-Type == Stop) -> FALSE Tue Jun 29 15:27:09 2010 : Info: ?? Skipping (WiMAX-Session-Continue == False) Tue Jun 29 15:27:09 2010 : Info: ++? if ((Acct-Status-Type == Stop) && (WiMAX-Session-Continue == False)) -> FALSE Tue Jun 29 15:27:09 2010 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> 90E6A2CE0489B3FC32EBF73572CC92E6(a)test.wisper-wireless.com Tue Jun 29 15:27:09 2010 : Debug: attr_filter: Matched entry DEFAULT at line 12 Tue Jun 29 15:27:09 2010 : Info: ++[attr_filter.accounting_response] returns updated Tue Jun 29 15:27:09 2010 : Info: } # server wimax-asn Sending Accounting-Response of id 18 to 172.17.2.20 port 6154 Tue Jun 29 15:27:09 2010 : Info: server originate-coa-wimax { Tue Jun 29 15:27:09 2010 : Info: WARNING: Empty pre-proxy section. Using default return values. Tue Jun 29 15:27:09 2010 : Info: } Sending Disconnect-Request of id 203 to 172.17.2.20 port 3799 User-Name = "90E6A2CE0489B3FC32EBF73572CC92E6(a)test.wisper-wireless.com" Calling-Station-Id = "00-26-82-4f-e2-d6" WiMAX-AAA-Session-Id = 0x626c6168626c6168626c6168 WiMAX-DM-Action-Code = Deregister-MS Tue Jun 29 15:27:09 2010 : Info: Finished request 0. Tue Jun 29 15:27:09 2010 : Info: Cleaning up request 0 ID 18 with timestamp +43 Tue Jun 29 15:27:09 2010 : Debug: Going to the next request Tue Jun 29 15:27:09 2010 : Debug: Waking up in 2.2 seconds. rad_recv: Disconnect-NAK packet from host 172.17.2.20 port 3799, id=203, length=32 Event-Timestamp = "Aug 19 2009 22:33:29 CDT" Error-Cause = Session-Context-Not-Found Tue Jun 29 15:27:09 2010 : Info: server originate-coa-wimax { Tue Jun 29 15:27:09 2010 : Info: +- entering group post-proxy {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Response-Packet-Type} -> Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-request:Packet-Type} -> Disconnect-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{request:Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: expand: %{reply:Packet-Type} -> Accounting-Response Tue Jun 29 15:27:09 2010 : Info: expand: %{Packet-Type} -> Accounting-Request Tue Jun 29 15:27:09 2010 : Info: ++[request] returns noop Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Packet-Type} -> Disconnect-NAK Tue Jun 29 15:27:09 2010 : Info: ++- entering switch %{proxy-reply:Packet-Type} {...} Tue Jun 29 15:27:09 2010 : Info: +++- entering case Disconnect-NAK {...} Tue Jun 29 15:27:09 2010 : Info: expand: %{proxy-reply:Error-Cause} -> Session-Context-Not-Found Tue Jun 29 15:27:09 2010 : Info: ++++[request] returns noop Tue Jun 29 15:27:09 2010 : Info: ++++[ok] returns ok Tue Jun 29 15:27:09 2010 : Info: +++- case Disconnect-NAK returns ok Tue Jun 29 15:27:09 2010 : Info: ++- switch %{proxy-reply:Packet-Type} returns ok Tue Jun 29 15:27:09 2010 : Info: } Tue Jun 29 15:27:09 2010 : Info: server wimax-asn { Tue Jun 29 15:27:09 2010 : Info: } # server wimax-asn Tue Jun 29 15:27:09 2010 : Info: Finished request 0. Tue Jun 29 15:27:09 2010 : Debug: Going to the next request Tue Jun 29 15:27:09 2010 : Debug: Waking up in 7.3 seconds. Ben

2 2