- Freeradius-Users - lists.freeradius.org

Very rare failure to expand Foreach-Variable
by Graham Clinch 20 Feb '19

20 Feb '19

Once or twice per day - after many tens of thousands of requests have been successfully processed, a single request will not be processed as expected - freeradius doens't crash and there's no sign of memory corruption - further requests continue to be processed as expected. Originally this was seen on v3.0.12, but I have taken one server up to 3.0.x revision 694d088 from git and continue to see this. Running with -t to disable threading has not helped. There's a lot of custom unlang in the configuration. When run with -xx, I observe one line is missing for requests that failed. Here's a snippet from one of the failing requests: -=- radiusd[7451]: (85278) update { radiusd[7451]: (85278) &control:LU-SQL-Bridge-Exploded-Result := &control:LU-SQL-Bridge-Result -> "&request:LU-NE-Id := 2\n&control:LU-SQL-Bridge-Return-Code := noop" radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) update { radiusd[7451]: (85278) &control:LU-SQL-Bridge-Return-Code !* ANY radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) EXPAND %{explode:control:LU-SQL-Bridge-Exploded-Result } radiusd[7451]: (85278) --> 2 radiusd[7451]: (85278) foreach &control:LU-SQL-Bridge-Exploded-Result radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85278) EXPAND Foreach-Variable-0 radiusd[7451]: (85278) --> &request:LU-NE-Id := 2 radiusd[7451]: (85278) EXPAND %{map:%{Foreach-Variable-0}} radiusd[7451]: (85278) --> radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) -> TRUE radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85278) update { radiusd[7451]: (85278) &request:Module-Failure-Message += 'SQL bridge result contains invalid map fragment' radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) [fail] = fail -=- And here is one (with identical inputs) that was processed as expected: -=- radiusd[7451]: (85308) update { radiusd[7451]: (85308) &control:LU-SQL-Bridge-Exploded-Result := &control:LU-SQL-Bridge-Result -> "&request:LU-NE-Id := 2\n&control:LU-SQL-Bridge-Return-Code := noop" radiusd[7451]: (85308) } # update = noop radiusd[7451]: (85308) update { radiusd[7451]: (85308) &control:LU-SQL-Bridge-Return-Code !* ANY radiusd[7451]: (85308) } # update = noop radiusd[7451]: (85308) EXPAND %{explode:control:LU-SQL-Bridge-Exploded-Result } radiusd[7451]: (85308) --> 2 radiusd[7451]: (85308) foreach &control:LU-SQL-Bridge-Exploded-Result radiusd[7451]: (85308) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85308) EXPAND Foreach-Variable-0 radiusd[7451]: (85308) --> &request:LU-NE-Id := 2 radiusd[7451]: (85308) &request:LU-NE-Id := 2 radiusd[7451]: (85308) EXPAND %{map:%{Foreach-Variable-0}} radiusd[7451]: (85308) --> 1 radiusd[7451]: (85308) if ("%{map:%{Foreach-Variable-0}}" != 1) -> FALSE -=- The line missing is '&request:LU-NE-Id := 2' - between "--> &request:LU-NE-Id := 2" and "EXPAND %{map:%{Foreach-Variable-0}}". I infer that the value of "&request:LU-NE-Id := 2" is not being returned from the expansion properly and thus map is being passed an empty string. I've had a glance around tmpl.c and modcall.c but I'm not making much progress working out where the variable value is normally printed. Can somebody more in touch with the unlang processor point me in the right direction? Graham

3 9

WG: New Message (sent by contact form at Network RADIUS)
by Schmid, Marco 20 Feb '19

20 Feb '19

Here's my question again. See the mail-history below! Greetings Marco Schmid Mit freundlichen Grüßen Marco Schmid Technik indasys connectivity GmbH Leitzstraße 4c D-70469 Stuttgart Telefon: +49 (711) 896659-110 Telefax: +49 (711) 896659-149 E-Mail: Marco.Schmid(a)indasys.de Web: www.indasys.de USID: DE273320932 HRB: 734651 AG Stuttgart Geschäftsführer: Sebastian Schwab, Dominik Appich -----Ursprüngliche Nachricht----- Von: Alan DeKok <aland(a)networkradius.com> Gesendet: Mittwoch, 20. Februar 2019 13:03 An: Schmid, Marco <Marco.Schmid(a)indasys.de> Betreff: Re: New Message (sent by contact form at Network RADIUS) > On Feb 20, 2019, at 4:24 AM, Schmid, Marco <Marco.Schmid(a)indasys.de> wrote: > > Hello Marc, My name is Alan, as seen in the email address. > but the documentation doesn't match with my log-entries: There are very good reasons for that. Again, we offer paid support. Free support is available on on freeradius-users mailing list. > For example, our freeradius-server logs this: >>>> > Sun Jan 27 12:28:28 2019 > Packet-Type = Access-Request > User-Name = "benedikt.schumacher" > NAS-IP-Address = 10.94.9.225 > NAS-Port = 0 > NAS-Identifier = "192.168.1.1" > NAS-Port-Type = Wireless-802.11 > Calling-Station-Id = "C0F4E6E0F137" > Called-Station-Id = "204C030306E8" > Service-Type = Framed-User > Framed-MTU = 1100 > EAP-Message = 0x020700061900 > State = 0x687fd3fb6d78cae55e81868c3d7bf0c0 > Aruba-Essid-Name = "ITS_L" > Aruba-Location-Id = "SWIS-AP92___1" > Aruba-AP-Group = "default" > Message-Authenticator = 0xdca6dccb7ca000b7fb4667d5f4bc3fc6 > Event-Timestamp = "Jan 27 2019 12:28:28 CET" > Timestamp = 1548588508 > <<< > > There's no "Acct-session-ID" like in your documentation: > https://wiki.freeradius.org/protocol/Disconnect%20Messages > > And for some reason, the "NAS-IP-Address" is wrong. > Because 10.94.9.225 is the Address for the server itself. > I'm waiting for your answer. > > > Greetings > Marco Schmid > Mit freundlichen Grüßen > > Marco Schmid > Technik > > > > indasys connectivity GmbH > Leitzstraße 4c > D-70469 Stuttgart > > Telefon: +49 (711) 896659-110 > Telefax: +49 (711) 896659-149 > E-Mail: Marco.Schmid(a)indasys.de > Web: www.indasys.de > > > > > USID: DE273320932 > HRB: 734651 AG Stuttgart > > Geschäftsführer: Sebastian Schwab, Dominik Appich -----Ursprüngliche > Nachricht----- > Von: Alan DeKok <aland(a)networkradius.com> > Gesendet: Montag, 18. Februar 2019 21:50 > An: Schmid, Marco <Marco.Schmid(a)indasys.de> > Cc: Rozier Marc <marc.rozier(a)networkradius.com> > Betreff: Re: New Message (sent by contact form at Network RADIUS) > > >> Person: Marco Schmid >> Email: marco.schmid(a)indasys.de >> >> We use FreeRADIUS Version 3.0.13 >> How can I trigger a CoA disconnect of an user? > > We're happy to help. Our support rates are available on our web site: > > https://networkradius.com/freeradius-support/index.html > > Or, free support is available via the "freeradius-users" mailing list. > >> According this instruction: >> https://kabellosblog.wordpress.com/2017/07/17/generating-coa-disconne >> cts-with-freeradius/ > > The server comes with extensive documentation, including how to trigger Disconnect-Request packets. There's usually no need to go to third-party web sites. Those sites are almost always out of date, or just wrong. > >> I should see a Session-ID in the Accept-Log: >> Acct-Session-Id = "607985949699040123" >> >> >> But in my log, I see this for example: >> Mon Jan 28 07:42:20 2019 >> Packet-Type = Access-Request >> User-Name = "g.ast" >> NAS-IP-Address = 10.94.9.225 >> NAS-Port = 0 >> NAS-Identifier = "192.168.1.1" >> NAS-Port-Type = Wireless-802.11 >> Calling-Station-Id = "9094971FA4F6" >> Called-Station-Id = "204C030306E8" >> Service-Type = Framed-User >> Framed-MTU = 1100 >> EAP-Message = 0x020b002e190017030300230000000000000004a1cf274ed5c660a3938195ef7110c99940f1edd77150dd82077959 >> State = 0x0eed3eba07e627368a56cd2bd5106f5c >> Aruba-Essid-Name = "ITS_L" >> Aruba-Location-Id = "24:f2:7f:c4:6e:dc" >> Aruba-AP-Group = "default" >> Aruba-Device-Type = "Linux" >> Message-Authenticator = 0x6df008dad3f18858f1720b6678d7b9bf >> Event-Timestamp = "Jan 28 2019 07:42:20 CET" >> Timestamp = 1548657740 >

2 1

Remotely monitoring server activity
by R3DNano 20 Feb '19

20 Feb '19

I'm trying to manage the global freeradius status from a remote location. The files under /var/log/radius/radacct are pretty detailed and have a lot of information about what is going on with the freeradius server. However, searching the old mailing list archives, I see there's a particular thread of someone asking how to send the radacct logs to a remote syslog being not a recommended practice. What's a practical way of having this information for further analysis outside of the freeradius server? Send it to an SQL database somehow perhaps? Also, about the logs sent to syslog (for further forwarding to a remote syslog server) - is there a way to customize what's being sent on those messages? Thanks.

6 9

What is a difference "Auth-Type eap"(with Auth-Type) and "eap"(without Auth-Type) in the "authenticate" section?
by Hiroyuki Sato 20 Feb '19

20 Feb '19

Hello, members. Could you tell me what is a difference "Auth-Type eap"(with Auth-Type) and "eap"(without Auth-Type) in the "authenticate" section? Below is an example. What document should I read? Best regards. (1) MS-CHAP authenticate { # # MSCHAP authentication. Auth-Type MS-CHAP { mschap } # # For old names, too. # mschap } (2) EAP authenticate { eap # # The older configurations sent a number of attributes in # Access-Challenge packets, which wasn't strictly correct. # If you want to filter out these attributes, uncomment # the following lines. # Auth-Type eap { eap { handled = 1 } if (handled && (Response-Packet-Type == Access-Challenge)) { attr_filter.access_challenge.post-auth handled # override the "updated" code from attr_filter } } } Environment * OS: CentOS7 * FreeRADIUS: 3.0.13 -- Hiroyuki Sato

2 4

A few questions about radsec
by work vlpl 19 Feb '19

19 Feb '19

Hello, I successfully configured freeradius server to support radsec and using radsecproxy to test it. But I have a few questions. I tried to find answers in the example configuration files, but it looks like there aren’t Why "Initial implementation" https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/raddb/sites-ava… something important is not supported yet? If I understand radsec rfc correctly there are 3 possible ways to identify clients https://tools.ietf.org/html/draft-ietf-radext-radsec-12#section-2.4 by rfc all 3 should use some part of client certificate or TLS identifier. But judging by configuration in `tls` file I assume that freeradius uses ip address + certificate. Or only ip address if `proto = tcp` https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/raddb/sites-ava… Am I right? It is very unlikely, but what if I will have to, or I will want to proxy radsec request to home server without client certificate (TLS-PSK). I should removed only secret value from configuration https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/raddb/sites-ava… ? To test radsec I used radsecproxy + radlclient/eapol_test. Is there any other worthy utility for this? This is the quote from RFC Introduction https://tools.ietf.org/html/draft-ietf-radext-radsec-12#section-1 > The new features in RADIUS over TLS obsolete the use of IP addresses and shared MD5 secrets to identify other peers and thus allow the use of more contemporary trust models, e.g. checking a certificate by inspecting the issuer and other certificate properties. I'm interested in radius clients identification. Is it possible to get radius client id in radius config section that support unlang? For example CN or fingerprint from radius client certificate, like its by done for EAP-TLS request. -- Vladimir

3 6

Applying the same rule to multiple values in an attribute/config value
by Stefan Paetow 17 Feb '19

17 Feb '19

Howdy! So, we're reviving the old RFC7542 chestnut because we've found that there is appetite for it. The basic policy for it is done, but a question was raised about the capability to apply the functionality to multiple realms. The basics are this: if (&request:User-Name =~ /([a-zA-Z0-9\.-]+)!([a-zA-Z0-9\.-]*)\(a)(.+)/) { # Store the three parts of the User-Name, store the original User-Name too update control { RFC7542-User-Name := &User-Name } # Format: not_local_realm!...@local_realm: Rewrite User-Name for suffix if (("%{1}" != "${policy.rfc7542_suffix}") && ("%{3}" == "${policy.rfc7542_suffix}")) { update request { User-Name := "%{2}@%{1}" } } # Format: local_realm!...@not_local_realm: Rewrite User-Name for suffix if (("%{1}" == "${policy.rfc7542_suffix}") && ("%{3}" != "${policy.rfc7542_suffix}")) { update request { User-Name := "%{2}@%{1}" } } # end of if suffix # Restore the User-Name to its original glory. if (&control:RFC7542-User-Name && (&request:User-Name != &control:RFC7542-User-Name)) { update request { User-Name := &control:RFC7542-User-Name } update control { RFC7542-User-Name !* ANY } } The question now is the '$policy.rfc7542_suffix' bit. This is currently just defined as a simple value, i.e. 'blahblah.realm'. If we were to define it as a multiple value (semicolon-separated), would it make sense to use a foreach() loop across it, turn each entry into a variable and just check if the value is contained in the regex? The worry I have here is that there's a lot of processing to do, a lot of looping, and if the powers that be (Alan, Arran, Matthew et al) have a better suggestion, I'd love to hear it. Please remember, this is for 3.0.x, with looking at upstreaming this to you guys to give FR RFC7542 capabilities. I await your suggestions :-) With Regards Stefan Paetow Consultant, Trust and Identity t: +44 (0)1235 822 125 gpg: 0x3FCE5142 xmpp: stefanp(a)jabber.dev.ja.net skype: stefan.paetow.janet jisc.ac.uk Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc’s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800.

4 22

changed from 2.2.8 to FreeRADIUS Version 3.0.16 now Access-Reject
by Stefan Rudat 16 Feb '19

16 Feb '19

Hello I struggle analysing the trace file finding the miss-configuration. I change the server ( daloRADIUS FreeRADIUS Version 2.2.8 to FreeRADIUS Version 3.0 ) and get now always Access-Reject. It would be very useful to get a hint how to go forward, I’m to blind to find my fault works perfekt FreeRADIUS Version 2.2.8, for host x86_64-pc-linux-gnu, built on Jul 26 2017 at 15:27:21 Sent Access-Reject FreeRADIUS Version 3.0.16, for host x86_64-pc-linux-gnu, built on Feb 28 2018 at 06:51:17 maybe that is the reason why it fails ?? "Authentication will fail unless a "known good" password is available“ mysql +----+----------+--------------------+----+-----------+ | id | username | attribute | op | value | +----+----------+--------------------+----+-----------+ | 5 | stefan | Cleartext-Password | := | frankfurt | +----+----------+--------------------+----+-----------+ +----+----------------+-----------+-------+-------+------------+--------+-----------+-------------+ | id | nasname | shortname | type | ports | secret | server | community | description | +----+----------------+-----------+-------+-------+------------+--------+-----------+-------------+ | 1 | 192.168.178.27 | local | other | 0 | testing123 | | | | | 2 | 127.0.0.1 | localhost | other | 0 | testing123 | | | | +----+----------------+-----------+-------+-------+------------+--------+-----------+-------------+ radtest stefan frankfurt localhost 18128 testing123 Sent Access-Request Id 205 from 0.0.0.0:38947 to 127.0.0.1:1812 length 76 User-Name = "stefan" User-Password = "frankfurt" NAS-IP-Address = 192.168.178.27 NAS-Port = 18128 Message-Authenticator = 0x00 Cleartext-Password = "frankfurt" Received Access-Reject Id 205 from 127.0.0.1:1812 to 0.0.0.0:0 length 20 (0) -: Expected Access-Accept got Access-Reject I see : Debug: (0) sql: SQL query returned: success WARNING: (1) pap: No "known good" password found for the user. Not setting Auth-Type WARNING: (1) pap: Authentication will fail unless a "known good" password is available ERROR: (1) No Auth-Type found: rejecting the user via Post-Auth-Type = Reject Debug: (0) attr_filter.access_reject: --> stefan Debug: (0) attr_filter.access_reject: Matched entry DEFAULT at line 11 Below the trace and the default ------------------------------ trace ------------------------------------- freeradius -Xxxx Fri Feb 15 22:33:18 2019 : Debug: Server was built with: Fri Feb 15 22:33:18 2019 : Debug: accounting : yes Fri Feb 15 22:33:18 2019 : Debug: authentication : yes Fri Feb 15 22:33:18 2019 : Debug: ascend-binary-attributes : yes Fri Feb 15 22:33:18 2019 : Debug: coa : yes Fri Feb 15 22:33:18 2019 : Debug: control-socket : yes Fri Feb 15 22:33:18 2019 : Debug: detail : yes Fri Feb 15 22:33:18 2019 : Debug: dhcp : yes Fri Feb 15 22:33:18 2019 : Debug: dynamic-clients : yes Fri Feb 15 22:33:18 2019 : Debug: osfc2 : no Fri Feb 15 22:33:18 2019 : Debug: proxy : yes Fri Feb 15 22:33:18 2019 : Debug: regex-pcre : yes Fri Feb 15 22:33:18 2019 : Debug: regex-posix : no Fri Feb 15 22:33:18 2019 : Debug: regex-posix-extended : no Fri Feb 15 22:33:18 2019 : Debug: session-management : yes Fri Feb 15 22:33:18 2019 : Debug: stats : yes Fri Feb 15 22:33:18 2019 : Debug: tcp : yes Fri Feb 15 22:33:18 2019 : Debug: threads : yes Fri Feb 15 22:33:18 2019 : Debug: tls : yes Fri Feb 15 22:33:18 2019 : Debug: unlang : yes Fri Feb 15 22:33:18 2019 : Debug: vmps : yes Fri Feb 15 22:33:18 2019 : Debug: developer : no Fri Feb 15 22:33:18 2019 : Debug: Server core libs: Fri Feb 15 22:33:18 2019 : Debug: freeradius-server : 3.0.16 Fri Feb 15 22:33:18 2019 : Debug: talloc : 2.1.* Fri Feb 15 22:33:18 2019 : Debug: ssl : 1.1.0g release Fri Feb 15 22:33:18 2019 : Debug: pcre : 8.39 2016-06-14 Fri Feb 15 22:33:18 2019 : Debug: Endianness: Fri Feb 15 22:33:18 2019 : Debug: little Fri Feb 15 22:33:18 2019 : Debug: Compilation flags: Fri Feb 15 22:33:18 2019 : Debug: cppflags : -Wdate-time -D_FORTIFY_SOURCE=2 Fri Feb 15 22:33:18 2019 : Debug: cflags : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g -O2 -fdebug-prefix-map=/build/freeradius-4V8Upi/freeradius-3.0.16+dfsg=. -fstack-protector-strong -Wformat -Werror=format-security -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Fri Feb 15 22:33:18 2019 : Debug: ldflags : -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now Fri Feb 15 22:33:18 2019 : Debug: libs : -lcrypto -lssl -ltalloc -lpcre -lcap -lnsl -lresolv -ldl -lpthread -lreadline Fri Feb 15 22:33:18 2019 : Debug: Fri Feb 15 22:33:18 2019 : Info: FreeRADIUS Version 3.0.16 Fri Feb 15 22:33:18 2019 : Info: Copyright (C) 1999-2017 The FreeRADIUS server project and contributors Fri Feb 15 22:33:18 2019 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Fri Feb 15 22:33:18 2019 : Info: PARTICULAR PURPOSE Fri Feb 15 22:33:18 2019 : Info: You may redistribute copies of FreeRADIUS under the terms of the Fri Feb 15 22:33:18 2019 : Info: GNU General Public License Fri Feb 15 22:33:18 2019 : Info: For more information about these matters, see the file named COPYRIGHT Fri Feb 15 22:33:18 2019 : Info: Starting - reading configuration files ... Fri Feb 15 22:33:18 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary Fri Feb 15 22:33:18 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary.dhcp Fri Feb 15 22:33:18 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary.vqp Fri Feb 15 22:33:18 2019 : Debug: including dictionary file /etc/freeradius/3.0/dictionary Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/radiusd.conf Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/proxy.conf Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/clients.conf Fri Feb 15 22:33:18 2019 : Debug: including files in directory /etc/freeradius/3.0/mods-enabled/ Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/replicate Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/cache_eap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/echo Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/expr Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/logintime Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/sql Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/main/sqlite/queries.conf Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/files Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/exec Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/utf8 Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/sradutmp Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/linelog Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/soh Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/expiration Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/detail Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/pap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/mschap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/ntlm_auth Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/unpack Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/passwd Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/chap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/eap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/digest Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/preprocess Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/dynamic_clients Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/radutmp Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/unix Fri Feb 15 22:33:18 2019 : Debug: including files in directory /etc/freeradius/3.0/policy.d/ Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/canonicalization Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/cui Fri Feb 15 22:33:18 2019 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Feb 15 22:33:18 2019 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Feb 15 22:33:18 2019 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Feb 15 22:33:18 2019 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/filter Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/operator-name Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/debug Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/dhcp Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/abfab-tr Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/accounting Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/moonshot-targeted-ids Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/eap Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/control Fri Feb 15 22:33:18 2019 : Debug: including files in directory /etc/freeradius/3.0/sites-enabled/ Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/sites-enabled/default Fri Feb 15 22:33:18 2019 : Debug: including configuration file /etc/freeradius/3.0/sites-enabled/inner-tunnel Fri Feb 15 22:33:18 2019 : Debug: main { Fri Feb 15 22:33:18 2019 : Debug: security { Fri Feb 15 22:33:18 2019 : Debug: user = "freerad" Fri Feb 15 22:33:18 2019 : Debug: group = "freerad" Fri Feb 15 22:33:18 2019 : Debug: allow_core_dumps = no Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[424]: The item 'max_attributes' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[442]: The item 'reject_delay' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[462]: The item 'status_server' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: name = "freeradius" Fri Feb 15 22:33:18 2019 : Debug: prefix = "/usr" Fri Feb 15 22:33:18 2019 : Debug: localstatedir = "/var" Fri Feb 15 22:33:18 2019 : Debug: logdir = "/var/log/freeradius" Fri Feb 15 22:33:18 2019 : Debug: run_dir = "/var/run/freeradius" Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[108]: The item 'libdir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[119]: The item 'pidfile' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[194]: The item 'max_request_time' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[213]: The item 'cleanup_delay' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[250]: The item 'hostname_lookups' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[334]: The item 'checkrad' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[483]: The item 'proxy_requests' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: main { Fri Feb 15 22:33:18 2019 : Debug: name = "freeradius" Fri Feb 15 22:33:18 2019 : Debug: prefix = "/usr" Fri Feb 15 22:33:18 2019 : Debug: localstatedir = "/var" Fri Feb 15 22:33:18 2019 : Debug: sbindir = "/usr/sbin" Fri Feb 15 22:33:18 2019 : Debug: logdir = "/var/log/freeradius" Fri Feb 15 22:33:18 2019 : Debug: run_dir = "/var/run/freeradius" Fri Feb 15 22:33:18 2019 : Debug: libdir = "/usr/lib/freeradius" Fri Feb 15 22:33:18 2019 : Debug: radacctdir = "/var/log/freeradius/radacct" Fri Feb 15 22:33:18 2019 : Debug: hostname_lookups = no Fri Feb 15 22:33:18 2019 : Debug: max_request_time = 30 Fri Feb 15 22:33:18 2019 : Debug: cleanup_delay = 5 Fri Feb 15 22:33:18 2019 : Debug: max_requests = 16384 Fri Feb 15 22:33:18 2019 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Fri Feb 15 22:33:18 2019 : Debug: checkrad = "/usr/sbin/checkrad" Fri Feb 15 22:33:18 2019 : Debug: debug_level = 0 Fri Feb 15 22:33:18 2019 : Debug: proxy_requests = yes Fri Feb 15 22:33:18 2019 : Debug: log { Fri Feb 15 22:33:18 2019 : Debug: stripped_names = no Fri Feb 15 22:33:18 2019 : Debug: auth = no Fri Feb 15 22:33:18 2019 : Debug: auth_badpass = no Fri Feb 15 22:33:18 2019 : Debug: auth_goodpass = no Fri Feb 15 22:33:18 2019 : Debug: colourise = yes Fri Feb 15 22:33:18 2019 : Debug: msg_denied = "You are already logged in - access denied" Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[268]: The item 'destination' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[285]: The item 'file' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[293]: The item 'syslog_facility' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: resources { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: security { Fri Feb 15 22:33:18 2019 : Debug: max_attributes = 200 Fri Feb 15 22:33:18 2019 : Debug: reject_delay = 1.000000 Fri Feb 15 22:33:18 2019 : Debug: status_server = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: radiusd: #### Loading Realms and Home Servers #### Fri Feb 15 22:33:18 2019 : Debug: proxy server { Fri Feb 15 22:33:18 2019 : Debug: retry_delay = 5 Fri Feb 15 22:33:18 2019 : Debug: retry_count = 3 Fri Feb 15 22:33:18 2019 : Debug: default_fallback = no Fri Feb 15 22:33:18 2019 : Debug: dead_time = 120 Fri Feb 15 22:33:18 2019 : Debug: wake_all_if_all_dead = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: home_server localhost { Fri Feb 15 22:33:18 2019 : Debug: ipaddr = 127.0.0.1 Fri Feb 15 22:33:18 2019 : Debug: port = 1812 Fri Feb 15 22:33:18 2019 : Debug: type = "auth" Fri Feb 15 22:33:18 2019 : Debug: secret = "testing123" Fri Feb 15 22:33:18 2019 : Debug: response_window = 20.000000 Fri Feb 15 22:33:18 2019 : Debug: response_timeouts = 1 Fri Feb 15 22:33:18 2019 : Debug: max_outstanding = 65536 Fri Feb 15 22:33:18 2019 : Debug: zombie_period = 40 Fri Feb 15 22:33:18 2019 : Debug: status_check = "status-server" Fri Feb 15 22:33:18 2019 : Debug: ping_interval = 30 Fri Feb 15 22:33:18 2019 : Debug: check_interval = 30 Fri Feb 15 22:33:18 2019 : Debug: check_timeout = 4 Fri Feb 15 22:33:18 2019 : Debug: num_answers_to_alive = 3 Fri Feb 15 22:33:18 2019 : Debug: revive_interval = 120 Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: max_requests = 0 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 0 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: coa { Fri Feb 15 22:33:18 2019 : Debug: irt = 2 Fri Feb 15 22:33:18 2019 : Debug: mrt = 16 Fri Feb 15 22:33:18 2019 : Debug: mrc = 5 Fri Feb 15 22:33:18 2019 : Debug: mrd = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: home_server_pool my_auth_failover { Fri Feb 15 22:33:18 2019 : Debug: type = fail-over Fri Feb 15 22:33:18 2019 : Debug: home_server = localhost Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: realm example.com { Fri Feb 15 22:33:18 2019 : Debug: auth_pool = my_auth_failover Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: realm LOCAL { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: radiusd: #### Loading Clients #### Fri Feb 15 22:33:18 2019 : Debug: client localhost { Fri Feb 15 22:33:18 2019 : Debug: ipaddr = 127.0.0.1 Fri Feb 15 22:33:18 2019 : Debug: require_message_authenticator = no Fri Feb 15 22:33:18 2019 : Debug: secret = "testing123" Fri Feb 15 22:33:18 2019 : Debug: nas_type = "other" Fri Feb 15 22:33:18 2019 : Debug: proto = "*" Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Fri Feb 15 22:33:18 2019 : Debug: client localhost_ipv6 { Fri Feb 15 22:33:18 2019 : Debug: ipv6addr = ::1 Fri Feb 15 22:33:18 2019 : Debug: require_message_authenticator = no Fri Feb 15 22:33:18 2019 : Debug: secret = "testing123" Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Fri Feb 15 22:33:18 2019 : Info: Debugger not attached Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = mschap Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = digest Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = eap Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = PAP Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = CHAP Fri Feb 15 22:33:18 2019 : Debug: # Creating Auth-Type = MS-CHAP Fri Feb 15 22:33:18 2019 : Debug: radiusd: #### Instantiating modules #### Fri Feb 15 22:33:18 2019 : Debug: modules { Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_replicate with path: /usr/lib/freeradius/rlm_replicate.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_replicate, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_replicate Fri Feb 15 22:33:18 2019 : Debug: # Loading module "replicate" from file /etc/freeradius/3.0/mods-enabled/replicate Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_cache with path: /usr/lib/freeradius/rlm_cache.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_cache, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_cache Fri Feb 15 22:33:18 2019 : Debug: # Loading module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap Fri Feb 15 22:33:18 2019 : Debug: cache cache_eap { Fri Feb 15 22:33:18 2019 : Debug: driver = "rlm_cache_rbtree" Fri Feb 15 22:33:18 2019 : Debug: key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" Fri Feb 15 22:33:18 2019 : Debug: ttl = 15 Fri Feb 15 22:33:18 2019 : Debug: max_entries = 0 Fri Feb 15 22:33:18 2019 : Debug: epoch = 0 Fri Feb 15 22:33:18 2019 : Debug: add_stats = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_attr_filter with path: /usr/lib/freeradius/rlm_attr_filter.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_attr_filter, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_attr_filter Fri Feb 15 22:33:18 2019 : Debug: # Loading module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: attr_filter attr_filter.post-proxy { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/post-proxy" Fri Feb 15 22:33:18 2019 : Debug: key = "%{Realm}" Fri Feb 15 22:33:18 2019 : Debug: relaxed = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: attr_filter attr_filter.pre-proxy { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/pre-proxy" Fri Feb 15 22:33:18 2019 : Debug: key = "%{Realm}" Fri Feb 15 22:33:18 2019 : Debug: relaxed = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: attr_filter attr_filter.access_reject { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_reject" Fri Feb 15 22:33:18 2019 : Debug: key = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: relaxed = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: attr_filter attr_filter.access_challenge { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_challenge" Fri Feb 15 22:33:18 2019 : Debug: key = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: relaxed = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: attr_filter attr_filter.accounting_response { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/accounting_response" Fri Feb 15 22:33:18 2019 : Debug: key = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: relaxed = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_exec with path: /usr/lib/freeradius/rlm_exec.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_exec, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_exec Fri Feb 15 22:33:18 2019 : Debug: # Loading module "echo" from file /etc/freeradius/3.0/mods-enabled/echo Fri Feb 15 22:33:18 2019 : Debug: exec echo { Fri Feb 15 22:33:18 2019 : Debug: wait = yes Fri Feb 15 22:33:18 2019 : Debug: program = "/bin/echo %{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: input_pairs = "request" Fri Feb 15 22:33:18 2019 : Debug: output_pairs = "reply" Fri Feb 15 22:33:18 2019 : Debug: shell_escape = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_expr with path: /usr/lib/freeradius/rlm_expr.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_expr, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_expr Fri Feb 15 22:33:18 2019 : Debug: # Loading module "expr" from file /etc/freeradius/3.0/mods-enabled/expr Fri Feb 15 22:33:18 2019 : Debug: expr { Fri Feb 15 22:33:18 2019 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_logintime with path: /usr/lib/freeradius/rlm_logintime.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_logintime, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_logintime Fri Feb 15 22:33:18 2019 : Debug: # Loading module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime Fri Feb 15 22:33:18 2019 : Debug: logintime { Fri Feb 15 22:33:18 2019 : Debug: minimum_timeout = 60 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_always with path: /usr/lib/freeradius/rlm_always.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_always, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_always Fri Feb 15 22:33:18 2019 : Debug: # Loading module "reject" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always reject { Fri Feb 15 22:33:18 2019 : Debug: rcode = "reject" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "fail" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always fail { Fri Feb 15 22:33:18 2019 : Debug: rcode = "fail" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "ok" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always ok { Fri Feb 15 22:33:18 2019 : Debug: rcode = "ok" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "handled" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always handled { Fri Feb 15 22:33:18 2019 : Debug: rcode = "handled" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "invalid" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always invalid { Fri Feb 15 22:33:18 2019 : Debug: rcode = "invalid" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "userlock" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always userlock { Fri Feb 15 22:33:18 2019 : Debug: rcode = "userlock" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "notfound" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always notfound { Fri Feb 15 22:33:18 2019 : Debug: rcode = "notfound" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "noop" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always noop { Fri Feb 15 22:33:18 2019 : Debug: rcode = "noop" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "updated" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: always updated { Fri Feb 15 22:33:18 2019 : Debug: rcode = "updated" Fri Feb 15 22:33:18 2019 : Debug: simulcount = 0 Fri Feb 15 22:33:18 2019 : Debug: mpp = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_sql with path: /usr/lib/freeradius/rlm_sql.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_sql, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_sql Fri Feb 15 22:33:18 2019 : Debug: # Loading module "sql" from file /etc/freeradius/3.0/mods-enabled/sql Fri Feb 15 22:33:18 2019 : Debug: sql { Fri Feb 15 22:33:18 2019 : Debug: driver = "rlm_sql_null" Fri Feb 15 22:33:18 2019 : Debug: server = "" Fri Feb 15 22:33:18 2019 : Debug: port = 0 Fri Feb 15 22:33:18 2019 : Debug: login = "" Fri Feb 15 22:33:18 2019 : Debug: password = "7z36tat" Fri Feb 15 22:33:18 2019 : Debug: radius_db = "radius" Fri Feb 15 22:33:18 2019 : Debug: read_groups = yes Fri Feb 15 22:33:18 2019 : Debug: read_profiles = yes Fri Feb 15 22:33:18 2019 : Debug: read_clients = yes Fri Feb 15 22:33:18 2019 : Debug: delete_stale_sessions = yes Fri Feb 15 22:33:18 2019 : Debug: sql_user_name = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: default_user_profile = "" Fri Feb 15 22:33:18 2019 : Debug: client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Fri Feb 15 22:33:18 2019 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Fri Feb 15 22:33:18 2019 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Fri Feb 15 22:33:18 2019 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id" Fri Feb 15 22:33:18 2019 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id" Fri Feb 15 22:33:18 2019 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Fri Feb 15 22:33:18 2019 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Fri Feb 15 22:33:18 2019 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-Group}' AND acctstoptime IS NULL" Fri Feb 15 22:33:18 2019 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Fri Feb 15 22:33:18 2019 : Debug: accounting { Fri Feb 15 22:33:18 2019 : Debug: reference = "%{tolower:type.%{Acct-Status-Type}.query}" Fri Feb 15 22:33:18 2019 : Debug: type { Fri Feb 15 22:33:18 2019 : Debug: accounting-on { Fri Feb 15 22:33:18 2019 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime= (%{%{integer:Event-Timestamp}:-strftime('%%s', 'now')} - strftime('%%s', acctstarttime)), acctterminatecause = '%{Acct-Terminate-Cause}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= %{integer:Event-Timestamp}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: accounting-off { Fri Feb 15 22:33:18 2019 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime= (%{%{integer:Event-Timestamp}:-strftime('%%s', 'now')} - strftime('%%s', acctstarttime)), acctterminatecause = '%{Acct-Terminate-Cause}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= %{integer:Event-Timestamp}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: start { Fri Feb 15 22:33:18 2019 : Debug: 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 ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', %{%{integer:Event-Timestamp}:-date('now')}, %{%{integer:Event-Timestamp}:-date('now')}, NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: interim-update { Fri Feb 15 22:33:18 2019 : Debug: query = "UPDATE radacct SET acctupdatetime = %{%{integer:Event-Timestamp}:-date('now')}, acctinterval = 0, framedipaddress = '%{Framed-IP-Address}', acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = %{%{Acct-Input-Gigawords}:-0} << 32 | %{%{Acct-Input-Octets}:-0}, acctoutputoctets = %{%{Acct-Output-Gigawords}:-0} << 32 | %{%{Acct-Output-Octets}:-0} WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: stop { Fri Feb 15 22:33:18 2019 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = %{%{Acct-Input-Gigawords}:-0} << 32 | %{%{Acct-Input-Octets}:-0}, acctoutputoctets = %{%{Acct-Output-Gigawords}:-0} << 32 | %{%{Acct-Output-Octets}:-0}, acctterminatecause = '%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: post-auth { Fri Feb 15 22:33:18 2019 : Debug: reference = ".query" Fri Feb 15 22:33:18 2019 : Debug: query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_sql_null with path: /usr/lib/freeradius/rlm_sql_null.so Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Driver rlm_sql_null (module rlm_sql_null) loaded and linked Fri Feb 15 22:33:18 2019 : Debug: Creating attribute SQL-Group Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_detail with path: /usr/lib/freeradius/rlm_detail.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_detail, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_detail Fri Feb 15 22:33:18 2019 : Debug: # Loading module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: detail auth_log { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Fri Feb 15 22:33:18 2019 : Debug: header = "%t" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: locking = no Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: log_packet_header = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: detail reply_log { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Fri Feb 15 22:33:18 2019 : Debug: header = "%t" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: locking = no Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: log_packet_header = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: detail pre_proxy_log { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Fri Feb 15 22:33:18 2019 : Debug: header = "%t" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: locking = no Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: log_packet_header = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: detail post_proxy_log { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Fri Feb 15 22:33:18 2019 : Debug: header = "%t" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: locking = no Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: log_packet_header = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_files with path: /usr/lib/freeradius/rlm_files.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_files, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_files Fri Feb 15 22:33:18 2019 : Debug: # Loading module "files" from file /etc/freeradius/3.0/mods-enabled/files Fri Feb 15 22:33:18 2019 : Debug: files { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/files/authorize" Fri Feb 15 22:33:18 2019 : Debug: acctusersfile = "/etc/freeradius/3.0/mods-config/files/accounting" Fri Feb 15 22:33:18 2019 : Debug: preproxy_usersfile = "/etc/freeradius/3.0/mods-config/files/pre-proxy" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "exec" from file /etc/freeradius/3.0/mods-enabled/exec Fri Feb 15 22:33:18 2019 : Debug: exec { Fri Feb 15 22:33:18 2019 : Debug: wait = no Fri Feb 15 22:33:18 2019 : Debug: input_pairs = "request" Fri Feb 15 22:33:18 2019 : Debug: shell_escape = yes Fri Feb 15 22:33:18 2019 : Debug: timeout = 10 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_utf8 with path: /usr/lib/freeradius/rlm_utf8.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_utf8, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_utf8 Fri Feb 15 22:33:18 2019 : Debug: # Loading module "utf8" from file /etc/freeradius/3.0/mods-enabled/utf8 Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_radutmp with path: /usr/lib/freeradius/rlm_radutmp.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_radutmp, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_radutmp Fri Feb 15 22:33:18 2019 : Debug: # Loading module "sradutmp" from file /etc/freeradius/3.0/mods-enabled/sradutmp Fri Feb 15 22:33:18 2019 : Debug: radutmp sradutmp { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/sradutmp" Fri Feb 15 22:33:18 2019 : Debug: username = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: case_sensitive = yes Fri Feb 15 22:33:18 2019 : Debug: check_with_nas = yes Fri Feb 15 22:33:18 2019 : Debug: permissions = 420 Fri Feb 15 22:33:18 2019 : Debug: caller_id = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_linelog with path: /usr/lib/freeradius/rlm_linelog.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_linelog, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_linelog Fri Feb 15 22:33:18 2019 : Debug: # Loading module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog Fri Feb 15 22:33:18 2019 : Debug: linelog { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/linelog" Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: syslog_severity = "info" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: format = "This is a log message for %{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog Fri Feb 15 22:33:18 2019 : Debug: linelog log_accounting { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/linelog-accounting" Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: syslog_severity = "info" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: format = "" Fri Feb 15 22:33:18 2019 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_soh with path: /usr/lib/freeradius/rlm_soh.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_soh, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_soh Fri Feb 15 22:33:18 2019 : Debug: # Loading module "soh" from file /etc/freeradius/3.0/mods-enabled/soh Fri Feb 15 22:33:18 2019 : Debug: soh { Fri Feb 15 22:33:18 2019 : Debug: dhcp = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_realm with path: /usr/lib/freeradius/rlm_realm.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_realm, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_realm Fri Feb 15 22:33:18 2019 : Debug: # Loading module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: realm IPASS { Fri Feb 15 22:33:18 2019 : Debug: format = "prefix" Fri Feb 15 22:33:18 2019 : Debug: delimiter = "/" Fri Feb 15 22:33:18 2019 : Debug: ignore_default = no Fri Feb 15 22:33:18 2019 : Debug: ignore_null = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: realm suffix { Fri Feb 15 22:33:18 2019 : Debug: format = "suffix" Fri Feb 15 22:33:18 2019 : Debug: delimiter = "@" Fri Feb 15 22:33:18 2019 : Debug: ignore_default = no Fri Feb 15 22:33:18 2019 : Debug: ignore_null = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: realm realmpercent { Fri Feb 15 22:33:18 2019 : Debug: format = "suffix" Fri Feb 15 22:33:18 2019 : Debug: delimiter = "%" Fri Feb 15 22:33:18 2019 : Debug: ignore_default = no Fri Feb 15 22:33:18 2019 : Debug: ignore_null = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: realm ntdomain { Fri Feb 15 22:33:18 2019 : Debug: format = "prefix" Fri Feb 15 22:33:18 2019 : Debug: delimiter = "\\" Fri Feb 15 22:33:18 2019 : Debug: ignore_default = no Fri Feb 15 22:33:18 2019 : Debug: ignore_null = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_expiration with path: /usr/lib/freeradius/rlm_expiration.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_expiration, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_expiration Fri Feb 15 22:33:18 2019 : Debug: # Loading module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration Fri Feb 15 22:33:18 2019 : Debug: # Loading module "detail" from file /etc/freeradius/3.0/mods-enabled/detail Fri Feb 15 22:33:18 2019 : Debug: detail { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Fri Feb 15 22:33:18 2019 : Debug: header = "%t" Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: locking = no Fri Feb 15 22:33:18 2019 : Debug: escape_filenames = no Fri Feb 15 22:33:18 2019 : Debug: log_packet_header = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_pap with path: /usr/lib/freeradius/rlm_pap.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_pap, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_pap Fri Feb 15 22:33:18 2019 : Debug: # Loading module "pap" from file /etc/freeradius/3.0/mods-enabled/pap Fri Feb 15 22:33:18 2019 : Debug: pap { Fri Feb 15 22:33:18 2019 : Debug: normalise = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_mschap with path: /usr/lib/freeradius/rlm_mschap.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_mschap, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_mschap Fri Feb 15 22:33:18 2019 : Debug: # Loading module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap Fri Feb 15 22:33:18 2019 : Debug: mschap { Fri Feb 15 22:33:18 2019 : Debug: use_mppe = yes Fri Feb 15 22:33:18 2019 : Debug: require_encryption = no Fri Feb 15 22:33:18 2019 : Debug: require_strong = no Fri Feb 15 22:33:18 2019 : Debug: with_ntdomain_hack = yes Fri Feb 15 22:33:18 2019 : Debug: passchange { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: allow_retry = yes Fri Feb 15 22:33:18 2019 : Debug: winbind_retry_with_normalised_username = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Loading module "ntlm_auth" from file /etc/freeradius/3.0/mods-enabled/ntlm_auth Fri Feb 15 22:33:18 2019 : Debug: exec ntlm_auth { Fri Feb 15 22:33:18 2019 : Debug: wait = yes Fri Feb 15 22:33:18 2019 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Fri Feb 15 22:33:18 2019 : Debug: shell_escape = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_unpack with path: /usr/lib/freeradius/rlm_unpack.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_unpack, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_unpack Fri Feb 15 22:33:18 2019 : Debug: # Loading module "unpack" from file /etc/freeradius/3.0/mods-enabled/unpack Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_passwd with path: /usr/lib/freeradius/rlm_passwd.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_passwd, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_passwd Fri Feb 15 22:33:18 2019 : Debug: # Loading module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd Fri Feb 15 22:33:18 2019 : Debug: passwd etc_passwd { Fri Feb 15 22:33:18 2019 : Debug: filename = "/etc/passwd" Fri Feb 15 22:33:18 2019 : Debug: format = "*User-Name:Crypt-Password:" Fri Feb 15 22:33:18 2019 : Debug: delimiter = ":" Fri Feb 15 22:33:18 2019 : Debug: ignore_nislike = no Fri Feb 15 22:33:18 2019 : Debug: ignore_empty = yes Fri Feb 15 22:33:18 2019 : Debug: allow_multiple_keys = no Fri Feb 15 22:33:18 2019 : Debug: hash_size = 100 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_chap with path: /usr/lib/freeradius/rlm_chap.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_chap, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_chap Fri Feb 15 22:33:18 2019 : Debug: # Loading module "chap" from file /etc/freeradius/3.0/mods-enabled/chap Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap with path: /usr/lib/freeradius/rlm_eap.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_eap, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_eap Fri Feb 15 22:33:18 2019 : Debug: # Loading module "eap" from file /etc/freeradius/3.0/mods-enabled/eap Fri Feb 15 22:33:18 2019 : Debug: eap { Fri Feb 15 22:33:18 2019 : Debug: default_eap_type = "md5" Fri Feb 15 22:33:18 2019 : Debug: timer_expire = 60 Fri Feb 15 22:33:18 2019 : Debug: ignore_unknown_eap_types = no Fri Feb 15 22:33:18 2019 : Debug: cisco_accounting_username_bug = no Fri Feb 15 22:33:18 2019 : Debug: max_sessions = 16384 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_digest with path: /usr/lib/freeradius/rlm_digest.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_digest, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_digest Fri Feb 15 22:33:18 2019 : Debug: # Loading module "digest" from file /etc/freeradius/3.0/mods-enabled/digest Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_preprocess with path: /usr/lib/freeradius/rlm_preprocess.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_preprocess, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_preprocess Fri Feb 15 22:33:18 2019 : Debug: # Loading module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess Fri Feb 15 22:33:18 2019 : Debug: preprocess { Fri Feb 15 22:33:18 2019 : Debug: huntgroups = "/etc/freeradius/3.0/mods-config/preprocess/huntgroups" Fri Feb 15 22:33:18 2019 : Debug: hints = "/etc/freeradius/3.0/mods-config/preprocess/hints" Fri Feb 15 22:33:18 2019 : Debug: with_ascend_hack = no Fri Feb 15 22:33:18 2019 : Debug: ascend_channels_per_line = 23 Fri Feb 15 22:33:18 2019 : Debug: with_ntdomain_hack = no Fri Feb 15 22:33:18 2019 : Debug: with_specialix_jetstream_hack = no Fri Feb 15 22:33:18 2019 : Debug: with_cisco_vsa_hack = no Fri Feb 15 22:33:18 2019 : Debug: with_alvarion_vsa_hack = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_dynamic_clients with path: /usr/lib/freeradius/rlm_dynamic_clients.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_dynamic_clients Fri Feb 15 22:33:18 2019 : Debug: # Loading module "dynamic_clients" from file /etc/freeradius/3.0/mods-enabled/dynamic_clients Fri Feb 15 22:33:18 2019 : Debug: # Loading module "radutmp" from file /etc/freeradius/3.0/mods-enabled/radutmp Fri Feb 15 22:33:18 2019 : Debug: radutmp { Fri Feb 15 22:33:18 2019 : Debug: filename = "/var/log/freeradius/radutmp" Fri Feb 15 22:33:18 2019 : Debug: username = "%{User-Name}" Fri Feb 15 22:33:18 2019 : Debug: case_sensitive = yes Fri Feb 15 22:33:18 2019 : Debug: check_with_nas = yes Fri Feb 15 22:33:18 2019 : Debug: permissions = 384 Fri Feb 15 22:33:18 2019 : Debug: caller_id = yes Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_unix with path: /usr/lib/freeradius/rlm_unix.so Fri Feb 15 22:33:18 2019 : Debug: Loaded rlm_unix, checking if it's valid Fri Feb 15 22:33:18 2019 : Debug: # Loaded module rlm_unix Fri Feb 15 22:33:18 2019 : Debug: # Loading module "unix" from file /etc/freeradius/3.0/mods-enabled/unix Fri Feb 15 22:33:18 2019 : Debug: unix { Fri Feb 15 22:33:18 2019 : Debug: radwtmp = "/var/log/freeradius/radwtmp" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Creating attribute Unix-Group Fri Feb 15 22:33:18 2019 : Debug: instantiate { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_cache_rbtree with path: /usr/lib/freeradius/rlm_cache_rbtree.so Fri Feb 15 22:33:18 2019 : Debug: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/post-proxy Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/pre-proxy Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_reject Fri Feb 15 22:33:18 2019 : Warning: [/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Feb 15 22:33:18 2019 : Warning: [/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec"found in filter list for realm "DEFAULT". Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_challenge Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/accounting_response Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "reject" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "fail" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "ok" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "handled" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "invalid" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "userlock" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "notfound" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "noop" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "updated" from file /etc/freeradius/3.0/mods-enabled/always Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "sql" from file /etc/freeradius/3.0/mods-enabled/sql Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Using local pool section Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): No pool reference found for config item "sql.pool" Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Initialising connection pool Fri Feb 15 22:33:18 2019 : Debug: pool { Fri Feb 15 22:33:18 2019 : Debug: start = 5 Fri Feb 15 22:33:18 2019 : Debug: min = 3 Fri Feb 15 22:33:18 2019 : Debug: max = 32 Fri Feb 15 22:33:18 2019 : Debug: spare = 10 Fri Feb 15 22:33:18 2019 : Debug: uses = 0 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: cleanup_interval = 30 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 60 Fri Feb 15 22:33:18 2019 : Debug: retry_delay = 30 Fri Feb 15 22:33:18 2019 : Debug: spread = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (0), 1 of 32 pending slots used Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (1), 1 of 31 pending slots used Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (2), 1 of 30 pending slots used Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (3), 1 of 29 pending slots used Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (4), 1 of 28 pending slots used Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Adding pool reference 0x55f6c43879a0 to config item "sql.pool" Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Processing generate_sql_clients Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Reserved connection (0) Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Executing select query: SELECT id, nasname, shortname, type, secret, server FROM nas Fri Feb 15 22:33:18 2019 : Debug: rlm_sql (sql): Released connection (0) Fri Feb 15 22:33:18 2019 : Info: Need 5 more connections to reach 10 spares Fri Feb 15 22:33:18 2019 : Info: rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "files" from file /etc/freeradius/3.0/mods-enabled/files Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/authorize Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/accounting Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/pre-proxy Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "detail" from file /etc/freeradius/3.0/mods-enabled/detail Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "pap" from file /etc/freeradius/3.0/mods-enabled/pap Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap Fri Feb 15 22:33:18 2019 : Debug: rlm_mschap (mschap): using internal authentication Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd Fri Feb 15 22:33:18 2019 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "eap" from file /etc/freeradius/3.0/mods-enabled/eap Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_md5 with path: /usr/lib/freeradius/rlm_eap_md5.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_md5 Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_leap with path: /usr/lib/freeradius/rlm_eap_leap.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_leap Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_gtc with path: /usr/lib/freeradius/rlm_eap_gtc.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_gtc Fri Feb 15 22:33:18 2019 : Debug: gtc { Fri Feb 15 22:33:18 2019 : Debug: challenge = "Password: " Fri Feb 15 22:33:18 2019 : Debug: auth_type = "PAP" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_tls with path: /usr/lib/freeradius/rlm_eap_tls.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_tls Fri Feb 15 22:33:18 2019 : Debug: tls { Fri Feb 15 22:33:18 2019 : Debug: tls = "tls-common" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: tls-config tls-common { Fri Feb 15 22:33:18 2019 : Debug: verify_depth = 0 Fri Feb 15 22:33:18 2019 : Debug: ca_path = "/etc/freeradius/3.0/certs" Fri Feb 15 22:33:18 2019 : Debug: pem_file_type = yes Fri Feb 15 22:33:18 2019 : Debug: private_key_file = "/etc/ssl/private/ssl-cert-snakeoil.key" Fri Feb 15 22:33:18 2019 : Debug: certificate_file = "/etc/ssl/certs/ssl-cert-snakeoil.pem" Fri Feb 15 22:33:18 2019 : Debug: ca_file = "/etc/ssl/certs/ca-certificates.crt" Fri Feb 15 22:33:18 2019 : Debug: private_key_password = "whatever" Fri Feb 15 22:33:18 2019 : Debug: dh_file = "/etc/freeradius/3.0/certs/dh" Fri Feb 15 22:33:18 2019 : Debug: fragment_size = 1024 Fri Feb 15 22:33:18 2019 : Debug: include_length = yes Fri Feb 15 22:33:18 2019 : Debug: auto_chain = yes Fri Feb 15 22:33:18 2019 : Debug: check_crl = no Fri Feb 15 22:33:18 2019 : Debug: check_all_crl = no Fri Feb 15 22:33:18 2019 : Debug: cipher_list = "DEFAULT" Fri Feb 15 22:33:18 2019 : Debug: cipher_server_preference = no Fri Feb 15 22:33:18 2019 : Debug: ecdh_curve = "prime256v1" Fri Feb 15 22:33:18 2019 : Debug: tls_max_version = "" Fri Feb 15 22:33:18 2019 : Debug: tls_min_version = "1.0" Fri Feb 15 22:33:18 2019 : Debug: cache { Fri Feb 15 22:33:18 2019 : Debug: enable = no Fri Feb 15 22:33:18 2019 : Debug: lifetime = 24 Fri Feb 15 22:33:18 2019 : Debug: max_entries = 255 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: verify { Fri Feb 15 22:33:18 2019 : Debug: skip_if_ocsp_ok = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: ocsp { Fri Feb 15 22:33:18 2019 : Debug: enable = no Fri Feb 15 22:33:18 2019 : Debug: override_cert_url = yes Fri Feb 15 22:33:18 2019 : Debug: url = "http://127.0.0.1/ocsp/" Fri Feb 15 22:33:18 2019 : Debug: use_nonce = yes Fri Feb 15 22:33:18 2019 : Debug: timeout = 0 Fri Feb 15 22:33:18 2019 : Debug: softfail = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_ttls with path: /usr/lib/freeradius/rlm_eap_ttls.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_ttls Fri Feb 15 22:33:18 2019 : Debug: ttls { Fri Feb 15 22:33:18 2019 : Debug: tls = "tls-common" Fri Feb 15 22:33:18 2019 : Debug: default_eap_type = "md5" Fri Feb 15 22:33:18 2019 : Debug: copy_request_to_tunnel = no Fri Feb 15 22:33:18 2019 : Debug: use_tunneled_reply = no Fri Feb 15 22:33:18 2019 : Debug: virtual_server = "inner-tunnel" Fri Feb 15 22:33:18 2019 : Debug: include_length = yes Fri Feb 15 22:33:18 2019 : Debug: require_client_cert = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: tls: Using cached TLS configuration from previous invocation Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_peap with path: /usr/lib/freeradius/rlm_eap_peap.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_peap Fri Feb 15 22:33:18 2019 : Debug: peap { Fri Feb 15 22:33:18 2019 : Debug: tls = "tls-common" Fri Feb 15 22:33:18 2019 : Debug: default_eap_type = "mschapv2" Fri Feb 15 22:33:18 2019 : Debug: copy_request_to_tunnel = no Fri Feb 15 22:33:18 2019 : Debug: use_tunneled_reply = no Fri Feb 15 22:33:18 2019 : Debug: proxy_tunneled_request_as_eap = yes Fri Feb 15 22:33:18 2019 : Debug: virtual_server = "inner-tunnel" Fri Feb 15 22:33:18 2019 : Debug: soh = no Fri Feb 15 22:33:18 2019 : Debug: require_client_cert = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: tls: Using cached TLS configuration from previous invocation Fri Feb 15 22:33:18 2019 : Debug: Loading rlm_eap_mschapv2 with path: /usr/lib/freeradius/rlm_eap_mschapv2.so Fri Feb 15 22:33:18 2019 : Debug: # Linked to sub-module rlm_eap_mschapv2 Fri Feb 15 22:33:18 2019 : Debug: mschapv2 { Fri Feb 15 22:33:18 2019 : Debug: with_ntdomain_hack = no Fri Feb 15 22:33:18 2019 : Debug: send_error = no Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: # Instantiating module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/huntgroups Fri Feb 15 22:33:18 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/hints Fri Feb 15 22:33:18 2019 : Debug: } # modules Fri Feb 15 22:33:18 2019 : Debug: radiusd: #### Loading Virtual Servers #### Fri Feb 15 22:33:18 2019 : Debug: server { # from file /etc/freeradius/3.0/radiusd.conf Fri Feb 15 22:33:18 2019 : Debug: } # server Fri Feb 15 22:33:18 2019 : Debug: server default { # from file /etc/freeradius/3.0/sites-enabled/default Fri Feb 15 22:33:18 2019 : Debug: authenticate { Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: pap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: chap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: digest Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: } # authenticate Fri Feb 15 22:33:18 2019 : Debug: authorize { Fri Feb 15 22:33:18 2019 : Debug: policy filter_username { Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name) { Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ / /) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /@[^@]*@/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /\.\./) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /(a)(.+)\.(.+)$/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /\.$/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /(a)\./) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: preprocess Fri Feb 15 22:33:18 2019 : Debug: chap Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: digest Fri Feb 15 22:33:18 2019 : Debug: suffix Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: files Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Feb 15 22:33:18 2019 : Debug: expiration Fri Feb 15 22:33:18 2019 : Debug: logintime Fri Feb 15 22:33:18 2019 : Debug: pap Fri Feb 15 22:33:18 2019 : Debug: } # authorize Fri Feb 15 22:33:18 2019 : Debug: preacct { Fri Feb 15 22:33:18 2019 : Debug: preprocess Fri Feb 15 22:33:18 2019 : Debug: policy acct_unique { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Tmp-String-9 := "ai:" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if ("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/ && "%{string:&Class}" =~ /^ai:([0-9a-f]{32})/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: else { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: suffix Fri Feb 15 22:33:18 2019 : Debug: files Fri Feb 15 22:33:18 2019 : Debug: } # preacct Fri Feb 15 22:33:18 2019 : Debug: accounting { Fri Feb 15 22:33:18 2019 : Debug: detail Fri Feb 15 22:33:18 2019 : Debug: unix Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Debug: exec Fri Feb 15 22:33:18 2019 : Debug: attr_filter.accounting_response Fri Feb 15 22:33:18 2019 : Debug: } # accounting Fri Feb 15 22:33:18 2019 : Debug: post-proxy { Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: } # post-proxy Fri Feb 15 22:33:18 2019 : Debug: post-auth { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &reply:[*] += &session-state:[*] Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Debug: exec Fri Feb 15 22:33:18 2019 : Debug: policy remove_reply_message_if_eap { Fri Feb 15 22:33:18 2019 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &reply:Reply-Message !* ANY Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: else { Fri Feb 15 22:33:18 2019 : Debug: noop Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Debug: attr_filter.access_reject Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: policy remove_reply_message_if_eap { Fri Feb 15 22:33:18 2019 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &reply:Reply-Message !* ANY Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: else { Fri Feb 15 22:33:18 2019 : Debug: noop Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } # post-auth Fri Feb 15 22:33:18 2019 : Debug: } # server default Fri Feb 15 22:33:18 2019 : Debug: server inner-tunnel { # from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Fri Feb 15 22:33:18 2019 : Debug: authenticate { Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: pap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: chap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: } # authenticate Fri Feb 15 22:33:18 2019 : Debug: authorize { Fri Feb 15 22:33:18 2019 : Debug: policy filter_username { Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name) { Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ / /) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /@[^@]*@/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /\.\./) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /(a)(.+)\.(.+)$/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /\.$/) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: if (&User-Name =~ /(a)\./) { Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: reject Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: chap Fri Feb 15 22:33:18 2019 : Debug: mschap Fri Feb 15 22:33:18 2019 : Debug: suffix Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &control:Proxy-To-Realm := LOCAL Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: files Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Debug: expiration Fri Feb 15 22:33:18 2019 : Debug: logintime Fri Feb 15 22:33:18 2019 : Debug: pap Fri Feb 15 22:33:18 2019 : Debug: } # authorize Fri Feb 15 22:33:18 2019 : Debug: session { Fri Feb 15 22:33:18 2019 : Debug: radutmp Fri Feb 15 22:33:18 2019 : Debug: } # session Fri Feb 15 22:33:18 2019 : Debug: post-proxy { Fri Feb 15 22:33:18 2019 : Debug: eap Fri Feb 15 22:33:18 2019 : Debug: } # post-proxy Fri Feb 15 22:33:18 2019 : Debug: post-auth { Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Info: # Skipping contents of 'if' as it is always 'false' -- /etc/freeradius/3.0/sites-enabled/inner-tunnel:331 Fri Feb 15 22:33:18 2019 : Debug: if (false) { Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: group { Fri Feb 15 22:33:18 2019 : Debug: sql Fri Feb 15 22:33:18 2019 : Debug: attr_filter.access_reject Fri Feb 15 22:33:18 2019 : Debug: update { Fri Feb 15 22:33:18 2019 : Debug: &outer.session-state:Module-Failure-Message := &Module-Failure-Message Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } # post-auth Fri Feb 15 22:33:18 2019 : Debug: } # server inner-tunnel Fri Feb 15 22:33:18 2019 : Debug: Created signal pipe. Read end FD 5, write end FD 6 Fri Feb 15 22:33:18 2019 : Debug: radiusd: #### Opening IP addresses and Ports #### Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth with path: /usr/lib/freeradius/proto_auth.so Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth failed: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory - No such file or directory Fri Feb 15 22:33:18 2019 : Debug: Loading library using linker search path(s) Fri Feb 15 22:33:18 2019 : Debug: Defaults : /lib:/usr/lib Fri Feb 15 22:33:18 2019 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 15 22:33:18 2019 : Debug: listen { Fri Feb 15 22:33:18 2019 : Debug: type = "auth" Fri Feb 15 22:33:18 2019 : Debug: ipaddr = * Fri Feb 15 22:33:18 2019 : Debug: port = 0 Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading proto_acct with path: /usr/lib/freeradius/proto_acct.so Fri Feb 15 22:33:18 2019 : Debug: Loading proto_acct failed: /usr/lib/freeradius/proto_acct.so: cannot open shared object file: No such file or directory - No such file or directory Fri Feb 15 22:33:18 2019 : Debug: Loading library using linker search path(s) Fri Feb 15 22:33:18 2019 : Debug: Defaults : /lib:/usr/lib Fri Feb 15 22:33:18 2019 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 15 22:33:18 2019 : Debug: listen { Fri Feb 15 22:33:18 2019 : Debug: type = "acct" Fri Feb 15 22:33:18 2019 : Debug: ipaddr = * Fri Feb 15 22:33:18 2019 : Debug: port = 0 Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth with path: /usr/lib/freeradius/proto_auth.so Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth failed: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory - No such file or directory Fri Feb 15 22:33:18 2019 : Debug: Loading library using linker search path(s) Fri Feb 15 22:33:18 2019 : Debug: Defaults : /lib:/usr/lib Fri Feb 15 22:33:18 2019 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 15 22:33:18 2019 : Debug: listen { Fri Feb 15 22:33:18 2019 : Debug: type = "auth" Fri Feb 15 22:33:18 2019 : Debug: ipv6addr = :: Fri Feb 15 22:33:18 2019 : Debug: port = 0 Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading proto_acct with path: /usr/lib/freeradius/proto_acct.so Fri Feb 15 22:33:18 2019 : Debug: Loading proto_acct failed: /usr/lib/freeradius/proto_acct.so: cannot open shared object file: No such file or directory - No such file or directory Fri Feb 15 22:33:18 2019 : Debug: Loading library using linker search path(s) Fri Feb 15 22:33:18 2019 : Debug: Defaults : /lib:/usr/lib Fri Feb 15 22:33:18 2019 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 15 22:33:18 2019 : Debug: listen { Fri Feb 15 22:33:18 2019 : Debug: type = "acct" Fri Feb 15 22:33:18 2019 : Debug: ipv6addr = :: Fri Feb 15 22:33:18 2019 : Debug: port = 0 Fri Feb 15 22:33:18 2019 : Debug: limit { Fri Feb 15 22:33:18 2019 : Debug: max_connections = 16 Fri Feb 15 22:33:18 2019 : Debug: lifetime = 0 Fri Feb 15 22:33:18 2019 : Debug: idle_timeout = 30 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth with path: /usr/lib/freeradius/proto_auth.so Fri Feb 15 22:33:18 2019 : Debug: Loading proto_auth failed: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory - No such file or directory Fri Feb 15 22:33:18 2019 : Debug: Loading library using linker search path(s) Fri Feb 15 22:33:18 2019 : Debug: Defaults : /lib:/usr/lib Fri Feb 15 22:33:18 2019 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 15 22:33:18 2019 : Debug: listen { Fri Feb 15 22:33:18 2019 : Debug: type = "auth" Fri Feb 15 22:33:18 2019 : Debug: ipaddr = 127.0.0.1 Fri Feb 15 22:33:18 2019 : Debug: port = 18120 Fri Feb 15 22:33:18 2019 : Debug: } Fri Feb 15 22:33:18 2019 : Debug: Listening on auth address * port 1812 bound to server default Fri Feb 15 22:33:18 2019 : Debug: Listening on acct address * port 1813 bound to server default Fri Feb 15 22:33:18 2019 : Debug: Listening on auth address :: port 1812 bound to server default Fri Feb 15 22:33:18 2019 : Debug: Listening on acct address :: port 1813 bound to server default Fri Feb 15 22:33:18 2019 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Fri Feb 15 22:33:18 2019 : Debug: Opened new proxy socket 'proxy address * port 39213' Fri Feb 15 22:33:18 2019 : Debug: Listening on proxy address * port 39213 Fri Feb 15 22:33:18 2019 : Debug: Opened new proxy socket 'proxy address :: port 59111' Fri Feb 15 22:33:18 2019 : Debug: Listening on proxy address :: port 59111 Fri Feb 15 22:33:18 2019 : Info: Ready to process requests Fri Feb 15 22:33:29 2019 : Debug: (0) Received Access-Request Id 109 from 127.0.0.1:47161 to 127.0.0.1:1812 length 76 Fri Feb 15 22:33:29 2019 : Debug: (0) User-Name = "stefan" Fri Feb 15 22:33:29 2019 : Debug: (0) User-Password = "frankfurt" Fri Feb 15 22:33:29 2019 : Debug: (0) NAS-IP-Address = 192.168.178.27 Fri Feb 15 22:33:29 2019 : Debug: (0) NAS-Port = 18128 Fri Feb 15 22:33:29 2019 : Debug: (0) Message-Authenticator = 0x71950e3750476151d2f158fb0f53c12f Fri Feb 15 22:33:29 2019 : Debug: (0) session-state: No State attribute Fri Feb 15 22:33:29 2019 : Debug: (0) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default Fri Feb 15 22:33:29 2019 : Debug: (0) authorize { Fri Feb 15 22:33:29 2019 : Debug: (0) policy filter_username { Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name) { Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name) -> TRUE Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name) { Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ / /) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ / /) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /\.\./ ) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /\.\./ ) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /\.$/) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /\.$/) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /(a)\./) { Fri Feb 15 22:33:29 2019 : Debug: No matches Fri Feb 15 22:33:29 2019 : Debug: (0) if (&User-Name =~ /(a)\./) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) } # if (&User-Name) = notfound Fri Feb 15 22:33:29 2019 : Debug: (0) } # policy filter_username = notfound Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Feb 15 22:33:29 2019 : Debug: (0) [preprocess] = ok Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling chap (rlm_chap) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from chap (rlm_chap) Fri Feb 15 22:33:29 2019 : Debug: (0) [chap] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) Fri Feb 15 22:33:29 2019 : Debug: (0) [mschap] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling digest (rlm_digest) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from digest (rlm_digest) Fri Feb 15 22:33:29 2019 : Debug: (0) [digest] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) Fri Feb 15 22:33:29 2019 : Debug: (0) suffix: Checking for suffix after "@" Fri Feb 15 22:33:29 2019 : Debug: (0) suffix: No '@' in User-Name = "stefan", looking up realm NULL Fri Feb 15 22:33:29 2019 : Debug: (0) suffix: No such realm "NULL" Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) Fri Feb 15 22:33:29 2019 : Debug: (0) [suffix] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) Fri Feb 15 22:33:29 2019 : Debug: (0) eap: No EAP-Message, not doing EAP Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) Fri Feb 15 22:33:29 2019 : Debug: (0) [eap] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling files (rlm_files) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from files (rlm_files) Fri Feb 15 22:33:29 2019 : Debug: (0) [files] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling sql (rlm_sql) Fri Feb 15 22:33:29 2019 : Debug: %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: attribute --> User-Name Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> stefan Fri Feb 15 22:33:29 2019 : Debug: (0) sql: SQL-User-Name set to 'stefan' Fri Feb 15 22:33:29 2019 : Debug: rlm_sql (sql): Reserved connection (1) Fri Feb 15 22:33:29 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Fri Feb 15 22:33:29 2019 : Debug: attribute --> SQL-User-Name Fri Feb 15 22:33:29 2019 : Debug: literal --> ' ORDER BY id Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'stefan' ORDER BY id Fri Feb 15 22:33:29 2019 : Debug: (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'stefan' ORDER BY id Fri Feb 15 22:33:29 2019 : Debug: (0) sql: ... falling-through to group processing Fri Feb 15 22:33:29 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Fri Feb 15 22:33:29 2019 : Debug: attribute --> SQL-User-Name Fri Feb 15 22:33:29 2019 : Debug: literal --> ' ORDER BY priority Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'stefan' ORDER BY priority Fri Feb 15 22:33:29 2019 : Debug: (0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'stefan' ORDER BY priority Fri Feb 15 22:33:29 2019 : Debug: (0) sql: User not found in any groups Fri Feb 15 22:33:29 2019 : Debug: (0) sql: ... falling-through to profile processing Fri Feb 15 22:33:29 2019 : Debug: rlm_sql (sql): Released connection (1) Fri Feb 15 22:33:29 2019 : Info: Need 4 more connections to reach 10 spares Fri Feb 15 22:33:29 2019 : Info: rlm_sql (sql): Opening additional connection (6), 1 of 26 pending slots used Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from sql (rlm_sql) Fri Feb 15 22:33:29 2019 : Debug: (0) [sql] = notfound Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling expiration (rlm_expiration) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Feb 15 22:33:29 2019 : Debug: (0) [expiration] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling logintime (rlm_logintime) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Feb 15 22:33:29 2019 : Debug: (0) [logintime] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap) Fri Feb 15 22:33:29 2019 : WARNING: (0) pap: No "known good" password found for the user. Not setting Auth-Type Fri Feb 15 22:33:29 2019 : WARNING: (0) pap: Authentication will fail unless a "known good" password is available Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap) Fri Feb 15 22:33:29 2019 : Debug: (0) [pap] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) } # authorize = ok Fri Feb 15 22:33:29 2019 : ERROR: (0) No Auth-Type found: rejecting the user via Post-Auth-Type = Reject Fri Feb 15 22:33:29 2019 : Debug: (0) Failed to authenticate the user Fri Feb 15 22:33:29 2019 : Debug: (0) Using Post-Auth-Type Reject Fri Feb 15 22:33:29 2019 : Debug: (0) # Executing group from file /etc/freeradius/3.0/sites-enabled/default Fri Feb 15 22:33:29 2019 : Debug: (0) Post-Auth-Type REJECT { Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: calling sql (rlm_sql) Fri Feb 15 22:33:29 2019 : Debug: .query Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: literal --> .query Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND .query Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> .query Fri Feb 15 22:33:29 2019 : Debug: (0) sql: Using query template 'query' Fri Feb 15 22:33:29 2019 : Debug: rlm_sql (sql): Reserved connection (2) Fri Feb 15 22:33:29 2019 : Debug: %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: attribute --> User-Name Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> stefan Fri Feb 15 22:33:29 2019 : Debug: (0) sql: SQL-User-Name set to 'stefan' Fri Feb 15 22:33:29 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Fri Feb 15 22:33:29 2019 : Debug: attribute --> SQL-User-Name Fri Feb 15 22:33:29 2019 : Debug: literal --> ', ' Fri Feb 15 22:33:29 2019 : Debug: XLAT-IF { Fri Feb 15 22:33:29 2019 : Debug: attribute --> User-Password Fri Feb 15 22:33:29 2019 : Debug: } Fri Feb 15 22:33:29 2019 : Debug: XLAT-ELSE { Fri Feb 15 22:33:29 2019 : Debug: attribute --> CHAP-Password Fri Feb 15 22:33:29 2019 : Debug: } Fri Feb 15 22:33:29 2019 : Debug: literal --> ', ' Fri Feb 15 22:33:29 2019 : Debug: attribute --> Packet-Type Fri Feb 15 22:33:29 2019 : Debug: literal --> ', ' Fri Feb 15 22:33:29 2019 : Debug: percent --> S Fri Feb 15 22:33:29 2019 : Debug: literal --> ') Fri Feb 15 22:33:29 2019 : Debug: (0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Fri Feb 15 22:33:29 2019 : Debug: (0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'stefan', 'frankfurt', 'Access-Reject', '2019-02-15 22:33:29') Fri Feb 15 22:33:29 2019 : Debug: (0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'stefan', 'frankfurt', 'Access-Reject', '2019-02-15 22:33:29') Fri Feb 15 22:33:29 2019 : Debug: (0) sql: SQL query returned: success Fri Feb 15 22:33:29 2019 : Debug: (0) sql: 1 record(s) updated Fri Feb 15 22:33:29 2019 : Debug: rlm_sql (sql): Released connection (2) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: returned from sql (rlm_sql) Fri Feb 15 22:33:29 2019 : Debug: (0) [sql] = ok Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) Fri Feb 15 22:33:29 2019 : Debug: %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: Parsed xlat tree: Fri Feb 15 22:33:29 2019 : Debug: attribute --> User-Name Fri Feb 15 22:33:29 2019 : Debug: (0) attr_filter.access_reject: EXPAND %{User-Name} Fri Feb 15 22:33:29 2019 : Debug: (0) attr_filter.access_reject: --> stefan Fri Feb 15 22:33:29 2019 : Debug: (0) attr_filter.access_reject: Matched entry DEFAULT at line 11 Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) Fri Feb 15 22:33:29 2019 : Debug: (0) [attr_filter.access_reject] = updated Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: calling eap (rlm_eap) Fri Feb 15 22:33:29 2019 : Debug: (0) eap: Request didn't contain an EAP-Message, not inserting EAP-Failure Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: returned from eap (rlm_eap) Fri Feb 15 22:33:29 2019 : Debug: (0) [eap] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) policy remove_reply_message_if_eap { Fri Feb 15 22:33:29 2019 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) { Fri Feb 15 22:33:29 2019 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Fri Feb 15 22:33:29 2019 : Debug: (0) else { Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: calling noop (rlm_always) Fri Feb 15 22:33:29 2019 : Debug: (0) modsingle[post-auth]: returned from noop (rlm_always) Fri Feb 15 22:33:29 2019 : Debug: (0) [noop] = noop Fri Feb 15 22:33:29 2019 : Debug: (0) } # else = noop Fri Feb 15 22:33:29 2019 : Debug: (0) } # policy remove_reply_message_if_eap = noop Fri Feb 15 22:33:29 2019 : Debug: (0) } # Post-Auth-Type REJECT = updated Fri Feb 15 22:33:29 2019 : Debug: (0) Delaying response for 1.000000 seconds Fri Feb 15 22:33:29 2019 : Debug: Waking up in 0.3 seconds. Fri Feb 15 22:33:29 2019 : Debug: Waking up in 0.6 seconds. Fri Feb 15 22:33:30 2019 : Debug: (0) Sending delayed response Fri Feb 15 22:33:30 2019 : Debug: (0) Sent Access-Reject Id 109 from 127.0.0.1:1812 to 127.0.0.1:47161 length 20 Fri Feb 15 22:33:30 2019 : Debug: Waking up in 3.9 seconds. Fri Feb 15 22:33:34 2019 : Debug: (0) Cleaning up request packet ID 109 with timestamp +11 Fri Feb 15 22:33:34 2019 : Info: Ready to process requests ------------------------------ end trace ------------------------------------- server default { listen { type = auth ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { ipaddr = * port = 0 type = acct limit { } } listen { type = auth port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { ipv6addr = :: port = 0 type = acct limit { } } authorize { filter_username preprocess chap mschap digest suffix eap { ok = return } files -sql -ldap expiration logintime pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap digest eap } preacct { preprocess acct_unique suffix files } accounting { detail unix -sql exec attr_filter.accounting_response } session { } post-auth { update { &reply: += &session-state: } -sql exec remove_reply_message_if_eap Post-Auth-Type REJECT { -sql attr_filter.access_reject eap remove_reply_message_if_eap } Post-Auth-Type Challenge { } } pre-proxy { } post-proxy { eap } } ---------------------- end setting file ----------------------

2 2

iOS SSL issue
by Mankomal Singh 15 Feb '19

15 Feb '19

Hi, So I got everything working, and am able to run TLS in my android phone but when I try thru my iPhone or my MacBook I get SSL error on RADIUS debug. Amazingly same certificate work on my android phone without any issues. Can someone share what could be the issue? A snippet of the error: *(140) eap_tls: ERROR: TLS_accept: Failed in SSLv3 read client certificate A* *(140) eap_tls: ERROR: Failed in __FUNCTION__ (SSL_read): error:140940E5:SSL routines:ssl3_read_bytes:ssl handshake failure* *(140) eap_tls: ERROR: System call (I/O) error (-1)* *(140) eap_tls: ERROR: TLS receive handshake failed during operation* *(140) eap_tls: ERROR: [eaptls process] = fail* *(140) eap: ERROR: Failed continuing EAP TLS (13) session. EAP sub-module failed* Complete EAP debug from failed devices: (156) Received Access-Request Id 238 from 103.46.239.184:36499 to 192.168.253.6:1812 length 226 (156) Service-Type = Framed-User (156) Framed-MTU = 1400 (156) User-Name = "macbook" (156) NAS-Port-Id = "wlan1" (156) NAS-Port-Type = Wireless-802.11 (156) Acct-Session-Id = "8220002d" (156) Acct-Multi-Session-Id = "CC-2D-E0-39-24-A6-B8-C1-11-D1-4D-50-82-20-00-00-00-00-00-2D" (156) Calling-Station-Id = "B8-C1-11-D1-4D-50" (156) Called-Station-Id = "CC-2D-E0-39-24-A6:THIS IS A TEST" (156) EAP-Message = 0x0200000c016d6163626f6f6b (156) Message-Authenticator = 0x9b1b6d0c79559268e6cfb2a0cbe5240d (156) NAS-Identifier = "MikroTik" (156) NAS-IP-Address = 192.168.88.2 (156) # Executing section authorize from file /etc/raddb/sites-enabled/default (156) authorize { (156) policy filter_username { (156) if (&User-Name) { (156) if (&User-Name) -> TRUE (156) if (&User-Name) { (156) if (&User-Name =~ / /) { (156) if (&User-Name =~ / /) -> FALSE (156) if (&User-Name =~ /@[^@]*@/ ) { (156) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (156) if (&User-Name =~ /\.\./ ) { (156) if (&User-Name =~ /\.\./ ) -> FALSE (156) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (156) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (156) if (&User-Name =~ /\.$/) { (156) if (&User-Name =~ /\.$/) -> FALSE (156) if (&User-Name =~ /(a)\./) { (156) if (&User-Name =~ /(a)\./) -> FALSE (156) } # if (&User-Name) = notfound (156) } # policy filter_username = notfound (156) [preprocess] = ok (156) eap: Peer sent EAP Response (code 2) ID 0 length 12 (156) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (156) [eap] = ok (156) } # authorize = ok (156) Found Auth-Type = eap (156) # Executing group from file /etc/raddb/sites-enabled/default (156) authenticate { (156) eap: Peer sent packet with method EAP Identity (1) (156) eap: Calling submodule eap_tls to process data (156) eap_tls: Initiating new EAP-TLS session (156) eap_tls: Setting verify mode to require certificate from client (156) eap_tls: [eaptls start] = request (156) eap: Sending EAP Request (code 1) ID 1 length 6 (156) eap: EAP session adding &reply:State = 0xccf8f142ccf9fce7 (156) [eap] = handled (156) } # authenticate = handled (156) Using Post-Auth-Type Challenge (156) # Executing group from file /etc/raddb/sites-enabled/default (156) Challenge { ... } # empty sub-section is ignored (156) Sent Access-Challenge Id 238 from 192.168.253.6:1812 to 103.46.239.184:36499 length 0 (156) EAP-Message = 0x010100060d20 (156) Message-Authenticator = 0x00000000000000000000000000000000 (156) State = 0xccf8f142ccf9fce75307e48862cef384 (156) Finished request Waking up in 4.9 seconds. (157) Received Access-Request Id 239 from 103.46.239.184:40285 to 192.168.253.6:1812 length 393 (157) Service-Type = Framed-User (157) Framed-MTU = 1400 (157) User-Name = "macbook" (157) State = 0xccf8f142ccf9fce75307e48862cef384 (157) NAS-Port-Id = "wlan1" (157) NAS-Port-Type = Wireless-802.11 (157) Acct-Session-Id = "8220002d" (157) Acct-Multi-Session-Id = "CC-2D-E0-39-24-A6-B8-C1-11-D1-4D-50-82-20-00-00-00-00-00-2D" (157) Calling-Station-Id = "B8-C1-11-D1-4D-50" (157) Called-Station-Id = "CC-2D-E0-39-24-A6:THIS IS A TEST" (157) EAP-Message = 0x020100a10d800000009716030300920100008e03035c66eda3b9189d8cb5e4f5d1b7da29789b4f95dc78ef817aeb5462abc249b93100002c00ffc02cc02bc024c023c00ac009c008c030c02fc028c027c014c013c012009d009c003d003c0035002f000a01000039000a00080006001700180019000b00 (157) Message-Authenticator = 0xf775fc6bc1a0190eb8997ecbcbb51f4f (157) NAS-Identifier = "MikroTik" (157) NAS-IP-Address = 192.168.88.2 (157) session-state: No cached attributes (157) # Executing section authorize from file /etc/raddb/sites-enabled/default (157) authorize { (157) policy filter_username { (157) if (&User-Name) { (157) if (&User-Name) -> TRUE (157) if (&User-Name) { (157) if (&User-Name =~ / /) { (157) if (&User-Name =~ / /) -> FALSE (157) if (&User-Name =~ /@[^@]*@/ ) { (157) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (157) if (&User-Name =~ /\.\./ ) { (157) if (&User-Name =~ /\.\./ ) -> FALSE (157) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (157) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (157) if (&User-Name =~ /\.$/) { (157) if (&User-Name =~ /\.$/) -> FALSE (157) if (&User-Name =~ /(a)\./) { (157) if (&User-Name =~ /(a)\./) -> FALSE (157) } # if (&User-Name) = notfound (157) } # policy filter_username = notfound (157) [preprocess] = ok (157) eap: Peer sent EAP Response (code 2) ID 1 length 161 (157) eap: No EAP Start, assuming it's an on-going EAP conversation (157) [eap] = updated (157) sql: EXPAND %{User-Name} (157) sql: --> macbook (157) sql: SQL-User-Name set to 'macbook' rlm_sql (sql): Reserved connection (60) (157) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (157) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (157) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (157) sql: User found in radcheck table (157) sql: Conditional check items matched, merging assignment check items (157) sql: Auth-Type := eap (157) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (157) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id (157) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id *(157) sql: WARNING: Cannot do check groups when group_membership_query is not set* rlm_sql (sql): Released connection (60) *Need 7 more connections to reach 10 spares* *rlm_sql (sql): Opening additional connection (63), 1 of 29 pending slots used* rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.6.43, protocol version 10 (157) [sql] = ok (157) if (notfound) { (157) if (notfound) -> FALSE (157) [expiration] = noop (157) [logintime] = noop (157) [pap] = noop (157) } # authorize = updated (157) Found Auth-Type = eap (157) # Executing group from file /etc/raddb/sites-enabled/default (157) authenticate { (157) eap: Expiring EAP session with state 0xccf8f142ccf9fce7 (157) eap: Finished EAP session with state 0xccf8f142ccf9fce7 (157) eap: Previous EAP request found for state 0xccf8f142ccf9fce7, released from the list (157) eap: Peer sent packet with method EAP TLS (13) (157) eap: Calling submodule eap_tls to process data (157) eap_tls: Continuing EAP-TLS (157) eap_tls: Peer indicated complete TLS record size will be 151 bytes (157) eap_tls: Got complete TLS record (151 bytes) (157) eap_tls: [eaptls verify] = length included (157) eap_tls: (other): before/accept initialization (157) eap_tls: TLS_accept: before/accept initialization (157) eap_tls: <<< recv TLS 1.2 [length 0092] (157) eap_tls: TLS_accept: SSLv3 read client hello A (157) eap_tls: >>> send TLS 1.2 [length 0039] (157) eap_tls: TLS_accept: SSLv3 write server hello A (157) eap_tls: >>> send TLS 1.2 [length 06ee] (157) eap_tls: TLS_accept: SSLv3 write certificate A (157) eap_tls: >>> send TLS 1.2 [length 00cd] (157) eap_tls: TLS_accept: SSLv3 write key exchange A (157) eap_tls: >>> send TLS 1.2 [length 00a5] (157) eap_tls: TLS_accept: SSLv3 write certificate request A (157) eap_tls: TLS_accept: SSLv3 flush data (157) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (157) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (157) eap_tls: In SSL Handshake Phase (157) eap_tls: In SSL Accept mode (157) eap_tls: [eaptls process] = handled (157) eap: Sending EAP Request (code 1) ID 2 length 1024 (157) eap: EAP session adding &reply:State = 0xccf8f142cdfafce7 (157) [eap] = handled (157) } # authenticate = handled (157) Using Post-Auth-Type Challenge (157) # Executing group from file /etc/raddb/sites-enabled/default (157) Challenge { ... } # empty sub-section is ignored (157) Sent Access-Challenge Id 239 from 192.168.253.6:1812 to 103.46.239.184:40285 length 0 (157) EAP-Message = 0x010204000dc0000008ad160303003902000035030368fd206e3ef60d7fd094ee6184fa23ad9edd6bc23b529f88b11669a0e088a95700c03000000dff01000100000b00040300010216030306ee0b0006ea0006e70003a03082039c30820305a003020102020101300d06092a864886f70d010105050030 (157) Message-Authenticator = 0x00000000000000000000000000000000 (157) State = 0xccf8f142cdfafce75307e48862cef384 (157) Finished request Waking up in 4.9 seconds. (158) Received Access-Request Id 240 from 103.46.239.184:53647 to 192.168.253.6:1812 length 238 (158) Service-Type = Framed-User (158) Framed-MTU = 1400 (158) User-Name = "macbook" (158) State = 0xccf8f142cdfafce75307e48862cef384 (158) NAS-Port-Id = "wlan1" (158) NAS-Port-Type = Wireless-802.11 (158) Acct-Session-Id = "8220002d" (158) Acct-Multi-Session-Id = "CC-2D-E0-39-24-A6-B8-C1-11-D1-4D-50-82-20-00-00-00-00-00-2D" (158) Calling-Station-Id = "B8-C1-11-D1-4D-50" (158) Called-Station-Id = "CC-2D-E0-39-24-A6:THIS IS A TEST" (158) EAP-Message = 0x020200060d00 (158) Message-Authenticator = 0xb397d9cf688e3c16bfacd51e63ee0677 (158) NAS-Identifier = "MikroTik" (158) NAS-IP-Address = 192.168.88.2 (158) session-state: No cached attributes (158) # Executing section authorize from file /etc/raddb/sites-enabled/default (158) authorize { (158) policy filter_username { (158) if (&User-Name) { (158) if (&User-Name) -> TRUE (158) if (&User-Name) { (158) if (&User-Name =~ / /) { (158) if (&User-Name =~ / /) -> FALSE (158) if (&User-Name =~ /@[^@]*@/ ) { (158) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (158) if (&User-Name =~ /\.\./ ) { (158) if (&User-Name =~ /\.\./ ) -> FALSE (158) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (158) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (158) if (&User-Name =~ /\.$/) { (158) if (&User-Name =~ /\.$/) -> FALSE (158) if (&User-Name =~ /(a)\./) { (158) if (&User-Name =~ /(a)\./) -> FALSE (158) } # if (&User-Name) = notfound (158) } # policy filter_username = notfound (158) [preprocess] = ok (158) eap: Peer sent EAP Response (code 2) ID 2 length 6 (158) eap: No EAP Start, assuming it's an on-going EAP conversation (158) [eap] = updated (158) sql: EXPAND %{User-Name} (158) sql: --> macbook (158) sql: SQL-User-Name set to 'macbook' rlm_sql (sql): Reserved connection (62) (158) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (158) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (158) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (158) sql: User found in radcheck table (158) sql: Conditional check items matched, merging assignment check items (158) sql: Auth-Type := eap (158) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (158) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id (158) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id *(158) sql: WARNING: Cannot do check groups when group_membership_query is not set* rlm_sql (sql): Released connection (62) (158) [sql] = ok (158) if (notfound) { (158) if (notfound) -> FALSE (158) [expiration] = noop (158) [logintime] = noop (158) [pap] = noop (158) } # authorize = updated (158) Found Auth-Type = eap (158) # Executing group from file /etc/raddb/sites-enabled/default (158) authenticate { (158) eap: Expiring EAP session with state 0xccf8f142cdfafce7 (158) eap: Finished EAP session with state 0xccf8f142cdfafce7 (158) eap: Previous EAP request found for state 0xccf8f142cdfafce7, released from the list (158) eap: Peer sent packet with method EAP TLS (13) (158) eap: Calling submodule eap_tls to process data (158) eap_tls: Continuing EAP-TLS (158) eap_tls: Peer ACKed our handshake fragment (158) eap_tls: [eaptls verify] = request (158) eap_tls: [eaptls process] = handled (158) eap: Sending EAP Request (code 1) ID 3 length 1024 (158) eap: EAP session adding &reply:State = 0xccf8f142cefbfce7 (158) [eap] = handled (158) } # authenticate = handled (158) Using Post-Auth-Type Challenge (158) # Executing group from file /etc/raddb/sites-enabled/default (158) Challenge { ... } # empty sub-section is ignored (158) Sent Access-Challenge Id 240 from 192.168.253.6:1812 to 103.46.239.184:53647 length 0 (158) EAP-Message = 0x010304000dc0000008ad02a6a003020102020900b184f1d60648f80a300d06092a864886f70d01010b05003073310b300906035504061302494e310b3009060355040813024445310e300c0603550407130544656c6869310f300d060355040a130653686f757574311230100603550403130953686f75 (158) Message-Authenticator = 0x00000000000000000000000000000000 (158) State = 0xccf8f142cefbfce75307e48862cef384 (158) Finished request Waking up in 4.8 seconds. (159) Received Access-Request Id 241 from 103.46.239.184:58701 to 192.168.253.6:1812 length 238 (159) Service-Type = Framed-User (159) Framed-MTU = 1400 (159) User-Name = "macbook" (159) State = 0xccf8f142cefbfce75307e48862cef384 (159) NAS-Port-Id = "wlan1" (159) NAS-Port-Type = Wireless-802.11 (159) Acct-Session-Id = "8220002d" (159) Acct-Multi-Session-Id = "CC-2D-E0-39-24-A6-B8-C1-11-D1-4D-50-82-20-00-00-00-00-00-2D" (159) Calling-Station-Id = "B8-C1-11-D1-4D-50" (159) Called-Station-Id = "CC-2D-E0-39-24-A6:THIS IS A TEST" (159) EAP-Message = 0x020300060d00 (159) Message-Authenticator = 0x599b7d41483b5ff646d709190859ad41 (159) NAS-Identifier = "MikroTik" (159) NAS-IP-Address = 192.168.88.2 (159) session-state: No cached attributes (159) # Executing section authorize from file /etc/raddb/sites-enabled/default (159) authorize { (159) policy filter_username { (159) if (&User-Name) { (159) if (&User-Name) -> TRUE (159) if (&User-Name) { (159) if (&User-Name =~ / /) { (159) if (&User-Name =~ / /) -> FALSE (159) if (&User-Name =~ /@[^@]*@/ ) { (159) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (159) if (&User-Name =~ /\.\./ ) { (159) if (&User-Name =~ /\.\./ ) -> FALSE (159) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (159) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (159) if (&User-Name =~ /\.$/) { (159) if (&User-Name =~ /\.$/) -> FALSE (159) if (&User-Name =~ /(a)\./) { (159) if (&User-Name =~ /(a)\./) -> FALSE (159) } # if (&User-Name) = notfound (159) } # policy filter_username = notfound (159) [preprocess] = ok (159) eap: Peer sent EAP Response (code 2) ID 3 length 6 (159) eap: No EAP Start, assuming it's an on-going EAP conversation (159) [eap] = updated (159) sql: EXPAND %{User-Name} (159) sql: --> macbook (159) sql: SQL-User-Name set to 'macbook' rlm_sql (sql): Reserved connection (61) (159) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (159) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (159) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (159) sql: User found in radcheck table (159) sql: Conditional check items matched, merging assignment check items (159) sql: Auth-Type := eap (159) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (159) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id (159) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id *(159) sql: WARNING: Cannot do check groups when group_membership_query is not set* rlm_sql (sql): Released connection (61) (159) [sql] = ok (159) if (notfound) { (159) if (notfound) -> FALSE (159) [expiration] = noop (159) [logintime] = noop (159) [pap] = noop (159) } # authorize = updated (159) Found Auth-Type = eap (159) # Executing group from file /etc/raddb/sites-enabled/default (159) authenticate { (159) eap: Expiring EAP session with state 0xccf8f142cefbfce7 (159) eap: Finished EAP session with state 0xccf8f142cefbfce7 (159) eap: Previous EAP request found for state 0xccf8f142cefbfce7, released from the list (159) eap: Peer sent packet with method EAP TLS (13) (159) eap: Calling submodule eap_tls to process data (159) eap_tls: Continuing EAP-TLS (159) eap_tls: Peer ACKed our handshake fragment (159) eap_tls: [eaptls verify] = request (159) eap_tls: [eaptls process] = handled (159) eap: Sending EAP Request (code 1) ID 4 length 203 (159) eap: EAP session adding &reply:State = 0xccf8f142cffcfce7 (159) [eap] = handled (159) } # authenticate = handled (159) Using Post-Auth-Type Challenge (159) # Executing group from file /etc/raddb/sites-enabled/default (159) Challenge { ... } # empty sub-section is ignored (159) Sent Access-Challenge Id 241 from 192.168.253.6:1812 to 103.46.239.184:58701 length 0 (159) EAP-Message = 0x010400cb0d80000008ad24a53a7915db5dc8993989d24c02cfa39af20337cc762c16030300a50d00009d03010240001e060106020603050105020503040104020403030103020303020102020203007700753073310b300906035504061302494e310b3009060355040813024445310e300c0603550407 (159) Message-Authenticator = 0x00000000000000000000000000000000 (159) State = 0xccf8f142cffcfce75307e48862cef384 (159) Finished request Waking up in 4.8 seconds. (160) Received Access-Request Id 242 from 103.46.239.184:59711 to 192.168.253.6:1812 length 249 (160) Service-Type = Framed-User (160) Framed-MTU = 1400 (160) User-Name = "macbook" (160) State = 0xccf8f142cffcfce75307e48862cef384 (160) NAS-Port-Id = "wlan1" (160) NAS-Port-Type = Wireless-802.11 (160) Acct-Session-Id = "8220002d" (160) Acct-Multi-Session-Id = "CC-2D-E0-39-24-A6-B8-C1-11-D1-4D-50-82-20-00-00-00-00-00-2D" (160) Calling-Station-Id = "B8-C1-11-D1-4D-50" (160) Called-Station-Id = "CC-2D-E0-39-24-A6:THIS IS A TEST" (160) EAP-Message = 0x020400110d800000000715030300020100 (160) Message-Authenticator = 0x0dd503fd540264a4baa68f7135caa25d (160) NAS-Identifier = "MikroTik" (160) NAS-IP-Address = 192.168.88.2 (160) session-state: No cached attributes (160) # Executing section authorize from file /etc/raddb/sites-enabled/default (160) authorize { (160) policy filter_username { (160) if (&User-Name) { (160) if (&User-Name) -> TRUE (160) if (&User-Name) { (160) if (&User-Name =~ / /) { (160) if (&User-Name =~ / /) -> FALSE (160) if (&User-Name =~ /@[^@]*@/ ) { (160) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (160) if (&User-Name =~ /\.\./ ) { (160) if (&User-Name =~ /\.\./ ) -> FALSE (160) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (160) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (160) if (&User-Name =~ /\.$/) { (160) if (&User-Name =~ /\.$/) -> FALSE (160) if (&User-Name =~ /(a)\./) { (160) if (&User-Name =~ /(a)\./) -> FALSE (160) } # if (&User-Name) = notfound (160) } # policy filter_username = notfound (160) [preprocess] = ok (160) eap: Peer sent EAP Response (code 2) ID 4 length 17 (160) eap: No EAP Start, assuming it's an on-going EAP conversation (160) [eap] = updated (160) sql: EXPAND %{User-Name} (160) sql: --> macbook (160) sql: SQL-User-Name set to 'macbook' rlm_sql (sql): Reserved connection (60) (160) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (160) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (160) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'macbook' ORDER BY id (160) sql: User found in radcheck table (160) sql: Conditional check items matched, merging assignment check items (160) sql: Auth-Type := eap (160) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (160) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id (160) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'macbook' ORDER BY id *(160) sql: WARNING: Cannot do check groups when group_membership_query is not set* rlm_sql (sql): Released connection (60) (160) [sql] = ok (160) if (notfound) { (160) if (notfound) -> FALSE (160) [expiration] = noop (160) [logintime] = noop (160) [pap] = noop (160) } # authorize = updated (160) Found Auth-Type = eap (160) # Executing group from file /etc/raddb/sites-enabled/default (160) authenticate { (160) eap: Expiring EAP session with state 0xccf8f142cffcfce7 (160) eap: Finished EAP session with state 0xccf8f142cffcfce7 (160) eap: Previous EAP request found for state 0xccf8f142cffcfce7, released from the list (160) eap: Peer sent packet with method EAP TLS (13) (160) eap: Calling submodule eap_tls to process data (160) eap_tls: Continuing EAP-TLS (160) eap_tls: Peer indicated complete TLS record size will be 7 bytes (160) eap_tls: Got complete TLS record (7 bytes) (160) eap_tls: [eaptls verify] = length included (160) eap_tls: <<< recv TLS 1.2 [length 0002] *(160) eap_tls: ERROR: TLS_accept: Failed in SSLv3 read client certificate A* *(160) eap_tls: ERROR: Failed in __FUNCTION__ (SSL_read): error:140940E5:SSL routines:ssl3_read_bytes:ssl handshake failure* *(160) eap_tls: ERROR: System call (I/O) error (-1)* *(160) eap_tls: ERROR: TLS receive handshake failed during operation* *(160) eap_tls: ERROR: [eaptls process] = fail* *(160) eap: ERROR: Failed continuing EAP TLS (13) session. EAP sub-module failed* (160) eap: Sending EAP Failure (code 4) ID 4 length 4 (160) eap: Failed in EAP select (160) [eap] = invalid (160) } # authenticate = invalid (160) Failed to authenticate the user (160) Using Post-Auth-Type Reject (160) # Executing group from file /etc/raddb/sites-enabled/default (160) Post-Auth-Type REJECT { (160) sql: EXPAND .query (160) sql: --> .query (160) sql: Using query template 'query' rlm_sql (sql): Reserved connection (63) (160) sql: EXPAND %{User-Name} (160) sql: --> macbook (160) sql: SQL-User-Name set to 'macbook' (160) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (160) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'macbook', '', 'Access-Reject', '2019-02-15 22:36:48.754856') (160) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'macbook', '', 'Access-Reject', '2019-02-15 22:36:48.754856') (160) sql: SQL query returned: success (160) sql: 1 record(s) updated rlm_sql (sql): Released connection (63) (160) [sql] = ok (160) attr_filter.access_reject: EXPAND %{User-Name} (160) attr_filter.access_reject: --> macbook (160) attr_filter.access_reject: Matched entry DEFAULT at line 11 (160) [attr_filter.access_reject] = updated (160) [eap] = noop (160) policy remove_reply_message_if_eap { (160) if (&reply:EAP-Message && &reply:Reply-Message) { (160) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (160) else { (160) [noop] = noop (160) } # else = noop (160) } # policy remove_reply_message_if_eap = noop (160) } # Post-Auth-Type REJECT = updated (160) Delaying response for 1.000000 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (160) Sending delayed response (160) Sent Access-Reject Id 242 from 192.168.253.6:1812 to 103.46.239.184:59711 length 44 (160) EAP-Message = 0x04040004 (160) Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 3.8 seconds. (156) Cleaning up request packet ID 238 with timestamp +5619 (157) Cleaning up request packet ID 239 with timestamp +5619 (158) Cleaning up request packet ID 240 with timestamp +5619 (159) Cleaning up request packet ID 241 with timestamp +5619 (160) Cleaning up request packet ID 242 with timestamp +5619 *Ready to process requests* Cheers MK Singh +91-9910416231 www.shouut.com

2 1

FreeRADIUS with custom multi-factor authentication
by Clint Lord 15 Feb '19

15 Feb '19

We are evaluating FreeRADIUS as a possible solution but we have a very specific authentication workflow and aren’t sure if FreeRADIUS will fit our needs. We’ve searched the documentation for insights into how we might accomplish our goals, but haven’t seen anything that quite matches up. Here is our workflow: 1. The user enters their username and password. 2. The system calls a web service to validate the username and password. 3. If the username and password are valid, and the user’s account has MFA enabled: a. The MFA method is executed (ex. OTP is sent via SMS message) b. The system sends the user a message asking them to enter the OTP and allows them to submit the value. c. The system validates their response by calling another web service. d. If the response is invalid the system sends another message informing them of the failure and allows them to respond again (a few times). All of the account data, username/password authentication and MFA processing is done behind web services, we just need FreeRADIUS to allow us to go through the multiple request and response steps as we call these web services. We thought we might be able to use rlm_python or rlm_perl to accomplish this, but we are only seeing simple “func_authenticate” implementations and can’t see how we can facilitate this back and forth communication with the user. All we are asking are some pointers or general guidance so we can continue our research and determine if FreeRADIUS will meet our needs. Thank you for any insights, guidance, links that might help. Clint Lord The Voodoo Cube

6 12

EAP-TLS - How to log TLS-Client-Cert-* attributes from expired certificates
by Andreas Gryphius 15 Feb '19

15 Feb '19

Hello freeradius user list, I have a running freeradius from the default package coming with Debian 9 stretch , which is based on version 3.0.12 . It is configured to auth only via EAP-TLS. Clients sent their certificates, no passwords and no (real) username. Accepts and Rejects work as expected. What I am not happy with is that I can not find a way to log the certificate details if a user is sending an expired certificate. For users with valid certificates I see all the values for TLS-Client-Cert-* in %{pairs:request:} in linelog . The linelog-command for successful auth is set in the post-auth{} section in sites-enabled/default . With expired client-certificates the eap module jumps direct into Post-Auth-Type REJECT {} (located within post-auth{} section) and none of the TLS-Client-Cert-* details are available (I tried with debug_all). Only Module-Failure-Message is mentioning "... expired certificate ..." and some SSL info. As all of the clients are configured to use an anonymised identity (all use the same) as the username I can not see to whom the expired certificate belongs. In debug mode it says there are TLS attributes created for an expired certificate. So there might be hope to save them for later use ... Does anyone have an idea how I can make these attributes available in linelog? This is an example what I get for an expired certificate in debug mode . Note the lines (226) eap_tls: Creating attributes from certificate OIDs I want to log the value of TLS-Client-Cert-Subject and/or TLS-Client-Cert-Common-Name. freeradius -fxx -l stdout 2>&1 | tee /tmp/freeradius_debug.log Thread 4 handling request 226, (92 handled so far) (226) Received Access-Request Id 110 from 10.1.2.3:32847 to 10.100.0.1:1812 length 554 (226) User-Name = "anonymous(a)example.org" (226) NAS-IP-Address = 192.168.1.12 (226) NAS-Identifier = "0418d67042af" (226) NAS-Port = 0 (226) Called-Station-Id = "04-18-D6-78-55-E1:wifi-radius" (226) Calling-Station-Id = "60-36-DD-7C-E2-DC" (226) Framed-MTU = 1400 (226) NAS-Port-Type = Wireless-802.11 (226) Connect-Info = "CONNECT 0Mbps 802.11b" (226) EAP-Message = xxxxxxxxx... (226) State = 0x3aec898e31c584882f19a28945c85c1b (226) Message-Authenticator = 0x8eeb70cc5c6a84bf36523e303d207ff6 (226) session-state: No cached attributes (226) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default (226) authorize { (226) policy split_username_nai { (226) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) { (226) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) -> TRUE (226) if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) { (226) update request { (226) EXPAND %{1} (226) --> anonymous (226) &Stripped-User-Name := anonymous (226) EXPAND %{3} (226) --> example.org (226) &Stripped-User-Domain = example.org (226) } # update request = noop (226) [updated] = updated (226) } # if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) = updated (226) ... skipping else: Preceding "if" was taken (226) } # policy split_username_nai = updated (226) if (noop || !&Stripped-User-Domain) { (226) if (noop || !&Stripped-User-Domain) -> FALSE (226) if (&Stripped-User-Domain != "example.org") { (226) if (&Stripped-User-Domain != "example.org") -> FALSE (226) if ( &Stripped-User-Name !~ /otherPKI/i ) { (226) if ( &Stripped-User-Name !~ /otherPKI/i ) -> TRUE (226) if ( &Stripped-User-Name !~ /otherPKI/i ) { (226) eap: Peer sent EAP Response (code 2) ID 41 length 369 (226) eap: No EAP Start, assuming it's an on-going EAP conversation (226) [eap] = updated (226) return (226) } # if ( &Stripped-User-Name !~ /otherPKI/i ) = updated (226) } # authorize = updated (226) Found Auth-Type = eap (226) # Executing group from file /etc/freeradius/3.0/sites-enabled/default (226) authenticate { (226) eap: Expiring EAP session with state 0x3aec898e31c58488 (226) eap: Finished EAP session with state 0x3aec898e31c58488 (226) eap: Previous EAP request found for state 0x3aec898e31c58488, released from the list (226) eap: Peer sent packet with method EAP TLS (13) (226) eap: Calling submodule eap_tls to process data (226) eap_tls: Continuing EAP-TLS (226) eap_tls: Got final TLS record fragment (363 bytes) (226) eap_tls: [eaptls verify] = ok (226) eap_tls: Done initial handshake (226) eap_tls: TLS_accept: SSLv3/TLS write server done (226) eap_tls: <<< recv TLS 1.2 [length 13a3] (226) eap_tls: Creating attributes from certificate OIDs (226) eap_tls: Creating attributes from certificate OIDs (226) eap_tls: Creating attributes from certificate OIDs (226) eap_tls: TLS-Cert-Serial := "17887d08b33e3d" (226) eap_tls: TLS-Cert-Expiration := "190709235900Z" (226) eap_tls: TLS-Cert-Subject := "/C=DE/O=Example/OU=ExampleOU/CN=Example-CA-02" (226) eap_tls: TLS-Cert-Issuer := "/C=DE/O=Example/OU=Example-PKI/CN=Example-CA-01" (226) eap_tls: TLS-Cert-Common-Name := "Example-CA-02" (226) eap_tls: TLS-Cert-Subject-Alt-Name-Email := "ca(a)example.org" (226) eap_tls: Creating attributes from certificate OIDs (226) eap_tls: TLS-Client-Cert-Serial := "1a694699888a48" (226) eap_tls: TLS-Client-Cert-Expiration := "181115121610Z" (226) eap_tls: TLS-Client-Cert-Subject := "/C=DE/ST=ExampleST/L=ExampleL/O=Example/OU=ExampleOU/CN=Expired_Example_Cert" (226) eap_tls: TLS-Client-Cert-Issuer := "/C=DE/O=Example/OU=ExampleOU/CN=Example-CA-02" (226) eap_tls: TLS-Client-Cert-Common-Name := "Expired_Example_Cert" (226) eap_tls: TLS-Client-Cert-Subject-Alt-Name-Upn := "anonymous(a)example.org" (226) eap_tls: TLS-Client-Cert-Subject-Alt-Name-Email := "gryphius(a)example.org" (226) eap_tls: ERROR: SSL says error 10 : certificate has expired (226) eap_tls: >>> send TLS 1.2 [length 0002] (226) eap_tls: ERROR: TLS Alert write:fatal:certificate expired tls: TLS_accept: Error in error (226) eap_tls: ERROR: Failed in __FUNCTION__ (SSL_read): error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed (226) eap_tls: ERROR: System call (I/O) error (-1) (226) eap_tls: ERROR: TLS receive handshake failed during operation (226) eap_tls: ERROR: [eaptls process] = fail (226) eap: ERROR: Failed continuing EAP TLS (13) session. EAP sub-module failed (226) eap: Sending EAP Failure (code 4) ID 41 length 4 (226) eap: Failed in EAP select (226) [eap] = invalid (226) } # authenticate = invalid (226) Failed to authenticate the user (226) Using Post-Auth-Type Reject (226) # Executing group from file /etc/freeradius/3.0/sites-enabled/default (226) Post-Auth-Type REJECT { (226) if ( &Module-Failure-Message[1] =~ /expired/ ) { (226) if ( &Module-Failure-Message[1] =~ /expired/ ) -> TRUE (226) if ( &Module-Failure-Message[1] =~ /expired/ ) -> TRUE (226) if ( &Module-Failure-Message[1] =~ /expired/ ) { (226) linelog_cert_expired: EXPAND +++++ linelog_CERT-EXPIRED +++++, %{pairs:session-state:} (226) linelog_cert_expired: --> +++++ linelog_CERT-EXPIRED +++++, (226) [linelog_cert_expired] = ok (226) } # if ( &Module-Failure-Message[1] =~ /expired/ ) = ok (226) attr_filter.access_reject: EXPAND %{User-Name} (226) attr_filter.access_reject: --> anonymous(a)example.org (226) attr_filter.access_reject: Matched entry DEFAULT at line 11 (226) [attr_filter.access_reject] = updated (226) linelog_send_reject: EXPAND action = Send-REJECT, User-Name = "%{User-Name}", Acesspoint-IP = "%{NAS-IP-Address}", Endgeraet-MAC = "%{Calling-Station-Id}", Stripped-User-Name = "%{Stripped-User-Name}", Stripped-User-Domain = "%{Stripped-User-Domain}", EAP-Type = "%{EAP-Type}", Module-Failure-Message(s) = "%{Module-Failure-Message[*]}" (226) linelog_send_reject: --> action = Send-REJECT, User-Name = "anonymous(a)example.org", Acesspoint-IP = "192.168.1.12", Endgeraet-MAC = "60-36-DD-7C-E2-DC", Stripped-User-Name = "anonymous", Stripped-User-Domain = "example.org", EAP-Type = "TLS", Module-Failure-Message(s) = "eap_tls: SSL says error 10 : certificate has expired,eap_tls: TLS Alert write:fatal:certificate expired,eap_tls: Failed in __FUNCTION__ (SSL_read): error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed,eap_tls: System call (I/O) error (-1),eap_tls: TLS receive handshake failed during operation,eap_tls: [eaptls process] = fail,eap: Failed continuing EAP TLS (13) session. EAP sub-module failed" (226) [linelog_send_reject] = ok (226) } # Post-Auth-Type REJECT = updated (226) Delaying response for 1.000000 seconds Thanks, Andreas

3 4