- Freeradius-Users - lists.freeradius.org

Freeradius + LDAP - WARNING: No "known good" password was found in LDAP
by Kermes - - 22 Dec '15

22 Dec '15

Morning list, I need some help with my freeradius + LDAP configuration, I'm stuck with a "WARNING: No "known good" password was found in LDAP" message, and I don't know how to continue with the debugging of this problem. First, versions: freeradius-ldap-2.2.6-6.el6_7.x86_64 freeradius-2.2.6-6.el6_7.x86_64 This is the output from "radiusd -X": rad_recv: Access-Request packet from host 10.252.218.2 port 12494, id=176, length=95 User-Name = "test" User-Password = "testpasswd" NAS-IP-Address = 10.252.218.4 NAS-Identifier = "example1" Calling-Station-Id = "10.100.100.10" NAS-Port = 11469 NAS-Port-Type = Virtual Mon Dec 21 08:14:30 2015 : Info: # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Dec 21 08:14:30 2015 : Info: +group authorize { Mon Dec 21 08:14:30 2015 : Info: ++[preprocess] = ok Mon Dec 21 08:14:30 2015 : Info: ++[chap] = noop Mon Dec 21 08:14:30 2015 : Info: ++[mschap] = noop Mon Dec 21 08:14:30 2015 : Info: ++[digest] = noop Mon Dec 21 08:14:30 2015 : Info: [suffix] No '@' in User-Name = "test", looking up realm NULL Mon Dec 21 08:14:30 2015 : Info: [suffix] No such realm "NULL" Mon Dec 21 08:14:30 2015 : Info: ++[suffix] = noop Mon Dec 21 08:14:30 2015 : Info: [eap] No EAP-Message, not doing EAP Mon Dec 21 08:14:30 2015 : Info: ++[eap] = noop Mon Dec 21 08:14:30 2015 : Info: [files] users: Matched entry DEFAULT at line 79 Mon Dec 21 08:14:30 2015 : Info: ++[files] = ok Mon Dec 21 08:14:30 2015 : Info: [ldap] performing user authorization for test Mon Dec 21 08:14:30 2015 : Info: [ldap] expand: %{Stripped-User-Name} -> Mon Dec 21 08:14:30 2015 : Info: [ldap] ... expanding second conditional Mon Dec 21 08:14:30 2015 : Info: [ldap] expand: %{User-Name} -> test Mon Dec 21 08:14:30 2015 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=test) Mon Dec 21 08:14:30 2015 : Info: [ldap] expand: ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local -> ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local Mon Dec 21 08:14:30 2015 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Mon Dec 21 08:14:30 2015 : Debug: [ldap] ldap_get_conn: Got Id: 0 Mon Dec 21 08:14:30 2015 : Debug: [ldap] attempting LDAP reconnection Mon Dec 21 08:14:30 2015 : Debug: [ldap] (re)connect to 10.252.25.20:389, authentication 0 Mon Dec 21 08:14:30 2015 : Debug: [ldap] bind as cn=binduser,cn=proxy,ou=clients,ou=nfra,dc=infra,dc=local/password to 10.252.25.20:389 Mon Dec 21 08:14:30 2015 : Debug: [ldap] waiting for bind result ... Mon Dec 21 08:14:30 2015 : Debug: [ldap] Bind was successful Mon Dec 21 08:14:30 2015 : Debug: [ldap] performing search in ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local with filter (uid=test) Mon Dec 21 08:14:30 2015 : Info: [ldap] looking for check items in directory... Mon Dec 21 08:14:30 2015 : Info: [ldap] looking for reply items in directory... Mon Dec 21 08:14:30 2015 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Mon Dec 21 08:14:30 2015 : Debug: [ldap] ldap_release_conn: Release Id: 0 Mon Dec 21 08:14:30 2015 : Info: ++[ldap] = ok Mon Dec 21 08:14:30 2015 : Info: ++[expiration] = noop Mon Dec 21 08:14:30 2015 : Info: ++[logintime] = noop Mon Dec 21 08:14:30 2015 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Mon Dec 21 08:14:30 2015 : Info: ++[pap] = noop Mon Dec 21 08:14:30 2015 : Info: +} # group authorize = ok Mon Dec 21 08:14:30 2015 : Info: ERROR: No authenticate method (Auth-Type) found for the request: Rejecting the user Mon Dec 21 08:14:30 2015 : Info: Failed to authenticate the user. When I run the "search" command from the OS and ldap tools, the output seems to be good (userPassword is {SHA} hashed): # ldapsearch -D "cn=binduser,cn=proxy,ou=clients,ou=nfra,dc=infra,dc=local" -w password -p 389 -h 10.252.25.20 -b "ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local" "uid=test" dn: uid=test,ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local maxFailedLogins: 3 passwordMinAlphaChars: 1 objectclass: account objectclass: top objectclass: posixaccount objectclass: shadowaccount passwordMaxRepeatedChars: 1 uid: test uidNumber: 18001 cn: test loginShell: /bin/bash passwordMinLength: 15 shadowMin: 1 gidNumber: 18000 passwordMinOtherChars: 3 shadowMax: 13 gecos: homeDirectory: /home/test passwordHistSize: 12 unsuccessfulLoginCount: 0 passwordFlags: ADMCHG userPassword:: e1NIQX1mVFA2NUFYOURHMXFPZkhsem5tQzg5NElJM3c9 This is my /etc/raddb/modules/ldap file: # grep -v "#" ldap ldap { server = "10.252.25.20" port = 389 identity = "cn=binduser,cn=proxy,ou=clients,ou=nfra,dc=infra,dc=local" password = password basedn = "ou=users,cn=secdb,cn=data,ou=ALL,ou=infra,dc=infra,dc=local" filter = "(uid=%{%{Stripped-User-Name}:-%{User-Name}})" ldap_connections_number = 5 max_uses = 0 timeout = 4 timelimit = 3 net_timeout = 1 tls { start_tls = no } dictionary_mapping = ${confdir}/ldap.attrmap edir_account_policy_check = no keepalive { idle = 60 probes = 3 interval = 3 } } Any ideas? I don't know how to get some more debug from the "ldap" module especifcally to try to solve that "No "known good" password" message. Thanks a lot in advance, Regards, Alex

3 3

authentication failure: inner or outer?
by Stefano Zanmarchi 21 Dec '15

21 Dec '15

Hi, my aim is to use linelog to log Access-Rejects differently when authentication fails because the user's home server says so from when it fails because "my" users type in a wrong password. If I'm not wrong the server (2.1.12) does not run the "Post-Auth-Type Reject" when in the inner tunnel, so how can I distinguish where the authentication failure happened? Thank you very much, Stefano

3 2

Re: ERROR: Invalid vendor name in attribute name "radiusCheckItem"
by Amir Tal 21 Dec '15

21 Dec '15

First, thanks for the detailed and helpful reply. For reference, I was able to get this working according to desired scheme. Dropped the use of 'radiusCheckItem' and 'radiusReplyItem'. Changed to : if ( reply:Framed-Pool =~ /fast/i || reply:Framed-Pool =~ /pro/i ) { update control { Pool-Name := "test_pool" } } Added this condition to 'authorize' section of sites-enabled/default, right after ldap item. This results in assigning an IP address from "test_pool" for every user having either "fast" of "pro" set as Framed-Pool in LDAP. No further questions at this time. Amir. [IMG]<http://www.ccc.co.il> Amir Tal [IMG] System Administrator +972 39201471 [IMG] Cloud Systems Support +972 39201442 [IMG]

1 0

Feature requests and current limitations in
by Herwin Weststrate 21 Dec '15

21 Dec '15

As discussed at https://github.com/FreeRADIUS/freeradius-server/issues/1451#issuecomment-16…, I'm currently trying to write a proposal to change the interface of the programming language that are currently supported as embedded languages within FreeRADIUS. The current list includes Perl, Python and Ruby (which should not be used). In the current status rlm_perl is far superior in terms of features to the other modules, and also has a completely different interface. My plan is to make a unified interface for these three modules, so they all have the same features and behave in the same way. At the moment, the biggest limitations that should be removed are the following: - Make the modules work in the same way, so an example in a language can simply be rewritten to another language (rlm_perl is currently the most mature and works completely different from rlm_python and rlm_ruby) - Don't limit the input of rlm_python and rlm_ruby to the request list, include other lists (like reply and session-state) as well - Don't limit the output of rlm_python and rlm_ruby to the reply and control list, include others lists (like session-state) as well Some lesser changes will include: - Allow random config structures to be passed to the module, as rlm_perl now has the "config" option <https://github.com/FreeRADIUS/freeradius-server/issues/1451> - Rewrite rlm_ruby to use mruby <https://github.com/FreeRADIUS/freeradius-server/issues/990> - Fix multithreading in rlm_python <https://github.com/FreeRADIUS/freeradius-server/issues/408> - Strip the extra quotes in rlm_python <https://github.com/FreeRADIUS/freeradius-server/issues/1452> - Lots of minor fixes (e.g. <https://github.com/FreeRADIUS/freeradius-server/pull/1459>) I don't know if anyone here uses one of these modules, or tried using one but stopped due to its limitations, but I'm really curious what kind of features people would want to see in these modules, or what limitations they'd experienced with using them. Disclaimer: I'll write the proposal for change, will discuss it on the mailing lists, and I'll try to implement it too. I have very limited experience in writing this kind of code, which means it may be a learnful but slow progress. Also, keep in mind that I'm not related to the FreeRADIUS project, other than just contributing a pull request every now and then: I'm not in a position to decide what comes into the code base and what not. -- Herwin Weststrate

3 3

How to deal with Access-challenge response?
by Michael Furman 21 Dec '15

21 Dec '15

I use Jradius for couple of years but I see the following problem first time. One of our customers uses Two Factor authentication and the server response with Access-challenge response.Unfortunately Jradius client start to repeat AccessRequest a lot of times and do not return an execution to its caller. Please see the attached image. How to deal with Access-challenge response? It will be great Jradius will return Access-challenge to its caller and will not repeat AccessRequest a lot of times.

2 2

3.0.10 and auth+acct type under the listen section
by Peter Lambrechtsen 21 Dec '15

21 Dec '15

Hi I'm working on an in-place rebuild of another radius product using 3.0.10 and noticed something very stupid that an upstream NAS is doing. It's going to be a major challenge to get the upstream NAS corrected. It's sending Auth & Acct messages on 1646. I tried setting the type to auth+acct in the sites-enabled/default listen section: listen { ipaddr = * port = 1646 type = auth+acct # interface = eth0 # clients = per_socket_clients But if I receive an accounting message on that port, it gets rejected: Listening on auth+acct address * port 1646 bound to server default Ready to process requests Receive - Invalid packet code 4 sent to authentication port from client Mobile port 50016 Ready to process requests If I swap it back to acct then the Auth messages get rejected. Any ideas on how to sort this?

3 3

ERROR: Invalid vendor name in attribute name "radiusCheckItem"
by Amir Tal 20 Dec '15

20 Dec '15

Hi, Using freeradius 2.1.12 on centos 5 Users are saved in LDAP, accounting data in MySQL. We are looking to implement IP addresses allocation in radius, using Rlm_sqlippool. Already implemented sql host with pool data (added sqlippool to /etc/raddb/sites-enabled/default) , working as expected. We do not want to add pool info the LDAP entries, but have the radius assign a pool according to other (existing) parameters. Added the following to 'post-auth' of /etc/raddb/sites-enabled/default (users with radiusReplyItem of certain type should get a radiusCheckItem with pool name): ... if ( radiusReplyItem =~ /fast/i ) { update request { radiusCheckItem := "Pool-Name := test_pool" } } ... Two issues exists with this : 1. Condition is never met, even for users that have : radiusReplyItem = "Framed-Pool:=fast" 2. Cannot even start radius with this syntax, I get an error: Sun Dec 20 17:37:41 2015 : Error: /usr/local/etc/raddb/sites-enabled/default[483]: ERROR: Invalid vendor name in attribute name "radiusCheckItem" Sun Dec 20 17:37:41 2015 : Error: /usr/local/etc/raddb/sites-enabled/default[482]: Failed to parse "update" subsection. Sun Dec 20 17:37:41 2015 : Error: /usr/local/etc/raddb/sites-enabled/default[479]: Errors parsing post-auth section. How can this be used for 'radiusCheckItem' and 'radiusReplyItem' ? it this possible at all? I'll be happy to provide additional info if needed, and/or example for user. Amir. [IMG]<http://www.ccc.co.il> Amir Tal [IMG] System Administrator +972 39201471 [IMG] Cloud Systems Support +972 39201442 [IMG]

2 1

Filter OpenLDAP users account upon Freeradius 3.0.10 NAS-Port-Id
by François Lacombe 19 Dec '15

19 Dec '15

Hi all, My Freeradius 3.0.10 setup currently accepts eap-mschapv2 requests by cheking credentials against LM/NT password checksums obtained from a LDAP. The only freeradius client is an IPSec server which forwards EAP protocol to the radius (strongswan 5.2.1 with eap-radius method) The LDAP module is configured to let the user connect when the diallupAccess is set to true. But it let any users connect to any network my VPN server is offering access to. What is the best method to filter users depending on which NAS-Port-Id they are using ? It will allow me to authorize several users to access any networks they need to access without puting any network configuration in the LDAP. Many thanks in advance for any help to improve this point of config. François Lacombe @InfosReseaux

3 12

Make sense of SQL Huntgroup HOWTO?
by Joel Bergmark 18 Dec '15

18 Dec '15

Hello After a week of trying to figure the HOWTO guide out (http://wiki.freeradius.org/guide/SQL%20Huntgroup%20HOWTO) and online searching I still cant make sense of the SQL and Huntgroup matching. Also tried the freeradius channel on IRC but to no luck. Basically my problem is the same as many others, and the people asked the same question didn't manage to get it working in the end. Im running Freeradius 2.1 with Daloradius frontend and the SQL_XLAT seemingly works and to the checks, and get correct IP and matching but in the end its not disallowing In the sites-enabled/default I use as described in the HOWTO: update request { Huntgroup-Name := "%{sql:SELECT groupname FROM radhuntgroup WHERE nasipaddress='%{NAS-IP-Address}'}" { } if (Huntgroup-Name == ''){ reject } I believe that the issue it the later of the above statement that supposed to match and reject that's the problem but as many others I can't figure out how to get this working. DEBUG INFO: Ready to process requests. rad_recv: Access-Request packet from host 46.23X.XX.170 port 1645, id=105, length=66 User-Name = "bl" User-Password = "asdfasdf" NAS-Port = 1 NAS-Port-Id = "tty1" NAS-Port-Type = Virtual NAS-IP-Address = 46.23X.XX.170 # Executing section authorize from file /etc/freeradius/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok sql_xlat expand: %{User-Name} -> bl sql_set_user escaped user --> 'bl' expand: SELECT groupname FROM radhuntgroup WHERE nasipaddress='%{NAS-IP-Address}' -> SELECT groupname FROM radhuntgroup WHERE nasipaddress='46.23X.XX.170' rlm_sql (sql): Reserving sql socket id: 3 sql_xlat finished rlm_sql (sql): Released sql socket id: 3 expand: %{sql:SELECT groupname FROM radhuntgroup WHERE nasipaddress='%{NAS-IP-Address}'} -> 3rdline ++[request] returns ok ++? if (Huntgroup-Name == '') ? Evaluating (Huntgroup-Name == '') -> FALSE ++? if (Huntgroup-Name == '') -> FALSE ++[chap] returns noop ++[mschap] returns noop ++[digest] returns noop [suffix] No '@' in User-Name = "bl", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [eap] No EAP-Message, not doing EAP ++[eap] returns noop [sql] expand: %{User-Name} -> bl [sql] sql_set_user escaped user --> 'bl' rlm_sql (sql): Reserving sql socket id: 2 [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'bl' ORDER BY id [sql] User found in radcheck table [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'bl' ORDER BY id [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'bl' ORDER BY priority [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '2ndline' ORDER BY id rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /etc/freeradius/sites-enabled/default +- entering group PAP {...} [pap] login attempt with password "asdfasdf" [pap] Using clear text password "asdfasdf" [pap] User authenticated successfully ++[pap] returns ok # Executing section post-auth from file /etc/freeradius/sites-enabled/default +- entering group post-auth {...} [sql] expand: %{User-Name} -> bl [sql] sql_set_user escaped user --> 'bl' [sql] expand: %{User-Password} -> asdfasdf [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bl', 'asdfasdf', 'Access-Accept', '2015-12-18 15:42:18') rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bl', 'asdfasdf', 'Access-Accept', '2015-12-18 15:42:18') rlm_sql (sql): Reserving sql socket id: 1 rlm_sql (sql): Released sql socket id: 1 ++[sql] returns ok ++[exec] returns noop Sending Access-Accept of id 105 to 46.23X.XX.170 port 1645 Finished request 0. Going to the next request Waking up in 4.9 seconds. Cleaning up request 0 ID 105 with timestamp +23 Ready to process requests. Thanks for any help!

4 18

Logging
by Süleyman Düzdaban 18 Dec '15

18 Dec '15

Hi, /(Excu//se my English after that time./) FR version: 3.0.10 I have two linelog instances for access ("linelog") and accounting ("log_accounting"). I put the "linelog" in innert-tunnel's post-auth section instead of default for Access-Accept and Access-Reject with inner identity and it seems like that:/ //Thu Dec 17 15:26:58 2015 Access accepted: ///1234567890/@realm-is-here NAS-IP-Address: 10.109.50.207 Called-Station-Id: A0-48-1C-56-C6-A1 Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:27:30 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.185 Called-Station-Id: A0-48-1C-56-C6-9D Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:27:44 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.202 Called-Station-Id: A0-48-1C-56-C6-A0 Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:30:42 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.201 Called-Station-Id: 14-58-D0-66-E6-55 Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:31:38 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.206 Called-Station-Id: 14-58-D0-66-B6-51 Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:32:43 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.222 Called-Station-Id: 14-58-D0-66-B6-9C Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:32:50 2015 Access accepted: //1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.192 Called-Station-Id: 14-58-D0-66-C6-7A Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90// //Thu Dec 17 15:32:51 2015 Access accepted: 1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.205 Called-Station-Id: 14-58-D0-66-C6-56 Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90/ As shown above, i can get the inner user identities but also i get multiple "Accept" lines for the same user after first login (15:26:58) although there is no attempt by the user for login. I see the same thing in the accounting log file too: / //Thu Dec 17 15:26:58 2015 Connect: 1234567890@realm-is-here sessId: 93e63906-0000077e called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90 port: 1385 ip: Thu Dec 17 15:27:14 2015 Connect: 1234567890@realm-is-here sessId: e85fb0d5-00000289 called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90 port: 533 ip: Thu Dec 17 15:27:16 2015 Connect: 1234567890@realm-is-here sessId: 758f27c1-000001e1 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90 port: 397 ip: Thu Dec 17 15:27:19 2015 Disconnect: 1234567890@realm-is-here sessId: 758f27c1-000001e1 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90 port: 397 ip: sessTime: 3 seconds input: 569B output: 967B Thu Dec 17 15:27:30 2015 Connect: 1234567890@realm-is-here sessId: 32b8e9e6-0000048e called: A0-48-1C-56-C6-9D calling: C0-BD-D1-89-0B-90 port: 841 ip: Thu Dec 17 15:27:42 2015 Disconnect: 1234567890@realm-is-here sessId: 15f28421-00000256 called: 14-58-D0-66-B6-E1 calling: C0-BD-D1-89-0B-90 port: 474 ip: 92.61.7.155 sessTime: seconds input: 6096B output: 7868B Thu Dec 17 15:27:44 2015 Connect: 1234567890@realm-is-here sessId: 6ee0534b-00001696 called: A0-48-1C-56-C6-A0 calling: C0-BD-D1-89-0B-90 port: 4162 ip: Thu Dec 17 15:27:52 2015 Disconnect: 1234567890@realm-is-here sessId: ba48b418-00000360 called: 14-58-D0-66-C6-61 calling: C0-BD-D1-89-0B-90 port: 634 ip: 92.61.7.155 sessTime: seconds input: 54571B output: 96205B Thu Dec 17 15:28:11 2015 Disconnect: 1234567890@realm-is-here sessId: e85fb0d5-00000289 called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90 port: 533 ip: 92.61.7.155 sessTime: seconds input: 569B output: 1183B Thu Dec 17 15:28:17 2015 Connect: 1234567890@realm-is-here sessId: 192aa670-00000e35 called: A0-48-1C-56-C6-A6 calling: C0-BD-D1-89-0B-90 port: 2558 ip: Thu Dec 17 15:28:22 2015 Disconnect: 1234567890@realm-is-here sessId: 93e63906-0000077e called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90 port: 1385 ip: 92.61.7.155 sessTime: seconds input: 4371B output: 3351B Thu Dec 17 15:29:13 2015 Disconnect: 1234567890@realm-is-here sessId: 32b8e9e6-0000048e called: A0-48-1C-56-C6-9D calling: C0-BD-D1-89-0B-90 port: 841 ip: 92.61.7.155 sessTime: seconds input: 94910B output: 28777B Thu Dec 17 15:29:14 2015 Disconnect: 1234567890@realm-is-here sessId: 6ee0534b-00001696 called: A0-48-1C-56-C6-A0 calling: C0-BD-D1-89-0B-90 port: 4162 ip: 92.61.7.155 sessTime: seconds input: 26866B output: 9369B Thu Dec 17 15:30:42 2015 Connect: 1234567890@realm-is-here sessId: 90649829-000001e3 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90 port: 399 ip: Thu Dec 17 15:30:43 2015 Disconnect: 1234567890@realm-is-here sessId: 192aa670-00000e35 called: A0-48-1C-56-C6-A6 calling: C0-BD-D1-89-0B-90 port: 2558 ip: 92.61.7.155 sessTime: seconds input: 7238B output: 7872B Thu Dec 17 15:31:38 2015 Connect: 1234567890@realm-is-here sessId: 88a18c10-0000028b called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90 port: 535 ip: Thu Dec 17 15:31:56 2015 Connect: 1234567890@realm-is-here sessId: 7d5f1897-0000077f called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90 port: 1386 ip: Thu Dec 17 15:32:06 2015 Connect: 1234567890@realm-is-here sessId: 68d0d39a-00000366 called: 14-58-D0-66-C6-61 calling: C0-BD-D1-89-0B-90 port: 639 ip: Thu Dec 17 15:32:36 2015 Disconnect: 1234567890@realm-is-here sessId: 90649829-000001e3 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90 port: 399 ip: 92.61.7.155 sessTime: seconds input: 55755B output: 34278B Thu Dec 17 15:32:43 2015 Connect: 1234567890@realm-is-here sessId: 2e5136a5-0000018c called: 14-58-D0-66-B6-9C calling: C0-BD-D1-89-0B-90 port: 293 ip: Thu Dec 17 15:32:45 2015 Connect: 1234567890@realm-is-here sessId: 80a8748c-000001be called: 14-58-D0-66-56-1E calling: C0-BD-D1-89-0B-90 port: 351 ip: Thu Dec 17 15:32:48 2015 Disconnect: 1234567890@realm-is-here sessId: 80a8748c-000001be called: 14-58-D0-66-56-1E calling: C0-BD-D1-89-0B-90 port: 351 ip: 92.61.7.155 sessTime: 3 seconds input: 4892B output: 2684B Thu Dec 17 15:32:50 2015 Connect: 1234567890@realm-is-here sessId: e767e76d-00000143 called: 14-58-D0-66-C6-7A calling: C0-BD-D1-89-0B-90 port: 262 ip: Thu Dec 17 15:32:51 2015 Connect: 1234567890@realm-is-here sessId: d9b51d3b-00000230 called: 14-58-D0-66-C6-56 calling: C0-BD-D1-89-0B-90 port: 442 ip: Thu Dec 17 15:32:51 2015 Disconnect: 1234567890@realm-is-here sessId: 88a18c10-0000028b called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90 port: 535 ip: 92.61.7.155 sessTime: seconds input: 5743B output: 3632B / Why do i get that much lines even when there is no login-logout attempt by the user? There is another issue with accounting. I can get the inner user name sometimes (As shown above both files look like okay) but sometimes I can't. That's the log (Some part of it actually that about the case for the user *1639**5**905204*/@realm-is-here/): (And again there is no attempt to login or logout by the user at all.) Access Accept/Reject: Thu Dec 17 17:26:20 2015 Access accepted: 16395905204@realm-is-here NAS-IP-Address: 10.50.43.204 Called-Station-Id: 00-03-52-0B-2B-93 Packet-Src-IP-Address: 80.251.40.40 Calling-Station-Id: 8C-00-6D-07-3B-9A Accounting: Thu Dec 17 17:24:50 2015 Disconnect: 16395905204@realm-is-here sessId: 9e57770c-0000010d called: 00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A port: 238 ip: 185.22.249.217 sessTime: 481 seconds input: 29613B output: 22215B Thu Dec 17 17:26:20 2015 Connect: 16395905204@realm-is-here sessId: 1f605712-0000010e called: 00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A port: 239 ip: Debug: (13337) Received Accounting-Request Id 62 from 80.251.40.40:54942 to 80.251.40.8:1813 length 364 (13337) Acct-Multi-Session-Id = "00-03-52-A6-A3-70-8C-00-6D-07-3B-9A-56-72-D1-E3-00-0E-DF-CA" (13337) Acct-Session-Id = "9e57770c-0000010d" (13337) NAS-Port = 238 (13337) NAS-Port-Type = Wireless-802.11 (13337) NAS-Identifier = "AU-MSC-5500-1" (13337) NAS-IP-Address = 10.50.43.204 (13337) Framed-MTU = 1496 (13337) Framed-IP-Address = 185.22.249.217 (13337) User-Name = "16395905204@realm-is-here" (13337) Calling-Station-Id = "8C-00-6D-07-3B-9A" (13337) Called-Station-Id = "00-03-52-0B-2B-93" (13337) Acct-Status-Type = Stop (13337) Acct-Session-Time = 481 (13337) Acct-Input-Packets = 102 (13337) Acct-Output-Packets = 217 (13337) Acct-Input-Octets = 29613 (13337) Acct-Output-Octets = 22215 (13337) Acct-Delay-Time = 0 (13337) Colubris-AVPair = "ssid=AU WiFi Net" (13337) Colubris-AVPair = "incoming-vlan-id=51" (13337) Colubris-AVPair = "group=TND-Yerleske" (13337) Colubris-AVPair = "phytype=IEEE802dot11g" (13337) Attr-26.8744.250 = 0x00000001 (13337) Attr-26.8744.249 = 0x50fb2808 (13337) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (13337) preacct { (13337) [preprocess] = ok (13337) policy acct_unique { (13337) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (13337) EXPAND %{string:Class} (13337) --> (13337) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (13337) else { (13337) update request { (13337) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (13337) --> c6f70635bf1e4b14ea52406bac73b3ee (13337) &Acct-Unique-Session-Id := c6f70635bf1e4b14ea52406bac73b3ee (13337) } # update request = noop (13337) } # else = noop (13337) } # policy acct_unique = noop (13337) suffix: Checking for suffix after "@" (13337) suffix: Looking up realm "ankara.edu.tr" for User-Name = "16395905204@realm-is-here" (13337) suffix: Found realm "ankara.edu.tr" (13337) suffix: Adding Stripped-User-Name = "16395905204" (13337) suffix: Adding Realm = "ankara.edu.tr" (13337) suffix: Accounting realm is LOCAL (13337) [suffix] = ok (13337) [files] = noop (13337) } # preacct = ok (13337) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (13337) accounting { (13337) detail: EXPAND /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/detail-%H00 (13337) detail: --> /usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/detail-1700 (13337) detail: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/detail-%H00 expands to /usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/detail-1700 (13337) detail: EXPAND %t (13337) detail: --> Thu Dec 17 17:24:50 2015 (13337) [detail] = ok (13337) log_accounting: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown} (13337) log_accounting: --> Accounting-Request.Stop (13337) log_accounting: EXPAND /usr/local/var/log/radius/linelog-accounting (13337) log_accounting: --> /usr/local/var/log/radius/linelog-accounting (13337) log_accounting: EXPAND %t Disconnect: %{User-Name} sessId: %{Acct-Session-Id} called: %{Called-Station-Id} calling: %{Calling-Station-Id} port: %{NAS-Port} ip: %{Framed-IP-Address} sessTime: %{Acct-Session-Time} seconds input: %{Acct-Input-Octets}B output: %{Acct-Output-Octets}B (13337) log_accounting: --> Thu Dec 17 17:24:50 2015 Disconnect: 16395905204@realm-is-here sessId: 9e57770c-0000010d called: 00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A port: 238 ip: 185.22.249.217 sessTime: 481 seconds input: 29613B output: 22215B (13337) [log_accounting] = ok (13337) [exec] = noop (13337) attr_filter.accounting_response: EXPAND %{User-Name} (13337) attr_filter.accounting_response: --> 16395905204@realm-is-here (13337) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (13337) [attr_filter.accounting_response] = updated (13337) } # accounting = updated (13337) Sent Accounting-Response Id 62 from 80.251.40.8:1813 to 80.251.40.40:54942 length 0 (13337) Finished request (13337) Cleaning up request packet ID 62 with timestamp +369 Waking up in 0.5 seconds. Above lines look like okay but then (at 17:26:20): (16180) Received Access-Request Id 135 from 80.251.40.40:54942 to 80.251.40.8:1812 length 368 (16180) Acct-Multi-Session-Id = "00-03-52-A6-A3-70-8C-00-6D-07-3B-9A-56-72-D4-1E-00-0D-4B-44" (16180) Acct-Session-Id = "1f605712-0000010e" (16180) NAS-Port = 239 (16180) NAS-Port-Type = Wireless-802.11 (16180) NAS-Identifier = "AU-MSC-5500-1" (16180) NAS-IP-Address = 10.50.43.204 (16180) Framed-MTU = 1496 (16180) User-Name = "anonymous@realm-is-here" (16180) Calling-Station-Id = "8C-00-6D-07-3B-9A" (16180) Called-Station-Id = "00-03-52-0B-2B-93" (16180) Service-Type = Framed-User (16180) EAP-Message = 0x02f8001c01616e6f6e796d6f757340616e6b6172612e6564752e7472 (16180) Colubris-AVPair = "ssid=AU WiFi Net" (16180) Colubris-AVPair = "incoming-vlan-id=51" (16180) Colubris-AVPair = "group=TND-Yerleske" (16180) Colubris-AVPair = "phytype=IEEE802dot11g" (16180) Attr-26.8744.250 = 0x00000001 (16180) Attr-26.8744.249 = 0x50fb2808 (16180) Message-Authenticator = 0x66886b75dae87c711e75232ce6e36114 (16180) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (16180) authorize { (16180) policy filter_username { (16180) if (!&User-Name) { (16180) if (!&User-Name) -> FALSE (16180) if (&User-Name =~ / /) { (16180) if (&User-Name =~ / /) -> FALSE (16180) if (&User-Name =~ /@.*@/ ) { (16180) if (&User-Name =~ /@.*@/ ) -> FALSE (16180) if (&User-Name =~ /\.\./ ) { (16180) if (&User-Name =~ /\.\./ ) -> FALSE (16180) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (16180) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (16180) if (&User-Name =~ /\.$/) { (16180) if (&User-Name =~ /\.$/) -> FALSE (16180) if (&User-Name =~ /(a)\./) { (16180) if (&User-Name =~ /(a)\./) -> FALSE (16180) } # policy filter_username = notfound (16180) [preprocess] = ok (16180) if ("%{User-Name}" == "eduroamtest(a)ulakbim.gov.tr") { (16180) if ("%{User-Name}" == "eduroamtest(a)ulakbim.gov.tr") -> FALSE (16180) elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ && NAS-Identifier =~ /^AU-MSC-5500-(.+)$/) { (16180) EXPAND %{User-Name} (16180) --> anonymous@realm-is-here (16180) elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ && NAS-Identifier =~ /^AU-MSC-5500-(.+)$/) -> TRUE (16180) elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ && NAS-Identifier =~ /^AU-MSC-5500-(.+)$/) { (16180) if (Colubris-AVPair == "ssid=eduroam") { (16180) if (Colubris-AVPair == "ssid=eduroam") -> FALSE (16180) else { (16180) [noop] = noop (16180) } # else = noop (16180) } # elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ && NAS-Identifier =~ /^AU-MSC-5500-(.+)$/) = noop (16180) ... skipping elsif for request 16180: Preceding "if" was taken (16180) ... skipping elsif for request 16180: Preceding "if" was taken (16180) ... skipping elsif for request 16180: Preceding "if" was taken (16180) auth_log: EXPAND /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/auth-detail-%H00 (16180) auth_log: --> /usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/auth-detail-1700 (16180) auth_log: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/auth-detail-%H00 expands to /usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/auth-detail-1700 (16180) auth_log: EXPAND %t (16180) auth_log: --> Thu Dec 17 17:26:20 2015 (16180) [auth_log] = ok (16180) [chap] = noop (16180) [mschap] = noop (16180) [digest] = noop (16180) eap: Peer sent EAP Response (code 2) ID 248 length 28 (16180) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (16180) [eap] = ok (16180) } # authorize = ok (16180) Found Auth-Type = EAP (16180) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (16180) authenticate { (16180) eap: Peer sent packet with method EAP Identity (1) (16180) eap: Calling submodule eap_ttls to process data (16180) eap_ttls: Initiating new EAP-TLS session (16180) eap_ttls: [eaptls start] = request (16180) eap: Sending EAP Request (code 1) ID 249 length 6 (16180) eap: EAP session adding &reply:State = 0xb7828561b77b903c (16180) [eap] = handled (16180) } # authenticate = handled (16180) Using Post-Auth-Type Challenge (16180) Post-Auth-Type sub-section not found. Ignoring. (16180) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (16180) Sent Access-Challenge Id 135 from 80.251.40.8:1812 to 80.251.40.40:54942 length 0 (16180) EAP-Message = 0x01f900061520 (16180) Message-Authenticator = 0x00000000000000000000000000000000 (16180) State = 0xb7828561b77b903c4f6473e0f27d0e52 (16180) Finished request Waking up in 0.2 seconds. Thanks.

2 1