January 2009 - Freeradius-Users - lists.freeradius.org

Problem with freeradius.org website
by Karl Auer 21 Jan '09

21 Jan '09

Is anyone else experiencing problems with the freeradius.org website? I'm new to freeradius, so maybe this is normal for the site, but I'm getting massive waits (minutes) generally ending in timeouts. Both the addresses are pingable. The Wiki is OK, it's just the website at freeradius.org. Regards, K. -- ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Karl Auer (kauer(a)biplane.com.au) +61-2-64957160 (h) http://www.biplane.com.au/~kauer/ +61-428-957160 (mob) GPG fingerprint: DD23 0DF3 2260 3060 7FEC 5CA8 1AF6 D9E3 CFEE 6B28

9 26

User not being rejected...
by qrt 20 Jan '09

20 Jan '09

Hello, I don't get it. Maybe someone sees my mistake... I have freeraradius on macos x. My Users file has these entries: /private/raddb/users > #------------------------------------------------------------------------------------------------- > # Allow members of group 'schueler' to WLAN-45 > > DEFAULT Ldap-Group == "schueler", Airespace-Wlan-Id == 4 > Auth-Type := opendirectory, > Service-Type = Login-User, > Reply-Message = "Schueler: WLAN-45 accept", > Fall-Through = 0 > > #------------------------------------------------------------------------------------------------- > # Reject members of group 'schueler' from any other than WLAN-45 > > DEFAULT Ldap-Group == "schueler", Airespace-Wlan-Id != 4 > Auth-Type := Reject, > Reply-Message = "Schueler: Wrong WLAN!!!", > > #------------------------------------------------------------------------------------------------- > # Allow members of group 'schuladministration' to WLAN-47 > > DEFAULT Ldap-Group == "schuladministration", Airespace-Wlan-Id == 6 > Auth-Type := opendirectory, > Service-Type = Login-User, > Reply-Message = "schuladministration: WLAN-47 accept", > Fall-Through = 0 > > #------------------------------------------------------------------------------------------------- > # Reject all others > > DEFAULT Auth-Type := Reject > Reply-Message = "Access denied." > > #------------------------------------------------------------------------------------------------- In the log file I see this: > rad_recv: Access-Request packet from host 192.168.95.10:32768, > id=151, length=197 > User-Name = "w45user" > Calling-Station-Id = "00-17-F2-E8-74-76" > Called-Station-Id = "00-1D-70-93-05-C0:WLAN-44" > NAS-Port = 29 > NAS-IP-Address = 192.168.95.10 > NAS-Identifier = "KSHP-UG-SRV-WLC-04" > Airespace-Wlan-Id = 3 > Service-Type = Framed-User > Framed-MTU = 1300 > NAS-Port-Type = Wireless-802.11 > Tunnel-Type:0 = VLAN > Tunnel-Medium-Type:0 = IEEE-802 > Tunnel-Private-Group-Id:0 = "44" > EAP-Message = 0x020300061500 > State = 0xe56af3902cf86936b5da18867203a336 > Message-Authenticator = 0x0b2df96b7f01043f6296236014935512 > Processing the authorize section of radiusd.conf > modcall: entering group authorize for request 43 > modcall[authorize]: module "preprocess" returns ok for request 43 > modcall[authorize]: module "chap" returns noop for request 43 > modcall[authorize]: module "mschap" returns noop for request 43 > rlm_realm: No '@' in User-Name = "w45user", looking up realm NULL > rlm_realm: No such realm "NULL" > modcall[authorize]: module "suffix" returns noop for request 43 > rlm_eap: EAP packet type response id 3 length 6 > rlm_eap: No EAP Start, assuming it's an on-going EAP conversation > modcall[authorize]: module "eap" returns updated for request 43 > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(uid=w45user)' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (uid=w45user) > rlm_ldap: ldap_release_conn: Release Id: 0 > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=wlan_test)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap: object not found or got ambiguous search result > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap::ldap_groupcmp: Group wlan_test not found or user is not a > member. > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=vpn_users)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap: object not found or got ambiguous search result > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap::ldap_groupcmp: Group vpn_users not found or user is not a > member. > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=angestellte)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap: object not found or got ambiguous search result > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap::ldap_groupcmp: Group angestellte not found or user is not > a member. > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=lehrer)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap: object not found or got ambiguous search result > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap::ldap_groupcmp: Group lehrer not found or user is not a > member. > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=lehrer)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap: object not found or got ambiguous search result > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap::ldap_groupcmp: Group lehrer not found or user is not a > member. > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=schueler)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap::ldap_groupcmp: User found in group schueler > rlm_ldap: ldap_release_conn: Release Id: 0 > rlm_ldap: Entering ldap_groupcmp() > radius_xlat: 'dc=ldap,dc=ksoe,dc=edu' > radius_xlat: '(&(objectClass=posixGroup)(memberUid=w45user))' > rlm_ldap: ldap_get_conn: Checking Id: 0 > rlm_ldap: ldap_get_conn: Got Id: 0 > rlm_ldap: performing search in dc=ldap,dc=ksoe,dc=edu, with filter > (&(cn=schueler)(&(objectClass=posixGroup)(memberUid=w45user))) > rlm_ldap::ldap_groupcmp: User found in group schueler > rlm_ldap: ldap_release_conn: Release Id: 0 > users: Matched entry DEFAULT at line 260 > modcall[authorize]: module "files" returns ok for request 43 > modcall: leaving group authorize (returns updated) for request 43 > rad_check_password: Found Auth-Type EAP > auth: type "EAP" > Processing the authenticate section of radiusd.conf > modcall: entering group authenticate for request 43 > 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 > rlm_eap_tls: Received EAP-TLS ACK message > rlm_eap_tls: ack handshake fragment handler > eaptls_verify returned 1 > eaptls_process returned 13 > modcall[authenticate]: module "eap" returns handled for request 43 > modcall: leaving group authenticate (returns handled) for request 43 > Sending Access-Challenge of id 151 to 192.168.95.10 port 32768 > Reply-Message = "Schueler: Wrong WLAN!!!" > EAP-Message = > 0x01040323158000000719010405003081ce310b3009060355040613025a41311530130603550408130c5765737465726e204361706531123010060355040713094361706520546f776e311d301b060355040a131454686177746520436f6e73756c74696e6720636331283026060355040b131f43657274696669636174696f6e205365727669636573204469766973696f6e3121301f06035504031318546861777465205072656d69756d205365727665722043413128302606092a864886f70d01090116197072656d69756d2d736572766572407468617774652e636f6d301e170d3936303830313030303030305a170d3230313233313233353935 > EAP-Message = > 0x395a3081ce310b3009060355040613025a41311530130603550408130c5765737465726e204361706531123010060355040713094361706520546f776e311d301b060355040a131454686177746520436f6e73756c74696e6720636331283026060355040b131f43657274696669636174696f6e205365727669636573204469766973696f6e3121301f06035504031318546861777465205072656d69756d205365727665722043413128302606092a864886f70d01090116197072656d69756d2d736572766572407468617774652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d236366a8bd7c25b9eda814162 > EAP-Message = > 0x8f38ee490455d6d0ef1c1b951647ef1848353a52f42b6a068f3b2fea56e3af868d9e17f79eb46575024defcb09a22151d89bd067d0ba0d92061473d493cb972a009c5c4e0cbcfa1552fcf2446eda114a6e089f2f2de3f9aa3a8673b6465358c88905bd8311b8733faa078df4424de7409d1c370203010001a3133011300f0603551d130101ff040530030101ff300d06092a864886f70d01010405000381810026482c16c258fae816740caaaa5f543ff2d7c978605e5e6e37632277367eb217c434b9f50885fcc90138ff4dbef2164243e7bb5a46fbc1c6111ff14ab02846c9c3c4427dbcfaab596ed5b7518811e3a485196b824ca40c12ade9a4ae3f > EAP-Message = > 0xf1c349659a8cc5c83e25b79499bb92327107f0865eed5027a60da623f9bbcba607144216030100040e000000 > Message-Authenticator = 0x00000000000000000000000000000000 > State = 0x287a38ce7b69dbc51126c71ef1bd49f3 > Finished request 43 > Going to the next request > Waking up in 6 seconds... As far as I can tell, I see this line: > users: Matched entry DEFAULT at line 260 > This is the line containing 'DEFAULT Ldap-Group == "schueler", Airespace-Wlan-Id != 4' which is correct. So if this works (I can also read the ' Reply-Message = "Schueler: Wrong WLAN!!!"', why does this user get an access? Why does the line 'Auth-Type := Reject,' not work? What do I have to do to have him beeing rejected? Any ideas Thanks Kurt

2 1

Tunnel attributes
by ramesh p 20 Jan '09

20 Jan '09

How to start supporting Tunnel attributes for freeradius vers 1.1.6. Any document references?? Which will be the starting point for this. Do i need to change configuration of mysql.conf file? Or directly creating database helps? some of the attributes to be highlighted.. Tunnel Type, Tunnel-Server-Endpoint, Tunnel-Client-Endpoint, Disc-Cause-Ext, PPP-Disconnect-Cause etc.. Please give me suggestions. Thanks in advance... Regards, Ramesh.

4 22

How to add new attributes?
by Fedotov Yuriy 20 Jan '09

20 Jan '09

Hi. Does enebody can help me with some problem? I wont add new attibute H323-setup-time to radus and get access. When i added to radius.h file #define PW_H323_SETUP_TIME 25 and rlm_example.c VALUE_PAIR *state; char *val; state = pairfind(request->packet->vps, PW_H323_SETUP_TIME); if (state) { val = state->vp_strvalue; DEBUG("\nPW_H323_SETUP_TIME = %s\n",val); } else printf("empty\n"); I allways received "empty" status --

2 1

simple radius auth in school??
by Sascha Schneider 20 Jan '09

20 Jan '09

Hi List, I'm new to freeradius and try to set up a radiusserver in our school for our teachers, whome till now had their access via AP with MAC-filtering. Freeradius with sql is up and running on OpenSuSe 11.0. radtest works fine, DHCP is provided by an IPCop box Now my questions, we have some new Edimax EW-7209APg, that support RADIUS Auth with EAP/MD5. 1) How can I setup that system to make it as simple as possible for our teachers. We don't need ssl or WAP or a splitted connection, where WLAN access is yust granted to the intra but not internet or vis-versa. I want to have my wired hosts and the wlan-hosts in one net (e.g. 192.168.10.0), no VLAN. As simple as possible, people with username/password can access the net wireless, wired clients are always on the net. 2) Is there a "best practice guide" for this kind of situation?? 3) Do I have to install a captive-portal?? 4) The EW-7209APg has a buildin RadiusServer, but I didn't manage to connect a laptop wireless to it, how is this done. (with no auth it works), but I don't understand what I have to do on the laptop to show me some kind of window to enter username and password, or is this done as some kind of dialup. Sorry for the bunch of questions Greetings from belgium, Sascha Schneider

2 1

Can't compile FR 2.1.3
by Chris Howley 20 Jan '09

20 Jan '09

Alan, I can't compile FR 2.1.3 in Solaris10. Thanks, Chris Howley SunOS netserv3 5.10 Generic_120012-14 i86pc i386 i86pc gcc -g -O2 -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -Wall -D_GNU_SOURCE -DNDEBUG -I/sandbox/freeradius-server-2.1.3/src -DHOSTINFO=\" i386-pc-solaris2.10\" -DRADIUSD_VERSION=\"2.1.3\" -DOPENSSL_NO_KRB5 -I/sandbox/freeradius-server-2.1.3/libltdl -c listen.c -fPIC -DP IC -o .libs/listen.o listen.c: In function `client_listener_find': listen.c:141: warning: passing arg 1 of pointer to function discards qualifiers from pointer target type listen.c:220: warning: assignment discards qualifiers from pointer target type In file included from listen.c:1024: command.c: In function `fr_server_domain_socket': command.c:151: error: invalid type argument of `->' command.c: In function `command_show_client_config': command.c:805: warning: passing arg 2 of `cf_section2file' discards qualifiers from pointer target type gmake[4]: *** [listen.lo] Error 1 gmake[4]: Leaving directory `/sandbox/freeradius-server-2.1.3/src/main' gmake[3]: *** [common] Error 2 gmake[3]: Leaving directory `/sandbox/freeradius-server-2.1.3/src' gmake[2]: *** [all] Error 2 gmake[2]: Leaving directory `/sandbox/freeradius-server-2.1.3/src' gmake[1]: *** [common] Error 2 gmake[1]: Leaving directory `/sandbox/freeradius-server-2.1.3' gmake: *** [all] Error 2

2 1

Question about authentication
by John Baldwin 20 Jan '09

20 Jan '09

Hello all I'm trying to configure freeradius on a Centos server to authenticate my logins on Cisco devices. I can see in the log file that my request is hitting the server. I'm advised to just add a username and password in the users file so I've done that, I've used the steve login and password of testing as used as an example in the file and as follows steve Cleartext-Password := "testing" All following lines are still commented out. I'm running radiusd -x. The following is the contents of the log file. Waking up in 0.9 seconds. rlm_pap: login attempt with password "CÃ?-Ã+CÃ½?AÃ ?Ã¼?RE" rlm_pap: Using clear text password "testing" rlm_pap: Passwords don't match Waking up in 3.9 seconds. Ready to process requests. Ready to process requests. Exiting normally. Listening on authentication address 192.168.72.100 port 1812 Listening on accounting address * port 1813 Listening on proxy address 192.168.72.100 port 1814 Ready to process requests. Waking up in 0.9 seconds. rlm_pap: login attempt with password "CVÃ¦Ã??)yc8Ã©?Ã?ir" rlm_pap: Using clear text password "testing" rlm_pap: Passwords don't match Waking up in 3.9 seconds. Any assistance you can provide would be greatly appreciated. Many thanks John [cid:image001.png@01C97B03.22F83520]<http://www.saxonfinancials.com/> John Baldwin Head of IT Saxon Financials Limited | Singapore 112 Robinson Road #06-04 Singapore 068902 Tel: (65) 6349 0000 Fax: (65) 6349 0001 Did: (65) 6349 0006 Cell: (65) 9144 6382 j.baldwin(a)saxonfinancials.com<mailto:j.baldwin@saxonfinancials.com> www.saxonfinancials.com<http://www.saxonfinancials.com> Click here<http://www.saxonfinancials.com/disclaimer.htm> for our email disclaimer.

2 1

ntlm_auth not working from within Freeradius with Domain in Username
by Holger Steppke 19 Jan '09

19 Jan '09

Hi, like to use freradius to authenticate wireless users against an existing windows AD. My enviorment Cisco AP, Router and Switch. An Windows 2003 AD server. My Freeradius server is an ubuntu 80.04 LTS with freeradius 1.1.7 compiled with tls of course. The relevant mschap configs looks like: mschap { use_mppe = no require_encryption = no require_strong = no with_ntdomain_hack = yes ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{Stripped-User-Name:-%{User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}" } So if i now try to connect with a Vista Client. It pops up with the 3 fields username/password/domain as usual. Now if i use username/password it works fine and if i use user/pass/domain it does not. As i may have multiple domains at the end i need that part working as well. I guess smb.conf/krb5.cnf is right as i can fire up the same output i see in the debug output from freeradius. Eg. su freerad -s /bin/sh -c 'ntlm_auth --username=TEST\\ingo --request-nt-key --challenge=25226c1fad0393e9 --nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585' NT_KEY: AE33A32DCA8C9821844F740D5B3F4D6C It comes back with the expected key. The keys are from one of the requests as seen in the Freeradius debug msg. Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: Told to do MS-CHAPv2 for ingo with NT-Password Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--username=TEST\\ingo' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat function of module mschap for string 'Challenge' Fri Jan 16 16:14:05 2009 : Debug: mschap2: 9c Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--challenge=25226c1fad0393e9' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat function of module mschap for string 'NT-Response' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585' Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads = 5/1/4 Fri Jan 16 16:14:05 2009 : Debug: Exec-Program output: Logon failure (0xc000006d) Fri Jan 16 16:14:05 2009 : Debug: Exec-Program-Wait: plaintext: Logon failure (0xc000006d) Fri Jan 16 16:14:05 2009 : Debug: Exec-Program: returned: 1 There is one difference ...... when i replace ntlm_auth with an own little script to just print the argv in file i do get: --request-nt-key --username=TEST\ingo --challenge=20ae2cce3a27e116 --nt-response=b862a58e5bccd288c367af67368ced711ded1e132159fc5a There is just one little difference compare to what i do on the bash itself. Thats the // vs / in the username. I guess Freeradius does send one / so TEST/ingo butif i woudl do it on the shell bash would strip it. so i need //. Apart from that i run out of ideas why auth fails as soon as i send a Domain name. Just username7password works as the radius servers samaba is in the Test Domain. Anyone an idea on how to furter debug ? I alreay tryed adding some prints infront of the relevant execve but they kill the logic of feeding the ntlm_response back to the parent. I guess it will look similar to what i see in the Script when i print the ARGV but not sure. Regards Holger Complete Debug msg: Fri Jan 16 16:12:56 2009 : Info: Starting - reading configuration files ... Fri Jan 16 16:12:56 2009 : Debug: reread_config: reading radiusd.conf Fri Jan 16 16:12:56 2009 : Debug: Config: including file: /etc/freeradius/proxy.conf Fri Jan 16 16:12:56 2009 : Debug: Config: including file: /etc/freeradius/clients.conf Fri Jan 16 16:12:56 2009 : Debug: Config: including file: /etc/freeradius/snmp.conf Fri Jan 16 16:12:56 2009 : Debug: Config: including file: /etc/freeradius/eap.conf Fri Jan 16 16:12:56 2009 : Debug: main: prefix = "/usr" Fri Jan 16 16:12:56 2009 : Debug: main: localstatedir = "/var" Fri Jan 16 16:12:56 2009 : Debug: main: logdir = "/var/log/freeradius" Fri Jan 16 16:12:56 2009 : Debug: main: libdir = "/usr/lib/freeradius" Fri Jan 16 16:12:56 2009 : Debug: main: radacctdir = "/var/log/freeradius/radacct" Fri Jan 16 16:12:56 2009 : Debug: main: hostname_lookups = no Fri Jan 16 16:12:56 2009 : Debug: main: snmp = no Fri Jan 16 16:12:56 2009 : Debug: main: max_request_time = 30 Fri Jan 16 16:12:56 2009 : Debug: main: cleanup_delay = 5 Fri Jan 16 16:12:56 2009 : Debug: main: max_requests = 1024 Fri Jan 16 16:12:56 2009 : Debug: main: delete_blocked_requests = 0 Fri Jan 16 16:12:56 2009 : Debug: main: port = 0 Fri Jan 16 16:12:56 2009 : Debug: main: allow_core_dumps = no Fri Jan 16 16:12:56 2009 : Debug: main: log_stripped_names = no Fri Jan 16 16:12:56 2009 : Debug: main: log_file = "/var/log/freeradius/radius.log" Fri Jan 16 16:12:56 2009 : Debug: main: log_auth = yes Fri Jan 16 16:12:56 2009 : Debug: main: log_auth_badpass = yes Fri Jan 16 16:12:56 2009 : Debug: main: log_auth_goodpass = yes Fri Jan 16 16:12:56 2009 : Debug: main: pidfile = "/var/run/freeradius/freeradius.pid" Fri Jan 16 16:12:56 2009 : Debug: main: user = "freerad" Fri Jan 16 16:12:56 2009 : Debug: main: group = "freerad" Fri Jan 16 16:12:56 2009 : Debug: main: usercollide = no Fri Jan 16 16:12:56 2009 : Debug: main: lower_user = "no" Fri Jan 16 16:12:56 2009 : Debug: main: lower_pass = "no" Fri Jan 16 16:12:56 2009 : Debug: main: nospace_user = "no" Fri Jan 16 16:12:56 2009 : Debug: main: nospace_pass = "no" Fri Jan 16 16:12:56 2009 : Debug: main: checkrad = "/usr/sbin/checkrad" Fri Jan 16 16:12:56 2009 : Debug: main: proxy_requests = yes Fri Jan 16 16:12:56 2009 : Debug: proxy: retry_delay = 5 Fri Jan 16 16:12:56 2009 : Debug: proxy: retry_count = 3 Fri Jan 16 16:12:56 2009 : Debug: proxy: synchronous = no Fri Jan 16 16:12:56 2009 : Debug: proxy: default_fallback = yes Fri Jan 16 16:12:56 2009 : Debug: proxy: dead_time = 120 Fri Jan 16 16:12:56 2009 : Debug: proxy: post_proxy_authorize = no Fri Jan 16 16:12:56 2009 : Debug: proxy: wake_all_if_all_dead = no Fri Jan 16 16:12:56 2009 : Debug: security: max_attributes = 200 Fri Jan 16 16:12:56 2009 : Debug: security: reject_delay = 1 Fri Jan 16 16:12:56 2009 : Debug: security: status_server = no Fri Jan 16 16:12:56 2009 : Debug: main: debug_level = 0 Fri Jan 16 16:12:56 2009 : Debug: read_config_files: reading dictionary Fri Jan 16 16:12:56 2009 : Debug: read_config_files: reading naslist Fri Jan 16 16:12:56 2009 : Info: Using deprecated naslist file. Support for this will go away soon. Fri Jan 16 16:12:56 2009 : Debug: read_config_files: reading clients Fri Jan 16 16:12:56 2009 : Debug: read_config_files: reading realms Fri Jan 16 16:12:56 2009 : Debug: radiusd: entering modules setup Fri Jan 16 16:12:56 2009 : Debug: Module: Library search path is /usr/lib/freeradius Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded exec Fri Jan 16 16:12:56 2009 : Debug: exec: wait = yes Fri Jan 16 16:12:56 2009 : Debug: exec: program = "(null)" Fri Jan 16 16:12:56 2009 : Debug: exec: input_pairs = "request" Fri Jan 16 16:12:56 2009 : Debug: exec: output_pairs = "(null)" Fri Jan 16 16:12:56 2009 : Debug: exec: packet_type = "(null)" Fri Jan 16 16:12:56 2009 : Info: rlm_exec: Wait=yes but no output defined. Did you mean output=none? Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated exec (exec) Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded expr Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated expr (expr) Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded PAP Fri Jan 16 16:12:56 2009 : Debug: pap: encryption_scheme = "crypt" Fri Jan 16 16:12:56 2009 : Debug: pap: auto_header = yes Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated pap (pap) Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded CHAP Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated chap (chap) Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded MS-CHAP Fri Jan 16 16:12:56 2009 : Debug: mschap: use_mppe = no Fri Jan 16 16:12:56 2009 : Debug: mschap: require_encryption = yes Fri Jan 16 16:12:56 2009 : Debug: mschap: require_strong = yes Fri Jan 16 16:12:56 2009 : Debug: mschap: with_ntdomain_hack = yes Fri Jan 16 16:12:56 2009 : Debug: mschap: passwd = "(null)" Fri Jan 16 16:12:56 2009 : Debug: mschap: ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{Stripped-User-Name:-%{User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}" Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated mschap (mschap) Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded eap Fri Jan 16 16:12:56 2009 : Debug: eap: default_eap_type = "peap" Fri Jan 16 16:12:56 2009 : Debug: eap: timer_expire = 60 Fri Jan 16 16:12:56 2009 : Debug: eap: ignore_unknown_eap_types = no Fri Jan 16 16:12:56 2009 : Debug: eap: cisco_accounting_username_bug = no Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type md5 Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type leap Fri Jan 16 16:12:56 2009 : Debug: gtc: challenge = "Password: " Fri Jan 16 16:12:56 2009 : Debug: gtc: auth_type = "PAP" Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type gtc Fri Jan 16 16:12:56 2009 : Debug: tls: rsa_key_exchange = no Fri Jan 16 16:12:56 2009 : Debug: tls: dh_key_exchange = yes Fri Jan 16 16:12:56 2009 : Debug: tls: rsa_key_length = 512 Fri Jan 16 16:12:56 2009 : Debug: tls: dh_key_length = 512 Fri Jan 16 16:12:56 2009 : Debug: tls: verify_depth = 0 Fri Jan 16 16:12:56 2009 : Debug: tls: CA_path = "(null)" Fri Jan 16 16:12:56 2009 : Debug: tls: pem_file_type = yes Fri Jan 16 16:12:56 2009 : Debug: tls: private_key_file = "/etc/freeradius/certs/cert-srv.pem" Fri Jan 16 16:12:56 2009 : Debug: tls: certificate_file = "/etc/freeradius/certs/cert-srv.pem" Fri Jan 16 16:12:56 2009 : Debug: tls: CA_file = "/etc/freeradius/certs/demoCA/cacert.pem" Fri Jan 16 16:12:56 2009 : Debug: tls: private_key_password = "whatever" Fri Jan 16 16:12:56 2009 : Debug: tls: dh_file = "/etc/freeradius/certs/dh" Fri Jan 16 16:12:56 2009 : Debug: tls: random_file = "/dev/urandom" Fri Jan 16 16:12:56 2009 : Debug: tls: fragment_size = 1024 Fri Jan 16 16:12:56 2009 : Debug: tls: include_length = yes Fri Jan 16 16:12:56 2009 : Debug: tls: check_crl = no Fri Jan 16 16:12:56 2009 : Debug: tls: check_cert_cn = "(null)" Fri Jan 16 16:12:56 2009 : Debug: tls: cipher_list = "(null)" Fri Jan 16 16:12:56 2009 : Debug: tls: check_cert_issuer = "(null)" Fri Jan 16 16:12:56 2009 : Info: rlm_eap_tls: Loading the certificate file as a chain Fri Jan 16 16:12:57 2009 : Info: WARNING: rlm_eap_tls: Unable to set DH parameters. DH cipher suites may not work! Fri Jan 16 16:12:57 2009 : Debug: WARNING: Fix this by running the OpenSSL command listed in eap.conf Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type tls Fri Jan 16 16:12:57 2009 : Debug: peap: default_eap_type = "mschapv2" Fri Jan 16 16:12:57 2009 : Debug: peap: copy_request_to_tunnel = no Fri Jan 16 16:12:57 2009 : Debug: peap: use_tunneled_reply = no Fri Jan 16 16:12:57 2009 : Debug: peap: proxy_tunneled_request_as_eap = yes Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type peap Fri Jan 16 16:12:57 2009 : Debug: mschapv2: with_ntdomain_hack = no Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type mschapv2 Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated eap (eap) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded preprocess Fri Jan 16 16:12:57 2009 : Debug: preprocess: huntgroups = "/etc/freeradius/huntgroups" Fri Jan 16 16:12:57 2009 : Debug: preprocess: hints = "/etc/freeradius/hints" Fri Jan 16 16:12:57 2009 : Debug: preprocess: with_ascend_hack = no Fri Jan 16 16:12:57 2009 : Debug: preprocess: ascend_channels_per_line = 23 Fri Jan 16 16:12:57 2009 : Debug: preprocess: with_ntdomain_hack = no Fri Jan 16 16:12:57 2009 : Debug: preprocess: with_specialix_jetstream_hack = no Fri Jan 16 16:12:57 2009 : Debug: preprocess: with_cisco_vsa_hack = no Fri Jan 16 16:12:57 2009 : Debug: preprocess: with_alvarion_vsa_hack = no Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated preprocess (preprocess) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded files Fri Jan 16 16:12:57 2009 : Debug: files: usersfile = "/etc/freeradius/users" Fri Jan 16 16:12:57 2009 : Debug: files: acctusersfile = "/etc/freeradius/acct_users" Fri Jan 16 16:12:57 2009 : Debug: files: preproxy_usersfile = "/etc/freeradius/preproxy_users" Fri Jan 16 16:12:57 2009 : Debug: files: compat = "no" Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated files (files) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded Acct-Unique-Session-Id Fri Jan 16 16:12:57 2009 : Debug: acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated acct_unique (acct_unique) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded realm Fri Jan 16 16:12:57 2009 : Debug: realm: format = "suffix" Fri Jan 16 16:12:57 2009 : Debug: realm: delimiter = "@" Fri Jan 16 16:12:57 2009 : Debug: realm: ignore_default = no Fri Jan 16 16:12:57 2009 : Debug: realm: ignore_null = no Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated realm (suffix) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded detail Fri Jan 16 16:12:57 2009 : Debug: detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Fri Jan 16 16:12:57 2009 : Debug: detail: detailperm = 384 Fri Jan 16 16:12:57 2009 : Debug: detail: dirperm = 493 Fri Jan 16 16:12:57 2009 : Debug: detail: locking = no Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated detail (detail) Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded radutmp Fri Jan 16 16:12:57 2009 : Debug: radutmp: filename = "/var/log/freeradius/radutmp" Fri Jan 16 16:12:57 2009 : Debug: radutmp: username = "%{User-Name}" Fri Jan 16 16:12:57 2009 : Debug: radutmp: case_sensitive = yes Fri Jan 16 16:12:57 2009 : Debug: radutmp: check_with_nas = yes Fri Jan 16 16:12:57 2009 : Debug: radutmp: perm = 384 Fri Jan 16 16:12:57 2009 : Debug: radutmp: callerid = yes Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated radutmp (radutmp) Fri Jan 16 16:12:57 2009 : Debug: Initializing the thread pool... Fri Jan 16 16:12:57 2009 : Debug: thread: start_servers = 5 Fri Jan 16 16:12:57 2009 : Debug: thread: max_servers = 32 Fri Jan 16 16:12:57 2009 : Debug: thread: min_spare_servers = 3 Fri Jan 16 16:12:57 2009 : Debug: thread: max_spare_servers = 10 Fri Jan 16 16:12:57 2009 : Debug: thread: max_requests_per_server = 0 Fri Jan 16 16:12:57 2009 : Debug: thread: cleanup_delay = 5 Fri Jan 16 16:12:57 2009 : Debug: Thread 1 waiting to be assigned a request Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 1. Total threads in pool: 1 Fri Jan 16 16:12:57 2009 : Debug: Thread 2 waiting to be assigned a request Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 2. Total threads in pool: 2 Fri Jan 16 16:12:57 2009 : Debug: Thread 3 waiting to be assigned a request Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 3. Total threads in pool: 3 Fri Jan 16 16:12:57 2009 : Debug: Thread 4 waiting to be assigned a request Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 4. Total threads in pool: 4 Fri Jan 16 16:12:57 2009 : Debug: Thread 5 waiting to be assigned a request Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 5. Total threads in pool: 5 Fri Jan 16 16:12:57 2009 : Debug: Thread pool initialized Fri Jan 16 16:12:57 2009 : Debug: Listening on authentication *:1812 Fri Jan 16 16:12:57 2009 : Debug: Listening on accounting *:1813 Fri Jan 16 16:12:57 2009 : Info: Ready to process requests. rad_recv: Access-Request packet from host 192.168.0.10:1645, id=119, length=131 Fri Jan 16 16:14:05 2009 : Debug: --- Walking the entire request list --- Fri Jan 16 16:14:05 2009 : Debug: Thread 1 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 1 handling request 0, (1 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xb84d1174c3d3c8b898c5fd8d95f4e061 EAP-Message = 0x0202000e01544553545c696e676f NAS-Port-Type = Wireless-802.11 NAS-Port = 447 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 2 length 14 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 0 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 0 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP Identity Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type tls Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Initiate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Start returned 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 0 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 0 Sending Access-Challenge of id 119 to 192.168.0.10 port 1645 EAP-Message = 0x010300061920 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3622b9d5d04e6552a9c7b3220f54bf19 Fri Jan 16 16:14:05 2009 : Debug: Finished request 0 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 1 waiting to be assigned a request Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads = 5/0/5 rad_recv: Access-Request packet from host 192.168.0.10:1645, id=120, length=255 Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... Fri Jan 16 16:14:05 2009 : Debug: Thread 2 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 2 handling request 1, (1 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0x81e0b531d499a03fad2cabbe0136dbcb EAP-Message = 0x0203007819800000006e16030100690100006503014970a43cd3c00043f4020f78dab64dd6fd1109b18b42781457d7ea678061b4dd000018002f00350005000ac009c00ac013c0140032003800130004010000240000000e000c000009746573745c696e676f000a00080006001700180019000b00020100 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0x3622b9d5d04e6552a9c7b3220f54bf19 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 3 length 120 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 1 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 1 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Length Included Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 11 Fri Jan 16 16:14:05 2009 : Debug: (other): before/accept initialization Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: before/accept initialization Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: <<< TLS 1.0 Handshake [length 0069], ClientHello Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 read client hello A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 write server hello A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 0694], Certificate Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 write certificate A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 write server done A Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 flush data Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: Need to read more data: SSLv3 read client certificate A Fri Jan 16 16:14:05 2009 : Debug: In SSL Handshake Phase Fri Jan 16 16:14:05 2009 : Debug: In SSL Accept mode Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 13 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_HANDLED Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 1 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 1 Sending Access-Challenge of id 120 to 192.168.0.10 port 1645 EAP-Message = 0x0104040a19c0000006f1160301004a0200004603014970a43d78dd332f6e7b648863347a1ce42c355ce4d73bc0d39f275d248c7e1f2049771b122c76f8f4a00bb4227b2d67d1fa90300f22e0b60a7891fae8ee5e7a92002f0016030106940b00069000068d0002cd308202c930820232a003020102020102300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e74206365 EAP-Message = 0x7274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d301e170d3034303132353133323631305a170d3035303132343133323631305a30819b310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f73743119301706035504031310526f6f74206365727469666963617465311f301d06092a864886f70d0109011610726f6f74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003 EAP-Message = 0x818d0030818902818100dac525422bfedb082629a2cba44b3449c90d0ab462fb72c8434a782098863d7eb7d7e70028c2b7ad555a51cc756cf4fa1d7091615ab450d5289553ae6616aff014a55085d6b8fb4aee98638e426175cdd36c665c63cda177d34920eb30585edc8773999c2980f81ad4638bbbea1c82d054023db7ef24a3ec1c3f6241a903d7f30203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101040500038181007a2d921b1cf13bf2982a9178ec9ede6d88edc178a2e8bd40a0a06fb6f0769957884cd7084537083496fd184165293f583c8e8240eb68e042c94b15752e4c07e80d09 EAP-Message = 0x779afa3dd55c24fa54ac292d77205d1c2477ed30d59f57caf9bd21ff2a8d16cc0911c50e4f295763fcb60efa3c3d2d0e43850f6e6fbe284902f6e83503650003ba308203b63082031fa003020102020100300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c EAP-Message = 0x652e636f6d301e170d3034303132353133323630375a Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc6268f888323c9f0e7a30ccefba3b3cb Fri Jan 16 16:14:05 2009 : Debug: Finished request 1 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 2 waiting to be assigned a request rad_recv: Access-Request packet from host 192.168.0.10:1645, id=121, length=141 Fri Jan 16 16:14:05 2009 : Debug: Thread 3 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 3 handling request 2, (1 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0x9a963396a2f5c8712852d13eda7fa047 EAP-Message = 0x020400061900 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0xc6268f888323c9f0e7a30ccefba3b3cb NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 4 length 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 2 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 2 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 2 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Received EAP-TLS ACK message Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: ack handshake fragment handler Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 1 Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 13 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_HANDLED Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 2 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 2 Sending Access-Challenge of id 121 to 192.168.0.10 port 1645 EAP-Message = 0x010502f71900170d3036303132343133323630375a30819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d4c5b19724f164acf1ffb189db1c8fbff4f14396ea7cb1e90f78d69451725377895dfe52ccb99b41e8 EAP-Message = 0x0ddeb58b127a943f4f58cbc562878192fbdc6fece9f871e7c130d35cf5188817e9b133249edd2a1c75d31043ae87553cec7a77ef26aa7d74281db9b77e17c6446c5dd9b188b43250ca0229963722a123a726b00b4027fd0203010001a381ff3081fc301d0603551d0e0416041468d36d3e1ee7bc9d5a057021c363da1365d1ade33081cc0603551d230481c43081c1801468d36d3e1ee7bc9d5a057021c363da1365d1ade3a181a5a481a230819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010 EAP-Message = 0x060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d820100300c0603551d13040530030101ff300d06092a864886f70d01010405000381810033c00b66b1e579ef73a06798252dab8d5e5511fc00fd276d80d12f834777c6743fdc2743fca1507704e4bc0979e4f60ac3ad9ee83e6f347369229d1f77229ba2e982359da563024a00163dba6d6c986c0bad28af85132ff8f0d76501bf1b7c2dff658ce1e62c01997b6e64e3e8d4373354ce9912847651539063b85bbc5485c516030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc169e337667edbcff6bf7f69ebbcfc49 Fri Jan 16 16:14:05 2009 : Debug: Finished request 2 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 3 waiting to be assigned a request Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... rad_recv: Access-Request packet from host 192.168.0.10:1645, id=122, length=343 Fri Jan 16 16:14:05 2009 : Debug: Thread 4 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 4 handling request 3, (1 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xb27f2fdc11072b8abd17ce396a96e291 EAP-Message = 0x020500d01980000000c6160301008610000082008004b963a40ee622d775f82f58e163cf262adad6bb6314eec472b6518be0f7a92daeeb9a59ef9470e6356765386cdb2dcdd423fa999d2564da9cb1fb9a51481d5c5b9b4f7cb28deb9301d451e5cd1c14f3f4decae2a60d851a75886993e9b84d4427b2b5a66e8d1cc83367e3bbe59123e798d864270f906dbb719f9f5ac019d51914030100010116030100309197bc5305f81c06f049831e54401892dea21c5aceeee70d50acf4adb201dca11da48f3da63a29d78fd500233eb850e7 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0xc169e337667edbcff6bf7f69ebbcfc49 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 5 length 208 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 3 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 3 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 3 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Length Included Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 11 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 read client key exchange A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001] Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 read finished A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001] Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 write change cipher spec A Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 write finished A Fri Jan 16 16:14:05 2009 : Debug: TLS_accept: SSLv3 flush data Fri Jan 16 16:14:05 2009 : Debug: (other): SSL negotiation finished successfully Fri Jan 16 16:14:05 2009 : Debug: SSL Connection Established Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 13 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_HANDLED Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 3 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 3 Sending Access-Challenge of id 122 to 192.168.0.10 port 1645 EAP-Message = 0x0106004119001403010001011603010030b39bf1c4a8799afd05f7cfb3a7886c2eb34c516f757a6f227bc8e9d0df34f2cbb1511cd2300d52108cdf79a3e3b0566f Message-Authenticator = 0x00000000000000000000000000000000 State = 0x448bc94717ef139356c77b3c4afde30a Fri Jan 16 16:14:05 2009 : Debug: Finished request 3 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 4 waiting to be assigned a request Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... rad_recv: Access-Request packet from host 192.168.0.10:1645, id=123, length=141 Fri Jan 16 16:14:05 2009 : Debug: Thread 5 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 5 handling request 4, (1 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xfa9425d520d21ba586c035292bd68e07 EAP-Message = 0x020600061900 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0x448bc94717ef139356c77b3c4afde30a NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 6 length 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 4 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 4 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 4 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Received EAP-TLS ACK message Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: ack handshake is finished Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 3 Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 3 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_SUCCESS Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 4 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 4 Sending Access-Challenge of id 123 to 192.168.0.10 port 1645 EAP-Message = 0x0107002b19001703010020358fa3be8c1b42a5648abf6663bbf31708f83b854ed45a2ee50b0070d2f5e4a6 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xbb9e5d984b6b1768046884bd3ccda3a9 Fri Jan 16 16:14:05 2009 : Debug: Finished request 4 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 5 waiting to be assigned a request Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... rad_recv: Access-Request packet from host 192.168.0.10:1645, id=124, length=178 Fri Jan 16 16:14:05 2009 : Debug: Thread 1 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 1 handling request 5, (2 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xdef3c12413c28597f3a7550b010e1faf EAP-Message = 0x0207002b19001703010020a8b1dda2c820274e487b7412c9ed15102f021fe8587d83588350f718066c156a NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0xbb9e5d984b6b1768046884bd3ccda3a9 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 7 length 43 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 5 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Done initial handshake Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_OK Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 01 54 45 53 54 5c 69 6e 67 6f Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Identity - TEST\ingo Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Tunneled data is valid. PEAP: Got tunneled EAP-Message EAP-Message = 0x0207000e01544553545c696e676f Fri Jan 16 16:14:05 2009 : Debug: PEAP: Got tunneled identity of TEST\ingo Fri Jan 16 16:14:05 2009 : Debug: PEAP: Setting default EAP type for tunneled EAP session. Fri Jan 16 16:14:05 2009 : Debug: PEAP: Setting User-Name to TEST\ingo PEAP: Sending tunneled request EAP-Message = 0x0207000e01544553545c696e676f FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "TEST\\ingo" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 7 length 14 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 5 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 5 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP Identity Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type mschapv2 Fri Jan 16 16:14:05 2009 : Info: rlm_eap_mschapv2: Issuing Challenge Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 5 PEAP: Got tunneled reply RADIUS code 11 EAP-Message = 0x010800231a0108001e109c2283a50e81eba9801ab35bfb7331d3544553545c696e676f Message-Authenticator = 0x00000000000000000000000000000000 State = 0x6ecfdf001baac997c755a948580aac74 PEAP: Processing from tunneled session code 0xb8054c88 11 EAP-Message = 0x010800231a0108001e109c2283a50e81eba9801ab35bfb7331d3544553545c696e676f Message-Authenticator = 0x00000000000000000000000000000000 State = 0x6ecfdf001baac997c755a948580aac74 Fri Jan 16 16:14:05 2009 : Debug: PEAP: Got tunneled Access-Challenge PEAP tunnel data out 0000: 1a 01 08 00 1e 10 9c 22 83 a5 0e 81 eb a9 80 1a PEAP tunnel data out 0010: b3 5b fb 73 31 d3 54 45 53 54 5c 69 6e 67 6f Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 5 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 5 Sending Access-Challenge of id 124 to 192.168.0.10 port 1645 EAP-Message = 0x0108004b1900170301004066eb0a0f0b73febf4d7c2e9cc39ecb6eff47350707ddc6d69acf0644f6fdc6e115e82635e3be487f34063c41df74f2cbbbea8f72c9e3b6f556094b533d4fd4af Message-Authenticator = 0x00000000000000000000000000000000 State = 0x02687132de20b37319a88307f0faeae1 Fri Jan 16 16:14:05 2009 : Debug: Finished request 5 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 1 waiting to be assigned a request Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... rad_recv: Access-Request packet from host 192.168.0.10:1645, id=125, length=242 Fri Jan 16 16:14:05 2009 : Debug: Thread 2 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 2 handling request 6, (2 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xb919f5edbb443c7c81d91d535a38c317 EAP-Message = 0x0208006b19001703010060d4fe15e2312afd8786e3a4db969bdf310aab5c52fc05ebc2b025bf25b053f18e565875f714a8962237b024779e724f8f6de423d67da9164de8951463da4c1155ae7823038b61a239686246b4a8ccaab645e9b645bb6bfbe3bb6353467ba53f77 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0x02687132de20b37319a88307f0faeae1 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 8 length 107 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 6 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Done initial handshake Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_OK Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 1a 02 08 00 3f 31 93 4c e3 9a ee 6c 35 ae fb 16 PEAP tunnel data in 0010: 5a 02 66 56 2c 02 00 00 00 00 00 00 00 00 02 5a PEAP tunnel data in 0020: f5 ee 1b 77 42 61 3e 7c 12 f0 df d0 1c eb 71 81 PEAP tunnel data in 0030: 7a df 60 5d b5 85 00 54 45 53 54 5c 69 6e 67 6f Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAP type mschapv2 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Tunneled data is valid. PEAP: Got tunneled EAP-Message EAP-Message = 0x020800441a0208003f31934ce39aee6c35aefb165a0266562c020000000000000000025af5ee1b7742613e7c12f0dfd01ceb71817adf605db58500544553545c696e676f Fri Jan 16 16:14:05 2009 : Debug: PEAP: Setting User-Name to TEST\ingo Fri Jan 16 16:14:05 2009 : Debug: PEAP: Adding old state with 6e cf PEAP: Sending tunneled request EAP-Message = 0x020800441a0208003f31934ce39aee6c35aefb165a0266562c020000000000000000025af5ee1b7742613e7c12f0dfd01ceb71817adf605db58500544553545c696e676f FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "TEST\\ingo" State = 0x6ecfdf001baac997c755a948580aac74 Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 8 length 68 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 6 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/mschapv2 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type mschapv2 Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group MS-CHAP for request 6 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: No User-Password configured. Cannot create LM-Password. Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: No User-Password configured. Cannot create NT-Password. Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: Told to do MS-CHAPv2 for ingo with NT-Password Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--username=TEST\\ingo' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat function of module mschap for string 'Challenge' Fri Jan 16 16:14:05 2009 : Debug: mschap2: 9c Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--challenge=25226c1fad0393e9' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat function of module mschap for string 'NT-Response' Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: '--nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585' Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads = 5/1/4 Fri Jan 16 16:14:05 2009 : Debug: Exec-Program output: Logon failure (0xc000006d) Fri Jan 16 16:14:05 2009 : Debug: Exec-Program-Wait: plaintext: Logon failure (0xc000006d) Fri Jan 16 16:14:05 2009 : Debug: Exec-Program: returned: 1 Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: External script failed. Fri Jan 16 16:14:05 2009 : Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "mschap" returns reject for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group MS-CHAP (returns reject) for request 6 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Freeing handler Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns reject for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns reject) for request 6 Fri Jan 16 16:14:05 2009 : Debug: auth: Failed to validate the user. Fri Jan 16 16:14:05 2009 : Auth: Login incorrect (rlm_mschap: Logon failure (0xc000006d)): [TEST\\ingo/<no User-Password attribute>] (from client localhost port 0) PEAP: Got tunneled reply RADIUS code 3 MS-CHAP-Error = "\010E=691 R=1" EAP-Message = 0x04080004 Message-Authenticator = 0x00000000000000000000000000000000 PEAP: Processing from tunneled session code 0xb802fb38 3 MS-CHAP-Error = "\010E=691 R=1" EAP-Message = 0x04080004 Message-Authenticator = 0x00000000000000000000000000000000 Fri Jan 16 16:14:05 2009 : Debug: PEAP: Tunneled authentication was rejected. Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: FAILURE Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns handled for request 6 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns handled) for request 6 Sending Access-Challenge of id 125 to 192.168.0.10 port 1645 EAP-Message = 0x0109002b190017030100208aa1588bd73ef98e213f02c61510d6b5f9c87bd67d5e78c82f44b534469acf8a Message-Authenticator = 0x00000000000000000000000000000000 State = 0x6d48ffddf81c42eee19afc937d511616 Fri Jan 16 16:14:05 2009 : Debug: Finished request 6 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 2 waiting to be assigned a request rad_recv: Access-Request packet from host 192.168.0.10:1645, id=126, length=178 Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds... Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads = 5/0/5 Fri Jan 16 16:14:05 2009 : Debug: Thread 3 got semaphore Fri Jan 16 16:14:05 2009 : Debug: Thread 3 handling request 7, (2 handled so far) User-Name = "TEST\\ingo" Framed-MTU = 1400 Called-Station-Id = "0014.1bb5.abe0" Calling-Station-Id = "001f.3ba6.c02f" Service-Type = Login-User Message-Authenticator = 0xd451d8a691c8df289e6318ddca2ca21f EAP-Message = 0x0209002b190017030100207a8219bad919c0e15ca4c4226cc59c5925aff5c81c8bfb5e0f5e066956224158 NAS-Port-Type = Wireless-802.11 NAS-Port = 447 State = 0x6d48ffddf81c42eee19afc937d511616 NAS-IP-Address = 192.168.0.10 NAS-Identifier = "ap" Fri Jan 16 16:14:05 2009 : Debug: Processing the authorize section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "preprocess" returns ok for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "chap" returns noop for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "mschap" returns noop for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP packet type response id 9 length 43 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "eap" returns updated for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling files (rlm_files) for request 7 Fri Jan 16 16:14:05 2009 : Debug: users: Matched entry DEFAULT at line 153 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "files" returns ok for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Fri Jan 16 16:14:05 2009 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authorize]: module "pap" returns noop for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize (returns updated) for request 7 Fri Jan 16 16:14:05 2009 : Debug: rad_check_password: Found Auth-Type EAP Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP" Fri Jan 16 16:14:05 2009 : Debug: Processing the authenticate section of radiusd.conf Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate for request 7 Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Request found, released from the list Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: processing type peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Authenticate Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: processing TLS Fri Jan 16 16:14:05 2009 : Debug: eaptls_verify returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Done initial handshake Fri Jan 16 16:14:05 2009 : Debug: eaptls_process returned 7 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: EAPTLS_OK Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Session established. Decoding tunneled attributes. PEAP tunnel data in 0000: 02 09 00 0b 21 80 03 00 02 00 02 Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Received EAP-TLV response. Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Tunneled data is valid. Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_peap: Had sent TLV failure. User was rejcted rejected earlier in this session. Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Handler failed in EAP/peap Fri Jan 16 16:14:05 2009 : Debug: rlm_eap: Failed in EAP select Fri Jan 16 16:14:05 2009 : Debug: modsingle[authenticate]: returned from eap (rlm_eap) for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall[authenticate]: module "eap" returns invalid for request 7 Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate (returns invalid) for request 7 Fri Jan 16 16:14:05 2009 : Debug: auth: Failed to validate the user. Fri Jan 16 16:14:05 2009 : Auth: Login incorrect: [TEST\\ingo/<no User-Password attribute>] (from client 192.168.0.10 port 447 cli 001f.3ba6.c02f) Fri Jan 16 16:14:05 2009 : Debug: Delaying request 7 for 1 seconds Fri Jan 16 16:14:05 2009 : Debug: Finished request 7 Fri Jan 16 16:14:05 2009 : Debug: Going to the next request Fri Jan 16 16:14:05 2009 : Debug: Thread 3 waiting to be assigned a request rad_recv: Access-Request packet from host 192.168.0.10:1645, id=126, length=178 Sending Access-Reject of id 126 to 192.168.0.10 port 1645 EAP-Message = 0x04090004 Message-Authenticator = 0x00000000000000000000000000000000 Fri Jan 16 16:14:10 2009 : Debug: --- Walking the entire request list --- Fri Jan 16 16:14:10 2009 : Debug: Waking up in 1 seconds... Fri Jan 16 16:14:11 2009 : Debug: --- Walking the entire request list --- Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 0 ID 119 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 1 ID 120 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 2 ID 121 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 3 ID 122 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 4 ID 123 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 5 ID 124 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 6 ID 125 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 7 ID 126 with timestamp 4970a43d Fri Jan 16 16:14:11 2009 : Debug: Nothing to do. Sleeping until we see a request.

2 3

unsubscribe
by Paul TAVERNIER 19 Jan '09

19 Jan '09

unsubscribe -- ============================ Paul TAVERNIER Equipe Reseaux-Securite Division Informatique Rectorat de ROUEN Tel: 02.32.08.94.18 Fax: 02.32.08.94.12 Mob: 06.25.45.84.10 "Dans votre ascension professionnelle, soyez toujours très gentil pour ceux que vous dépassez en montant. Vous les retrouverez au même endroit en redescendant." (W. Allen) ============================

1 0

Handing out duplicate IP addresses
by Dave 19 Jan '09

19 Jan '09

I thought I had this problem licked, but I still suffer from it. Anyone know why FR 2.1.3 with sqlippool (mysql) might decide to hand out the same IP more than once while its processing more than one request at a time? Wed Jan 14 22:05:59 2009 : Info: Allocated IP: 75.119.xxx,211 from IP-Pool (did jarvis cli 00:18:D2:00:3E:63 port 449756 user pcollyer) Wed Jan 14 22:05:59 2009 : Info: Allocated IP: 75.119.xxx.211 from IP-Pool (did jarvis cli 00:18:D2:00:5B:0D port 449755 user jhogeterp) Wed Jan 14 22:05:59 2009 : Info: Allocated IP: 75.119.xxx.211 from IP-Pool (did jarvis cli 00:18:D2:00:2E:C1 port 449752 user mellerpoultry) The requests all came in at the same time, to the second (among others), its like FR took 3 requests and looked at the database at the exact same time, saw it was an available IP and all those 3 requests assigned it. My NAS rejects two of the 3 because the IP is assigned, and Freeradius clears the IP from the ip-pool to be later distributed (even though its still in use) Im open to any suggestions. Its hard to debug!

5 14