July 2015 - Freeradius-Users - lists.freeradius.org

Re: "[eap] = reject" after "Calling eap_md5 to process EAP data"
by Kris Armstrong 09 Jul '15

09 Jul '15

here is what I am seeing since uncommenting the "nostrip" (168) # Executing section authorize from file /etc/raddb/sites-enabled/default (168) authorize { (168) filter_username filter_username { (168) if (!&User-Name) (168) if (!&User-Name) -> FALSE (168) if (&User-Name =~ / /) (168) if (&User-Name =~ / /) -> FALSE (168) if (&User-Name =~ /@.*@/ ) (168) if (&User-Name =~ /@.*@/ ) -> FALSE (168) if (&User-Name =~ /\\.\\./ ) (168) if (&User-Name =~ /\\.\\./ ) -> FALSE (168) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (168) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (168) if (&User-Name =~ /\\.$/) (168) if (&User-Name =~ /\\.$/) -> FALSE (168) if (&User-Name =~ /(a)\\./) (168) if (&User-Name =~ /(a)\\./) -> FALSE (168) } # filter_username filter_username = notfound (168) WARNING: preprocess : There are more than 10 Proxy-State attributes in the request (168) WARNING: preprocess : You have likely configured an infinite proxy loop (168) [preprocess] = ok (168) [chap] = noop (168) [mschap] = noop (168) [digest] = noop (168) suffix : Checking for suffix after "@" (168) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (168) suffix : Found realm "example.com" (168) suffix : Adding Realm = "example.com" (168) suffix : Proxying request from user user(a)example.com to realm example.com (168) suffix : Preparing to proxy authentication request to realm "example.com" (168) [suffix] = updated (168) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (168) [eap] = noop (168) [files] = noop (168) sql : EXPAND %{User-Name} (168) sql : --> user(a)example.com (168) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (4) (168) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (168) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (168) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (168) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (168) sql : User not found in any groups rlm_sql (sql): Released connection (4) (168) [sql] = notfound (168) [expiration] = noop (168) [logintime] = noop (168) [pap] = noop (168) } # authorize = updated (168) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (168) Sending Access-Request packet to host 127.0.0.1 port 1812, id=152, length=0 (168) User-Name = 'user(a)example.com' (168) NAS-IP-Address = 10.250.8.180 (168) Called-Station-Id = 'c8d71992a9d7' (168) Calling-Station-Id = '00c01732012e' (168) NAS-Identifier = 'c8d71992a9d7' (168) NAS-Port = 29 (168) Framed-MTU = 1400 (168) NAS-Port-Type = Wireless-802.11 (168) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (168) Message-Authenticator = 0xbeb9ebda3594a94e4cef4cb918c81000 (168) Event-Timestamp = 'Jul 8 2015 14:48:00 MDT' (168) Proxy-State = 0x30 On Jul 08, 2015, at 02:40 AM, A.L.M.Buxey(a)lboro.ac.uk wrote: Hi, I tried uncommenting the line nostrip from the proxy.con. that didn’t work. ....and...... (what does the debug NOW look like? ) if you dont help us, by providing that output, we cannot help you. alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

4 4

openssl gendh during make install
by Michael Ströder 08 Jul '15

08 Jul '15

HI! I have to admit that I find the openssl gendh during make install not ideal. The reason is that most .spec files use make install to create files in a build root during package build. And therefore at least it wastes a lot of CPU cycles during the build process for generating a file which the admin should re-generate *after* installing the package anyway. Any possible solution for this? E.g. I'd prefer start scripts to invoke openssl gendh if the file does not exist yet. Ciao, Michael.

3 2

SQL error - Incorrect datetime value
by Renato Sousa 08 Jul '15

08 Jul '15

Hello everyone, I'm setting up a freeradius server 3.0.8 on FreeBSD 10. I am getting an error in sql: (29) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('00001A59-00000028', '8698639b48376aea32f23dc9a7989089', 'myuser', 'DEFAULT', '172.19.13.15', '0', 'Wireless-802.11', 1436344658, 1436344658, NULL, '0', 'RADIUS', 'CONNECT 0Mbps 802.11b', '', '0', '0', '2A-A4-3C-B2-FB-AD:mySSID', '34-BB-26-C2-1D-60', '', '', '', '') (29) sql: ERROR: rlm_sql_mysql: ERROR 1292 (Incorrect datetime value: '1436344658' for column 'acctstarttime' at row 1): 22007 I created the database using the mysql (version 5.6.24) schema.sql file provided on freeradius. The problem is in mysql or freeradius? Regards, Renato

3 7

how to account different table sql by time decision
by johan firdianto 08 Jul '15

08 Jul '15

hi guys i want to store accounting packet to different table sql with if time condition. like if (time > 1 am) and (time < 9 am) { store to acct2} else { store to acct1} i think the solution is using unlang language and put in radius conf. im not familiar with unlang language. i would appreciate if anybody here could help me. johan

3 3

Checking values of attributes
by Pshem Kowalczyk 08 Jul '15

08 Jul '15

Hi, I've recently upgraded our servers from 3.0.4 to 3.0.8. We have two radius servers that replicate received accounting packets to each other (so the local DBs remain in sync). In order to prevent loops before the packet is sent a local attribute is added (defined in the dictionary) to indicate that it should only be processed locally (and not replicated again). In 3.0.4 we used the following syntax: preacct { ... if ( request:SV-Handled != True ){ update { request:SV-Handled := True } replicate } ... } with the attribute defined like this: ATTRIBUTE SV-Handled 2 integer VALUE SV-Handled False 0 VALUE SV-Handled True 1 and that condition worked well - only packets from the NAS (that didn't have the attribute at all) were matched. Now, with 3.0.8 the behaviour has changed: if the packet has the attribute: (0) Received Accounting-Request Id 147 from 10.100.34.17:34759 to 10.100.34.18:1813 length 1213 ... (0) SV-Handled = True (0) # Executing section preacct from file /etc/raddb/sites-enabled/frontend (0) preacct { (0) frontend_files: acct_users: Matched entry DEFAULT at line 1 (0) [frontend_files] = ok (0) if ( request:SV-Handled != True ){ (0) if ( request:SV-Handled != True ) -> FALSE and if the packed doesn't have it: (4) # Executing section preacct from file /etc/raddb/sites-enabled/frontend (4) preacct { (4) frontend_files: acct_users: Matched entry DEFAULT at line 1 (4) [frontend_files] = ok (4) if ( request:SV-Handled != True ){ (4) ERROR: Failed retrieving values required to evaluate condition So, I've changed the condition to read: if ( %{%{request:SV-Handled}:-False} != True ){ But that doesn't seem to work as expected: When the attribute is there (and set to True) it evaluates: (0) Received Accounting-Request Id 239 from 10.100.34.17:52319 to 10.100.34.18:1813 length 1120 ... (0) SV-Handled = True (0) # Executing section preacct from file /etc/raddb/sites-enabled/frontend (0) preacct { (0) frontend_files: acct_users: Matched entry DEFAULT at line 2 (0) [frontend_files] = ok (0) if ( %{%{request:SV-Handled}:-False} != True ){ (0) if ( %{%{request:SV-Handled}:-False} != True ) -> TRUE So, not so good. I've tried a different setup as well: if ( %{%{integer:request:SV-Handled}:-0} != 1 ){ but that suffers from the same problem: (6) SV-Handled = True (6) # Executing section preacct from file /etc/raddb/sites-enabled/frontend (6) preacct { (6) frontend_files: acct_users: Matched entry DEFAULT at line 1 (6) [frontend_files] = ok (6) if ( %{%{integer:request:SV-Handled}:-0} != 1 ){ (6) if ( %{%{integer:request:SV-Handled}:-0} != 1 ) -> TRUE What's the correct syntax here? kind regards Pshem

2 5

"[eap] = reject" after "Calling eap_md5 to process EAP data"
by Zeus Panchenko 08 Jul '15

08 Jul '15

hi, I am trying to configure MAC auth by implementing EAP/MD5 as it is described here: http://wiki.freeradius.org/modules/Rlm_eap#My-Userbase-is-in-LDAP-and-I-wan… FR v.3.0.8 is on FreeBSD 10.1R supplicant is on FreeBSD 10.1R connected (by wire) to FR wia switch but something is wrong and I can not understand what ... please help me to see what I do not see ... as backend I have LDAP and in it, userPassword format is Cleartext-Password (for the sample from the debug bellow it is `00-25-90-D9-76-2C' as I understand from the debug bellow, I successfully pass authorization but fail to authenticate against eap_md5 ... why? ---[ quotation start ]------------------------------------------- Mon Jul 6 20:27:36 2015 : Debug: (0) Received Access-Request Id 200 from 192.168.0.1:49205 to 192.168.0.254:1812 length 137 Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-IP-Address = 192.168.0.1 Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-Port-Type = Ethernet Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-Port = 14 Mon Jul 6 20:27:36 2015 : Debug: (0) User-Name = '002590d9762c' Mon Jul 6 20:27:36 2015 : Debug: (0) Acct-Session-Id = '050002C0' Mon Jul 6 20:27:36 2015 : Debug: (0) Called-Station-Id = '5C-A4-8A-6F-33-C6' Mon Jul 6 20:27:36 2015 : Debug: (0) Calling-Station-Id = '00-25-90-D9-76-2C' Mon Jul 6 20:27:36 2015 : Debug: (0) EAP-Message = 0x0200001101303032353930643937363263 Mon Jul 6 20:27:36 2015 : Debug: (0) Message-Authenticator = 0xa54f71eb9a3b95ad330025032c88cedb Mon Jul 6 20:27:36 2015 : Debug: (0) session-state: No State attribute Mon Jul 6 20:27:36 2015 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Jul 6 20:27:36 2015 : Debug: (0) authorize { Mon Jul 6 20:27:36 2015 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Jul 6 20:27:36 2015 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Jul 6 20:27:36 2015 : Debug: (0) [preprocess] = ok Mon Jul 6 20:27:36 2015 : Debug: (0) policy rewrite_called_station_id { ... Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: User object found at DN "uid=00-25-90-D9-76-2C,authorizedService=802.1x-mac@xyz,uid=jdoe,ou=People,dc=xyz" Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Processing user attributes Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: control:Cleartext-Password += '00-25-90-D9-76-2C' Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: control:Password-With-Header += '00-25-90-D9-76-2C' Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Service-Type := Framed-User Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Type := VLAN Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Medium-Type := IEEE-802 Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Private-Group-Id := 'VLAN3499' Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Attribute "radiusCheckAttributes" not found in LDAP object Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Attribute "radiusReplyAttributes" not found in LDAP object Mon Jul 6 20:27:36 2015 : Debug: rlm_ldap (ldap): Released connection (4) Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from ldap (rlm_ldap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [ldap] = updated Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Peer sent code Response (2) ID 1 length 34 Mon Jul 6 20:27:36 2015 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = updated Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling files (rlm_files) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) files: Searching for user in group "disabled" ... Mon Jul 6 20:27:36 2015 : Debug: (1) files: User is not a member of "disabled" Mon Jul 6 20:27:36 2015 : Debug: (1) files: Searching for user in group "auth-mac" ... Mon Jul 6 20:27:36 2015 : Debug: (1) files: EXPAND (&(radiusGroupName=auth-mac)(|(&(cn=%{%{Stripped-User-Name}:-%{Calling-Station-Id}})(|(authorizedService=802.1x@xyz)(authorizedService=802.1x-mac@xyz)))(&(cn=%{User-Name})(authorizedService=802.1x-eap-tls@xyz)))(|(cn=%{Stripped-User-Name})(cn=%{User-Name})(cn=%{Calling-Station-Id})))-76-2C)(|(authorizedService=802.1x@xyz)(authorizedService=802.1x-mac@xyz)))(&(cn=002590d9762c)(authorizedService=802.1x-eap-tls@xyz)))(|(cn=)(cn=002590d9762c)(cn=00-25-90-D9-76-2C))) EXPAND TMPL LITERAL Mon Jul 6 20:27:36 2015 : Debug: (1) files: Performing search in "ou=People,dc=xyz" with filter "(&(radiusGroupName=auth-mac)(|(&(cn=00-25-90-D9-76-2C)(|(authorizedService=802.1x@xyz)(authorizedService=802.1x-mac@xyz)))(&(cn=002590d9762c)(authorizedService=802.1x-eap-tls@xyz)))(|(cn=)(cn=002590d9762c)(cn=00-25-90-D9-76-2C)))", scope "sub" Mon Jul 6 20:27:36 2015 : Debug: (1) files: User found in group object "ou=People,dc=xyz" Mon Jul 6 20:27:36 2015 : Debug: rlm_ldap (ldap): Released connection (4) Mon Jul 6 20:27:36 2015 : Debug: (1) files: users: Matched entry DEFAULT at line 238 Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: FROM 2 TO 4 MAX 6 Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: Examining Reply-Message Mon Jul 6 20:27:36 2015 : Debug: %{User-Name}, you are comming as MAC Auth object. Mon Jul 6 20:27:36 2015 : Debug: Parsed xlat tree: Mon Jul 6 20:27:36 2015 : Debug: attribute --> User-Name Mon Jul 6 20:27:36 2015 : Debug: literal --> , you are comming as MAC Auth object. Mon Jul 6 20:27:36 2015 : Debug: (1) files: EXPAND %{User-Name}, you are comming as MAC Auth object. Mon Jul 6 20:27:36 2015 : Debug: (1) files: --> 002590d9762c, you are comming as MAC Auth object. Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: APPENDING Reply-Message FROM 0 TO 4 Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: Examining Fall-Through Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: APPENDING Fall-Through FROM 1 TO 5 Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: TO in 4 out 6 Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[0] = Service-Type Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[1] = Tunnel-Type Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[2] = Tunnel-Medium-Type Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[3] = Tunnel-Private-Group-Id Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[4] = Reply-Message Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[5] = Fall-Through Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from files (rlm_files) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [files] = ok Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [expiration] = noop Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [logintime] = noop Mon Jul 6 20:27:36 2015 : Debug: (1) if (notfound){ Mon Jul 6 20:27:36 2015 : Debug: (1) if (notfound) -> FALSE Mon Jul 6 20:27:36 2015 : Debug: (1) if (reject){ Mon Jul 6 20:27:36 2015 : Debug: (1) if (reject) -> FALSE Mon Jul 6 20:27:36 2015 : Debug: (1) } # authorize = updated Mon Jul 6 20:27:36 2015 : Debug: (1) Found Auth-Type = EAP Mon Jul 6 20:27:36 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Jul 6 20:27:36 2015 : Debug: (1) authenticate { Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Expiring EAP session with state 0xeb89e5b7eb88e1eb Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Finished EAP session with state 0xeb89e5b7eb88e1eb Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Previous EAP request found for state 0xeb89e5b7eb88e1eb, released from the list Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Peer sent method MD5 (4) Mon Jul 6 20:27:36 2015 : Debug: (1) eap: EAP MD5 (4) Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Calling eap_md5 to process EAP data Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Freeing handler Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = reject Mon Jul 6 20:27:36 2015 : Debug: (1) } # authenticate = reject Mon Jul 6 20:27:36 2015 : Debug: (1) Failed to authenticate the user Mon Jul 6 20:27:36 2015 : Debug: (1) Using Post-Auth-Type Reject ... Mon Jul 6 20:27:36 2015 : Debug: (1) Post-Auth-Type REJECT { Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 1 Mon Jul 6 20:27:36 2015 : Debug: %{User-Name} Mon Jul 6 20:27:36 2015 : Debug: Parsed xlat tree: Mon Jul 6 20:27:36 2015 : Debug: attribute --> User-Name Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: EXPAND %{User-Name} Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: --> 002590d9762c Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Matched entry DEFAULT at line 17 Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Service-Type" allowed by 0 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Type" allowed by 0 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Medium-Type" allowed by 0 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Private-Group-Id" allowed by 0 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Reply-Message = '002590d9762c, you are comming as MAC Auth object.' allowed by Reply-Message =* '' Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Reply-Message" allowed by 1 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: EAP-Message = 0x04010004 allowed by EAP-Message =* 0x Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [attr_filter.access_reject] = updated Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: calling eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: returned from eap (rlm_eap) for request 1 Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = noop Mon Jul 6 20:27:36 2015 : Debug: (1) policy remove_reply_message_if_eap { Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Jul 6 20:27:36 2015 : Debug: (1) update reply { Mon Jul 6 20:27:36 2015 : Debug: (1) &Reply-Message !* ANY Mon Jul 6 20:27:36 2015 : Debug: (1) } # update reply = noop Mon Jul 6 20:27:36 2015 : Debug: (1) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop Mon Jul 6 20:27:36 2015 : Debug: (1) ... skipping else for request 1: Preceding "if" was taken Mon Jul 6 20:27:36 2015 : Debug: (1) } # policy remove_reply_message_if_eap = noop Mon Jul 6 20:27:36 2015 : Debug: (1) } # Post-Auth-Type REJECT = updated Mon Jul 6 20:27:36 2015 : Debug: (1) Delaying response for 1.000000 seconds Mon Jul 6 20:27:36 2015 : Debug: Waking up in 0.3 seconds. Mon Jul 6 20:27:36 2015 : Debug: Waking up in 0.6 seconds. ---[ quotation end ]------------------------------------------- -- Zeus V. Panchenko jid:zeus@im.ibs.dn.ua IT Dpt., I.B.S. LLC GMT+2 (EET)

4 14

Re: LDAP search failed
by Hatim CHIKHI 08 Jul '15

08 Jul '15

Hi again, I found the solution for the ldap slow search here: http://lists.freeradius.org/pipermail/freeradius-users/2013-January/064566.… There is just an option in the ldap configuration of freeradius that must be modified: ldap { ... chase_referrals = no } Thanks a lot for your help. Regards! 2015-07-07 15:10 GMT+02:00 Hatim CHIKHI <hatim.networking(a)gmail.com>: > Hi again, > > I found the solution for the slow search here: > > http://lists.freeradius.org/pipermail/freeradius-users/2013-January/064566.… > > There is just an option in the ldap configuration of freeradius that must > be modified: > > ldap { > ... > chase_referrals = no > } > > > Thanks a lot for your help. > > > Regards! > > > 2015-07-06 17:26 GMT+02:00 Danner, Mearl [via FreeRADIUS] < > ml-node+s1045715n5735140h71(a)n5.nabble.com>: > >> >> >> > -----Original Message----- >> > From: Freeradius-Users [mailto:freeradius-users- >> > bounces+jmdanner=[hidden email] >> <http:///user/SendEmail.jtp?type=node&node=5735140&i=0>] On Behalf Of >> Hatim >> > CHIKHI >> > Sent: Monday, July 06, 2015 10:10 AM >> > To: FreeRadius users mailing list >> > Subject: Re: LDAP search failed >> > >> > > myserver:389 >> > > [ldap] waiting for bind result ... >> > > [ldap] Bind was successful >> > > [ldap] performing search in dc=3Dad,dc=3D****,dc=3Dfr, with filter >> > > sAMAccountName=3Dhatim >> > > [ldap] rebind to URL ldap://***** >> > > [ldap] rebind to URL ldap://***** >> > > [ldap] rebind to URL ldap://***** >> > > [ldap] no uid attribute - access denied by default >> > >> > >Active Directory has no uid by default. The schema needs to be >> extended to >> > provide it. And most provisioning software does not populate it even if >> it >> > exists. >> > >> > So this was the problem, I changed the value uid and set >> > "sAMAccountName" >> > and now it works. >> > Thank you guys for you help. >> > >> > >> > I have an other question, the ldap search is taking too much time, more >> > than 10 seconds. >> > I don't know if there is a way to speed up the search?? >> >> Probably a back end problem, not Freeradius. >> >> Do you get the same lag using a command line ldap search? >> >> Could be chasing referrals. Try the GC port 3268 (3269 for ssl). Not all >> attributes are available in the Global Catalog unless specified in the >> schema. They can be exposed by one of your AD admins if needed. >> >> Also make sure all the attributes in your search strings are indexed. If >> they aren't search returns can be slow in a large directory. >> >> > >> > >> > Thanks! >> > >> > 2015-07-06 16:10 GMT+02:00 Hatim CHIKHI <[hidden email] >> <http:///user/SendEmail.jtp?type=node&node=5735140&i=1>>: >> > >> > > > myserver:389 >> > > > [ldap] waiting for bind result ... >> > > > [ldap] Bind was successful >> > > > [ldap] performing search in dc=3Dad,dc=3D****,dc=3Dfr, with >> filter >> > > > sAMAccountName=3Dhatim >> > > > [ldap] rebind to URL ldap://***** >> > > > [ldap] rebind to URL ldap://***** >> > > > [ldap] rebind to URL ldap://***** >> > > > [ldap] no uid attribute - access denied by default >> > > >> > > >Active Directory has no uid by default. The schema needs to be >> extended >> > > to provide it. And most provisioning software does not populate it >> even if >> > > it exists. >> > > >> > > So this was the problem, I changed the value uid and set >> > "sAMAccountName" >> > > and now it works. >> > > Thank you guys for you help. >> > > >> > > >> > > I have an other question, the ldap search is taking too much time, >> more >> > > than 10 seconds. >> > > I don't know if there is a way to speed up the search?? >> > > >> > > >> > > Thanks! >> > > >> > > 2015-07-03 18:05 GMT+02:00 Hatim CHIKHI >> > <[hidden email] <http:///user/SendEmail.jtp?type=node&node=5735140&i=2>>: >> >> > > >> > >> >> > >> >When FreeRADIUS does the search for the user, it gets nothing. >> > >> > >> > >> > Perhaps because the search string is broken? >> > >> >> > >> But I get a result when I issue the search with ldapsearch >> > >> >> > >> >> > >> >That doesn't look right. Where does that string come from? >> > >> The 3D is added by gmail so it's not a problem >> > >> >> > >> >> > >> >> > >> 2015-07-03 15:25 GMT+02:00 Alan DeKok-2 [via FreeRADIUS] < >> > >> [hidden email] >> <http:///user/SendEmail.jtp?type=node&node=5735140&i=3>>: >> > >> >> > >>> On Jul 3, 2015, at 7:01 AM, Hatim CHIKHI <[hidden email] >> > >>> <http:///user/SendEmail.jtp?type=node&node=5735114&i=0>> wrote: >> > >>> > When I issue an ldap search I get many information about the user >> I'm >> > >>> > looking for but I'm not sure if the search is successful: >> > >>> >> > >>> When FreeRADIUS does the search for the user, it gets nothing. >> > >>> >> > >>> Perhaps because the search string is broken? >> > >>> >> > >>> > In the radius logs, this time I'm getting this error: >> > >>> > >> > >>> > [ldap] performing user authorization for hatim >> > >>> > [ldap] expand: sAMAccountName=3D%{User-Name} -> >> > >>> sAMAccountName=3Dhatim >> > >>> > [ldap] expand: dc=3Dad,dc=3D****,dc=3Dfr -> >> > dc=3Dad,dc=3D****,dc=3Dfr >> > >>> >> > >>> That doesn't look right. Where does that string come from? >> > >>> >> > >>> Alan DeKok. >> > >>> >> > >>> - >> > >>> List info/subscribe/unsubscribe? See >> > >>> http://www.freeradius.org/list/users.html >> > >>> >> > >>> ------------------------------ >> > >>> If you reply to this email, your message will be added to the >> > >>> discussion below: >> > >>> >> > >>> http://freeradius.1045715.n5.nabble.com/LDAP-search-failed- >> > tp5735079p5735114.html >> > >>> To unsubscribe from FreeRADIUS, click here >> > >>> >> > <http://freeradius.1045715.n5.nabble.com/template/NamlServlet.jtp?macro >> > =unsubscribe_by_code&node=2740692&code=aGF0aW0ubmV0d29ya2luZ0B >> > nbWFpbC5jb218Mjc0MDY5MnwxNzU1NTY4NDU2> >> > >>> . >> > >>> NAML >> > >>> >> > <http://freeradius.1045715.n5.nabble.com/template/NamlServlet.jtp?macro >> > =macro_viewer&id=instant_html%21nabble%3Aemail.naml&base=nabble.n >> > aml.namespaces.BasicNamespace- >> > nabble.view.web.template.NabbleNamespace- >> > nabble.view.web.template.NodeNamespace&breadcrumbs=notify_subscrib >> > ers%21nabble%3Aemail.naml-instant_emails%21nabble%3Aemail.naml- >> > send_instant_email%21nabble%3Aemail.naml> >> > >>> >> > >> >> > >> >> > > >> > - >> > List info/subscribe/unsubscribe? See >> > http://www.freeradius.org/list/users.html >> >> - >> List info/subscribe/unsubscribe? See >> http://www.freeradius.org/list/users.html >> >> ------------------------------ >> If you reply to this email, your message will be added to the >> discussion below: >> >> http://freeradius.1045715.n5.nabble.com/LDAP-search-failed-tp5735079p573514… >> To unsubscribe from FreeRADIUS, click here >> <http://freeradius.1045715.n5.nabble.com/template/NamlServlet.jtp?macro=unsu…> >> . >> NAML >> <http://freeradius.1045715.n5.nabble.com/template/NamlServlet.jtp?macro=macr…> >> > >

4 5

EAP/TLS Fails FR3.0.4 Centos7
by Kris Armstrong 07 Jul '15

07 Jul '15

I've installed CentOS 7 with all patches and then installed FR3.04 along with Mysql authentications. Since installing MYSQL authentication I can't get EAP/TLS to work. I'm using the default Certs at this point created by FR3.04 durring the install. It looks like FR3.0.4 is still attempting authentication via the SQL database even when the client is using EAP-TLS. Any ideas why? how to fix? Below is is FR3.0.4 in Debug Mode Ready to process requests soh { dhcp = yes } # Instantiating module "sradutmp" from file /etc/raddb/mods-enabled/sradutmp radutmp sradutmp { filename = "/var/log/radius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } # Loaded module rlm_unix # Instantiating module "unix" from file /etc/raddb/mods-enabled/unix unix { radwtmp = "/var/log/radius/radwtmp" } # Loaded module rlm_unpack # Instantiating module "unpack" from file /etc/raddb/mods-enabled/unpack # Loaded module rlm_utf8 # Instantiating module "utf8" from file /etc/raddb/mods-enabled/utf8 # Loaded module rlm_sql # Instantiating module "sql" from file /etc/raddb/mods-enabled/sql sql { driver = "rlm_sql_mysql" server = "localhost" port = "3306" login = "radius" password = <<< secret >>> radius_db = "radius" read_groups = yes read_profiles = yes read_clients = yes delete_stale_sessions = yes sql_user_name = "%{User-Name}" default_user_profile = "" client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" simul_count_query = "" simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" } accounting { reference = "%{tolower:type.%{Acct-Status-Type}.query}" } post-auth { reference = ".query" } mysql { tls { } } rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked rlm_sql (sql): Attempting to connect to database "radius" rlm_sql (sql): Initialising connection pool pool { start = 5 min = 4 max = 32 spare = 3 uses = 0 lifetime = 0 cleanup_interval = 30 idle_timeout = 60 retry_delay = 1 spread = no } rlm_sql (sql): Opening additional connection (0) rlm_sql_mysql: Starting connect to MySQL server rlm_sql (sql): Opening additional connection (1) rlm_sql_mysql: Starting connect to MySQL server rlm_sql (sql): Opening additional connection (2) rlm_sql_mysql: Starting connect to MySQL server rlm_sql (sql): Opening additional connection (3) rlm_sql_mysql: Starting connect to MySQL server rlm_sql (sql): Opening additional connection (4) rlm_sql_mysql: Starting connect to MySQL server rlm_sql (sql): Processing generate_sql_clients rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas rlm_sql (sql): Reserved connection (4) rlm_sql (sql): Executing query: 'SELECT id, nasname, shortname, type, secret, server FROM nas' rlm_sql (sql): Adding client 10.250.0.0/23 (network) to global clients list Failed to add duplicate client network Failed to add client, possible duplicate? rlm_sql (sql): Adding client 10.250.8.0/23 (AP) to global clients list rlm_sql (10.250.8.0): Client "AP" (sql) added rlm_sql (sql): Released connection (4) } # modules radiusd: #### Loading Virtual Servers #### server { # from file /etc/raddb/radiusd.conf } # server server default { # from file /etc/raddb/sites-enabled/default # Creating Auth-Type = digest # Loading authenticate {...} # Loading authorize {...} Ignoring "ldap" (see raddb/mods-available/README.rst) # Loading preacct {...} # Loading accounting {...} # Loading post-proxy {...} # Loading post-auth {...} } # server default server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel # Loading authenticate {...} # Loading authorize {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} } # server inner-tunnel radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipaddr = 127.0.0.1 port = 18120 } Listening on auth address * port 1812 as server default Listening on acct address * port 1813 as server default Listening on auth address :: port 1812 as server default Listening on acct address :: port 1813 as server default Listening on auth address 127.0.0.1 port 18120 as server inner-tunnel Opening new proxy socket 'proxy address * port 0' Listening on proxy address * port 59282 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c (0) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (0) User-Name = 'user(a)example.com' (0) NAS-IP-Address = 10.250.8.180 (0) Called-Station-Id = 'c8d71992a9d7' (0) Calling-Station-Id = '00c01732012e' (0) NAS-Identifier = 'c8d71992a9d7' (0) NAS-Port = 29 (0) Framed-MTU = 1400 (0) NAS-Port-Type = Wireless-802.11 (0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c (0) # Executing section authorize from file /etc/raddb/sites-enabled/default (0) authorize { (0) filter_username filter_username { (0) if (!&User-Name) (0) if (!&User-Name) -> FALSE (0) if (&User-Name =~ / /) (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\\.\\./ ) (0) if (&User-Name =~ /\\.\\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\\.$/) (0) if (&User-Name =~ /\\.$/) -> FALSE (0) if (&User-Name =~ /(a)\\./) (0) if (&User-Name =~ /(a)\\./) -> FALSE (0) } # filter_username filter_username = notfound (0) [preprocess] = ok (0) [chap] = noop (0) [mschap] = noop (0) [digest] = noop (0) suffix : Checking for suffix after "@" (0) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (0) suffix : Found realm "example.com" (0) suffix : Adding Stripped-User-Name = "user" (0) suffix : Adding Realm = "example.com" (0) suffix : Proxying request from user user to realm example.com (0) suffix : Preparing to proxy authentication request to realm "example.com" (0) [suffix] = updated (0) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (0) [eap] = noop (0) [files] = noop (0) sql : EXPAND %{User-Name} (0) sql : --> user(a)example.com (0) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (4) (0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (0) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (0) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (0) sql : User not found in any groups rlm_sql (sql): Released connection (4) rlm_sql (sql): Closing connection (0), from 1 unused connections rlm_sql_mysql: Socket destructor called, closing socket (0) [sql] = notfound (0) [expiration] = noop (0) [logintime] = noop (0) [pap] = noop (0) } # authorize = updated Opening new proxy socket 'proxy address * port 0' Listening on proxy address * port 36256 (0) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (0) Sending Access-Request packet to host 127.0.0.1 port 1812, id=241, length=0 (0) User-Name = 'user' (0) NAS-IP-Address = 10.250.8.180 (0) Called-Station-Id = 'c8d71992a9d7' (0) Calling-Station-Id = '00c01732012e' (0) NAS-Identifier = 'c8d71992a9d7' (0) NAS-Port = 29 (0) Framed-MTU = 1400 (0) NAS-Port-Type = Wireless-802.11 (0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c (0) Event-Timestamp = 'Jul 7 2015 10:46:25 MDT' (0) Stripped-User-Name = 'user' (0) Realm = 'example.com' (0) EAP-Type = Identity (0) Proxy-State = 0x32 Sending Access-Request Id 241 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c Event-Timestamp = 'Jul 7 2015 10:46:25 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 241 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x90c2755352698013c98625381ba727bf Event-Timestamp = 'Jul 7 2015 10:46:25 MDT' Proxy-State = 0x32 (1) Received Access-Request packet from host 127.0.0.1 port 36256, id=241, length=142 (1) User-Name = 'user' (1) NAS-IP-Address = 10.250.8.180 (1) Called-Station-Id = 'c8d71992a9d7' (1) Calling-Station-Id = '00c01732012e' (1) NAS-Identifier = 'c8d71992a9d7' (1) NAS-Port = 29 (1) Framed-MTU = 1400 (1) NAS-Port-Type = Wireless-802.11 (1) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (1) Message-Authenticator = 0x90c2755352698013c98625381ba727bf (1) Event-Timestamp = 'Jul 7 2015 10:46:25 MDT' (1) Proxy-State = 0x32 (1) # Executing section authorize from file /etc/raddb/sites-enabled/default (1) authorize { (1) filter_username filter_username { (1) if (!&User-Name) (1) if (!&User-Name) -> FALSE (1) if (&User-Name =~ / /) (1) if (&User-Name =~ / /) -> FALSE (1) if (&User-Name =~ /@.*@/ ) (1) if (&User-Name =~ /@.*@/ ) -> FALSE (1) if (&User-Name =~ /\\.\\./ ) (1) if (&User-Name =~ /\\.\\./ ) -> FALSE (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (1) if (&User-Name =~ /\\.$/) (1) if (&User-Name =~ /\\.$/) -> FALSE (1) if (&User-Name =~ /(a)\\./) (1) if (&User-Name =~ /(a)\\./) -> FALSE (1) } # filter_username filter_username = notfound (1) [preprocess] = ok (1) [chap] = noop (1) [mschap] = noop (1) [digest] = noop (1) suffix : Checking for suffix after "@" (1) suffix : No '@' in User-Name = "user", looking up realm NULL (1) suffix : No such realm "NULL" (1) [suffix] = noop (1) eap : Peer sent code Response (2) ID 0 length 21 (1) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = EAP (1) # Executing group from file /etc/raddb/sites-enabled/default (1) authenticate { (1) eap : Identity does not match User-Name, setting from EAP Identity (1) eap : Failed in handler (1) [eap] = invalid (1) } # authenticate = invalid (1) Failed to authenticate the user (1) Using Post-Auth-Type Reject (1) # Executing group from file /etc/raddb/sites-enabled/default (1) Post-Auth-Type REJECT { (1) sql : EXPAND .query (1) sql : --> .query (1) sql : Using query template 'query' rlm_sql (sql): Reserved connection (4) (1) sql : EXPAND %{User-Name} (1) sql : --> user (1) sql : SQL-User-Name set to 'user' (1) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (1) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:46:25') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:46:25')' rlm_sql (sql): Released connection (4) (1) [sql] = ok (1) attr_filter.access_reject : EXPAND %{User-Name} (1) attr_filter.access_reject : --> user (1) attr_filter.access_reject : Matched entry DEFAULT at line 11 (1) [attr_filter.access_reject] = updated (1) eap : Identity does not match User-Name, setting from EAP Identity (1) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (1) [eap] = noop (1) remove_reply_message_if_eap remove_reply_message_if_eap { (1) if (&reply:EAP-Message && &reply:Reply-Message) (1) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (1) else else { (1) [noop] = noop (1) } # else else = noop (1) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (1) } # Post-Auth-Type REJECT = updated (1) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (0) Expecting proxy response no later than 19.499798 seconds from now Waking up in 0.5 seconds. (1) Sending delayed response (1) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=241, length=0 (1) Proxy-State = 0x32 Sending Access-Reject Id 241 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 241 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (0) Received Access-Reject packet from host 127.0.0.1 port 1812, id=241, length=23 (0) Proxy-State = 0x32 (0) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (0) post-proxy { (0) eap : No pre-existing handler found (0) [eap] = noop (0) } # post-proxy = noop (0) Using Post-Auth-Type Reject (0) # Executing group from file /etc/raddb/sites-enabled/default (0) Post-Auth-Type REJECT { (0) sql : EXPAND .query (0) sql : --> .query (0) sql : Using query template 'query' rlm_sql (sql): Reserved connection (4) (0) sql : EXPAND %{User-Name} (0) sql : --> user(a)example.com (0) sql : SQL-User-Name set to 'user(a)example.com' (0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:46:25') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:46:25')' rlm_sql (sql): Released connection (4) (0) [sql] = ok (0) attr_filter.access_reject : EXPAND %{User-Name} (0) attr_filter.access_reject : --> user(a)example.com (0) attr_filter.access_reject : Matched entry DEFAULT at line 11 (0) [attr_filter.access_reject] = updated (0) eap : Request was previously rejected, inserting EAP-Failure (0) [eap] = updated (0) remove_reply_message_if_eap remove_reply_message_if_eap { (0) if (&reply:EAP-Message && &reply:Reply-Message) (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (0) else else { (0) [noop] = noop (0) } # else else = noop (0) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (0) } # Post-Auth-Type REJECT = updated (0) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (0) Sending delayed response (0) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (0) EAP-Message = 0x04000004 (0) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04000004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (1) Cleaning up request packet ID 241 with timestamp +40 Waking up in 0.9 seconds. (0) Cleaning up request packet ID 2 with timestamp +40 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c (0) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (0) User-Name = 'user(a)example.com' (0) NAS-IP-Address = 10.250.8.180 (0) Called-Station-Id = 'c8d71992a9d7' (0) Calling-Station-Id = '00c01732012e' (0) NAS-Identifier = 'c8d71992a9d7' (0) NAS-Port = 29 (0) Framed-MTU = 1400 (0) NAS-Port-Type = Wireless-802.11 (0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c (0) # Executing section authorize from file /etc/raddb/sites-enabled/default (0) authorize { (0) filter_username filter_username { (0) if (!&User-Name) (0) if (!&User-Name) -> FALSE (0) if (&User-Name =~ / /) (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\\.\\./ ) (0) if (&User-Name =~ /\\.\\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\\.$/) (0) if (&User-Name =~ /\\.$/) -> FALSE (0) if (&User-Name =~ /(a)\\./) (0) if (&User-Name =~ /(a)\\./) -> FALSE (0) } # filter_username filter_username = notfound (0) [preprocess] = ok (0) [chap] = noop (0) [mschap] = noop (0) [digest] = noop (0) suffix : Checking for suffix after "@" (0) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (0) suffix : Found realm "example.com" (0) suffix : Adding Stripped-User-Name = "user" (0) suffix : Adding Realm = "example.com" (0) suffix : Proxying request from user user to realm example.com (0) suffix : Preparing to proxy authentication request to realm "example.com" (0) [suffix] = updated (0) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (0) [eap] = noop (0) [files] = noop (0) sql : EXPAND %{User-Name} (0) sql : --> user(a)example.com (0) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (4) (0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (0) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (0) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (0) sql : User not found in any groups rlm_sql (sql): Released connection (4) rlm_sql (sql): Closing connection (0), from 1 unused connections rlm_sql_mysql: Socket destructor called, closing socket (0) [sql] = notfound (0) [expiration] = noop (0) [logintime] = noop (0) [pap] = noop (0) } # authorize = updated Opening new proxy socket 'proxy address * port 0' Listening on proxy address * port 36256 (0) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (0) Sending Access-Request packet to host 127.0.0.1 port 1812, id=241, length=0 (0) User-Name = 'user' (0) NAS-IP-Address = 10.250.8.180 (0) Called-Station-Id = 'c8d71992a9d7' (0) Calling-Station-Id = '00c01732012e' (0) NAS-Identifier = 'c8d71992a9d7' (0) NAReceived Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7 (2) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (2) User-Name = 'user(a)example.com' (2) NAS-IP-Address = 10.250.8.180 (2) Called-Station-Id = 'c8d71992a9d7' (2) Calling-Station-Id = '00c01732012e' (2) NAS-Identifier = 'c8d71992a9d7' (2) NAS-Port = 29 (2) Framed-MTU = 1400 (2) NAS-Port-Type = Wireless-802.11 (2) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (2) Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7 (2) # Executing section authorize from file /etc/raddb/sites-enabled/default (2) authorize { (2) filter_username filter_username { (2) if (!&User-Name) (2) if (!&User-Name) -> FALSE (2) if (&User-Name =~ / /) (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@.*@/ ) (2) if (&User-Name =~ /@.*@/ ) -> FALSE (2) if (&User-Name =~ /\\.\\./ ) (2) if (&User-Name =~ /\\.\\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\\.$/) (2) if (&User-Name =~ /\\.$/) -> FALSE (2) if (&User-Name =~ /(a)\\./) (2) if (&User-Name =~ /(a)\\./) -> FALSE (2) } # filter_username filter_username = notfound (2) [preprocess] = ok (2) [chap] = noop (2) [mschap] = noop (2) [digest] = noop (2) suffix : Checking for suffix after "@" (2) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (2) suffix : Found realm "example.com" (2) suffix : Adding Stripped-User-Name = "user" (2) suffix : Adding Realm = "example.com" (2) suffix : Proxying request from user user to realm example.com (2) suffix : Preparing to proxy authentication request to realm "example.com" (2) [suffix] = updated (2) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (2) [eap] = noop (2) [files] = noop (2) sql : EXPAND %{User-Name} (2) sql : --> user(a)example.com (2) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (4) (2) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (2) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (2) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (2) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (2) sql : User not found in any groups rlm_sql (sql): Released connection (4) rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 134 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 134 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 134 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket (2) [sql] = notfound (2) [expiration] = noop (2) [logintime] = noop (2) [pap] = noop (2) } # authorize = updated (2) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (2) Sending Access-Request packet to host 127.0.0.1 port 1812, id=195, length=0 (2) User-Name = 'user' (2) NAS-IP-Address = 10.250.8.180 (2) Called-Station-Id = 'c8d71992a9d7' (2) Calling-Station-Id = '00c01732012e' (2) NAS-Identifier = 'c8d71992a9d7' (2) NAS-Port = 29 (2) Framed-MTU = 1400 (2) NAS-Port-Type = Wireless-802.11 (2) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (2) Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7 (2) Event-Timestamp = 'Jul 7 2015 10:47:59 MDT' (2) Stripped-User-Name = 'user' (2) Realm = 'example.com' (2) EAP-Type = Identity (2) Proxy-State = 0x32 Sending Access-Request Id 195 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7 Event-Timestamp = 'Jul 7 2015 10:47:59 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 195 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0xb0b349a74d58945205b266f508870912 Event-Timestamp = 'Jul 7 2015 10:47:59 MDT' Proxy-State = 0x32 (3) Received Access-Request packet from host 127.0.0.1 port 36256, id=195, length=142 (3) User-Name = 'user' (3) NAS-IP-Address = 10.250.8.180 (3) Called-Station-Id = 'c8d71992a9d7' (3) Calling-Station-Id = '00c01732012e' (3) NAS-Identifier = 'c8d71992a9d7' (3) NAS-Port = 29 (3) Framed-MTU = 1400 (3) NAS-Port-Type = Wireless-802.11 (3) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (3) Message-Authenticator = 0xb0b349a74d58945205b266f508870912 (3) Event-Timestamp = 'Jul 7 2015 10:47:59 MDT' (3) Proxy-State = 0x32 (3) # Executing section authorize from file /etc/raddb/sites-enabled/default (3) authorize { (3) filter_username filter_username { (3) if (!&User-Name) (3) if (!&User-Name) -> FALSE (3) if (&User-Name =~ / /) (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@.*@/ ) (3) if (&User-Name =~ /@.*@/ ) -> FALSE (3) if (&User-Name =~ /\\.\\./ ) (3) if (&User-Name =~ /\\.\\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\\.$/) (3) if (&User-Name =~ /\\.$/) -> FALSE (3) if (&User-Name =~ /(a)\\./) (3) if (&User-Name =~ /(a)\\./) -> FALSE (3) } # filter_username filter_username = notfound (3) [preprocess] = ok (3) [chap] = noop (3) [mschap] = noop (3) [digest] = noop (3) suffix : Checking for suffix after "@" (3) suffix : No '@' in User-Name = "user", looking up realm NULL (3) suffix : No such realm "NULL" (3) [suffix] = noop (3) eap : Peer sent code Response (2) ID 1 length 21 (3) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = EAP (3) # Executing group from file /etc/raddb/sites-enabled/default (3) authenticate { (3) eap : Identity does not match User-Name, setting from EAP Identity (3) eap : Failed in handler (3) [eap] = invalid (3) } # authenticate = invalid (3) Failed to authenticate the user (3) Using Post-Auth-Type Reject (3) # Executing group from file /etc/raddb/sites-enabled/default (3) Post-Auth-Type REJECT { (3) sql : EXPAND .query (3) sql : --> .query (3) sql : Using query template 'query' rlm_sql (sql): Reserved connection (4) (3) sql : EXPAND %{User-Name} (3) sql : --> user (3) sql : SQL-User-Name set to 'user' (3) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (3) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:47:59') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:47:59')' rlm_sql (sql): Released connection (4) (3) [sql] = ok (3) attr_filter.access_reject : EXPAND %{User-Name} (3) attr_filter.access_reject : --> user (3) attr_filter.access_reject : Matched entry DEFAULT at line 11 (3) [attr_filter.access_reject] = updated (3) eap : Identity does not match User-Name, setting from EAP Identity (3) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (3) [eap] = noop (3) remove_reply_message_if_eap remove_reply_message_if_eap { (3) if (&reply:EAP-Message && &reply:Reply-Message) (3) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (3) else else { (3) [noop] = noop (3) } # else else = noop (3) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (3) } # Post-Auth-Type REJECT = updated (3) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (2) Expecting proxy response no later than 19.499792 seconds from now Waking up in 0.5 seconds. (3) Sending delayed response (3) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=195, length=0 (3) Proxy-State = 0x32 Sending Access-Reject Id 195 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 195 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (2) Received Access-Reject packet from host 127.0.0.1 port 1812, id=195, length=23 (2) Proxy-State = 0x32 (2) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (2) post-proxy { (2) eap : No pre-existing handler found (2) [eap] = noop (2) } # post-proxy = noop (2) Using Post-Auth-Type Reject (2) # Executing group from file /etc/raddb/sites-enabled/default (2) Post-Auth-Type REJECT { (2) sql : EXPAND .query (2) sql : --> .query (2) sql : Using query template 'query' rlm_sql (sql): Reserved connection (4) (2) sql : EXPAND %{User-Name} (2) sql : --> user(a)example.com (2) sql : SQL-User-Name set to 'user(a)example.com' (2) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (2) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:47:59') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:47:59')' rlm_sql (sql): Released connection (4) rlm_sql (sql): 0 of 1 connections in use. Need more spares rlm_sql (sql): Opening additional connection (5) rlm_sql_mysql: Starting connect to MySQL server (2) [sql] = ok (2) attr_filter.access_reject : EXPAND %{User-Name} (2) attr_filter.access_reject : --> user(a)example.com (2) attr_filter.access_reject : Matched entry DEFAULT at line 11 (2) [attr_filter.access_reject] = updated (2) eap : Request was previously rejected, inserting EAP-Failure (2) [eap] = updated (2) remove_reply_message_if_eap remove_reply_message_if_eap { (2) if (&reply:EAP-Message && &reply:Reply-Message) (2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (2) else else { (2) [noop] = noop (2) } # else else = noop (2) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (2) } # Post-Auth-Type REJECT = updated (2) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (2) Sending delayed response (2) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (2) EAP-Message = 0x04010004 (2) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04010004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (3) Cleaning up request packet ID 195 with timestamp +134 Waking up in 0.9 seconds. (2) Cleaning up request packet ID 2 with timestamp +134 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47 (4) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (4) User-Name = 'user(a)example.com' (4) NAS-IP-Address = 10.250.8.180 (4) Called-Station-Id = 'c8d71992a9d7' (4) Calling-Station-Id = '00c01732012e' (4) NAS-Identifier = 'c8d71992a9d7' (4) NAS-Port = 29 (4) Framed-MTU = 1400 (4) NAS-Port-Type = Wireless-802.11 (4) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (4) Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47 (4) # Executing section authorize from file /etc/raddb/sites-enabled/default (4) authorize { (4) filter_username filter_username { (4) if (!&User-Name) (4) if (!&User-Name) -> FALSE (4) if (&User-Name =~ / /) (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@.*@/ ) (4) if (&User-Name =~ /@.*@/ ) -> FALSE (4) if (&User-Name =~ /\\.\\./ ) (4) if (&User-Name =~ /\\.\\./ ) -> FALSE (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (4) if (&User-Name =~ /\\.$/) (4) if (&User-Name =~ /\\.$/) -> FALSE (4) if (&User-Name =~ /(a)\\./) (4) if (&User-Name =~ /(a)\\./) -> FALSE (4) } # filter_username filter_username = notfound (4) [preprocess] = ok (4) [chap] = noop (4) [mschap] = noop (4) [digest] = noop (4) suffix : Checking for suffix after "@" (4) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (4) suffix : Found realm "example.com" (4) suffix : Adding Stripped-User-Name = "user" (4) suffix : Adding Realm = "example.com" (4) suffix : Proxying request from user user to realm example.com (4) suffix : Preparing to proxy authentication request to realm "example.com" (4) [suffix] = updated (4) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (4) [eap] = noop (4) [files] = noop (4) sql : EXPAND %{User-Name} (4) sql : --> user(a)example.com (4) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (5) (4) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (4) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (4) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (4) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (4) sql : User not found in any groups rlm_sql (sql): Released connection (5) rlm_sql (sql): 0 of 2 connections in use. Need more spares rlm_sql (sql): Opening additional connection (6) rlm_sql_mysql: Starting connect to MySQL server (4) [sql] = notfound (4) [expiration] = noop (4) [logintime] = noop (4) [pap] = noop (4) } # authorize = updated (4) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (4) Sending Access-Request packet to host 127.0.0.1 port 1812, id=230, length=0 (4) User-Name = 'user' (4) NAS-IP-Address = 10.250.8.180 (4) Called-Station-Id = 'c8d71992a9d7' (4) Calling-Station-Id = '00c01732012e' (4) NAS-Identifier = 'c8d71992a9d7' (4) NAS-Port = 29 (4) Framed-MTU = 1400 (4) NAS-Port-Type = Wireless-802.11 (4) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (4) Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47 (4) Event-Timestamp = 'Jul 7 2015 10:48:07 MDT' (4) Stripped-User-Name = 'user' (4) Realm = 'example.com' (4) EAP-Type = Identity (4) Proxy-State = 0x32 Sending Access-Request Id 230 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47 Event-Timestamp = 'Jul 7 2015 10:48:07 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 230 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x4c386d1361dbbd34947533bd5874d113 Event-Timestamp = 'Jul 7 2015 10:48:07 MDT' Proxy-State = 0x32 (5) Received Access-Request packet from host 127.0.0.1 port 36256, id=230, length=142 (5) User-Name = 'user' (5) NAS-IP-Address = 10.250.8.180 (5) Called-Station-Id = 'c8d71992a9d7' (5) Calling-Station-Id = '00c01732012e' (5) NAS-Identifier = 'c8d71992a9d7' (5) NAS-Port = 29 (5) Framed-MTU = 1400 (5) NAS-Port-Type = Wireless-802.11 (5) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (5) Message-Authenticator = 0x4c386d1361dbbd34947533bd5874d113 (5) Event-Timestamp = 'Jul 7 2015 10:48:07 MDT' (5) Proxy-State = 0x32 (5) # Executing section authorize from file /etc/raddb/sites-enabled/default (5) authorize { (5) filter_username filter_username { (5) if (!&User-Name) (5) if (!&User-Name) -> FALSE (5) if (&User-Name =~ / /) (5) if (&User-Name =~ / /) -> FALSE (5) if (&User-Name =~ /@.*@/ ) (5) if (&User-Name =~ /@.*@/ ) -> FALSE (5) if (&User-Name =~ /\\.\\./ ) (5) if (&User-Name =~ /\\.\\./ ) -> FALSE (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (5) if (&User-Name =~ /\\.$/) (5) if (&User-Name =~ /\\.$/) -> FALSE (5) if (&User-Name =~ /(a)\\./) (5) if (&User-Name =~ /(a)\\./) -> FALSE (5) } # filter_username filter_username = notfound (5) [preprocess] = ok (5) [chap] = noop (5) [mschap] = noop (5) [digest] = noop (5) suffix : Checking for suffix after "@" (5) suffix : No '@' in User-Name = "user", looking up realm NULL (5) suffix : No such realm "NULL" (5) [suffix] = noop (5) eap : Peer sent code Response (2) ID 0 length 21 (5) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = EAP (5) # Executing group from file /etc/raddb/sites-enabled/default (5) authenticate { (5) eap : Identity does not match User-Name, setting from EAP Identity (5) eap : Failed in handler (5) [eap] = invalid (5) } # authenticate = invalid (5) Failed to authenticate the user (5) Using Post-Auth-Type Reject (5) # Executing group from file /etc/raddb/sites-enabled/default (5) Post-Auth-Type REJECT { (5) sql : EXPAND .query (5) sql : --> .query (5) sql : Using query template 'query' rlm_sql (sql): Reserved connection (6) (5) sql : EXPAND %{User-Name} (5) sql : --> user (5) sql : SQL-User-Name set to 'user' (5) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (5) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:48:07') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:48:07')' rlm_sql (sql): Released connection (6) (5) [sql] = ok (5) attr_filter.access_reject : EXPAND %{User-Name} (5) attr_filter.access_reject : --> user (5) attr_filter.access_reject : Matched entry DEFAULT at line 11 (5) [attr_filter.access_reject] = updated (5) eap : Identity does not match User-Name, setting from EAP Identity (5) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (5) [eap] = noop (5) remove_reply_message_if_eap remove_reply_message_if_eap { (5) if (&reply:EAP-Message && &reply:Reply-Message) (5) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (5) else else { (5) [noop] = noop (5) } # else else = noop (5) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (5) } # Post-Auth-Type REJECT = updated (5) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (4) Expecting proxy response no later than 19.499792 seconds from now Waking up in 0.5 seconds. (5) Sending delayed response (5) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=230, length=0 (5) Proxy-State = 0x32 Sending Access-Reject Id 230 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 230 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (4) Received Access-Reject packet from host 127.0.0.1 port 1812, id=230, length=23 (4) Proxy-State = 0x32 (4) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (4) post-proxy { (4) eap : No pre-existing handler found (4) [eap] = noop (4) } # post-proxy = noop (4) Using Post-Auth-Type Reject (4) # Executing group from file /etc/raddb/sites-enabled/default (4) Post-Auth-Type REJECT { (4) sql : EXPAND .query (4) sql : --> .query (4) sql : Using query template 'query' rlm_sql (sql): Reserved connection (6) (4) sql : EXPAND %{User-Name} (4) sql : --> user(a)example.com (4) sql : SQL-User-Name set to 'user(a)example.com' (4) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (4) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:48:07') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:48:07')' rlm_sql (sql): Released connection (6) rlm_sql (sql): 0 of 3 connections in use. Need more spares rlm_sql (sql): Opening additional connection (7) rlm_sql_mysql: Starting connect to MySQL server (4) [sql] = ok (4) attr_filter.access_reject : EXPAND %{User-Name} (4) attr_filter.access_reject : --> user(a)example.com (4) attr_filter.access_reject : Matched entry DEFAULT at line 11 (4) [attr_filter.access_reject] = updated (4) eap : Request was previously rejected, inserting EAP-Failure (4) [eap] = updated (4) remove_reply_message_if_eap remove_reply_message_if_eap { (4) if (&reply:EAP-Message && &reply:Reply-Message) (4) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (4) else else { (4) [noop] = noop (4) } # else else = noop (4) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (4) } # Post-Auth-Type REJECT = updated (4) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (4) Sending delayed response (4) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (4) EAP-Message = 0x04000004 (4) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04000004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (5) Cleaning up request packet ID 230 with timestamp +142 Waking up in 0.9 seconds. (4) Cleaning up request packet ID 2 with timestamp +142 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831 (6) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (6) User-Name = 'user(a)example.com' (6) NAS-IP-Address = 10.250.8.180 (6) Called-Station-Id = 'c8d71992a9d7' (6) Calling-Station-Id = '00c01732012e' (6) NAS-Identifier = 'c8d71992a9d7' (6) NAS-Port = 29 (6) Framed-MTU = 1400 (6) NAS-Port-Type = Wireless-802.11 (6) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (6) Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831 (6) # Executing section authorize from file /etc/raddb/sites-enabled/default (6) authorize { (6) filter_username filter_username { (6) if (!&User-Name) (6) if (!&User-Name) -> FALSE (6) if (&User-Name =~ / /) (6) if (&User-Name =~ / /) -> FALSE (6) if (&User-Name =~ /@.*@/ ) (6) if (&User-Name =~ /@.*@/ ) -> FALSE (6) if (&User-Name =~ /\\.\\./ ) (6) if (&User-Name =~ /\\.\\./ ) -> FALSE (6) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (6) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (6) if (&User-Name =~ /\\.$/) (6) if (&User-Name =~ /\\.$/) -> FALSE (6) if (&User-Name =~ /(a)\\./) (6) if (&User-Name =~ /(a)\\./) -> FALSE (6) } # filter_username filter_username = notfound (6) [preprocess] = ok (6) [chap] = noop (6) [mschap] = noop (6) [digest] = noop (6) suffix : Checking for suffix after "@" (6) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (6) suffix : Found realm "example.com" (6) suffix : Adding Stripped-User-Name = "user" (6) suffix : Adding Realm = "example.com" (6) suffix : Proxying request from user user to realm example.com (6) suffix : Preparing to proxy authentication request to realm "example.com" (6) [suffix] = updated (6) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (6) [eap] = noop (6) [files] = noop (6) sql : EXPAND %{User-Name} (6) sql : --> user(a)example.com (6) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (7) (6) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (6) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (6) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (6) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (6) sql : User not found in any groups rlm_sql (sql): Released connection (7) rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 63 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 64 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 71 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket (6) [sql] = notfound (6) [expiration] = noop (6) [logintime] = noop (6) [pap] = noop (6) } # authorize = updated (6) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (6) Sending Access-Request packet to host 127.0.0.1 port 1812, id=123, length=0 (6) User-Name = 'user' (6) NAS-IP-Address = 10.250.8.180 (6) Called-Station-Id = 'c8d71992a9d7' (6) Calling-Station-Id = '00c01732012e' (6) NAS-Identifier = 'c8d71992a9d7' (6) NAS-Port = 29 (6) Framed-MTU = 1400 (6) NAS-Port-Type = Wireless-802.11 (6) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (6) Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831 (6) Event-Timestamp = 'Jul 7 2015 10:49:11 MDT' (6) Stripped-User-Name = 'user' (6) Realm = 'example.com' (6) EAP-Type = Identity (6) Proxy-State = 0x32 Sending Access-Request Id 123 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831 Event-Timestamp = 'Jul 7 2015 10:49:11 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 123 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x633c8474dcfb64843fbce8453a51c816 Event-Timestamp = 'Jul 7 2015 10:49:11 MDT' Proxy-State = 0x32 (7) Received Access-Request packet from host 127.0.0.1 port 36256, id=123, length=142 (7) User-Name = 'user' (7) NAS-IP-Address = 10.250.8.180 (7) Called-Station-Id = 'c8d71992a9d7' (7) Calling-Station-Id = '00c01732012e' (7) NAS-Identifier = 'c8d71992a9d7' (7) NAS-Port = 29 (7) Framed-MTU = 1400 (7) NAS-Port-Type = Wireless-802.11 (7) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (7) Message-Authenticator = 0x633c8474dcfb64843fbce8453a51c816 (7) Event-Timestamp = 'Jul 7 2015 10:49:11 MDT' (7) Proxy-State = 0x32 (7) # Executing section authorize from file /etc/raddb/sites-enabled/default (7) authorize { (7) filter_username filter_username { (7) if (!&User-Name) (7) if (!&User-Name) -> FALSE (7) if (&User-Name =~ / /) (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\\.\\./ ) (7) if (&User-Name =~ /\\.\\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\\.$/) (7) if (&User-Name =~ /\\.$/) -> FALSE (7) if (&User-Name =~ /(a)\\./) (7) if (&User-Name =~ /(a)\\./) -> FALSE (7) } # filter_username filter_username = notfound (7) [preprocess] = ok (7) [chap] = noop (7) [mschap] = noop (7) [digest] = noop (7) suffix : Checking for suffix after "@" (7) suffix : No '@' in User-Name = "user", looking up realm NULL (7) suffix : No such realm "NULL" (7) [suffix] = noop (7) eap : Peer sent code Response (2) ID 1 length 21 (7) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /etc/raddb/sites-enabled/default (7) authenticate { (7) eap : Identity does not match User-Name, setting from EAP Identity (7) eap : Failed in handler (7) [eap] = invalid (7) } # authenticate = invalid (7) Failed to authenticate the user (7) Using Post-Auth-Type Reject (7) # Executing group from file /etc/raddb/sites-enabled/default (7) Post-Auth-Type REJECT { (7) sql : EXPAND .query (7) sql : --> .query (7) sql : Using query template 'query' rlm_sql (sql): Reserved connection (7) (7) sql : EXPAND %{User-Name} (7) sql : --> user (7) sql : SQL-User-Name set to 'user' (7) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (7) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:11') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:11')' rlm_sql (sql): Released connection (7) (7) [sql] = ok (7) attr_filter.access_reject : EXPAND %{User-Name} (7) attr_filter.access_reject : --> user (7) attr_filter.access_reject : Matched entry DEFAULT at line 11 (7) [attr_filter.access_reject] = updated (7) eap : Identity does not match User-Name, setting from EAP Identity (7) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (7) [eap] = noop (7) remove_reply_message_if_eap remove_reply_message_if_eap { (7) if (&reply:EAP-Message && &reply:Reply-Message) (7) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (7) else else { (7) [noop] = noop (7) } # else else = noop (7) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (7) } # Post-Auth-Type REJECT = updated (7) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (6) Expecting proxy response no later than 19.499801 seconds from now Waking up in 0.5 seconds. (7) Sending delayed response (7) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=123, length=0 (7) Proxy-State = 0x32 Sending Access-Reject Id 123 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 123 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (6) Received Access-Reject packet from host 127.0.0.1 port 1812, id=123, length=23 (6) Proxy-State = 0x32 (6) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (6) post-proxy { (6) eap : No pre-existing handler found (6) [eap] = noop (6) } # post-proxy = noop (6) Using Post-Auth-Type Reject (6) # Executing group from file /etc/raddb/sites-enabled/default (6) Post-Auth-Type REJECT { (6) sql : EXPAND .query (6) sql : --> .query (6) sql : Using query template 'query' rlm_sql (sql): Reserved connection (7) (6) sql : EXPAND %{User-Name} (6) sql : --> user(a)example.com (6) sql : SQL-User-Name set to 'user(a)example.com' (6) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (6) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:49:11') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:49:11')' rlm_sql (sql): Released connection (7) rlm_sql (sql): 0 of 1 connections in use. Need more spares rlm_sql (sql): Opening additional connection (8) rlm_sql_mysql: Starting connect to MySQL server (6) [sql] = ok (6) attr_filter.access_reject : EXPAND %{User-Name} (6) attr_filter.access_reject : --> user(a)example.com (6) attr_filter.access_reject : Matched entry DEFAULT at line 11 (6) [attr_filter.access_reject] = updated (6) eap : Request was previously rejected, inserting EAP-Failure (6) [eap] = updated (6) remove_reply_message_if_eap remove_reply_message_if_eap { (6) if (&reply:EAP-Message && &reply:Reply-Message) (6) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (6) else else { (6) [noop] = noop (6) } # else else = noop (6) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (6) } # Post-Auth-Type REJECT = updated (6) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (6) Sending delayed response (6) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (6) EAP-Message = 0x04010004 (6) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04010004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (7) Cleaning up request packet ID 123 with timestamp +206 Waking up in 0.9 seconds. (6) Cleaning up request packet ID 2 with timestamp +206 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653 (8) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (8) User-Name = 'user(a)example.com' (8) NAS-IP-Address = 10.250.8.180 (8) Called-Station-Id = 'c8d71992a9d7' (8) Calling-Station-Id = '00c01732012e' (8) NAS-Identifier = 'c8d71992a9d7' (8) NAS-Port = 29 (8) Framed-MTU = 1400 (8) NAS-Port-Type = Wireless-802.11 (8) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (8) Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653 (8) # Executing section authorize from file /etc/raddb/sites-enabled/default (8) authorize { (8) filter_username filter_username { (8) if (!&User-Name) (8) if (!&User-Name) -> FALSE (8) if (&User-Name =~ / /) (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /(a)\\./) (8) if (&User-Name =~ /(a)\\./) -> FALSE (8) } # filter_username filter_username = notfound (8) [preprocess] = ok (8) [chap] = noop (8) [mschap] = noop (8) [digest] = noop (8) suffix : Checking for suffix after "@" (8) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (8) suffix : Found realm "example.com" (8) suffix : Adding Stripped-User-Name = "user" (8) suffix : Adding Realm = "example.com" (8) suffix : Proxying request from user user to realm example.com (8) suffix : Preparing to proxy authentication request to realm "example.com" (8) [suffix] = updated (8) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (8) [eap] = noop (8) [files] = noop (8) sql : EXPAND %{User-Name} (8) sql : --> user(a)example.com (8) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (8) (8) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (8) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (8) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (8) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (8) sql : User not found in any groups rlm_sql (sql): Released connection (8) rlm_sql (sql): 0 of 2 connections in use. Need more spares rlm_sql (sql): Opening additional connection (9) rlm_sql_mysql: Starting connect to MySQL server (8) [sql] = notfound (8) [expiration] = noop (8) [logintime] = noop (8) [pap] = noop (8) } # authorize = updated (8) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (8) Sending Access-Request packet to host 127.0.0.1 port 1812, id=41, length=0 (8) User-Name = 'user' (8) NAS-IP-Address = 10.250.8.180 (8) Called-Station-Id = 'c8d71992a9d7' (8) Calling-Station-Id = '00c01732012e' (8) NAS-Identifier = 'c8d71992a9d7' (8) NAS-Port = 29 (8) Framed-MTU = 1400 (8) NAS-Port-Type = Wireless-802.11 (8) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (8) Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653 (8) Event-Timestamp = 'Jul 7 2015 10:49:19 MDT' (8) Stripped-User-Name = 'user' (8) Realm = 'example.com' (8) EAP-Type = Identity (8) Proxy-State = 0x32 Sending Access-Request Id 41 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653 Event-Timestamp = 'Jul 7 2015 10:49:19 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 41 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020000150175736572406578616d706c652e636f6d Message-Authenticator = 0x518309c772102e181c99a2850fa821ba Event-Timestamp = 'Jul 7 2015 10:49:19 MDT' Proxy-State = 0x32 (9) Received Access-Request packet from host 127.0.0.1 port 36256, id=41, length=142 (9) User-Name = 'user' (9) NAS-IP-Address = 10.250.8.180 (9) Called-Station-Id = 'c8d71992a9d7' (9) Calling-Station-Id = '00c01732012e' (9) NAS-Identifier = 'c8d71992a9d7' (9) NAS-Port = 29 (9) Framed-MTU = 1400 (9) NAS-Port-Type = Wireless-802.11 (9) EAP-Message = 0x020000150175736572406578616d706c652e636f6d (9) Message-Authenticator = 0x518309c772102e181c99a2850fa821ba (9) Event-Timestamp = 'Jul 7 2015 10:49:19 MDT' (9) Proxy-State = 0x32 (9) # Executing section authorize from file /etc/raddb/sites-enabled/default (9) authorize { (9) filter_username filter_username { (9) if (!&User-Name) (9) if (!&User-Name) -> FALSE (9) if (&User-Name =~ / /) (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /(a)\\./) (9) if (&User-Name =~ /(a)\\./) -> FALSE (9) } # filter_username filter_username = notfound (9) [preprocess] = ok (9) [chap] = noop (9) [mschap] = noop (9) [digest] = noop (9) suffix : Checking for suffix after "@" (9) suffix : No '@' in User-Name = "user", looking up realm NULL (9) suffix : No such realm "NULL" (9) [suffix] = noop (9) eap : Peer sent code Response (2) ID 0 length 21 (9) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (9) [eap] = ok (9) } # authorize = ok (9) Found Auth-Type = EAP (9) # Executing group from file /etc/raddb/sites-enabled/default (9) authenticate { (9) eap : Identity does not match User-Name, setting from EAP Identity (9) eap : Failed in handler (9) [eap] = invalid (9) } # authenticate = invalid (9) Failed to authenticate the user (9) Using Post-Auth-Type Reject (9) # Executing group from file /etc/raddb/sites-enabled/default (9) Post-Auth-Type REJECT { (9) sql : EXPAND .query (9) sql : --> .query (9) sql : Using query template 'query' rlm_sql (sql): Reserved connection (9) (9) sql : EXPAND %{User-Name} (9) sql : --> user (9) sql : SQL-User-Name set to 'user' (9) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (9) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:19') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:19')' rlm_sql (sql): Released connection (9) (9) [sql] = ok (9) attr_filter.access_reject : EXPAND %{User-Name} (9) attr_filter.access_reject : --> user (9) attr_filter.access_reject : Matched entry DEFAULT at line 11 (9) [attr_filter.access_reject] = updated (9) eap : Identity does not match User-Name, setting from EAP Identity (9) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (9) [eap] = noop (9) remove_reply_message_if_eap remove_reply_message_if_eap { (9) if (&reply:EAP-Message && &reply:Reply-Message) (9) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (9) else else { (9) [noop] = noop (9) } # else else = noop (9) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (9) } # Post-Auth-Type REJECT = updated (9) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (8) Expecting proxy response no later than 19.499781 seconds from now Waking up in 0.5 seconds. (9) Sending delayed response (9) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=41, length=0 (9) Proxy-State = 0x32 Sending Access-Reject Id 41 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 41 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (8) Received Access-Reject packet from host 127.0.0.1 port 1812, id=41, length=23 (8) Proxy-State = 0x32 (8) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (8) post-proxy { (8) eap : No pre-existing handler found (8) [eap] = noop (8) } # post-proxy = noop (8) Using Post-Auth-Type Reject (8) # Executing group from file /etc/raddb/sites-enabled/default (8) Post-Auth-Type REJECT { (8) sql : EXPAND .query (8) sql : --> .query (8) sql : Using query template 'query' rlm_sql (sql): Reserved connection (9) (8) sql : EXPAND %{User-Name} (8) sql : --> user(a)example.com (8) sql : SQL-User-Name set to 'user(a)example.com' (8) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (8) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:49:19') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:49:19')' rlm_sql (sql): Released connection (9) rlm_sql (sql): 0 of 3 connections in use. Need more spares rlm_sql (sql): Opening additional connection (10) rlm_sql_mysql: Starting connect to MySQL server (8) [sql] = ok (8) attr_filter.access_reject : EXPAND %{User-Name} (8) attr_filter.access_reject : --> user(a)example.com (8) attr_filter.access_reject : Matched entry DEFAULT at line 11 (8) [attr_filter.access_reject] = updated (8) eap : Request was previously rejected, inserting EAP-Failure (8) [eap] = updated (8) remove_reply_message_if_eap remove_reply_message_if_eap { (8) if (&reply:EAP-Message && &reply:Reply-Message) (8) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (8) else else { (8) [noop] = noop (8) } # else else = noop (8) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (8) } # Post-Auth-Type REJECT = updated (8) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (8) Sending delayed response (8) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (8) EAP-Message = 0x04000004 (8) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04000004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (9) Cleaning up request packet ID 41 with timestamp +214 Waking up in 0.9 seconds. (8) Cleaning up request packet ID 2 with timestamp +214 Ready to process requests Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145 User-Name = 'user(a)example.com' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0 (10) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145 (10) User-Name = 'user(a)example.com' (10) NAS-IP-Address = 10.250.8.180 (10) Called-Station-Id = 'c8d71992a9d7' (10) Calling-Station-Id = '00c01732012e' (10) NAS-Identifier = 'c8d71992a9d7' (10) NAS-Port = 29 (10) Framed-MTU = 1400 (10) NAS-Port-Type = Wireless-802.11 (10) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (10) Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0 (10) # Executing section authorize from file /etc/raddb/sites-enabled/default (10) authorize { (10) filter_username filter_username { (10) if (!&User-Name) (10) if (!&User-Name) -> FALSE (10) if (&User-Name =~ / /) (10) if (&User-Name =~ / /) -> FALSE (10) if (&User-Name =~ /@.*@/ ) (10) if (&User-Name =~ /@.*@/ ) -> FALSE (10) if (&User-Name =~ /\\.\\./ ) (10) if (&User-Name =~ /\\.\\./ ) -> FALSE (10) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (10) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (10) if (&User-Name =~ /\\.$/) (10) if (&User-Name =~ /\\.$/) -> FALSE (10) if (&User-Name =~ /(a)\\./) (10) if (&User-Name =~ /(a)\\./) -> FALSE (10) } # filter_username filter_username = notfound (10) [preprocess] = ok (10) [chap] = noop (10) [mschap] = noop (10) [digest] = noop (10) suffix : Checking for suffix after "@" (10) suffix : Looking up realm "example.com" for User-Name = "user(a)example.com" (10) suffix : Found realm "example.com" (10) suffix : Adding Stripped-User-Name = "user" (10) suffix : Adding Realm = "example.com" (10) suffix : Proxying request from user user to realm example.com (10) suffix : Preparing to proxy authentication request to realm "example.com" (10) [suffix] = updated (10) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP. (10) [eap] = noop (10) [files] = noop (10) sql : EXPAND %{User-Name} (10) sql : --> user(a)example.com (10) sql : SQL-User-Name set to 'user(a)example.com' rlm_sql (sql): Reserved connection (10) (10) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (10) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user(a)example.com' ORDER BY id' (10) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (10) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user(a)example.com' ORDER BY priority' (10) sql : User not found in any groups rlm_sql (sql): Released connection (10) rlm_sql (sql): Closing connection (9): Hit idle_timeout, was idle for 62 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (8): Hit idle_timeout, was idle for 63 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (7): Hit idle_timeout, was idle for 70 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket (10) [sql] = notfound (10) [expiration] = noop (10) [logintime] = noop (10) [pap] = noop (10) } # authorize = updated (10) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000 (10) Sending Access-Request packet to host 127.0.0.1 port 1812, id=200, length=0 (10) User-Name = 'user' (10) NAS-IP-Address = 10.250.8.180 (10) Called-Station-Id = 'c8d71992a9d7' (10) Calling-Station-Id = '00c01732012e' (10) NAS-Identifier = 'c8d71992a9d7' (10) NAS-Port = 29 (10) Framed-MTU = 1400 (10) NAS-Port-Type = Wireless-802.11 (10) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (10) Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0 (10) Event-Timestamp = 'Jul 7 2015 10:50:22 MDT' (10) Stripped-User-Name = 'user' (10) Realm = 'example.com' (10) EAP-Type = Identity (10) Proxy-State = 0x32 Sending Access-Request Id 200 from 0.0.0.0:36256 to 127.0.0.1:1812 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0 Event-Timestamp = 'Jul 7 2015 10:50:22 MDT' Proxy-State = 0x32 Waking up in 0.3 seconds. Received Access-Request Id 200 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142 User-Name = 'user' NAS-IP-Address = 10.250.8.180 Called-Station-Id = 'c8d71992a9d7' Calling-Station-Id = '00c01732012e' NAS-Identifier = 'c8d71992a9d7' NAS-Port = 29 Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020100150175736572406578616d706c652e636f6d Message-Authenticator = 0x1cc629a26c42673ec8925d9b46a9cdad Event-Timestamp = 'Jul 7 2015 10:50:22 MDT' Proxy-State = 0x32 (11) Received Access-Request packet from host 127.0.0.1 port 36256, id=200, length=142 (11) User-Name = 'user' (11) NAS-IP-Address = 10.250.8.180 (11) Called-Station-Id = 'c8d71992a9d7' (11) Calling-Station-Id = '00c01732012e' (11) NAS-Identifier = 'c8d71992a9d7' (11) NAS-Port = 29 (11) Framed-MTU = 1400 (11) NAS-Port-Type = Wireless-802.11 (11) EAP-Message = 0x020100150175736572406578616d706c652e636f6d (11) Message-Authenticator = 0x1cc629a26c42673ec8925d9b46a9cdad (11) Event-Timestamp = 'Jul 7 2015 10:50:22 MDT' (11) Proxy-State = 0x32 (11) # Executing section authorize from file /etc/raddb/sites-enabled/default (11) authorize { (11) filter_username filter_username { (11) if (!&User-Name) (11) if (!&User-Name) -> FALSE (11) if (&User-Name =~ / /) (11) if (&User-Name =~ / /) -> FALSE (11) if (&User-Name =~ /@.*@/ ) (11) if (&User-Name =~ /@.*@/ ) -> FALSE (11) if (&User-Name =~ /\\.\\./ ) (11) if (&User-Name =~ /\\.\\./ ) -> FALSE (11) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) (11) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (11) if (&User-Name =~ /\\.$/) (11) if (&User-Name =~ /\\.$/) -> FALSE (11) if (&User-Name =~ /(a)\\./) (11) if (&User-Name =~ /(a)\\./) -> FALSE (11) } # filter_username filter_username = notfound (11) [preprocess] = ok (11) [chap] = noop (11) [mschap] = noop (11) [digest] = noop (11) suffix : Checking for suffix after "@" (11) suffix : No '@' in User-Name = "user", looking up realm NULL (11) suffix : No such realm "NULL" (11) [suffix] = noop (11) eap : Peer sent code Response (2) ID 1 length 21 (11) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (11) [eap] = ok (11) } # authorize = ok (11) Found Auth-Type = EAP (11) # Executing group from file /etc/raddb/sites-enabled/default (11) authenticate { (11) eap : Identity does not match User-Name, setting from EAP Identity (11) eap : Failed in handler (11) [eap] = invalid (11) } # authenticate = invalid (11) Failed to authenticate the user (11) Using Post-Auth-Type Reject (11) # Executing group from file /etc/raddb/sites-enabled/default (11) Post-Auth-Type REJECT { (11) sql : EXPAND .query (11) sql : --> .query (11) sql : Using query template 'query' rlm_sql (sql): Reserved connection (10) (11) sql : EXPAND %{User-Name} (11) sql : --> user (11) sql : SQL-User-Name set to 'user' (11) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (11) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:50:22') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:50:22')' rlm_sql (sql): Released connection (10) (11) [sql] = ok (11) attr_filter.access_reject : EXPAND %{User-Name} (11) attr_filter.access_reject : --> user (11) attr_filter.access_reject : Matched entry DEFAULT at line 11 (11) [attr_filter.access_reject] = updated (11) eap : Identity does not match User-Name, setting from EAP Identity (11) eap : Failed to get handler, probably already removed, not inserting EAP-Failure (11) [eap] = noop (11) remove_reply_message_if_eap remove_reply_message_if_eap { (11) if (&reply:EAP-Message && &reply:Reply-Message) (11) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (11) else else { (11) [noop] = noop (11) } # else else = noop (11) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (11) } # Post-Auth-Type REJECT = updated (11) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.1 seconds. (10) Expecting proxy response no later than 19.499789 seconds from now Waking up in 0.5 seconds. (11) Sending delayed response (11) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=200, length=0 (11) Proxy-State = 0x32 Sending Access-Reject Id 200 from 127.0.0.1:1812 to 127.0.0.1:36256 Proxy-State = 0x32 Waking up in 3.9 seconds. Received Access-Reject Id 200 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23 Proxy-State = 0x32 (10) Received Access-Reject packet from host 127.0.0.1 port 1812, id=200, length=23 (10) Proxy-State = 0x32 (10) # Executing section post-proxy from file /etc/raddb/sites-enabled/default (10) post-proxy { (10) eap : No pre-existing handler found (10) [eap] = noop (10) } # post-proxy = noop (10) Using Post-Auth-Type Reject (10) # Executing group from file /etc/raddb/sites-enabled/default (10) Post-Auth-Type REJECT { (10) sql : EXPAND .query (10) sql : --> .query (10) sql : Using query template 'query' rlm_sql (sql): Reserved connection (10) (10) sql : EXPAND %{User-Name} (10) sql : --> user(a)example.com (10) sql : SQL-User-Name set to 'user(a)example.com' (10) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (10) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:50:22') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user(a)example.com', '', 'Access-Reject', '2015-07-07 10:50:22')' rlm_sql (sql): Released connection (10) rlm_sql (sql): 0 of 1 connections in use. Need more spares rlm_sql (sql): Opening additional connection (11) rlm_sql_mysql: Starting connect to MySQL server (10) [sql] = ok (10) attr_filter.access_reject : EXPAND %{User-Name} (10) attr_filter.access_reject : --> user(a)example.com (10) attr_filter.access_reject : Matched entry DEFAULT at line 11 (10) [attr_filter.access_reject] = updated (10) eap : Request was previously rejected, inserting EAP-Failure (10) [eap] = updated (10) remove_reply_message_if_eap remove_reply_message_if_eap { (10) if (&reply:EAP-Message && &reply:Reply-Message) (10) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (10) else else { (10) [noop] = noop (10) } # else else = noop (10) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop (10) } # Post-Auth-Type REJECT = updated (10) Delaying response for 1 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (10) Sending delayed response (10) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0 (10) EAP-Message = 0x04010004 (10) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695 EAP-Message = 0x04010004 Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 2.9 seconds. (11) Cleaning up request packet ID 200 with timestamp +277 Waking up in 0.9 seconds. (10) Cleaning up request packet ID 2 with timestamp +277 Ready to process requests

3 3

FR3 and MySQL
by Andrés Gómez 07 Jul '15

07 Jul '15

Hi everybody!! Today I'm testing FR3 in order to migrate some simple FR2 servers. In old servers is running a simple configuration usng mysql to match username/password with a simple web auth (captive portal). I installed FR3, then I actived sql mod: cd mods-enabled ln -s ../mods-available/sql then I configured the sql connection: sql { driver = "rlm_sql_mysql" server = "localhost" port = 3306 login = "MYUSER" password = "MYPASSWORD" radius_db = "radius" acct_table1 = "radacct" acct_table2 = "radacct" postauth_table = "radpostauth" authcheck_table = "radcheck" groupcheck_table = "radgroupcheck" authreply_table = "radreply" groupreply_table = "radgroupreply" usergroup_table = "radusergroup" delete_stale_sessions = yes ... } I'm using the same schema that I used to use in FR2. I created and user in radcheck table, and It works, but I cant write accounting data. There is this error: Tue Jul 7 07:23:06 2015 : Auth: (0) Login OK: [andres/andres] (from client todos port 0) Tue Jul 7 07:23:06 2015 : Error: rlm_sql (sql): Unknown column 'username' in 'field list' Tue Jul 7 07:23:06 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:06 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'username' in 'field list'' Tue Jul 7 07:23:27 2015 : Error: rlm_sql (sql): Unknown column 'acctupdatetime' in 'field list' Tue Jul 7 07:23:27 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:27 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'acctupdatetime' in 'field list'' Tue Jul 7 07:23:27 2015 : Error: rlm_sql (sql): Unknown column 'acctupdatetime' in 'field list' Tue Jul 7 07:23:27 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:27 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'acctupdatetime' in 'field list'' Tue Jul 7 07:23:41 2015 : Error: rlm_sql (sql): Unknown column 'acctupdatetime' in 'field list' Tue Jul 7 07:23:41 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:41 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'acctupdatetime' in 'field list'' Tue Jul 7 07:23:41 2015 : Error: rlm_sql (sql): Unknown column 'acctupdatetime' in 'field list' Tue Jul 7 07:23:41 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:41 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'acctupdatetime' in 'field list'' Tue Jul 7 07:23:41 2015 : Info: rlm_sql (sql): Closing connection (0), from 1 unused connections Tue Jul 7 07:23:47 2015 : Error: rlm_sql (sql): Unknown column 'acctupdatetime' in 'field list' Tue Jul 7 07:23:47 2015 : Error: rlm_sql_mysql: Cannot store result Tue Jul 7 07:23:47 2015 : Error: rlm_sql_mysql: MySQL error 'Unknown column 'acctupdatetime' in 'field list'' What am I missing? Thanks a lot!! -- *C. Andrés Gómez R.*

3 3

v3.0.8: Failure message does not appear in radius.log
by Lai Fu Keung 07 Jul '15

07 Jul '15

Hi, I am using v3.0.8 for EAP-PEAP-MSCHAPv2 authentication. Login with correct username/password is fine. But for login with incorrect username or password, the failure message "mschap: ERROR: MS-CHAP2-Response is incorrect" does not appear in the final radius.log. I only get this: Login incorrect: [mytest] while I was expecting this: Login incorrect (mschap: MS-CHAP2-Response is incorrect): [mytest] Module-Failure-Message is empty too when I try to do linelog in Post-Auth-Reject. What have I missed in the configration? Debug log follows. I can upload inner-tunnel config. if required. Thanks in advance. Fu (0) Received Access-Request Id 36 from 10.210.123.29:3629 to 10.210.235.64:1812 length 208 (0) User-Name = 'mytest' (0) Framed-MTU = 1450 (0) EAP-Message = 0x0201000b016d7974657374 (0) Message-Authenticator = 0x5ef5fbebae79922073ab55353f8aaa59 (0) Chargeable-User-Identity = 0x00 (0) NAS-IP-Address = 10.210.123.29 (0) NAS-Identifier = 'ITS-TEST' (0) NAS-Port = 33779942 (0) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (0) NAS-Port-Type = Wireless-802.11 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) Calling-Station-Id = '10-1C-0C-79-26-49' (0) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (0) Acct-Session-Id = '11505301634460' (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (0) authorize { (0) policy filter_username { (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) { (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\\.\\./ ) { (0) if (&User-Name =~ /\\.\\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\\.$/) { (0) if (&User-Name =~ /\\.$/) -> FALSE (0) if (&User-Name =~ /(a)\\./) { (0) if (&User-Name =~ /(a)\\./) -> FALSE (0) } # policy filter_username = notfound (0) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (0) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (0) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (0) auth_log: EXPAND %t (0) auth_log: --> Tue Jun 30 16:38:41 2015 (0) [auth_log] = ok (0) [mschap] = noop (0) suffix: Checking for suffix after "@" (0) suffix: No '@' in User-Name = "mytest", looking up realm NULL (0) suffix: Found realm "NULL" (0) suffix: Adding Stripped-User-Name = "mytest" (0) suffix: Adding Realm = "NULL" (0) suffix: Authentication realm is LOCAL (0) [suffix] = ok (0) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (0) EXPAND %{Aruba-Essid-Name} (0) --> (0) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (0) eap: Peer sent code Response (2) ID 1 length 11 (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (0) [eap] = ok (0) } # authorize = ok (0) Found Auth-Type = EAP (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) authenticate { (0) eap: Peer sent method Identity (1) (0) eap: Calling eap_peap to process EAP data (0) eap_peap: Flushing SSL sessions (of #0) (0) eap_peap: Initiate (0) eap_peap: Start returned 1 (0) eap: EAP session adding &reply:State = 0xb8002a16b8023321 (0) [eap] = handled (0) } # authenticate = handled (0) Using Post-Auth-Type Challenge (0) Post-Auth-Type sub-section not found. Ignoring. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Sent Access-Challenge Id 36 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (0) EAP-Message = 0x010200061920 (0) Message-Authenticator = 0x00000000000000000000000000000000 (0) State = 0xb8002a16b802332133d295a612409a37 (0) Finished request Waking up in 4.9 seconds. (1) Received Access-Request Id 37 from 10.210.123.29:3629 to 10.210.235.64:1812 length 367 (1) User-Name = 'mytest' (1) Framed-MTU = 1450 (1) EAP-Message = 0x0202009819800000008e1603010089010000850301559255b2a9f020b42bfb6e9e57951f914de87bceaf3b356c31516db4eadf4c6200004a00ffc024c023c00ac009c008c028c027c014c013c012c026c025c005c004c003c02ac029c00fc00ec00d006b0067003900330016003d003c0035002f000ac0 (1) Message-Authenticator = 0x42a035744890fef59847539df9854c9f (1) Chargeable-User-Identity = 0x00 (1) NAS-IP-Address = 10.210.123.29 (1) NAS-Identifier = 'ITS-TEST' (1) NAS-Port = 33779942 (1) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (1) NAS-Port-Type = Wireless-802.11 (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) Calling-Station-Id = '10-1C-0C-79-26-49' (1) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (1) Acct-Session-Id = '11505301634460' (1) State = 0xb8002a16b802332133d295a612409a37 (1) session-state: No cached attributes (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (1) authorize { (1) policy filter_username { (1) if (&User-Name =~ / /) { (1) if (&User-Name =~ / /) -> FALSE (1) if (&User-Name =~ /@.*@/ ) { (1) if (&User-Name =~ /@.*@/ ) -> FALSE (1) if (&User-Name =~ /\\.\\./ ) { (1) if (&User-Name =~ /\\.\\./ ) -> FALSE (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (1) if (&User-Name =~ /\\.$/) { (1) if (&User-Name =~ /\\.$/) -> FALSE (1) if (&User-Name =~ /(a)\\./) { (1) if (&User-Name =~ /(a)\\./) -> FALSE (1) } # policy filter_username = notfound (1) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (1) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (1) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (1) auth_log: EXPAND %t (1) auth_log: --> Tue Jun 30 16:38:41 2015 (1) [auth_log] = ok (1) [mschap] = noop (1) suffix: Checking for suffix after "@" (1) suffix: No '@' in User-Name = "mytest", looking up realm NULL (1) suffix: Found realm "NULL" (1) suffix: Adding Stripped-User-Name = "mytest" (1) suffix: Adding Realm = "NULL" (1) suffix: Authentication realm is LOCAL (1) [suffix] = ok (1) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (1) EXPAND %{Aruba-Essid-Name} (1) --> (1) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (1) eap: Peer sent code Response (2) ID 2 length 152 (1) eap: Continuing tunnel setup (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = EAP (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) authenticate { (1) eap: Expiring EAP session with state 0xb8002a16b8023321 (1) eap: Finished EAP session with state 0xb8002a16b8023321 (1) eap: Previous EAP request found for state 0xb8002a16b8023321, released from the list (1) eap: Peer sent method PEAP (25) (1) eap: EAP PEAP (25) (1) eap: Calling eap_peap to process EAP data (1) eap_peap: processing EAP-TLS (1) eap_peap: TLS Length 142 (1) eap_peap: Length Included (1) eap_peap: eaptls_verify returned 11 (1) eap_peap: (other): before/accept initialization (1) eap_peap: TLS_accept: before/accept initialization (1) eap_peap: <<< TLS 1.0 Handshake [length 0089], ClientHello (1) eap_peap: TLS_accept: SSLv3 read client hello A (1) eap_peap: >>> TLS 1.0 Handshake [length 0059], ServerHello (1) eap_peap: TLS_accept: SSLv3 write server hello A (1) eap_peap: >>> TLS 1.0 Handshake [length 0cb2], Certificate (1) eap_peap: TLS_accept: SSLv3 write certificate A (1) eap_peap: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange (1) eap_peap: TLS_accept: SSLv3 write key exchange A (1) eap_peap: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone (1) eap_peap: TLS_accept: SSLv3 write server done A (1) eap_peap: TLS_accept: SSLv3 flush data (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A (1) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A In SSL Handshake Phase In SSL Accept mode (1) eap_peap: eaptls_process returned 13 (1) eap_peap: FR_TLS_HANDLED (1) eap: EAP session adding &reply:State = 0xb8002a16b9033321 (1) [eap] = handled (1) } # authenticate = handled (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) Sent Access-Challenge Id 37 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (1) EAP-Message = 0x010303ec19c000000e6e160301005902000055030155925591c68e2c1bcc1799abb16c902a30a09565eff0e27d68ab22a7e10b0fde20ebdaba7f9ed922848678bdc00894241de12ab724eb6c292dc8076e90cbe463e7c01400000dff01000100000b0004030001021603010cb20b000cae000cab00054c (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0xb8002a16b903332133d295a612409a37 (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 38 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (2) User-Name = 'mytest' (2) Framed-MTU = 1450 (2) EAP-Message = 0x020300061900 (2) Message-Authenticator = 0x8ae28f5ddd086665c5f0f0cf4328e5b3 (2) Chargeable-User-Identity = 0x00 (2) NAS-IP-Address = 10.210.123.29 (2) NAS-Identifier = 'ITS-TEST' (2) NAS-Port = 33779942 (2) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (2) NAS-Port-Type = Wireless-802.11 (2) Service-Type = Framed-User (2) Framed-Protocol = PPP (2) Calling-Station-Id = '10-1C-0C-79-26-49' (2) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (2) Acct-Session-Id = '11505301634460' (2) State = 0xb8002a16b903332133d295a612409a37 (2) session-state: No cached attributes (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (2) authorize { (2) policy filter_username { (2) if (&User-Name =~ / /) { (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@.*@/ ) { (2) if (&User-Name =~ /@.*@/ ) -> FALSE (2) if (&User-Name =~ /\\.\\./ ) { (2) if (&User-Name =~ /\\.\\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\\.$/) { (2) if (&User-Name =~ /\\.$/) -> FALSE (2) if (&User-Name =~ /(a)\\./) { (2) if (&User-Name =~ /(a)\\./) -> FALSE (2) } # policy filter_username = notfound (2) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (2) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (2) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (2) auth_log: EXPAND %t (2) auth_log: --> Tue Jun 30 16:38:41 2015 (2) [auth_log] = ok (2) [mschap] = noop (2) suffix: Checking for suffix after "@" (2) suffix: No '@' in User-Name = "mytest", looking up realm NULL (2) suffix: Found realm "NULL" (2) suffix: Adding Stripped-User-Name = "mytest" (2) suffix: Adding Realm = "NULL" (2) suffix: Authentication realm is LOCAL (2) [suffix] = ok (2) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (2) EXPAND %{Aruba-Essid-Name} (2) --> (2) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (2) eap: Peer sent code Response (2) ID 3 length 6 (2) eap: Continuing tunnel setup (2) [eap] = ok (2) } # authorize = ok (2) Found Auth-Type = EAP (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) authenticate { (2) eap: Expiring EAP session with state 0xb8002a16b9033321 (2) eap: Finished EAP session with state 0xb8002a16b9033321 (2) eap: Previous EAP request found for state 0xb8002a16b9033321, released from the list (2) eap: Peer sent method PEAP (25) (2) eap: EAP PEAP (25) (2) eap: Calling eap_peap to process EAP data (2) eap_peap: processing EAP-TLS (2) eap_peap: Received TLS ACK (2) eap_peap: Received TLS ACK (2) eap_peap: ACK handshake fragment handler (2) eap_peap: eaptls_verify returned 1 (2) eap_peap: eaptls_process returned 13 (2) eap_peap: FR_TLS_HANDLED (2) eap: EAP session adding &reply:State = 0xb8002a16ba043321 (2) [eap] = handled (2) } # authenticate = handled (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) Sent Access-Challenge Id 38 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (2) EAP-Message = 0x010403e8194006082b0601050507010104693067302c06082b060105050730018620687474703a2f2f677473736c64762d6f6373702e67656f74727573742e636f6d303706082b06010505073002862b687474703a2f2f677473736c64762d6169612e67656f74727573742e636f6d2f677473736c6476 (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0xb8002a16ba04332133d295a612409a37 (2) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 39 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (3) User-Name = 'mytest' (3) Framed-MTU = 1450 (3) EAP-Message = 0x020400061900 (3) Message-Authenticator = 0x08de5c8d37eff88ee339c2447c43e240 (3) Chargeable-User-Identity = 0x00 (3) NAS-IP-Address = 10.210.123.29 (3) NAS-Identifier = 'ITS-TEST' (3) NAS-Port = 33779942 (3) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (3) NAS-Port-Type = Wireless-802.11 (3) Service-Type = Framed-User (3) Framed-Protocol = PPP (3) Calling-Station-Id = '10-1C-0C-79-26-49' (3) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (3) Acct-Session-Id = '11505301634460' (3) State = 0xb8002a16ba04332133d295a612409a37 (3) session-state: No cached attributes (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (3) authorize { (3) policy filter_username { (3) if (&User-Name =~ / /) { (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@.*@/ ) { (3) if (&User-Name =~ /@.*@/ ) -> FALSE (3) if (&User-Name =~ /\\.\\./ ) { (3) if (&User-Name =~ /\\.\\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\\.$/) { (3) if (&User-Name =~ /\\.$/) -> FALSE (3) if (&User-Name =~ /(a)\\./) { (3) if (&User-Name =~ /(a)\\./) -> FALSE (3) } # policy filter_username = notfound (3) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (3) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (3) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (3) auth_log: EXPAND %t (3) auth_log: --> Tue Jun 30 16:38:41 2015 (3) [auth_log] = ok (3) [mschap] = noop (3) suffix: Checking for suffix after "@" (3) suffix: No '@' in User-Name = "mytest", looking up realm NULL (3) suffix: Found realm "NULL" (3) suffix: Adding Stripped-User-Name = "mytest" (3) suffix: Adding Realm = "NULL" (3) suffix: Authentication realm is LOCAL (3) [suffix] = ok (3) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (3) EXPAND %{Aruba-Essid-Name} (3) --> (3) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (3) eap: Peer sent code Response (2) ID 4 length 6 (3) eap: Continuing tunnel setup (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = EAP (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) authenticate { (3) eap: Expiring EAP session with state 0xb8002a16ba043321 (3) eap: Finished EAP session with state 0xb8002a16ba043321 (3) eap: Previous EAP request found for state 0xb8002a16ba043321, released from the list (3) eap: Peer sent method PEAP (25) (3) eap: EAP PEAP (25) (3) eap: Calling eap_peap to process EAP data (3) eap_peap: processing EAP-TLS (3) eap_peap: Received TLS ACK (3) eap_peap: Received TLS ACK (3) eap_peap: ACK handshake fragment handler (3) eap_peap: eaptls_verify returned 1 (3) eap_peap: eaptls_process returned 13 (3) eap_peap: FR_TLS_HANDLED (3) eap: EAP session adding &reply:State = 0xb8002a16bb053321 (3) [eap] = handled (3) } # authenticate = handled (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) Sent Access-Challenge Id 39 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (3) EAP-Message = 0x010503e81940150203010001a381d93081d6300e0603551d0f0101ff040403020106301d0603551d0e041604148cf4d9930a47bc00a04ace4b756ea0b6b0b27efc301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e30120603551d130101ff040830060101ff02010030 (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0xb8002a16bb05332133d295a612409a37 (3) Finished request Waking up in 4.9 seconds. (4) Received Access-Request Id 40 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (4) User-Name = 'mytest' (4) Framed-MTU = 1450 (4) EAP-Message = 0x020500061900 (4) Message-Authenticator = 0xda837ef88f7b38871aaead005e3a54b0 (4) Chargeable-User-Identity = 0x00 (4) NAS-IP-Address = 10.210.123.29 (4) NAS-Identifier = 'ITS-TEST' (4) NAS-Port = 33779942 (4) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (4) NAS-Port-Type = Wireless-802.11 (4) Service-Type = Framed-User (4) Framed-Protocol = PPP (4) Calling-Station-Id = '10-1C-0C-79-26-49' (4) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (4) Acct-Session-Id = '11505301634460' (4) State = 0xb8002a16bb05332133d295a612409a37 (4) session-state: No cached attributes (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (4) authorize { (4) policy filter_username { (4) if (&User-Name =~ / /) { (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@.*@/ ) { (4) if (&User-Name =~ /@.*@/ ) -> FALSE (4) if (&User-Name =~ /\\.\\./ ) { (4) if (&User-Name =~ /\\.\\./ ) -> FALSE (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (4) if (&User-Name =~ /\\.$/) { (4) if (&User-Name =~ /\\.$/) -> FALSE (4) if (&User-Name =~ /(a)\\./) { (4) if (&User-Name =~ /(a)\\./) -> FALSE (4) } # policy filter_username = notfound (4) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (4) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (4) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (4) auth_log: EXPAND %t (4) auth_log: --> Tue Jun 30 16:38:41 2015 (4) [auth_log] = ok (4) [mschap] = noop (4) suffix: Checking for suffix after "@" (4) suffix: No '@' in User-Name = "mytest", looking up realm NULL (4) suffix: Found realm "NULL" (4) suffix: Adding Stripped-User-Name = "mytest" (4) suffix: Adding Realm = "NULL" (4) suffix: Authentication realm is LOCAL (4) [suffix] = ok (4) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (4) EXPAND %{Aruba-Essid-Name} (4) --> (4) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (4) eap: Peer sent code Response (2) ID 5 length 6 (4) eap: Continuing tunnel setup (4) [eap] = ok (4) } # authorize = ok (4) Found Auth-Type = EAP (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) authenticate { (4) eap: Expiring EAP session with state 0xb8002a16bb053321 (4) eap: Finished EAP session with state 0xb8002a16bb053321 (4) eap: Previous EAP request found for state 0xb8002a16bb053321, released from the list (4) eap: Peer sent method PEAP (25) (4) eap: EAP PEAP (25) (4) eap: Calling eap_peap to process EAP data (4) eap_peap: processing EAP-TLS (4) eap_peap: Received TLS ACK (4) eap_peap: Received TLS ACK (4) eap_peap: ACK handshake fragment handler (4) eap_peap: eaptls_verify returned 1 (4) eap_peap: eaptls_process returned 13 (4) eap_peap: FR_TLS_HANDLED (4) eap: EAP session adding &reply:State = 0xb8002a16bc063321 (4) [eap] = handled (4) } # authenticate = handled (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) Sent Access-Challenge Id 40 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (4) EAP-Message = 0x010602ce1900f90203010001a3533051300f0603551d130101ff040530030101ff301d0603551d0e04160414c07a98688d89fbab05640c117daa7d65b8cacc4e301f0603551d23041830168014c07a98688d89fbab05640c117daa7d65b8cacc4e300d06092a864886f70d0101050500038201010035e3 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0xb8002a16bc06332133d295a612409a37 (4) Finished request Waking up in 4.9 seconds. (5) Received Access-Request Id 41 from 10.210.123.29:3629 to 10.210.235.64:1812 length 359 (5) User-Name = 'mytest' (5) Framed-MTU = 1450 (5) EAP-Message = 0x020600901980000000861603010046100000424104daab08aafa18f5c2c9eb22fc1604897509e5a299ef0ebe092b4a69330d014b443560a4ceea8642f5be01212032dc50db73a8f82362675d08f5ea12ac7ac7b60b14030100010116030100307ffbf690c0dac1e79a7f7d24c5477d4a12aa6d0e99221a (5) Message-Authenticator = 0x1d2150a6f034a5dc3b195884d34e474d (5) Chargeable-User-Identity = 0x00 (5) NAS-IP-Address = 10.210.123.29 (5) NAS-Identifier = 'ITS-TEST' (5) NAS-Port = 33779942 (5) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (5) NAS-Port-Type = Wireless-802.11 (5) Service-Type = Framed-User (5) Framed-Protocol = PPP (5) Calling-Station-Id = '10-1C-0C-79-26-49' (5) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (5) Acct-Session-Id = '11505301634460' (5) State = 0xb8002a16bc06332133d295a612409a37 (5) session-state: No cached attributes (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (5) authorize { (5) policy filter_username { (5) if (&User-Name =~ / /) { (5) if (&User-Name =~ / /) -> FALSE (5) if (&User-Name =~ /@.*@/ ) { (5) if (&User-Name =~ /@.*@/ ) -> FALSE (5) if (&User-Name =~ /\\.\\./ ) { (5) if (&User-Name =~ /\\.\\./ ) -> FALSE (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (5) if (&User-Name =~ /\\.$/) { (5) if (&User-Name =~ /\\.$/) -> FALSE (5) if (&User-Name =~ /(a)\\./) { (5) if (&User-Name =~ /(a)\\./) -> FALSE (5) } # policy filter_username = notfound (5) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (5) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (5) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (5) auth_log: EXPAND %t (5) auth_log: --> Tue Jun 30 16:38:41 2015 (5) [auth_log] = ok (5) [mschap] = noop (5) suffix: Checking for suffix after "@" (5) suffix: No '@' in User-Name = "mytest", looking up realm NULL (5) suffix: Found realm "NULL" (5) suffix: Adding Stripped-User-Name = "mytest" (5) suffix: Adding Realm = "NULL" (5) suffix: Authentication realm is LOCAL (5) [suffix] = ok (5) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (5) EXPAND %{Aruba-Essid-Name} (5) --> (5) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (5) eap: Peer sent code Response (2) ID 6 length 144 (5) eap: Continuing tunnel setup (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = EAP (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) authenticate { (5) eap: Expiring EAP session with state 0xb8002a16bc063321 (5) eap: Finished EAP session with state 0xb8002a16bc063321 (5) eap: Previous EAP request found for state 0xb8002a16bc063321, released from the list (5) eap: Peer sent method PEAP (25) (5) eap: EAP PEAP (25) (5) eap: Calling eap_peap to process EAP data (5) eap_peap: processing EAP-TLS (5) eap_peap: TLS Length 134 (5) eap_peap: Length Included (5) eap_peap: eaptls_verify returned 11 (5) eap_peap: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange (5) eap_peap: TLS_accept: SSLv3 read client key exchange A (5) eap_peap: <<< TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_peap: <<< TLS 1.0 Handshake [length 0010], Finished (5) eap_peap: TLS_accept: SSLv3 read finished A (5) eap_peap: >>> TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_peap: TLS_accept: SSLv3 write change cipher spec A (5) eap_peap: >>> TLS 1.0 Handshake [length 0010], Finished (5) eap_peap: TLS_accept: SSLv3 write finished A (5) eap_peap: TLS_accept: SSLv3 flush data TLS: adding session ebdaba7f9ed922848678bdc00894241de12ab724eb6c292dc8076e90cbe463e7 to cache (5) eap_peap: (other): SSL negotiation finished successfully SSL Connection Established (5) eap_peap: eaptls_process returned 13 (5) eap_peap: FR_TLS_HANDLED (5) eap: EAP session adding &reply:State = 0xb8002a16bd073321 (5) [eap] = handled (5) } # authenticate = handled (5) Using Post-Auth-Type Challenge (5) Post-Auth-Type sub-section not found. Ignoring. (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) Sent Access-Challenge Id 41 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (5) EAP-Message = 0x0107004119001403010001011603010030cf354b5e12d99508901f44db8ea05526d42a5f671f1ceb081722b1fec033c99b05ebe23bde2c546223aebc064a1e4eea (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) State = 0xb8002a16bd07332133d295a612409a37 (5) Finished request Waking up in 4.8 seconds. (6) Received Access-Request Id 42 from 10.210.123.29:3629 to 10.210.235.64:1812 length 221 (6) User-Name = 'mytest' (6) Framed-MTU = 1450 (6) EAP-Message = 0x020700061900 (6) Message-Authenticator = 0x03b7e4a2a231036e9283d475a4caa3ec (6) Chargeable-User-Identity = 0x00 (6) NAS-IP-Address = 10.210.123.29 (6) NAS-Identifier = 'ITS-TEST' (6) NAS-Port = 33779942 (6) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (6) NAS-Port-Type = Wireless-802.11 (6) Service-Type = Framed-User (6) Framed-Protocol = PPP (6) Calling-Station-Id = '10-1C-0C-79-26-49' (6) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (6) Acct-Session-Id = '11505301634460' (6) State = 0xb8002a16bd07332133d295a612409a37 (6) session-state: No cached attributes (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (6) authorize { (6) policy filter_username { (6) if (&User-Name =~ / /) { (6) if (&User-Name =~ / /) -> FALSE (6) if (&User-Name =~ /@.*@/ ) { (6) if (&User-Name =~ /@.*@/ ) -> FALSE (6) if (&User-Name =~ /\\.\\./ ) { (6) if (&User-Name =~ /\\.\\./ ) -> FALSE (6) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (6) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (6) if (&User-Name =~ /\\.$/) { (6) if (&User-Name =~ /\\.$/) -> FALSE (6) if (&User-Name =~ /(a)\\./) { (6) if (&User-Name =~ /(a)\\./) -> FALSE (6) } # policy filter_username = notfound (6) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (6) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (6) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (6) auth_log: EXPAND %t (6) auth_log: --> Tue Jun 30 16:38:41 2015 (6) [auth_log] = ok (6) [mschap] = noop (6) suffix: Checking for suffix after "@" (6) suffix: No '@' in User-Name = "mytest", looking up realm NULL (6) suffix: Found realm "NULL" (6) suffix: Adding Stripped-User-Name = "mytest" (6) suffix: Adding Realm = "NULL" (6) suffix: Authentication realm is LOCAL (6) [suffix] = ok (6) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (6) EXPAND %{Aruba-Essid-Name} (6) --> (6) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (6) eap: Peer sent code Response (2) ID 7 length 6 (6) eap: Continuing tunnel setup (6) [eap] = ok (6) } # authorize = ok (6) Found Auth-Type = EAP (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) authenticate { (6) eap: Expiring EAP session with state 0xb8002a16bd073321 (6) eap: Finished EAP session with state 0xb8002a16bd073321 (6) eap: Previous EAP request found for state 0xb8002a16bd073321, released from the list (6) eap: Peer sent method PEAP (25) (6) eap: EAP PEAP (25) (6) eap: Calling eap_peap to process EAP data (6) eap_peap: processing EAP-TLS (6) eap_peap: Received TLS ACK (6) eap_peap: Received TLS ACK (6) eap_peap: ACK handshake is finished (6) eap_peap: eaptls_verify returned 3 (6) eap_peap: eaptls_process returned 3 (6) eap_peap: FR_TLS_SUCCESS (6) eap_peap: Session established. Decoding tunneled attributes (6) eap_peap: PEAP state TUNNEL ESTABLISHED (6) eap: EAP session adding &reply:State = 0xb8002a16be083321 (6) [eap] = handled (6) } # authenticate = handled (6) Using Post-Auth-Type Challenge (6) Post-Auth-Type sub-section not found. Ignoring. (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) Sent Access-Challenge Id 42 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (6) EAP-Message = 0x0108002b19001703010020d965153eadcdfd834b3415bebe178548d5f749ba6d9a4c4b316b4d771f57223b (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0xb8002a16be08332133d295a612409a37 (6) Finished request Waking up in 4.8 seconds. (7) Received Access-Request Id 43 from 10.210.123.29:3629 to 10.210.235.64:1812 length 258 (7) User-Name = 'mytest' (7) Framed-MTU = 1450 (7) EAP-Message = 0x0208002b190017030100205ee29c7181f7daeab27186b96e313d25f613fbf75c9187c43dadb0eef059ef4c (7) Message-Authenticator = 0xcce60a3b273c10f259bd83bb13cb4939 (7) Chargeable-User-Identity = 0x00 (7) NAS-IP-Address = 10.210.123.29 (7) NAS-Identifier = 'ITS-TEST' (7) NAS-Port = 33779942 (7) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (7) NAS-Port-Type = Wireless-802.11 (7) Service-Type = Framed-User (7) Framed-Protocol = PPP (7) Calling-Station-Id = '10-1C-0C-79-26-49' (7) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (7) Acct-Session-Id = '11505301634460' (7) State = 0xb8002a16be08332133d295a612409a37 (7) session-state: No cached attributes (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (7) authorize { (7) policy filter_username { (7) if (&User-Name =~ / /) { (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) { (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\\.\\./ ) { (7) if (&User-Name =~ /\\.\\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\\.$/) { (7) if (&User-Name =~ /\\.$/) -> FALSE (7) if (&User-Name =~ /(a)\\./) { (7) if (&User-Name =~ /(a)\\./) -> FALSE (7) } # policy filter_username = notfound (7) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (7) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (7) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (7) auth_log: EXPAND %t (7) auth_log: --> Tue Jun 30 16:38:41 2015 (7) [auth_log] = ok (7) [mschap] = noop (7) suffix: Checking for suffix after "@" (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL (7) suffix: Found realm "NULL" (7) suffix: Adding Stripped-User-Name = "mytest" (7) suffix: Adding Realm = "NULL" (7) suffix: Authentication realm is LOCAL (7) [suffix] = ok (7) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (7) EXPAND %{Aruba-Essid-Name} (7) --> (7) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (7) eap: Peer sent code Response (2) ID 8 length 43 (7) eap: Continuing tunnel setup (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) authenticate { (7) eap: Expiring EAP session with state 0xb8002a16be083321 (7) eap: Finished EAP session with state 0xb8002a16be083321 (7) eap: Previous EAP request found for state 0xb8002a16be083321, released from the list (7) eap: Peer sent method PEAP (25) (7) eap: EAP PEAP (25) (7) eap: Calling eap_peap to process EAP data (7) eap_peap: processing EAP-TLS (7) eap_peap: eaptls_verify returned 7 (7) eap_peap: Done initial handshake (7) eap_peap: eaptls_process returned 7 (7) eap_peap: FR_TLS_OK (7) eap_peap: Session established. Decoding tunneled attributes (7) eap_peap: PEAP state WAITING FOR INNER IDENTITY (7) eap_peap: Identity - mytest (7) eap_peap: Got inner identity 'mytest' (7) eap_peap: Setting default EAP type for tunneled EAP session (7) eap_peap: Got tunneled request (7) eap_peap: EAP-Message = 0x0208000b016d7974657374 (7) eap_peap: Setting User-Name to mytest (7) eap_peap: Sending tunneled request to inner-tunnel (7) eap_peap: EAP-Message = 0x0208000b016d7974657374 (7) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (7) eap_peap: User-Name = 'mytest' (7) Virtual server inner-tunnel received request (7) EAP-Message = 0x0208000b016d7974657374 (7) FreeRADIUS-Proxied-To = 127.0.0.1 (7) User-Name = 'mytest' (7) server inner-tunnel { (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (7) authorize { (7) policy filter_username { (7) if (&User-Name =~ / /) { (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) { (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\\.\\./ ) { (7) if (&User-Name =~ /\\.\\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\\.$/) { (7) if (&User-Name =~ /\\.$/) -> FALSE (7) if (&User-Name =~ /(a)\\./) { (7) if (&User-Name =~ /(a)\\./) -> FALSE (7) } # policy filter_username = notfound (7) [mschap] = noop (7) suffix: Checking for suffix after "@" (7) suffix: No '@' in User-Name = "mytest", looking up realm NULL (7) suffix: Found realm "NULL" (7) suffix: Adding Stripped-User-Name = "mytest" (7) suffix: Adding Realm = "NULL" (7) suffix: Authentication realm is LOCAL (7) [suffix] = ok (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (7) EXPAND %{Realm} (7) --> NULL (7) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (7) else { (7) update control { (7) &Proxy-To-Realm := LOCAL (7) } # update control = noop (7) } # else = noop (7) eap: Peer sent code Response (2) ID 8 length 11 (7) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (7) authenticate { (7) eap: Peer sent method Identity (1) (7) eap: Calling eap_mschapv2 to process EAP data (7) eap_mschapv2: Issuing Challenge (7) eap: EAP session adding &reply:State = 0xb62146a8b6285c8a (7) [eap] = handled (7) } # authenticate = handled (7) } # server inner-tunnel (7) Virtual server sending reply (7) EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled reply code 11 (7) eap_peap: EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled reply RADIUS code 11 (7) eap_peap: EAP-Message = 0x0109002a1a0109002510d806e435541f76a81bf76d4ba07cfb3a667265657261646975732d332e302e38 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (7) eap_peap: Got tunneled Access-Challenge (7) eap: EAP session adding &reply:State = 0xb8002a16bf093321 (7) [eap] = handled (7) } # authenticate = handled (7) Using Post-Auth-Type Challenge (7) Post-Auth-Type sub-section not found. Ignoring. (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) Sent Access-Challenge Id 43 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (7) EAP-Message = 0x0109004b190017030100405c844afbd67aa1e344ecf9725c6d6e727a8cc5b3c340fc155069a4150c4b9739e7f54fd75c4ad8c7542786eedd338c3740cbc6b9da5b1e8278c5eb21f54e6c35 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0xb8002a16bf09332133d295a612409a37 (7) Finished request Waking up in 4.8 seconds. (8) Received Access-Request Id 44 from 10.210.123.29:3629 to 10.210.235.64:1812 length 322 (8) User-Name = 'mytest' (8) Framed-MTU = 1450 (8) EAP-Message = 0x0209006b19001703010060d0240973b1e837e4960a6ccac86a002917ab9cd054c3b22a82da98cad9e8e84c56c7cec93bb1499708cb05c6c914b86ea9522b58a4e5b33401505daa42c4b40e7350d563f2458393666b4c2cc9e17931d9a301545c74a28405ca6e5bafcd4653 (8) Message-Authenticator = 0x696f809746b8ab1507126d8351be5024 (8) Chargeable-User-Identity = 0x00 (8) NAS-IP-Address = 10.210.123.29 (8) NAS-Identifier = 'ITS-TEST' (8) NAS-Port = 33779942 (8) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=2250' (8) NAS-Port-Type = Wireless-802.11 (8) Service-Type = Framed-User (8) Framed-Protocol = PPP (8) Calling-Station-Id = '10-1C-0C-79-26-49' (8) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (8) Acct-Session-Id = '11505301634460' (8) State = 0xb8002a16bf09332133d295a612409a37 (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (8) authorize { (8) policy filter_username { (8) if (&User-Name =~ / /) { (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) { (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) { (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) { (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /(a)\\./) { (8) if (&User-Name =~ /(a)\\./) -> FALSE (8) } # policy filter_username = notfound (8) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (8) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (8) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (8) auth_log: EXPAND %t (8) auth_log: --> Tue Jun 30 16:38:41 2015 (8) [auth_log] = ok (8) [mschap] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "mytest" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (8) EXPAND %{Aruba-Essid-Name} (8) --> (8) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (8) eap: Peer sent code Response (2) ID 9 length 107 (8) eap: Continuing tunnel setup (8) [eap] = ok (8) } # authorize = ok (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) authenticate { (8) eap: Expiring EAP session with state 0xb62146a8b6285c8a (8) eap: Finished EAP session with state 0xb8002a16bf093321 (8) eap: Previous EAP request found for state 0xb8002a16bf093321, released from the list (8) eap: Peer sent method PEAP (25) (8) eap: EAP PEAP (25) (8) eap: Calling eap_peap to process EAP data (8) eap_peap: processing EAP-TLS (8) eap_peap: eaptls_verify returned 7 (8) eap_peap: Done initial handshake (8) eap_peap: eaptls_process returned 7 (8) eap_peap: FR_TLS_OK (8) eap_peap: Session established. Decoding tunneled attributes (8) eap_peap: PEAP state phase2 (8) eap_peap: EAP type MSCHAPv2 (26) (8) eap_peap: Got tunneled request (8) eap_peap: EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) eap_peap: Setting User-Name to mytest (8) eap_peap: Sending tunneled request to inner-tunnel (8) eap_peap: EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (8) eap_peap: User-Name = 'mytest' (8) eap_peap: State = 0xb62146a8b6285c8a3fe68614a37a338a (8) Virtual server inner-tunnel received request (8) EAP-Message = 0x020900411a0209003c316a2051c2ef6b4f01437a8e0768e8ed840000000000000000c9939c062c9c25dc878baf49c1c1b486042217fc6242c109006d7974657374 (8) FreeRADIUS-Proxied-To = 127.0.0.1 (8) User-Name = 'mytest' (8) State = 0xb62146a8b6285c8a3fe68614a37a338a (8) server inner-tunnel { (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authorize { (8) policy filter_username { (8) if (&User-Name =~ / /) { (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) { (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) { (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (8) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) { (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /(a)\\./) { (8) if (&User-Name =~ /(a)\\./) -> FALSE (8) } # policy filter_username = notfound (8) [mschap] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "mytest", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "mytest" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (8) EXPAND %{Realm} (8) --> NULL (8) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (8) else { (8) update control { (8) &Proxy-To-Realm := LOCAL (8) } # update control = noop (8) } # else = noop (8) eap: Peer sent code Response (2) ID 9 length 65 (8) eap: No EAP Start, assuming it's an on-going EAP conversation (8) [eap] = updated (8) if (&EAP-Message) { (8) if (&EAP-Message) -> TRUE (8) if (&EAP-Message) { (8) redundant ldap_Portal_redundant { rlm_ldap (ldap_DB_1): Reserved connection (4) (8) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (8) ldap_DB_1: --> (&(uid=mytest)) (8) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=mytest))", scope "sub" (8) ldap_DB_1: Waiting for search result... (8) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (4) rlm_ldap (ldap_DB_1): Closing connection (0), from 2 unused connections (8) [ldap_DB_1] = notfound (8) } # redundant ldap_Portal_redundant = notfound (8) } # if (&EAP-Message) = notfound (8) ... skipping else for request 8: Preceding "if" was taken (8) [expiration] = noop (8) [logintime] = noop (8) [pap] = noop (8) } # authorize = updated (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authenticate { (8) eap: Expiring EAP session with state 0xb62146a8b6285c8a (8) eap: Finished EAP session with state 0xb62146a8b6285c8a (8) eap: Previous EAP request found for state 0xb62146a8b6285c8a, released from the list (8) eap: Peer sent method MSCHAPv2 (26) (8) eap: EAP MSCHAPv2 (26) (8) eap: Calling eap_mschapv2 to process EAP data (8) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) eap_mschapv2: Auth-Type MS-CHAP { (8) mschap: WARNING: No Cleartext-Password configured. Cannot create NT-Password (8) mschap: WARNING: No Cleartext-Password configured. Cannot create LM-Password (8) mschap: Creating challenge hash with username: mytest (8) mschap: Client is using MS-CHAPv2 (8) mschap: ERROR: FAILED: No NT/LM-Password. Cannot perform authentication (8) mschap: ERROR: MS-CHAP2-Response is incorrect (8) [mschap] = reject (8) } # Auth-Type MS-CHAP = reject (8) MSCHAP-Error: E=691 R=1 (8) Could not parse new challenge from MS-CHAP-Error: 2 (8) ERROR: MSCHAP Failure (8) eap: EAP session adding &reply:State = 0xb62146a8b72b5c8a (8) [eap] = handled (8) } # authenticate = handled (8) } # server inner-tunnel (8) Virtual server sending reply (8) EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled reply code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled reply RADIUS code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (8) eap_peap: Got tunneled Access-Challenge (8) eap: EAP session adding &reply:State = 0xb8002a16b00a3321 (8) [eap] = handled (8) } # authenticate = handled (8) Using Post-Auth-Type Challenge (8) Post-Auth-Type sub-section not found. Ignoring. (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) Sent Access-Challenge Id 44 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (8) EAP-Message = 0x010a003b19001703010030df92ce1aac52b4b30ccdffebe206a0cec12b7a3d6c5372f4f5694631578719f749d5aba9df6c3ee020a59e55b53a1390 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xb8002a16b00a332133d295a612409a37 (8) Finished request Waking up in 4.8 seconds. (9) Received Access-Request Id 45 from 10.210.123.29:3629 to 10.210.235.64:1812 length 258 (9) User-Name = 'mytest' (9) Framed-MTU = 1450 (9) EAP-Message = 0x020a002b190017030100209af5ad585c8b395c928213c3ee8b1504f55db4183f261d436e584d6c501d9a9b (9) Message-Authenticator = 0xcf11096137cdd8dbd7aec6683a15595f (9) Chargeable-User-Identity = 0x00 (9) NAS-IP-Address = 10.210.123.29 (9) NAS-Identifier = 'ITS-TEST' (9) NAS-Port = 33779942 (9) NAS-Port-Id = 'slot=2;subslot=0;port=55;vlanid=230' (9) NAS-Port-Type = Wireless-802.11 (9) Service-Type = Framed-User (9) Framed-Protocol = PPP (9) Calling-Station-Id = '10-1C-0C-79-26-49' (9) Called-Station-Id = '58-6A-B1-2A-F5-E0:its-test' (9) Acct-Session-Id = '11505301634460' (9) State = 0xb8002a16b00a332133d295a612409a37 (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (9) authorize { (9) policy filter_username { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) { (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) { (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) { (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /(a)\\./) { (9) if (&User-Name =~ /(a)\\./) -> FALSE (9) } # policy filter_username = notfound (9) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d (9) auth_log: --> /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (9) auth_log: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.210.123.29/auth-20150630 (9) auth_log: EXPAND %t (9) auth_log: --> Tue Jun 30 16:38:41 2015 (9) [auth_log] = ok (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "mytest" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) { (9) EXPAND %{Aruba-Essid-Name} (9) --> (9) if (Called-Station-Id =~ /Test SSID/ || "%{Aruba-Essid-Name}" =~ /Test SSID/) -> FALSE (9) eap: Peer sent code Response (2) ID 10 length 43 (9) eap: Continuing tunnel setup (9) [eap] = ok (9) } # authorize = ok (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) authenticate { (9) eap: Expiring EAP session with state 0xb62146a8b72b5c8a (9) eap: Finished EAP session with state 0xb8002a16b00a3321 (9) eap: Previous EAP request found for state 0xb8002a16b00a3321, released from the list (9) eap: Peer sent method PEAP (25) (9) eap: EAP PEAP (25) (9) eap: Calling eap_peap to process EAP data (9) eap_peap: processing EAP-TLS (9) eap_peap: eaptls_verify returned 7 (9) eap_peap: Done initial handshake (9) eap_peap: eaptls_process returned 7 (9) eap_peap: FR_TLS_OK (9) eap_peap: Session established. Decoding tunneled attributes (9) eap_peap: PEAP state phase2 (9) eap_peap: EAP type MSCHAPv2 (26) (9) eap_peap: Got tunneled request (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: Setting User-Name to mytest (9) eap_peap: Sending tunneled request to inner-tunnel (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (9) eap_peap: User-Name = 'mytest' (9) eap_peap: State = 0xb62146a8b72b5c8a3fe68614a37a338a (9) Virtual server inner-tunnel received request (9) EAP-Message = 0x020a00091a04090004 (9) FreeRADIUS-Proxied-To = 127.0.0.1 (9) User-Name = 'mytest' (9) State = 0xb62146a8b72b5c8a3fe68614a37a338a (9) server inner-tunnel { (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authorize { (9) policy filter_username { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) { (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) { (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) { (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /(a)\\./) { (9) if (&User-Name =~ /(a)\\./) -> FALSE (9) } # policy filter_username = notfound (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "mytest", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "mytest" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') { (9) EXPAND %{Realm} (9) --> NULL (9) if ("%{Realm}" != NULL && "%{Realm}" != 'test.hk') -> FALSE (9) else { (9) update control { (9) &Proxy-To-Realm := LOCAL (9) } # update control = noop (9) } # else = noop (9) eap: Peer sent code Response (2) ID 10 length 9 (9) eap: No EAP Start, assuming it's an on-going EAP conversation (9) [eap] = updated (9) if (&EAP-Message) { (9) if (&EAP-Message) -> TRUE (9) if (&EAP-Message) { (9) redundant ldap_Portal_redundant { rlm_ldap (ldap_DB_1): Reserved connection (4) (9) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (9) ldap_DB_1: --> (&(uid=mytest)) (9) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=mytest))", scope "sub" (9) ldap_DB_1: Waiting for search result... (9) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (4) (9) [ldap_DB_1] = notfound (9) } # redundant ldap_Portal_redundant = notfound (9) } # if (&EAP-Message) = notfound (9) ... skipping else for request 9: Preceding "if" was taken (9) [expiration] = noop (9) [logintime] = noop (9) [pap] = noop (9) } # authorize = updated (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authenticate { (9) eap: Expiring EAP session with state 0xb62146a8b72b5c8a (9) eap: Finished EAP session with state 0xb62146a8b72b5c8a (9) eap: Previous EAP request found for state 0xb62146a8b72b5c8a, released from the list (9) eap: Peer sent method MSCHAPv2 (26) (9) eap: EAP MSCHAPv2 (26) (9) eap: Calling eap_mschapv2 to process EAP data (9) eap: Freeing handler (9) [eap] = reject (9) } # authenticate = reject (9) Failed to authenticate the user (9) Login incorrect: [mytest] (from client radius-test-123.29 port 0 via TLS tunnel) (9) Using Post-Auth-Type Reject (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) Post-Auth-Type REJECT { (9) attr_filter.access_reject: EXPAND %{User-Name} (9) attr_filter.access_reject: --> mytest (9) attr_filter.access_reject: Matched entry DEFAULT at line 16 (9) [attr_filter.access_reject] = updated (9) update { (9) EXPAND Login incorrect: %{Module-Failure-Message} (9) --> Login incorrect: (9) &Module-Failure-Message := Login incorrect: (9) } # update = noop (9) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (9) linelog: --> messages.Access-Reject (9) linelog: EXPAND /usr/local/var/log/radius/log/linelog-%Y%m%d (9) linelog: --> /usr/local/var/log/radius/log/linelog-20150630 (9) linelog: EXPAND %S,%{reply:Packet-Type},%{Packet-Src-IP-Address},%{NAS-IP-Address},%{User-Name},%{Calling-Station-Id},%{%{Aruba-Essid-Name}:-%{Called-Station-Id}},%{reply:Reply-Message},%{%{reply:Module-Failure-Message}:-%{Module-Failure-Message}} (9) linelog: --> 2015-06-30 16:38:41,Access-Reject,10.210.123.29,,mytest,,,,Login incorrect: (9) [linelog] = ok (9) } # Post-Auth-Type REJECT = updated (9) } # server inner-tunnel (9) Virtual server sending reply (9) EAP-Message = 0x040a0004 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply RADIUS code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Tunneled authentication was rejected (9) eap_peap: FAILURE (9) eap: EAP session adding &reply:State = 0xb8002a16b10b3321 (9) [eap] = handled (9) } # authenticate = handled (9) Using Post-Auth-Type Challenge (9) Post-Auth-Type sub-section not found. Ignoring. (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) Sent Access-Challenge Id 45 from 10.210.235.64:1812 to 10.210.123.29:3629 length 0 (9) EAP-Message = 0x010b002b190017030100206881fd9bcb736b457f738468f3088581bb4afa523344876e3aa398a833a2cfb4 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) State = 0xb8002a16b10b332133d295a612409a37 (9) Finished request Waking up in 4.7 seconds. (0) <done>: Cleaning up request packet ID 36 with timestamp +108 (1) <done>: Cleaning up request packet ID 37 with timestamp +108 (2) <done>: Cleaning up request packet ID 38 with timestamp +108 (3) <done>: Cleaning up request packet ID 39 with timestamp +108 (4) <done>: Cleaning up request packet ID 40 with timestamp +108 (5) <done>: Cleaning up request packet ID 41 with timestamp +108 (6) <done>: Cleaning up request packet ID 42 with timestamp +108 (7) <done>: Cleaning up request packet ID 43 with timestamp +108 (8) <done>: Cleaning up request packet ID 44 with timestamp +108 (9) <done>: Cleaning up request packet ID 45 with timestamp +108 Ready to process requests

3 4