So far, I’ve come up with post-auth section rule (in my network only eap and md5 are used, pap is for radtest): # sql # sql input only for PAP and MD5 Post-Auth-Type MD5 { sql } Post-Auth-Type PAP { sql } I’ll be testing it and revert back with results... Martin

Wiadomość napisana przez Marcin Marszałkowski <m.marszal@wp.pl> w dniu 18.08.2019, o godz. 15:47:

Thanks Alan B.! I’ve tested your advice - disabling sql in default server post-auth section, and it works. But won’t it affect MD5 protocol (MAC based auth.)? If so, can I apply some conditional rule in default post-auth, i.e.: Auth-Type MD5 { sql }

And any word on:

...

...

On top of that I have a problems with accounting, it seems like NAS doesn’t like Gigawords - quite often reports 4GB up and down. More often it happens when session is longer than shorter. Is there any any fix available on Freeradius side? Ubiquiti claims https://help.ubnt.com/hc/en-us/articles/115005255907-UniFi-Hotspot-RADIUS-At... their APs should be working with this attribute. NAS it is Unifi AP AC Pro.

Simply NAS reports false bandwidth usage despite Ubiquiti claims it should work. I tried enabling and disabling „acct_counters64” but it doesn’t change anything. I’ve seen this: For Cisco <https://wiki.freeradius.org/vendor/Cisco> IOS, this usually achieved by entering

aaa accounting gigawords but it seems like I can’t use it on Unifi NAS/AP. Any suggestions?

Regards Martin

...

Wiadomość napisana przez Alan Buxey <alan.buxey@gmail.com> w dniu 18.08.2019, o godz. 13:39:

hi,

in your debug, step 10 is in the inner-tunnel - calling post-auth section there... update SQL... step 11 is in the default (outer) post-auth section - updating SQL there. if you only want one entry, make sure you only call the post-auth with SQL update in the inner (where username is real etc) and dont do it in outer.

for PEAP its usually 10 to 11 parts to the conversation (phase 1, setup etc) then phase 2 - auth in the TLS tunnel) - a quick google brings me a suitable example resource such as https://sites.google.com/site/amitsciscozone/home/switching/peap---protected...

alan

On Sun, 18 Aug 2019 at 08:36, Marcin Marszałkowski <m.marszal@wp.pl> wrote:

...

Hi,

I’m newbie to Freeradius and have been pulling my hair out… Installed Freeradius 3.16 with mysql and Daloradius. Autheticating and authorizing work (I think so). But I might have something misconfigured - radpostauth table is full of duplicated/always double entries with the same timestamp. And it happens only for EAP auth., PAP (radtest) and MD5 (MAC based auth.) are not affected. Does it may affect accounting?

Following is request debug where double input to radpostauth is visible: ———————————————— Sat Aug 17 18:23:36 2019 : Debug: (10) Received Access-Request Id 248 from 172.16.0.5:48453 to 172.16.0.12:1812 length 242 Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name = "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) NAS-Identifier = "feec3a9aeda5" Sat Aug 17 18:23:36 2019 : Debug: (10) Called-Station-Id = "FE-EC-3A-9A-ED-A5:Guest" Sat Aug 17 18:23:36 2019 : Debug: (10) NAS-Port-Type = Wireless-802.11 Sat Aug 17 18:23:36 2019 : Debug: (10) Service-Type = Framed-User Sat Aug 17 18:23:36 2019 : Debug: (10) Calling-Station-Id = "04-DB-56-F0-C3-36" Sat Aug 17 18:23:36 2019 : Debug: (10) Connect-Info = "CONNECT 0Mbps 802.11b" Sat Aug 17 18:23:36 2019 : Debug: (10) Acct-Session-Id = "D9B312EA0EEDF1F6" Sat Aug 17 18:23:36 2019 : Debug: (10) Mobility-Domain-Id = 1826 Sat Aug 17 18:23:36 2019 : Debug: (10) WLAN-Pairwise-Cipher = 1027076 Sat Aug 17 18:23:36 2019 : Debug: (10) WLAN-Group-Cipher = 1027076 Sat Aug 17 18:23:36 2019 : Debug: (10) WLAN-AKM-Suite = 1027075 Sat Aug 17 18:23:36 2019 : Debug: (10) Framed-MTU = 1400 Sat Aug 17 18:23:36 2019 : Debug: (10) EAP-Message = 0x021b00251900170303001a7ee7eda10323b3262a8342edbba1f2cff9ae93b8127cc51c3b47 Sat Aug 17 18:23:36 2019 : Debug: (10) State = 0x7d7976aa75626f6ce06082b82288935b Sat Aug 17 18:23:36 2019 : Debug: (10) Message-Authenticator = 0xdcedbfc0f49a2c315fa3a073561ea26c Sat Aug 17 18:23:36 2019 : Debug: (10) session-state: No cached attributes Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (10) authorize { Sat Aug 17 18:23:36 2019 : Debug: (10) policy filter_username { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ / /) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ / /) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@[^@]*@/ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.\./ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.\./ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.$/) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.$/) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@\./) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@\./) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) } # if (&User-Name) = notfound Sat Aug 17 18:23:36 2019 : Debug: (10) } # policy filter_username = notfound Sat Aug 17 18:23:36 2019 : Debug: (10) policy filter_password { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Password && (&User-Password != "%{string:User-Password}")) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) } # policy filter_password = notfound Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling preprocess (rlm_preprocess) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sat Aug 17 18:23:36 2019 : Debug: (10) [preprocess] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) update request { Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (10) EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (10) --> Robert Sat Aug 17 18:23:36 2019 : Debug: (10) SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (6) Sat Aug 17 18:23:36 2019 : Debug: (10) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (6) Sat Aug 17 18:23:36 2019 : Debug: (10) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} Sat Aug 17 18:23:36 2019 : Debug: (10) --> WiFi Sat Aug 17 18:23:36 2019 : Debug: (10) Huntgroup-Name := WiFi Sat Aug 17 18:23:36 2019 : Debug: (10) } # update request = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (10) [mschap] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: Checking for suffix after "@" Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: No '@' in User-Name = "Robert", looking up realm NULL Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: No such realm "NULL" Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (10) [suffix] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Peer sent EAP Response (code 2) ID 27 length 37 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Continuing tunnel setup Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) [eap] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) } # authorize = ok Sat Aug 17 18:23:36 2019 : Debug: (10) Found Auth-Type = eap Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing group from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (10) authenticate { Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authenticate]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Expiring EAP session with state 0xba6ef1b9bb75eb14 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Finished EAP session with state 0x7d7976aa75626f6c Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Previous EAP request found for state 0x7d7976aa75626f6c, released from the list Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Peer sent packet with method EAP PEAP (25) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Calling submodule eap_peap to process data Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Continuing EAP-TLS Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Peer sent flags --- Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: [eaptls verify] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Done initial handshake Sat Aug 17 18:23:36 2019 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: [eaptls process] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Session established. Decoding tunneled attributes Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: PEAP state phase2 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: EAP method MSCHAPv2 (26) Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Got tunneled request Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: EAP-Message = 0x021b00061a03 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Setting User-Name to Robert Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Sending tunneled request to inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: EAP-Message = 0x021b00061a03 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: User-Name = "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: State = 0xba6ef1b9bb75eb14f919ef4d049db6e4 Sat Aug 17 18:23:36 2019 : Debug: (10) Virtual server inner-tunnel received request Sat Aug 17 18:23:36 2019 : Debug: (10) EAP-Message = 0x021b00061a03 Sat Aug 17 18:23:36 2019 : Debug: (10) FreeRADIUS-Proxied-To = 127.0.0.1 Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name = "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) State = 0xba6ef1b9bb75eb14f919ef4d049db6e4 Sat Aug 17 18:23:36 2019 : WARNING: (10) Outer and inner identities are the same. User privacy is compromised. Sat Aug 17 18:23:36 2019 : Debug: (10) server inner-tunnel { Sat Aug 17 18:23:36 2019 : Debug: (10) session-state: No cached attributes Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) authorize { Sat Aug 17 18:23:36 2019 : Debug: (10) policy filter_username { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ / /) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ / /) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@[^@]*@/ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.\./ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.\./ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.$/) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /\.$/) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@\./) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (10) if (&User-Name =~ /@\./) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (10) } # if (&User-Name) = notfound Sat Aug 17 18:23:36 2019 : Debug: (10) } # policy filter_username = notfound Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (10) [mschap] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: Checking for suffix after "@" Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: No '@' in User-Name = "Robert", looking up realm NULL Sat Aug 17 18:23:36 2019 : Debug: (10) suffix: No such realm "NULL" Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (10) [suffix] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) update control { Sat Aug 17 18:23:36 2019 : Debug: (10) &Proxy-To-Realm := LOCAL Sat Aug 17 18:23:36 2019 : Debug: (10) } # update control = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Peer sent EAP Response (code 2) ID 27 length 6 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: No EAP Start, assuming it's an on-going EAP conversation Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) [eap] = updated Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> Robert Sat Aug 17 18:23:36 2019 : Debug: (10) sql: SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (8) Sat Aug 17 18:23:36 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY 'Robert' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY 'Robert' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: User found in radcheck table Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Conditional check items matched, merging assignment check items Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Cleartext-Password := "Atina2011!" Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: FROM 1 TO 2 MAX 3 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Cleartext-Password Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Cleartext-Password FROM 0 TO 2 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: TO in 2 out 2 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: to[0] = Proxy-To-Realm Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: to[1] = Auth-Type Sat Aug 17 18:23:36 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY 'Robert' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY 'Robert' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ... falling-through to group processing Sat Aug 17 18:23:36 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = BINARY '%{SQL-User-Name}' ORDER BY priority Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = BINARY ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ' ORDER BY priority Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = BINARY '%{SQL-User-Name}' ORDER BY priority Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT groupname FROM radusergroup WHERE username = BINARY 'Robert' ORDER BY priority Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = BINARY 'Robert' ORDER BY priority Sat Aug 17 18:23:36 2019 : Debug: (10) sql: User found in the group table Sat Aug 17 18:23:36 2019 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-Group Sat Aug 17 18:23:36 2019 : Debug: literal --> ' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'Dzieci' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'Dzieci' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Group "Dzieci": Conditional check items matched Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Group "Dzieci": Merging assignment check items Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Simultaneous-Use := 2 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Max-Daily-Session := 10800 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Login-Time := "Wk1200-2330,Sa0800-2330,Su0800-2300" Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: FROM 3 TO 3 MAX 6 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Simultaneous-Use Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Simultaneous-Use FROM 0 TO 3 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Max-Daily-Session Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Max-Daily-Session FROM 1 TO 3 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Login-Time Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Login-Time FROM 2 TO 3 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: TO in 3 out 3 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: to[0] = Proxy-To-Realm Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: to[1] = Auth-Type Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: to[2] = Cleartext-Password Sat Aug 17 18:23:36 2019 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-Group Sat Aug 17 18:23:36 2019 : Debug: literal --> ' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'Dzieci' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'Dzieci' ORDER BY id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Group "Dzieci": Merging reply items Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Tunnel-Private-Group-Id := "11" Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Tunnel-Type := VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Tunnel-Medium-Type := IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Fall-Through = Yes Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Session-Timeout := 3600 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Acct-Interim-Interval := 300 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Idle-Timeout := 450 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Termination-Action := RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: FROM 8 TO 0 MAX 8 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Tunnel-Private-Group-Id Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Tunnel-Private-Group-Id FROM 0 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Tunnel-Type Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Tunnel-Type FROM 1 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Tunnel-Medium-Type Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Tunnel-Medium-Type FROM 2 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Fall-Through Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Fall-Through FROM 3 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Session-Timeout Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Session-Timeout FROM 4 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Acct-Interim-Interval Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Acct-Interim-Interval FROM 5 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Idle-Timeout Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Idle-Timeout FROM 6 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: Examining Termination-Action Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: APPENDING Termination-Action FROM 7 TO 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ::: TO in 0 out 0 Sat Aug 17 18:23:36 2019 : Debug: (10) sql: ... falling-through to profile processing Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (8) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: (10) [sql] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling dailycounter (rlm_sqlcounter) Sat Aug 17 18:23:36 2019 : Debug: sqlcounter_expand: 'SELECT SUM(acctsessiontime) FROM radacct WHERE username = '%{User-Name}' AND acctstarttime BETWEEN FROM_UNIXTIME('1565992800') AND FROM_UNIXTIME('1566079200')' Sat Aug 17 18:23:36 2019 : Debug: %{sql:SELECT SUM(acctsessiontime) FROM radacct WHERE username = '%{User-Name}' AND acctstarttime BETWEEN FROM_UNIXTIME('1565992800') AND FROM_UNIXTIME('1566079200')} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: xlat --> sql Sat Aug 17 18:23:36 2019 : Debug: { Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT SUM(acctsessiontime) FROM radacct WHERE username = ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ' AND acctstarttime BETWEEN FROM_UNIXTIME('1565992800') AND FROM_UNIXTIME('1566079200') Sat Aug 17 18:23:36 2019 : Debug: } Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: --> Robert Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (7) Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: Executing select query: SELECT SUM(acctsessiontime) FROM radacct WHERE username = 'Robert' AND acctstarttime BETWEEN FROM_UNIXTIME('1565992800') AND FROM_UNIXTIME('1566079200') Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (7) Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: EXPAND %{sql:SELECT SUM(acctsessiontime) FROM radacct WHERE username = '%{User-Name}' AND acctstarttime BETWEEN FROM_UNIXTIME('1565992800') AND FROM_UNIXTIME('1566079200')} Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: --> 9927 Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: Allowing user, &control:Max-Daily-Session value (10800) is greater than counter value (9927) Sat Aug 17 18:23:36 2019 : Debug: (10) dailycounter: Setting &reply:Session-Timeout value to 873 Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from dailycounter (rlm_sqlcounter) Sat Aug 17 18:23:36 2019 : Debug: (10) [dailycounter] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling expiration (rlm_expiration) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from expiration (rlm_expiration) Sat Aug 17 18:23:36 2019 : Debug: (10) [expiration] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling logintime (rlm_logintime) Sat Aug 17 18:23:36 2019 : Debug: (10) logintime: Checking Login-Time Sat Aug 17 18:23:36 2019 : Debug: (10) logintime: Login within allowed time-slot, 18480 seconds left in this session Sat Aug 17 18:23:36 2019 : Debug: (10) logintime: reply:Session-Timeout set to 18480 Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from logintime (rlm_logintime) Sat Aug 17 18:23:36 2019 : Debug: (10) [logintime] = updated Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: calling pap (rlm_pap) Sat Aug 17 18:23:36 2019 : WARNING: (10) pap: Auth-Type already set. Not setting to PAP Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authorize]: returned from pap (rlm_pap) Sat Aug 17 18:23:36 2019 : Debug: (10) [pap] = noop Sat Aug 17 18:23:36 2019 : Debug: (10) } # authorize = updated Sat Aug 17 18:23:36 2019 : Debug: (10) Found Auth-Type = eap Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing group from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) authenticate { Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authenticate]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Expiring EAP session with state 0xba6ef1b9bb75eb14 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Finished EAP session with state 0xba6ef1b9bb75eb14 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Previous EAP request found for state 0xba6ef1b9bb75eb14, released from the list Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Peer sent packet with method EAP MSCHAPv2 (26) Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Calling submodule eap_mschapv2 to process data Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Sending EAP Success (code 3) ID 27 length 4 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Freeing handler Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authenticate]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) [eap] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) } # authenticate = ok Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing section session from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) session { Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[session]: calling sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> Robert Sat Aug 17 18:23:36 2019 : Debug: (10) sql: SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> SELECT COUNT(*) FROM radacct WHERE username = ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ' AND acctstoptime IS NULL Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'Robert' AND acctstoptime IS NULL Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (6) Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'Robert' AND acctstoptime IS NULL Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (6) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[session]: returned from sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: (10) [sql] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) } # session = ok Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing section post-auth from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) post-auth { Sat Aug 17 18:23:36 2019 : Debug: (10) update reply { Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name := &request:User-Name -> 'Robert' Sat Aug 17 18:23:36 2019 : Debug: (10) Overwriting value "Robert" with "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) } # update reply = noop Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[post-auth]: calling sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: .query Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> .query Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND .query Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> .query Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Using query template 'query' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (8) Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> Robert Sat Aug 17 18:23:36 2019 : Debug: (10) sql: SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: XLAT-IF { Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Password Sat Aug 17 18:23:36 2019 : Debug: } Sat Aug 17 18:23:36 2019 : Debug: XLAT-ELSE { Sat Aug 17 18:23:36 2019 : Debug: attribute --> CHAP-Password Sat Aug 17 18:23:36 2019 : Debug: } Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> Packet-Type Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: percent --> S Sat Aug 17 18:23:36 2019 : Debug: literal --> ') Sat Aug 17 18:23:36 2019 : Debug: (10) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sat Aug 17 18:23:36 2019 : Debug: (10) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Robert', '', 'Access-Accept', '2019-08-17 18:23:36') Sat Aug 17 18:23:36 2019 : Debug: (10) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Robert', '', 'Access-Accept', '2019-08-17 18:23:36') Sat Aug 17 18:23:36 2019 : Debug: (10) sql: SQL query returned: success Sat Aug 17 18:23:36 2019 : Debug: (10) sql: 1 record(s) updated Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (8) Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[post-auth]: returned from sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: (10) [sql] = ok Sat Aug 17 18:23:36 2019 : Debug: (10) if (1) { Sat Aug 17 18:23:36 2019 : Debug: (10) if (1) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (10) if (1) { Sat Aug 17 18:23:36 2019 : Debug: (10) update reply { Sat Aug 17 18:23:36 2019 : Debug: (10) Message-Authenticator !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) EAP-Message !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) Proxy-State !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) MS-MPPE-Encryption-Types !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) MS-MPPE-Encryption-Policy !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) MS-MPPE-Send-Key !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) MS-MPPE-Recv-Key !* ANY Sat Aug 17 18:23:36 2019 : Debug: (10) } # update reply = noop Sat Aug 17 18:23:36 2019 : Debug: (10) update { Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Tunnel-Private-Group-Id += &reply:Tunnel-Private-Group-Id[*] -> '11' Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Tunnel-Type += &reply:Tunnel-Type[*] -> VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Tunnel-Medium-Type += &reply:Tunnel-Medium-Type[*] -> IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Fall-Through += &reply:Fall-Through[*] -> Yes Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Session-Timeout += &reply:Session-Timeout[*] -> 873 Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Acct-Interim-Interval += &reply:Acct-Interim-Interval[*] -> 300 Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Idle-Timeout += &reply:Idle-Timeout[*] -> 450 Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::Termination-Action += &reply:Termination-Action[*] -> RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) &outer.session-state::User-Name += &reply:User-Name[*] -> 'Robert' Sat Aug 17 18:23:36 2019 : Debug: (10) } # update = noop Sat Aug 17 18:23:36 2019 : Debug: (10) } # if (1) = noop Sat Aug 17 18:23:36 2019 : Debug: (10) } # post-auth = ok Sat Aug 17 18:23:36 2019 : Debug: (10) } # server inner-tunnel Sat Aug 17 18:23:36 2019 : Debug: (10) Virtual server sending reply Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Private-Group-Id = "11" Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Type = VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Medium-Type = IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) Fall-Through = Yes Sat Aug 17 18:23:36 2019 : Debug: (10) Session-Timeout = 873 Sat Aug 17 18:23:36 2019 : Debug: (10) Acct-Interim-Interval = 300 Sat Aug 17 18:23:36 2019 : Debug: (10) Idle-Timeout = 450 Sat Aug 17 18:23:36 2019 : Debug: (10) Termination-Action = RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name := "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Got tunneled reply code 2 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Private-Group-Id = "11" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Type = VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Medium-Type = IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Fall-Through = Yes Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Session-Timeout = 873 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Acct-Interim-Interval = 300 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Idle-Timeout = 450 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Termination-Action = RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: User-Name := "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Got tunneled reply RADIUS code 2 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Private-Group-Id = "11" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Type = VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunnel-Medium-Type = IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Fall-Through = Yes Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Session-Timeout = 873 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Acct-Interim-Interval = 300 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Idle-Timeout = 450 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Termination-Action = RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: User-Name := "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Tunneled authentication was successful Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: SUCCESS Sat Aug 17 18:23:36 2019 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0 Sat Aug 17 18:23:36 2019 : Debug: (10) eap_peap: Saving tunneled attributes for later Sat Aug 17 18:23:36 2019 : Debug: (10) eap: Sending EAP Request (code 1) ID 28 length 46 Sat Aug 17 18:23:36 2019 : Debug: (10) eap: EAP session adding &reply:State = 0x7d7976aa74656f6c Sat Aug 17 18:23:36 2019 : Debug: (10) modsingle[authenticate]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (10) [eap] = handled Sat Aug 17 18:23:36 2019 : Debug: (10) } # authenticate = handled Sat Aug 17 18:23:36 2019 : Debug: (10) Using Post-Auth-Type Challenge Sat Aug 17 18:23:36 2019 : Debug: (10) Post-Auth-Type sub-section not found. Ignoring. Sat Aug 17 18:23:36 2019 : Debug: (10) # Executing group from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (10) session-state: Saving cached attributes Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Private-Group-Id += "11" Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Type += VLAN Sat Aug 17 18:23:36 2019 : Debug: (10) Tunnel-Medium-Type += IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (10) Session-Timeout += 873 Sat Aug 17 18:23:36 2019 : Debug: (10) Acct-Interim-Interval += 300 Sat Aug 17 18:23:36 2019 : Debug: (10) Idle-Timeout += 450 Sat Aug 17 18:23:36 2019 : Debug: (10) Termination-Action += RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name += "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) Sent Access-Challenge Id 248 from 172.16.0.12:1812 to 172.16.0.5:48453 length 0 Sat Aug 17 18:23:36 2019 : Debug: (10) EAP-Message = 0x011c002e19001703030023b6cc9859d9e1d9fbccb915ae16456ad2c329aa053517b0282f4ff9fdf0e8bc45841a94 Sat Aug 17 18:23:36 2019 : Debug: (10) Message-Authenticator = 0x00000000000000000000000000000000 Sat Aug 17 18:23:36 2019 : Debug: (10) State = 0x7d7976aa74656f6ce06082b82288935b Sat Aug 17 18:23:36 2019 : Debug: (10) Finished request Sat Aug 17 18:23:36 2019 : Debug: Waking up in 2.7 seconds. Sat Aug 17 18:23:36 2019 : Debug: (11) Received Access-Request Id 249 from 172.16.0.5:48453 to 172.16.0.12:1812 length 251 Sat Aug 17 18:23:36 2019 : Debug: (11) User-Name = "Robert" Sat Aug 17 18:23:36 2019 : Debug: (11) NAS-Identifier = "feec3a9aeda5" Sat Aug 17 18:23:36 2019 : Debug: (11) Called-Station-Id = "FE-EC-3A-9A-ED-A5:Guest" Sat Aug 17 18:23:36 2019 : Debug: (11) NAS-Port-Type = Wireless-802.11 Sat Aug 17 18:23:36 2019 : Debug: (11) Service-Type = Framed-User Sat Aug 17 18:23:36 2019 : Debug: (11) Calling-Station-Id = "04-DB-56-F0-C3-36" Sat Aug 17 18:23:36 2019 : Debug: (11) Connect-Info = "CONNECT 0Mbps 802.11b" Sat Aug 17 18:23:36 2019 : Debug: (11) Acct-Session-Id = "D9B312EA0EEDF1F6" Sat Aug 17 18:23:36 2019 : Debug: (11) Mobility-Domain-Id = 1826 Sat Aug 17 18:23:36 2019 : Debug: (11) WLAN-Pairwise-Cipher = 1027076 Sat Aug 17 18:23:36 2019 : Debug: (11) WLAN-Group-Cipher = 1027076 Sat Aug 17 18:23:36 2019 : Debug: (11) WLAN-AKM-Suite = 1027075 Sat Aug 17 18:23:36 2019 : Debug: (11) Framed-MTU = 1400 Sat Aug 17 18:23:36 2019 : Debug: (11) EAP-Message = 0x021c002e190017030300237ee7eda10323b327ee4332f9f48ce3978ef4ac3929fc08c00d246f066c893b4a182b1d Sat Aug 17 18:23:36 2019 : Debug: (11) State = 0x7d7976aa74656f6ce06082b82288935b Sat Aug 17 18:23:36 2019 : Debug: (11) Message-Authenticator = 0xd6f3c9ee16eb98c8d0217d85c9804c2e Sat Aug 17 18:23:36 2019 : Debug: (11) Restoring &session-state Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Tunnel-Private-Group-Id += "11" Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Tunnel-Type += VLAN Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Tunnel-Medium-Type += IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Session-Timeout += 873 Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Acct-Interim-Interval += 300 Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Idle-Timeout += 450 Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:Termination-Action += RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (11) &session-state:User-Name += "Robert" Sat Aug 17 18:23:36 2019 : Debug: (11) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (11) authorize { Sat Aug 17 18:23:36 2019 : Debug: (11) policy filter_username { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ / /) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ / /) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /@[^@]*@/ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /\.\./ ) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /\.\./ ) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /\.$/) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /\.$/) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /@\./) { Sat Aug 17 18:23:36 2019 : Debug: No matches Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Name =~ /@\./) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) } # if (&User-Name) = notfound Sat Aug 17 18:23:36 2019 : Debug: (11) } # policy filter_username = notfound Sat Aug 17 18:23:36 2019 : Debug: (11) policy filter_password { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Password && (&User-Password != "%{string:User-Password}")) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) } # policy filter_password = notfound Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: calling preprocess (rlm_preprocess) Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sat Aug 17 18:23:36 2019 : Debug: (11) [preprocess] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) update request { Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (11) EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (11) --> Robert Sat Aug 17 18:23:36 2019 : Debug: (11) SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (7) Sat Aug 17 18:23:36 2019 : Debug: (11) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (7) Sat Aug 17 18:23:36 2019 : Debug: (11) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} Sat Aug 17 18:23:36 2019 : Debug: (11) --> WiFi Sat Aug 17 18:23:36 2019 : Debug: (11) Huntgroup-Name := WiFi Sat Aug 17 18:23:36 2019 : Debug: (11) } # update request = noop Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: calling mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: returned from mschap (rlm_mschap) Sat Aug 17 18:23:36 2019 : Debug: (11) [mschap] = noop Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: calling suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (11) suffix: Checking for suffix after "@" Sat Aug 17 18:23:36 2019 : Debug: (11) suffix: No '@' in User-Name = "Robert", looking up realm NULL Sat Aug 17 18:23:36 2019 : Debug: (11) suffix: No such realm "NULL" Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: returned from suffix (rlm_realm) Sat Aug 17 18:23:36 2019 : Debug: (11) [suffix] = noop Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Peer sent EAP Response (code 2) ID 28 length 46 Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Continuing tunnel setup Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authorize]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (11) [eap] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) } # authorize = ok Sat Aug 17 18:23:36 2019 : Debug: (11) Found Auth-Type = eap Sat Aug 17 18:23:36 2019 : Debug: (11) # Executing group from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (11) authenticate { Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authenticate]: calling eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Expiring EAP session with state 0x7d7976aa74656f6c Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Finished EAP session with state 0x7d7976aa74656f6c Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Previous EAP request found for state 0x7d7976aa74656f6c, released from the list Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Peer sent packet with method EAP PEAP (25) Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Calling submodule eap_peap to process data Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Continuing EAP-TLS Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Peer sent flags --- Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: [eaptls verify] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Done initial handshake Sat Aug 17 18:23:36 2019 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0 Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: [eaptls process] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Session established. Decoding tunneled attributes Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: PEAP state send tlv success Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Received EAP-TLV response Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Success Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Using saved attributes from the original Access-Accept Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Tunnel-Private-Group-Id = "11" Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Tunnel-Type = VLAN Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Tunnel-Medium-Type = IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Fall-Through = Yes Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Session-Timeout = 873 Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Acct-Interim-Interval = 300 Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Idle-Timeout = 450 Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: Termination-Action = RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (11) eap_peap: User-Name := "Robert" Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Sending EAP Success (code 3) ID 28 length 4 Sat Aug 17 18:23:36 2019 : Debug: (11) eap: Freeing handler Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[authenticate]: returned from eap (rlm_eap) Sat Aug 17 18:23:36 2019 : Debug: (11) [eap] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) } # authenticate = ok Sat Aug 17 18:23:36 2019 : Debug: (11) # Executing section post-auth from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:23:36 2019 : Debug: (11) post-auth { Sat Aug 17 18:23:36 2019 : Debug: (11) if (!&reply:State) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (!&reply:State) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (11) if (!&reply:State) { Sat Aug 17 18:23:36 2019 : Debug: (11) update reply { Sat Aug 17 18:23:36 2019 : Debug: (11) EXPAND 0x%{randstr:16h} Sat Aug 17 18:23:36 2019 : Debug: (11) --> 0x8ce7b66eb9b9d607320857ccac1d3c220f Sat Aug 17 18:23:36 2019 : Debug: (11) State := 0x8ce7b66eb9b9d607320857ccac1d3c220f Sat Aug 17 18:23:36 2019 : Debug: (11) } # update reply = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # if (!&reply:State) = noop Sat Aug 17 18:23:36 2019 : Debug: (11) update { Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Tunnel-Private-Group-Id += &session-state:Tunnel-Private-Group-Id[*] -> '11' Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Tunnel-Type += &session-state:Tunnel-Type[*] -> VLAN Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Tunnel-Medium-Type += &session-state:Tunnel-Medium-Type[*] -> IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Session-Timeout += &session-state:Session-Timeout[*] -> 873 Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Acct-Interim-Interval += &session-state:Acct-Interim-Interval[*] -> 300 Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Idle-Timeout += &session-state:Idle-Timeout[*] -> 450 Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::Termination-Action += &session-state:Termination-Action[*] -> RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (11) &reply::User-Name += &session-state:User-Name[*] -> 'Robert' Sat Aug 17 18:23:36 2019 : Debug: (11) } # update = noop Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: calling sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: .query Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> .query Sat Aug 17 18:23:36 2019 : Debug: (11) sql: EXPAND .query Sat Aug 17 18:23:36 2019 : Debug: (11) sql: --> .query Sat Aug 17 18:23:36 2019 : Debug: (11) sql: Using query template 'query' Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Reserved connection (6) Sat Aug 17 18:23:36 2019 : Debug: %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Name Sat Aug 17 18:23:36 2019 : Debug: (11) sql: EXPAND %{User-Name} Sat Aug 17 18:23:36 2019 : Debug: (11) sql: --> Robert Sat Aug 17 18:23:36 2019 : Debug: (11) sql: SQL-User-Name set to 'Robert' Sat Aug 17 18:23:36 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sat Aug 17 18:23:36 2019 : Debug: Parsed xlat tree: Sat Aug 17 18:23:36 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> SQL-User-Name Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: XLAT-IF { Sat Aug 17 18:23:36 2019 : Debug: attribute --> User-Password Sat Aug 17 18:23:36 2019 : Debug: } Sat Aug 17 18:23:36 2019 : Debug: XLAT-ELSE { Sat Aug 17 18:23:36 2019 : Debug: attribute --> CHAP-Password Sat Aug 17 18:23:36 2019 : Debug: } Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: attribute --> Packet-Type Sat Aug 17 18:23:36 2019 : Debug: literal --> ', ' Sat Aug 17 18:23:36 2019 : Debug: percent --> S Sat Aug 17 18:23:36 2019 : Debug: literal --> ') Sat Aug 17 18:23:36 2019 : Debug: (11) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sat Aug 17 18:23:36 2019 : Debug: (11) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Robert', '', 'Access-Accept', '2019-08-17 18:23:36') Sat Aug 17 18:23:36 2019 : Debug: (11) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Robert', '', 'Access-Accept', '2019-08-17 18:23:36') Sat Aug 17 18:23:36 2019 : Debug: (11) sql: SQL query returned: success Sat Aug 17 18:23:36 2019 : Debug: (11) sql: 1 record(s) updated Sat Aug 17 18:23:36 2019 : Debug: rlm_sql (sql): Released connection (6) Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: returned from sql (rlm_sql) Sat Aug 17 18:23:36 2019 : Debug: (11) [sql] = ok Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: calling exec (rlm_exec) Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: returned from exec (rlm_exec) Sat Aug 17 18:23:36 2019 : Debug: (11) [exec] = noop Sat Aug 17 18:23:36 2019 : Debug: (11) policy insert_acct_class { Sat Aug 17 18:23:36 2019 : Debug: (11) update reply { Sat Aug 17 18:23:36 2019 : Debug: (11) EXPAND ai:%{md5:%t,%I,%{Packet-Src-Port},%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}},%{NAS-IP-Address},%{Calling-Station-ID},%{User-Name}} Sat Aug 17 18:23:36 2019 : Debug: (11) --> ai:acc29570a803c6c1a2268e867f1ed360 Sat Aug 17 18:23:36 2019 : Debug: (11) &Class = 0x61693a6163633239353730613830336336633161323236386538363766316564333630 Sat Aug 17 18:23:36 2019 : Debug: (11) } # update reply = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # policy insert_acct_class = noop Sat Aug 17 18:23:36 2019 : Debug: (11) if (&reply:EAP-Session-Id) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&reply:EAP-Session-Id) -> TRUE Sat Aug 17 18:23:36 2019 : Debug: (11) if (&reply:EAP-Session-Id) { Sat Aug 17 18:23:36 2019 : Debug: (11) update reply { Sat Aug 17 18:23:36 2019 : Debug: (11) EAP-Key-Name := &reply:EAP-Session-Id -> 0x195d582a086518d8626f3c8c8eb4ed1ae02b0e4d222b2363d0d6bb66028aebd9db3ec9aff3e280360a837f90ade646df976f66d4b2d287de285083a6df4935b8d7 Sat Aug 17 18:23:36 2019 : Debug: (11) } # update reply = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # if (&reply:EAP-Session-Id) = noop Sat Aug 17 18:23:36 2019 : Debug: (11) policy remove_reply_message_if_eap { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&reply:EAP-Message && &reply:Reply-Message) { Sat Aug 17 18:23:36 2019 : Debug: (11) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Sat Aug 17 18:23:36 2019 : Debug: (11) else { Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: calling noop (rlm_always) Sat Aug 17 18:23:36 2019 : Debug: (11) modsingle[post-auth]: returned from noop (rlm_always) Sat Aug 17 18:23:36 2019 : Debug: (11) [noop] = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # else = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # policy remove_reply_message_if_eap = noop Sat Aug 17 18:23:36 2019 : Debug: (11) } # post-auth = ok Sat Aug 17 18:23:36 2019 : Debug: (11) Sent Access-Accept Id 249 from 172.16.0.12:1812 to 172.16.0.5:48453 length 0 Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Private-Group-Id = "11" Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Type = VLAN Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Medium-Type = IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (11) Session-Timeout = 873 Sat Aug 17 18:23:36 2019 : Debug: (11) Acct-Interim-Interval = 300 Sat Aug 17 18:23:36 2019 : Debug: (11) Idle-Timeout = 450 Sat Aug 17 18:23:36 2019 : Debug: (11) Termination-Action = RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (11) User-Name := "Robert" Sat Aug 17 18:23:36 2019 : Debug: (11) MS-MPPE-Recv-Key = 0x452f2e97de2dbf05277fd62b8844b590145d436fb68df569f785b973c302e8c2 Sat Aug 17 18:23:36 2019 : Debug: (11) MS-MPPE-Send-Key = 0x4512fafa8219e461fbc3822b8f22ed4bde669628ef7a05918a3192c173cbfbaf Sat Aug 17 18:23:36 2019 : Debug: (11) EAP-Message = 0x031c0004 Sat Aug 17 18:23:36 2019 : Debug: (11) Message-Authenticator = 0x00000000000000000000000000000000 Sat Aug 17 18:23:36 2019 : Debug: (11) State := 0x8ce7b66eb9b9d607320857ccac1d3c220f Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Private-Group-Id += "11" Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Type += VLAN Sat Aug 17 18:23:36 2019 : Debug: (11) Tunnel-Medium-Type += IEEE-802 Sat Aug 17 18:23:36 2019 : Debug: (11) Session-Timeout += 873 Sat Aug 17 18:23:36 2019 : Debug: (11) Acct-Interim-Interval += 300 Sat Aug 17 18:23:36 2019 : Debug: (11) Idle-Timeout += 450 Sat Aug 17 18:23:36 2019 : Debug: (11) Termination-Action += RADIUS-Request Sat Aug 17 18:23:36 2019 : Debug: (11) User-Name += "Robert" Sat Aug 17 18:23:36 2019 : Debug: (11) Class = 0x61693a6163633239353730613830336336633161323236386538363766316564333630 Sat Aug 17 18:23:36 2019 : Debug: (11) EAP-Key-Name := 0x195d582a086518d8626f3c8c8eb4ed1ae02b0e4d222b2363d0d6bb66028aebd9db3ec9aff3e280360a837f90ade646df976f66d4b2d287de285083a6df4935b8d7 Sat Aug 17 18:23:36 2019 : Debug: (11) Finished request

————————————————

Server configuration: ————————————— Sat Aug 17 18:20:38 2019 : Info: Starting - reading configuration files ... Sat Aug 17 18:20:38 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary Sat Aug 17 18:20:38 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary.dhcp Sat Aug 17 18:20:38 2019 : Debug: including dictionary file /usr/share/freeradius/dictionary.vqp Sat Aug 17 18:20:38 2019 : Debug: including dictionary file /etc/freeradius/3.0/dictionary Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/radiusd.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/proxy.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/clients.conf Sat Aug 17 18:20:38 2019 : Debug: including files in directory /etc/freeradius/3.0/mods-enabled/ Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/cache_eap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/chap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/detail Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/digest Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/dynamic_clients Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/eap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/echo Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/exec Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/expiration Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/expr Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/files Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/linelog Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/logintime Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/mschap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/ntlm_auth Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/pap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/passwd Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/preprocess Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/radutmp Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/replicate Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/soh Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/sradutmp Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/unix Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/unpack Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/utf8 Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/sql Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/main/mysql/queries.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/counter/mysql/dailycounter.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/counter/mysql/monthlycounter.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/counter/mysql/noresetcounter.conf Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/mods-config/sql/counter/mysql/expire_on_login.conf Sat Aug 17 18:20:38 2019 : Debug: including files in directory /etc/freeradius/3.0/policy.d/ Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/abfab-tr Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/accounting Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/canonicalization Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/control Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/cui Sat Aug 17 18:20:38 2019 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Sat Aug 17 18:20:38 2019 : Debug: OPTIMIZING (no == yes) --> FALSE Sat Aug 17 18:20:38 2019 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Sat Aug 17 18:20:38 2019 : Debug: OPTIMIZING (no == yes) --> FALSE Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/debug Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/dhcp Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/eap Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/filter Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/moonshot-targeted-ids Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/policy.d/operator-name Sat Aug 17 18:20:38 2019 : Debug: including files in directory /etc/freeradius/3.0/sites-enabled/ Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:20:38 2019 : Debug: including configuration file /etc/freeradius/3.0/sites-enabled/status Sat Aug 17 18:20:38 2019 : Debug: main { Sat Aug 17 18:20:38 2019 : Debug: security { Sat Aug 17 18:20:38 2019 : Debug: user = "freerad" Sat Aug 17 18:20:38 2019 : Debug: group = "freerad" Sat Aug 17 18:20:38 2019 : Debug: allow_core_dumps = no Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[424]: The item 'max_attributes' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[442]: The item 'reject_delay' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[462]: The item 'status_server' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: name = "freeradius" Sat Aug 17 18:20:38 2019 : Debug: prefix = "/usr" Sat Aug 17 18:20:38 2019 : Debug: localstatedir = "/var" Sat Aug 17 18:20:38 2019 : Debug: logdir = "/var/log/freeradius" Sat Aug 17 18:20:38 2019 : Debug: run_dir = "/var/run/freeradius" Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[108]: The item 'libdir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[119]: The item 'pidfile' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[194]: The item 'max_request_time' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[213]: The item 'cleanup_delay' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[250]: The item 'hostname_lookups' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[334]: The item 'checkrad' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[483]: The item 'proxy_requests' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: main { Sat Aug 17 18:20:38 2019 : Debug: name = "freeradius" Sat Aug 17 18:20:38 2019 : Debug: prefix = "/usr" Sat Aug 17 18:20:38 2019 : Debug: localstatedir = "/var" Sat Aug 17 18:20:38 2019 : Debug: sbindir = "/usr/sbin" Sat Aug 17 18:20:38 2019 : Debug: logdir = "/var/log/freeradius" Sat Aug 17 18:20:38 2019 : Debug: run_dir = "/var/run/freeradius" Sat Aug 17 18:20:38 2019 : Debug: libdir = "/usr/lib/freeradius" Sat Aug 17 18:20:38 2019 : Debug: radacctdir = "/var/log/freeradius/radacct" Sat Aug 17 18:20:38 2019 : Debug: hostname_lookups = no Sat Aug 17 18:20:38 2019 : Debug: max_request_time = 15 Sat Aug 17 18:20:38 2019 : Debug: cleanup_delay = 3 Sat Aug 17 18:20:38 2019 : Debug: max_requests = 16384 Sat Aug 17 18:20:38 2019 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Sat Aug 17 18:20:38 2019 : Debug: checkrad = "/usr/sbin/checkrad" Sat Aug 17 18:20:38 2019 : Debug: debug_level = 0 Sat Aug 17 18:20:38 2019 : Debug: proxy_requests = yes Sat Aug 17 18:20:38 2019 : Debug: log { Sat Aug 17 18:20:38 2019 : Debug: stripped_names = no Sat Aug 17 18:20:38 2019 : Debug: auth = no Sat Aug 17 18:20:38 2019 : Debug: auth_badpass = no Sat Aug 17 18:20:38 2019 : Debug: auth_goodpass = no Sat Aug 17 18:20:38 2019 : Debug: colourise = yes Sat Aug 17 18:20:38 2019 : Debug: msg_denied = "You are already logged in - access denied" Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[268]: The item 'destination' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[285]: The item 'file' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[293]: The item 'syslog_facility' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: resources { Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: security { Sat Aug 17 18:20:38 2019 : Debug: max_attributes = 200 Sat Aug 17 18:20:38 2019 : Debug: reject_delay = 1.000000 Sat Aug 17 18:20:38 2019 : Debug: status_server = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: radiusd: #### Loading Realms and Home Servers #### Sat Aug 17 18:20:38 2019 : Debug: proxy server { Sat Aug 17 18:20:38 2019 : Debug: retry_delay = 5 Sat Aug 17 18:20:38 2019 : Debug: retry_count = 3 Sat Aug 17 18:20:38 2019 : Debug: default_fallback = no Sat Aug 17 18:20:38 2019 : Debug: dead_time = 120 Sat Aug 17 18:20:38 2019 : Debug: wake_all_if_all_dead = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: home_server localhost { Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 127.0.0.1 Sat Aug 17 18:20:38 2019 : Debug: port = 1812 Sat Aug 17 18:20:38 2019 : Debug: type = "auth" Sat Aug 17 18:20:38 2019 : Debug: secret = "testing123" Sat Aug 17 18:20:38 2019 : Debug: response_window = 20.000000 Sat Aug 17 18:20:38 2019 : Debug: response_timeouts = 1 Sat Aug 17 18:20:38 2019 : Debug: max_outstanding = 65536 Sat Aug 17 18:20:38 2019 : Debug: zombie_period = 40 Sat Aug 17 18:20:38 2019 : Debug: status_check = "status-server" Sat Aug 17 18:20:38 2019 : Debug: ping_interval = 30 Sat Aug 17 18:20:38 2019 : Debug: check_interval = 30 Sat Aug 17 18:20:38 2019 : Debug: check_timeout = 4 Sat Aug 17 18:20:38 2019 : Debug: num_answers_to_alive = 3 Sat Aug 17 18:20:38 2019 : Debug: revive_interval = 120 Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: max_requests = 0 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 0 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: coa { Sat Aug 17 18:20:38 2019 : Debug: irt = 2 Sat Aug 17 18:20:38 2019 : Debug: mrt = 16 Sat Aug 17 18:20:38 2019 : Debug: mrc = 5 Sat Aug 17 18:20:38 2019 : Debug: mrd = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Warning: WARNING: Ignoring "response_window = 20.000000", forcing to "response_window = 15.000000" Sat Aug 17 18:20:38 2019 : Debug: home_server_pool my_auth_failover { Sat Aug 17 18:20:38 2019 : Debug: type = fail-over Sat Aug 17 18:20:38 2019 : Debug: home_server = localhost Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: realm example.com { Sat Aug 17 18:20:38 2019 : Debug: auth_pool = my_auth_failover Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: realm LOCAL { Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: radiusd: #### Loading Clients #### Sat Aug 17 18:20:38 2019 : Debug: client localhost { Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 127.0.0.1 Sat Aug 17 18:20:38 2019 : Debug: require_message_authenticator = no Sat Aug 17 18:20:38 2019 : Debug: secret = "testing123" Sat Aug 17 18:20:38 2019 : Debug: nas_type = "other" Sat Aug 17 18:20:38 2019 : Debug: proto = "*" Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: client localhost_ipv6 { Sat Aug 17 18:20:38 2019 : Debug: ipv6addr = ::1 Sat Aug 17 18:20:38 2019 : Debug: require_message_authenticator = no Sat Aug 17 18:20:38 2019 : Debug: secret = "testing123" Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Sat Aug 17 18:20:38 2019 : Info: Debug state unknown (cap_sys_ptrace capability not set) Sat Aug 17 18:20:38 2019 : Debug: # Creating Auth-Type = mschap Sat Aug 17 18:20:38 2019 : Debug: # Creating Auth-Type = eap Sat Aug 17 18:20:38 2019 : Debug: # Creating Auth-Type = PAP Sat Aug 17 18:20:38 2019 : Debug: # Creating Auth-Type = MS-CHAP Sat Aug 17 18:20:38 2019 : Debug: # Creating Autz-Type = radius-status Sat Aug 17 18:20:38 2019 : Debug: # Creating Acct-Type = radius-status Sat Aug 17 18:20:38 2019 : Debug: radiusd: #### Instantiating modules #### Sat Aug 17 18:20:38 2019 : Debug: modules { Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_always with path: /usr/lib/freeradius/rlm_always.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_always, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_always Sat Aug 17 18:20:38 2019 : Debug: # Loading module "reject" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always reject { Sat Aug 17 18:20:38 2019 : Debug: rcode = "reject" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "fail" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always fail { Sat Aug 17 18:20:38 2019 : Debug: rcode = "fail" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "ok" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always ok { Sat Aug 17 18:20:38 2019 : Debug: rcode = "ok" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "handled" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always handled { Sat Aug 17 18:20:38 2019 : Debug: rcode = "handled" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "invalid" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always invalid { Sat Aug 17 18:20:38 2019 : Debug: rcode = "invalid" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "userlock" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always userlock { Sat Aug 17 18:20:38 2019 : Debug: rcode = "userlock" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "notfound" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always notfound { Sat Aug 17 18:20:38 2019 : Debug: rcode = "notfound" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "noop" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always noop { Sat Aug 17 18:20:38 2019 : Debug: rcode = "noop" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "updated" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: always updated { Sat Aug 17 18:20:38 2019 : Debug: rcode = "updated" Sat Aug 17 18:20:38 2019 : Debug: simulcount = 0 Sat Aug 17 18:20:38 2019 : Debug: mpp = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_attr_filter with path: /usr/lib/freeradius/rlm_attr_filter.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_attr_filter, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_attr_filter Sat Aug 17 18:20:38 2019 : Debug: # Loading module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: attr_filter attr_filter.post-proxy { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/post-proxy" Sat Aug 17 18:20:38 2019 : Debug: key = "%{Realm}" Sat Aug 17 18:20:38 2019 : Debug: relaxed = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: attr_filter attr_filter.pre-proxy { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/pre-proxy" Sat Aug 17 18:20:38 2019 : Debug: key = "%{Realm}" Sat Aug 17 18:20:38 2019 : Debug: relaxed = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: attr_filter attr_filter.access_reject { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_reject" Sat Aug 17 18:20:38 2019 : Debug: key = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: relaxed = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: attr_filter attr_filter.access_challenge { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_challenge" Sat Aug 17 18:20:38 2019 : Debug: key = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: relaxed = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: attr_filter attr_filter.accounting_response { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/attr_filter/accounting_response" Sat Aug 17 18:20:38 2019 : Debug: key = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: relaxed = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_cache with path: /usr/lib/freeradius/rlm_cache.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_cache, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_cache Sat Aug 17 18:20:38 2019 : Debug: # Loading module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap Sat Aug 17 18:20:38 2019 : Debug: cache cache_eap { Sat Aug 17 18:20:38 2019 : Debug: driver = "rlm_cache_rbtree" Sat Aug 17 18:20:38 2019 : Debug: key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" Sat Aug 17 18:20:38 2019 : Debug: ttl = 15 Sat Aug 17 18:20:38 2019 : Debug: max_entries = 0 Sat Aug 17 18:20:38 2019 : Debug: epoch = 0 Sat Aug 17 18:20:38 2019 : Debug: add_stats = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_chap with path: /usr/lib/freeradius/rlm_chap.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_chap, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_chap Sat Aug 17 18:20:38 2019 : Debug: # Loading module "chap" from file /etc/freeradius/3.0/mods-enabled/chap Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_detail with path: /usr/lib/freeradius/rlm_detail.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_detail, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_detail Sat Aug 17 18:20:38 2019 : Debug: # Loading module "detail" from file /etc/freeradius/3.0/mods-enabled/detail Sat Aug 17 18:20:38 2019 : Debug: detail { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Sat Aug 17 18:20:38 2019 : Debug: header = "%t" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: locking = no Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: log_packet_header = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: detail auth_log { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Sat Aug 17 18:20:38 2019 : Debug: header = "%t" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: locking = no Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: log_packet_header = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: detail reply_log { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Sat Aug 17 18:20:38 2019 : Debug: header = "%t" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: locking = no Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: log_packet_header = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: detail pre_proxy_log { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Sat Aug 17 18:20:38 2019 : Debug: header = "%t" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: locking = no Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: log_packet_header = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: detail post_proxy_log { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Sat Aug 17 18:20:38 2019 : Debug: header = "%t" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: locking = no Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: log_packet_header = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_digest with path: /usr/lib/freeradius/rlm_digest.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_digest, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_digest Sat Aug 17 18:20:38 2019 : Debug: # Loading module "digest" from file /etc/freeradius/3.0/mods-enabled/digest Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_dynamic_clients with path: /usr/lib/freeradius/rlm_dynamic_clients.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_dynamic_clients Sat Aug 17 18:20:38 2019 : Debug: # Loading module "dynamic_clients" from file /etc/freeradius/3.0/mods-enabled/dynamic_clients Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_eap with path: /usr/lib/freeradius/rlm_eap.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_eap, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_eap Sat Aug 17 18:20:38 2019 : Debug: # Loading module "eap" from file /etc/freeradius/3.0/mods-enabled/eap Sat Aug 17 18:20:38 2019 : Debug: eap { Sat Aug 17 18:20:38 2019 : Debug: default_eap_type = "peap" Sat Aug 17 18:20:38 2019 : Debug: timer_expire = 60 Sat Aug 17 18:20:38 2019 : Debug: ignore_unknown_eap_types = no Sat Aug 17 18:20:38 2019 : Debug: cisco_accounting_username_bug = no Sat Aug 17 18:20:38 2019 : Debug: max_sessions = 16384 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_exec with path: /usr/lib/freeradius/rlm_exec.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_exec, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_exec Sat Aug 17 18:20:38 2019 : Debug: # Loading module "echo" from file /etc/freeradius/3.0/mods-enabled/echo Sat Aug 17 18:20:38 2019 : Debug: exec echo { Sat Aug 17 18:20:38 2019 : Debug: wait = yes Sat Aug 17 18:20:38 2019 : Debug: program = "/bin/echo %{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: input_pairs = "request" Sat Aug 17 18:20:38 2019 : Debug: output_pairs = "reply" Sat Aug 17 18:20:38 2019 : Debug: shell_escape = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "exec" from file /etc/freeradius/3.0/mods-enabled/exec Sat Aug 17 18:20:38 2019 : Debug: exec { Sat Aug 17 18:20:38 2019 : Debug: wait = no Sat Aug 17 18:20:38 2019 : Debug: input_pairs = "request" Sat Aug 17 18:20:38 2019 : Debug: shell_escape = yes Sat Aug 17 18:20:38 2019 : Debug: timeout = 10 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_expiration with path: /usr/lib/freeradius/rlm_expiration.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_expiration, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_expiration Sat Aug 17 18:20:38 2019 : Debug: # Loading module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_expr with path: /usr/lib/freeradius/rlm_expr.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_expr, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_expr Sat Aug 17 18:20:38 2019 : Debug: # Loading module "expr" from file /etc/freeradius/3.0/mods-enabled/expr Sat Aug 17 18:20:38 2019 : Debug: expr { Sat Aug 17 18:20:38 2019 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_files with path: /usr/lib/freeradius/rlm_files.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_files, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_files Sat Aug 17 18:20:38 2019 : Debug: # Loading module "files" from file /etc/freeradius/3.0/mods-enabled/files Sat Aug 17 18:20:38 2019 : Debug: files { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/freeradius/3.0/mods-config/files/authorize" Sat Aug 17 18:20:38 2019 : Debug: acctusersfile = "/etc/freeradius/3.0/mods-config/files/accounting" Sat Aug 17 18:20:38 2019 : Debug: preproxy_usersfile = "/etc/freeradius/3.0/mods-config/files/pre-proxy" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_linelog with path: /usr/lib/freeradius/rlm_linelog.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_linelog, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_linelog Sat Aug 17 18:20:38 2019 : Debug: # Loading module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog Sat Aug 17 18:20:38 2019 : Debug: linelog { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/linelog" Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: syslog_severity = "info" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: format = "This is a log message for %{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog Sat Aug 17 18:20:38 2019 : Debug: linelog log_accounting { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/linelog-accounting" Sat Aug 17 18:20:38 2019 : Debug: escape_filenames = no Sat Aug 17 18:20:38 2019 : Debug: syslog_severity = "info" Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: format = "" Sat Aug 17 18:20:38 2019 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_logintime with path: /usr/lib/freeradius/rlm_logintime.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_logintime, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_logintime Sat Aug 17 18:20:38 2019 : Debug: # Loading module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime Sat Aug 17 18:20:38 2019 : Debug: logintime { Sat Aug 17 18:20:38 2019 : Debug: minimum_timeout = 60 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_mschap with path: /usr/lib/freeradius/rlm_mschap.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_mschap, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_mschap Sat Aug 17 18:20:38 2019 : Debug: # Loading module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap Sat Aug 17 18:20:38 2019 : Debug: mschap { Sat Aug 17 18:20:38 2019 : Debug: use_mppe = yes Sat Aug 17 18:20:38 2019 : Debug: require_encryption = no Sat Aug 17 18:20:38 2019 : Debug: require_strong = no Sat Aug 17 18:20:38 2019 : Debug: with_ntdomain_hack = yes Sat Aug 17 18:20:38 2019 : Debug: passchange { Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: allow_retry = yes Sat Aug 17 18:20:38 2019 : Debug: winbind_retry_with_normalised_username = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "ntlm_auth" from file /etc/freeradius/3.0/mods-enabled/ntlm_auth Sat Aug 17 18:20:38 2019 : Debug: exec ntlm_auth { Sat Aug 17 18:20:38 2019 : Debug: wait = yes Sat Aug 17 18:20:38 2019 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Sat Aug 17 18:20:38 2019 : Debug: shell_escape = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_pap with path: /usr/lib/freeradius/rlm_pap.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_pap, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_pap Sat Aug 17 18:20:38 2019 : Debug: # Loading module "pap" from file /etc/freeradius/3.0/mods-enabled/pap Sat Aug 17 18:20:38 2019 : Debug: pap { Sat Aug 17 18:20:38 2019 : Debug: normalise = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_passwd with path: /usr/lib/freeradius/rlm_passwd.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_passwd, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_passwd Sat Aug 17 18:20:38 2019 : Debug: # Loading module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd Sat Aug 17 18:20:38 2019 : Debug: passwd etc_passwd { Sat Aug 17 18:20:38 2019 : Debug: filename = "/etc/passwd" Sat Aug 17 18:20:38 2019 : Debug: format = "*User-Name:Crypt-Password:" Sat Aug 17 18:20:38 2019 : Debug: delimiter = ":" Sat Aug 17 18:20:38 2019 : Debug: ignore_nislike = no Sat Aug 17 18:20:38 2019 : Debug: ignore_empty = yes Sat Aug 17 18:20:38 2019 : Debug: allow_multiple_keys = no Sat Aug 17 18:20:38 2019 : Debug: hash_size = 100 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_preprocess with path: /usr/lib/freeradius/rlm_preprocess.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_preprocess, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_preprocess Sat Aug 17 18:20:38 2019 : Debug: # Loading module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess Sat Aug 17 18:20:38 2019 : Debug: preprocess { Sat Aug 17 18:20:38 2019 : Debug: huntgroups = "/etc/freeradius/3.0/mods-config/preprocess/huntgroups" Sat Aug 17 18:20:38 2019 : Debug: hints = "/etc/freeradius/3.0/mods-config/preprocess/hints" Sat Aug 17 18:20:38 2019 : Debug: with_ascend_hack = no Sat Aug 17 18:20:38 2019 : Debug: ascend_channels_per_line = 23 Sat Aug 17 18:20:38 2019 : Debug: with_ntdomain_hack = no Sat Aug 17 18:20:38 2019 : Debug: with_specialix_jetstream_hack = no Sat Aug 17 18:20:38 2019 : Debug: with_cisco_vsa_hack = no Sat Aug 17 18:20:38 2019 : Debug: with_alvarion_vsa_hack = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_radutmp with path: /usr/lib/freeradius/rlm_radutmp.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_radutmp, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_radutmp Sat Aug 17 18:20:38 2019 : Debug: # Loading module "radutmp" from file /etc/freeradius/3.0/mods-enabled/radutmp Sat Aug 17 18:20:38 2019 : Debug: radutmp { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/radutmp" Sat Aug 17 18:20:38 2019 : Debug: username = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: case_sensitive = yes Sat Aug 17 18:20:38 2019 : Debug: check_with_nas = yes Sat Aug 17 18:20:38 2019 : Debug: permissions = 384 Sat Aug 17 18:20:38 2019 : Debug: caller_id = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_realm with path: /usr/lib/freeradius/rlm_realm.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_realm, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_realm Sat Aug 17 18:20:38 2019 : Debug: # Loading module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: realm IPASS { Sat Aug 17 18:20:38 2019 : Debug: format = "prefix" Sat Aug 17 18:20:38 2019 : Debug: delimiter = "/" Sat Aug 17 18:20:38 2019 : Debug: ignore_default = no Sat Aug 17 18:20:38 2019 : Debug: ignore_null = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: realm suffix { Sat Aug 17 18:20:38 2019 : Debug: format = "suffix" Sat Aug 17 18:20:38 2019 : Debug: delimiter = "@" Sat Aug 17 18:20:38 2019 : Debug: ignore_default = no Sat Aug 17 18:20:38 2019 : Debug: ignore_null = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: realm realmpercent { Sat Aug 17 18:20:38 2019 : Debug: format = "suffix" Sat Aug 17 18:20:38 2019 : Debug: delimiter = "%" Sat Aug 17 18:20:38 2019 : Debug: ignore_default = no Sat Aug 17 18:20:38 2019 : Debug: ignore_null = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: realm ntdomain { Sat Aug 17 18:20:38 2019 : Debug: format = "prefix" Sat Aug 17 18:20:38 2019 : Debug: delimiter = "\\" Sat Aug 17 18:20:38 2019 : Debug: ignore_default = no Sat Aug 17 18:20:38 2019 : Debug: ignore_null = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_replicate with path: /usr/lib/freeradius/rlm_replicate.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_replicate, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_replicate Sat Aug 17 18:20:38 2019 : Debug: # Loading module "replicate" from file /etc/freeradius/3.0/mods-enabled/replicate Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_soh with path: /usr/lib/freeradius/rlm_soh.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_soh, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_soh Sat Aug 17 18:20:38 2019 : Debug: # Loading module "soh" from file /etc/freeradius/3.0/mods-enabled/soh Sat Aug 17 18:20:38 2019 : Debug: soh { Sat Aug 17 18:20:38 2019 : Debug: dhcp = yes Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "sradutmp" from file /etc/freeradius/3.0/mods-enabled/sradutmp Sat Aug 17 18:20:38 2019 : Debug: radutmp sradutmp { Sat Aug 17 18:20:38 2019 : Debug: filename = "/var/log/freeradius/sradutmp" Sat Aug 17 18:20:38 2019 : Debug: username = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: case_sensitive = yes Sat Aug 17 18:20:38 2019 : Debug: check_with_nas = yes Sat Aug 17 18:20:38 2019 : Debug: permissions = 420 Sat Aug 17 18:20:38 2019 : Debug: caller_id = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_unix with path: /usr/lib/freeradius/rlm_unix.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_unix, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_unix Sat Aug 17 18:20:38 2019 : Debug: # Loading module "unix" from file /etc/freeradius/3.0/mods-enabled/unix Sat Aug 17 18:20:38 2019 : Debug: unix { Sat Aug 17 18:20:38 2019 : Debug: radwtmp = "/var/log/freeradius/radwtmp" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Creating attribute Unix-Group Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_unpack with path: /usr/lib/freeradius/rlm_unpack.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_unpack, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_unpack Sat Aug 17 18:20:38 2019 : Debug: # Loading module "unpack" from file /etc/freeradius/3.0/mods-enabled/unpack Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_utf8 with path: /usr/lib/freeradius/rlm_utf8.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_utf8, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_utf8 Sat Aug 17 18:20:38 2019 : Debug: # Loading module "utf8" from file /etc/freeradius/3.0/mods-enabled/utf8 Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_sql with path: /usr/lib/freeradius/rlm_sql.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_sql, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_sql Sat Aug 17 18:20:38 2019 : Debug: # Loading module "sql" from file /etc/freeradius/3.0/mods-enabled/sql Sat Aug 17 18:20:38 2019 : Debug: sql { Sat Aug 17 18:20:38 2019 : Debug: driver = "rlm_sql_mysql" Sat Aug 17 18:20:38 2019 : Debug: server = "localhost" Sat Aug 17 18:20:38 2019 : Debug: port = 3306 Sat Aug 17 18:20:38 2019 : Debug: login = "root" Sat Aug 17 18:20:38 2019 : Debug: password = "XXXX" Sat Aug 17 18:20:38 2019 : Debug: radius_db = "radius" Sat Aug 17 18:20:38 2019 : Debug: read_groups = yes Sat Aug 17 18:20:38 2019 : Debug: read_profiles = yes Sat Aug 17 18:20:38 2019 : Debug: read_clients = yes Sat Aug 17 18:20:38 2019 : Debug: delete_stale_sessions = yes Sat Aug 17 18:20:38 2019 : Debug: sql_user_name = "%{User-Name}" Sat Aug 17 18:20:38 2019 : Debug: default_user_profile = "" Sat Aug 17 18:20:38 2019 : Debug: client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Sat Aug 17 18:20:38 2019 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Sat Aug 17 18:20:38 2019 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id" Sat Aug 17 18:20:38 2019 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id" Sat Aug 17 18:20:38 2019 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id" Sat Aug 17 18:20:38 2019 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = BINARY '%{SQL-User-Name}' ORDER BY priority" Sat Aug 17 18:20:38 2019 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Sat Aug 17 18:20:38 2019 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Sat Aug 17 18:20:38 2019 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Sat Aug 17 18:20:38 2019 : Debug: query_timeout = 5 Sat Aug 17 18:20:38 2019 : Debug: accounting { Sat Aug 17 18:20:38 2019 : Debug: reference = "%{tolower:type.%{Acct-Status-Type}.query}" Sat Aug 17 18:20:38 2019 : Debug: type { Sat Aug 17 18:20:38 2019 : Debug: accounting-on { Sat Aug 17 18:20:38 2019 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = '%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: accounting-off { Sat Aug 17 18:20:38 2019 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = '%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: start { Sat Aug 17 18:20:38 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}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: interim-update { Sat Aug 17 18:20:38 2019 : Debug: query = "UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctinterval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), 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}'" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: stop { Sat Aug 17 18:20:38 2019 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), 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}'" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: post-auth { Sat Aug 17 18:20:38 2019 : Debug: reference = ".query" Sat Aug 17 18:20:38 2019 : Debug: query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_sql_mysql with path: /usr/lib/freeradius/rlm_sql_mysql.so Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Sat Aug 17 18:20:38 2019 : Debug: Creating attribute SQL-Group Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_sqlcounter with path: /usr/lib/freeradius/rlm_sqlcounter.so Sat Aug 17 18:20:38 2019 : Debug: Loaded rlm_sqlcounter, checking if it's valid Sat Aug 17 18:20:38 2019 : Debug: # Loaded module rlm_sqlcounter Sat Aug 17 18:20:38 2019 : Debug: # Loading module "dailycounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: sqlcounter dailycounter { Sat Aug 17 18:20:38 2019 : Debug: sql_module_instance = "sql" Sat Aug 17 18:20:38 2019 : Debug: key = "User-Name" Sat Aug 17 18:20:38 2019 : Debug: query = "SELECT SUM(acctsessiontime) FROM radacct WHERE username = '%{User-Name}' AND acctstarttime BETWEEN FROM_UNIXTIME('%%b') AND FROM_UNIXTIME('%%e')" Sat Aug 17 18:20:38 2019 : Debug: reset = "daily" Sat Aug 17 18:20:38 2019 : Debug: counter_name = "Daily-Session-Time" Sat Aug 17 18:20:38 2019 : Debug: check_name = "Max-Daily-Session" Sat Aug 17 18:20:38 2019 : Debug: reply_name = "Session-Timeout" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "monthlycounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: sqlcounter monthlycounter { Sat Aug 17 18:20:38 2019 : Debug: sql_module_instance = "sql" Sat Aug 17 18:20:38 2019 : Debug: key = "User-Name" Sat Aug 17 18:20:38 2019 : Debug: query = "SELECT SUM(acctsessiontime - GREATEST((%%b - UNIX_TIMESTAMP(acctstarttime)), 0)) FROM radacct WHERE username='%{User-Name}' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '%%b'" Sat Aug 17 18:20:38 2019 : Debug: reset = "monthly" Sat Aug 17 18:20:38 2019 : Debug: counter_name = "Monthly-Session-Time" Sat Aug 17 18:20:38 2019 : Debug: check_name = "Max-Monthly-Session" Sat Aug 17 18:20:38 2019 : Debug: reply_name = "Session-Timeout" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "noresetcounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: sqlcounter noresetcounter { Sat Aug 17 18:20:38 2019 : Debug: sql_module_instance = "sql" Sat Aug 17 18:20:38 2019 : Debug: key = "User-Name" Sat Aug 17 18:20:38 2019 : Debug: query = "SELECT IFNULL(SUM(AcctSessionTime),0) FROM radacct WHERE UserName='%{User-Name}'" Sat Aug 17 18:20:38 2019 : Debug: reset = "never" Sat Aug 17 18:20:38 2019 : Debug: counter_name = "Max-All-Session-Time" Sat Aug 17 18:20:38 2019 : Debug: check_name = "Max-All-Session" Sat Aug 17 18:20:38 2019 : Debug: reply_name = "Session-Timeout" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Loading module "expire_on_login" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: sqlcounter expire_on_login { Sat Aug 17 18:20:38 2019 : Debug: sql_module_instance = "sql" Sat Aug 17 18:20:38 2019 : Debug: key = "User-Name" Sat Aug 17 18:20:38 2019 : Debug: query = "SELECT IFNULL( MAX(TIME_TO_SEC(TIMEDIFF(NOW(), acctstarttime))),0) FROM radacct WHERE UserName='%{User-Name}' ORDER BY acctstarttime LIMIT 1;" Sat Aug 17 18:20:38 2019 : Debug: reset = "never" Sat Aug 17 18:20:38 2019 : Debug: counter_name = "Expire-After-Initial-Login" Sat Aug 17 18:20:38 2019 : Debug: check_name = "Expire-After" Sat Aug 17 18:20:38 2019 : Debug: reply_name = "Session-Timeout" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: instantiate { Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "dailycounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: rlm_sqlcounter: Current Time: 1566058838 [2019-08-17 18:20:38], Prev reset 1565992800 [2019-08-17 00:00:00] Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "reject" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "fail" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "ok" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "handled" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "invalid" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "userlock" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "notfound" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "noop" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "updated" from file /etc/freeradius/3.0/mods-enabled/always Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/post-proxy Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/pre-proxy Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_reject Sat Aug 17 18:20:38 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". Sat Aug 17 18:20:38 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". Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_challenge Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/accounting_response Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_cache_rbtree with path: /usr/lib/freeradius/rlm_cache_rbtree.so Sat Aug 17 18:20:38 2019 : Debug: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "detail" from file /etc/freeradius/3.0/mods-enabled/detail Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "eap" from file /etc/freeradius/3.0/mods-enabled/eap Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_eap_tls with path: /usr/lib/freeradius/rlm_eap_tls.so Sat Aug 17 18:20:38 2019 : Debug: # Linked to sub-module rlm_eap_tls Sat Aug 17 18:20:38 2019 : Debug: tls { Sat Aug 17 18:20:38 2019 : Debug: tls = "tls-common" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: tls-config tls-common { Sat Aug 17 18:20:38 2019 : Debug: verify_depth = 0 Sat Aug 17 18:20:38 2019 : Debug: ca_path = "/etc/freeradius/3.0/certs" Sat Aug 17 18:20:38 2019 : Debug: pem_file_type = yes Sat Aug 17 18:20:38 2019 : Debug: private_key_file = "/etc/ssl/private/server.key" Sat Aug 17 18:20:38 2019 : Debug: certificate_file = "/etc/ssl/private/server.pem" Sat Aug 17 18:20:38 2019 : Debug: ca_file = "/etc/ssl/certs/ca-certificates.crt" Sat Aug 17 18:20:38 2019 : Debug: private_key_password = "whatever" Sat Aug 17 18:20:38 2019 : Debug: dh_file = "/etc/freeradius/3.0/certs/dh" Sat Aug 17 18:20:38 2019 : Debug: fragment_size = 1024 Sat Aug 17 18:20:38 2019 : Debug: include_length = yes Sat Aug 17 18:20:38 2019 : Debug: auto_chain = yes Sat Aug 17 18:20:38 2019 : Debug: check_crl = no Sat Aug 17 18:20:38 2019 : Debug: check_all_crl = no Sat Aug 17 18:20:38 2019 : Debug: cipher_list = "DEFAULT" Sat Aug 17 18:20:38 2019 : Debug: cipher_server_preference = no Sat Aug 17 18:20:38 2019 : Debug: ecdh_curve = "prime256v1" Sat Aug 17 18:20:38 2019 : Debug: tls_max_version = "" Sat Aug 17 18:20:38 2019 : Debug: tls_min_version = "1.0" Sat Aug 17 18:20:38 2019 : Debug: cache { Sat Aug 17 18:20:38 2019 : Debug: enable = no Sat Aug 17 18:20:38 2019 : Debug: lifetime = 24 Sat Aug 17 18:20:38 2019 : Debug: max_entries = 255 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: verify { Sat Aug 17 18:20:38 2019 : Debug: skip_if_ocsp_ok = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: ocsp { Sat Aug 17 18:20:38 2019 : Debug: enable = no Sat Aug 17 18:20:38 2019 : Debug: override_cert_url = yes Sat Aug 17 18:20:38 2019 : Debug: url = "http://127.0.0.1/ocsp/" Sat Aug 17 18:20:38 2019 : Debug: use_nonce = yes Sat Aug 17 18:20:38 2019 : Debug: timeout = 0 Sat Aug 17 18:20:38 2019 : Debug: softfail = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_eap_ttls with path: /usr/lib/freeradius/rlm_eap_ttls.so Sat Aug 17 18:20:38 2019 : Debug: # Linked to sub-module rlm_eap_ttls Sat Aug 17 18:20:38 2019 : Debug: ttls { Sat Aug 17 18:20:38 2019 : Debug: tls = "tls-common" Sat Aug 17 18:20:38 2019 : Debug: default_eap_type = "md5" Sat Aug 17 18:20:38 2019 : Debug: copy_request_to_tunnel = no Sat Aug 17 18:20:38 2019 : Debug: use_tunneled_reply = yes Sat Aug 17 18:20:38 2019 : Debug: virtual_server = "inner-tunnel" Sat Aug 17 18:20:38 2019 : Debug: include_length = yes Sat Aug 17 18:20:38 2019 : Debug: require_client_cert = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: tls: Using cached TLS configuration from previous invocation Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_eap_peap with path: /usr/lib/freeradius/rlm_eap_peap.so Sat Aug 17 18:20:38 2019 : Debug: # Linked to sub-module rlm_eap_peap Sat Aug 17 18:20:38 2019 : Debug: peap { Sat Aug 17 18:20:38 2019 : Debug: tls = "tls-common" Sat Aug 17 18:20:38 2019 : Debug: default_eap_type = "mschapv2" Sat Aug 17 18:20:38 2019 : Debug: copy_request_to_tunnel = no Sat Aug 17 18:20:38 2019 : Debug: use_tunneled_reply = yes Sat Aug 17 18:20:38 2019 : Debug: proxy_tunneled_request_as_eap = yes Sat Aug 17 18:20:38 2019 : Debug: virtual_server = "inner-tunnel" Sat Aug 17 18:20:38 2019 : Debug: soh = no Sat Aug 17 18:20:38 2019 : Debug: require_client_cert = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: tls: Using cached TLS configuration from previous invocation Sat Aug 17 18:20:38 2019 : Debug: Loading rlm_eap_mschapv2 with path: /usr/lib/freeradius/rlm_eap_mschapv2.so Sat Aug 17 18:20:38 2019 : Debug: # Linked to sub-module rlm_eap_mschapv2 Sat Aug 17 18:20:38 2019 : Debug: mschapv2 { Sat Aug 17 18:20:38 2019 : Debug: with_ntdomain_hack = no Sat Aug 17 18:20:38 2019 : Debug: send_error = no Sat Aug 17 18:20:38 2019 : Debug: identity = "daloradius.marszalkowscy.pl" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "files" from file /etc/freeradius/3.0/mods-enabled/files Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/authorize Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/accounting Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/files/pre-proxy Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap Sat Aug 17 18:20:38 2019 : Debug: rlm_mschap (mschap): using internal authentication Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "pap" from file /etc/freeradius/3.0/mods-enabled/pap Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd Sat Aug 17 18:20:38 2019 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/huntgroups Sat Aug 17 18:20:38 2019 : Debug: reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/hints Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "sql" from file /etc/freeradius/3.0/mods-enabled/sql Sat Aug 17 18:20:38 2019 : Info: rlm_sql_mysql: libmysql version: 5.7.27 Sat Aug 17 18:20:38 2019 : Debug: mysql { Sat Aug 17 18:20:38 2019 : Debug: tls { Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: warnings = "auto" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Attempting to connect to database "radius" Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Using local pool section Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): No pool reference found for config item "sql.pool" Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Initialising connection pool Sat Aug 17 18:20:38 2019 : Debug: pool { Sat Aug 17 18:20:38 2019 : Debug: start = 5 Sat Aug 17 18:20:38 2019 : Debug: min = 3 Sat Aug 17 18:20:38 2019 : Debug: max = 32 Sat Aug 17 18:20:38 2019 : Debug: spare = 10 Sat Aug 17 18:20:38 2019 : Debug: uses = 0 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: cleanup_interval = 30 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 60 Sat Aug 17 18:20:38 2019 : Debug: retry_delay = 30 Sat Aug 17 18:20:38 2019 : Debug: spread = no Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (0), 1 of 32 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (1), 1 of 31 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (2), 1 of 30 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (3), 1 of 29 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (4), 1 of 28 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding pool reference 0x556e9959ea80 to config item "sql.pool" Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Processing generate_sql_clients Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Reserved connection (0) Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Executing select query: SELECT id, nasname, shortname, type, secret, server FROM nas Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding client 172.16.0.1 (USG) to global clients list Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.1/32 (172.16.0.1) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (172.16.0.1): Client "USG" (sql) added Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding client 172.16.0.2 (USW-16) to global clients list Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.2/32 (172.16.0.2) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (172.16.0.2): Client "USW-16" (sql) added Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding client 172.16.0.3 (USW-8) to global clients list Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.3/32 (172.16.0.3) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (172.16.0.3): Client "USW-8" (sql) added Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding client 172.16.0.4 (Pietro) to global clients list Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.4/32 (172.16.0.4) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (172.16.0.4): Client "Pietro" (sql) added Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Adding client 172.16.0.5 (Parter) to global clients list Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.5/32 (172.16.0.5) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (172.16.0.5): Client "Parter" (sql) added Sat Aug 17 18:20:38 2019 : Debug: rlm_sql (sql): Released connection (0) Sat Aug 17 18:20:38 2019 : Info: Need 5 more connections to reach 10 spares Sat Aug 17 18:20:38 2019 : Info: rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sat Aug 17 18:20:38 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "monthlycounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: rlm_sqlcounter: Current Time: 1566058838 [2019-08-17 18:20:38], Prev reset 1564610400 [2019-08-01 00:00:00] Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "noresetcounter" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: rlm_sqlcounter: Current Time: 1566058838 [2019-08-17 18:20:38], Prev reset 0 [2019-08-17 18:00:00] Sat Aug 17 18:20:38 2019 : Debug: # Instantiating module "expire_on_login" from file /etc/freeradius/3.0/mods-enabled/sqlcounter Sat Aug 17 18:20:38 2019 : Debug: rlm_sqlcounter: Current Time: 1566058838 [2019-08-17 18:20:38], Prev reset 0 [2019-08-17 18:00:00] Sat Aug 17 18:20:38 2019 : Debug: } # modules Sat Aug 17 18:20:38 2019 : Debug: radiusd: #### Loading Virtual Servers #### Sat Aug 17 18:20:38 2019 : Debug: server { # from file /etc/freeradius/3.0/radiusd.conf Sat Aug 17 18:20:38 2019 : Debug: } # server Sat Aug 17 18:20:38 2019 : Debug: server DOM { # from file /etc/freeradius/3.0/sites-enabled/default Sat Aug 17 18:20:38 2019 : Debug: authenticate { Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: pap Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: } # authenticate Sat Aug 17 18:20:38 2019 : Debug: authorize { Sat Aug 17 18:20:38 2019 : Debug: policy filter_username { Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name) { Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ / /) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@[^@]*@/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /\.\./) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /\.$/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@\./) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: policy filter_password { Sat Aug 17 18:20:38 2019 : Debug: if (&User-Password && !&User-Password == "%{string:User-Password}") { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Tmp-String-0 := "%{string:User-Password}" Sat Aug 17 18:20:38 2019 : Debug: &User-Password := "%{string:Tmp-String-0}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: preprocess Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/default[309]: Please change attribute reference to '&Huntgroup-Name := ...' Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Huntgroup-Name := "%{sql:select groupname from radhuntgroup where nasipaddress=\"%{NAS-IP-Address}\"}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: suffix Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: dailycounter Sat Aug 17 18:20:38 2019 : Debug: expiration Sat Aug 17 18:20:38 2019 : Debug: logintime Sat Aug 17 18:20:38 2019 : Debug: pap Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # authorize Sat Aug 17 18:20:38 2019 : Debug: preacct { Sat Aug 17 18:20:38 2019 : Debug: preprocess Sat Aug 17 18:20:38 2019 : Debug: policy acct_counters64.preacct { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Acct-Input-Octets64 = "%{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}" Sat Aug 17 18:20:38 2019 : Debug: &Acct-Output-Octets64 = "%{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &FreeRADIUS-Acct-Session-Start-Time = "%{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: policy acct_unique { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Tmp-String-9 := "ai:" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if ("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/ && "%{string:&Class}" =~ /^ai:([0-9a-f]{32})/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: else { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 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}}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: suffix Sat Aug 17 18:20:38 2019 : Debug: } # preacct Sat Aug 17 18:20:38 2019 : Debug: accounting { Sat Aug 17 18:20:38 2019 : Debug: detail Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: exec Sat Aug 17 18:20:38 2019 : Debug: attr_filter.accounting_response Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # accounting Sat Aug 17 18:20:38 2019 : Debug: session { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: } # session Sat Aug 17 18:20:38 2019 : Debug: post-proxy { Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: } # post-proxy Sat Aug 17 18:20:38 2019 : Debug: post-auth { Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/default[706]: Please change attribute reference to '&State := ...' Sat Aug 17 18:20:38 2019 : Debug: if (!&reply:State) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:State := "0x%{randstr:16h}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:[*] += &session-state:[*] Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: exec Sat Aug 17 18:20:38 2019 : Debug: policy insert_acct_class { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:Class = "ai:%{md5:%t,%I,%{Packet-Src-Port},%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}},%{NAS-IP-Address},%{Calling-Station-ID},%{User-Name}}" Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/default[822]: Please change attribute reference to '&EAP-Key-Name := ...' Sat Aug 17 18:20:38 2019 : Debug: if (&reply:EAP-Session-Id) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:EAP-Key-Name := &reply:EAP-Session-Id Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: policy remove_reply_message_if_eap { Sat Aug 17 18:20:38 2019 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:Reply-Message !* ANY Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: else { Sat Aug 17 18:20:38 2019 : Debug: noop Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: attr_filter.access_reject Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: policy remove_reply_message_if_eap { Sat Aug 17 18:20:38 2019 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:Reply-Message !* ANY Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: else { Sat Aug 17 18:20:38 2019 : Debug: noop Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # post-auth Sat Aug 17 18:20:38 2019 : Debug: } # server DOM Sat Aug 17 18:20:38 2019 : Debug: server inner-tunnel { # from file /etc/freeradius/3.0/sites-enabled/inner-tunnel Sat Aug 17 18:20:38 2019 : Debug: authenticate { Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: pap Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: } # authenticate Sat Aug 17 18:20:38 2019 : Debug: authorize { Sat Aug 17 18:20:38 2019 : Debug: policy filter_username { Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name) { Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ / /) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@[^@]*@/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /\.\./) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /\.$/) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: if (&User-Name =~ /@\./) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: reject Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: mschap Sat Aug 17 18:20:38 2019 : Debug: suffix Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &control:Proxy-To-Realm := LOCAL Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: dailycounter Sat Aug 17 18:20:38 2019 : Debug: expiration Sat Aug 17 18:20:38 2019 : Debug: logintime Sat Aug 17 18:20:38 2019 : Debug: pap Sat Aug 17 18:20:38 2019 : Debug: } # authorize Sat Aug 17 18:20:38 2019 : Debug: session { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: } # session Sat Aug 17 18:20:38 2019 : Debug: post-proxy { Sat Aug 17 18:20:38 2019 : Debug: eap Sat Aug 17 18:20:38 2019 : Debug: } # post-proxy Sat Aug 17 18:20:38 2019 : Debug: post-auth { Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[289]: Please change attribute reference to '&User-Name := ...' Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:User-Name := &User-Name Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[343]: Please change attribute reference to '&Message-Authenticator !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[344]: Please change attribute reference to '&EAP-Message !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[345]: Please change attribute reference to '&Proxy-State !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[346]: Please change attribute reference to '&MS-MPPE-Encryption-Types !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[347]: Please change attribute reference to '&MS-MPPE-Encryption-Policy !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[348]: Please change attribute reference to '&MS-MPPE-Send-Key !* ...' Sat Aug 17 18:20:38 2019 : Warning: /etc/freeradius/3.0/sites-enabled/inner-tunnel[349]: Please change attribute reference to '&MS-MPPE-Recv-Key !* ...' Sat Aug 17 18:20:38 2019 : Debug: if (true) { Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &reply:Message-Authenticator !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:EAP-Message !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:Proxy-State !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:MS-MPPE-Encryption-Types !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:MS-MPPE-Encryption-Policy !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:MS-MPPE-Send-Key !* ANY Sat Aug 17 18:20:38 2019 : Debug: &reply:MS-MPPE-Recv-Key !* ANY Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &outer.session-state:[*] += &reply:[*] Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: sql Sat Aug 17 18:20:38 2019 : Debug: attr_filter.access_reject Sat Aug 17 18:20:38 2019 : Debug: update { Sat Aug 17 18:20:38 2019 : Debug: &outer.session-state:Module-Failure-Message := &Module-Failure-Message Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # post-auth Sat Aug 17 18:20:38 2019 : Debug: } # server inner-tunnel Sat Aug 17 18:20:38 2019 : Debug: server radius-status { # from file /etc/freeradius/3.0/sites-enabled/status Sat Aug 17 18:20:38 2019 : Debug: authorize { Sat Aug 17 18:20:38 2019 : Debug: ok Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: ok Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # authorize Sat Aug 17 18:20:38 2019 : Debug: accounting { Sat Aug 17 18:20:38 2019 : Debug: ok Sat Aug 17 18:20:38 2019 : Debug: group { Sat Aug 17 18:20:38 2019 : Debug: ok Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } # accounting Sat Aug 17 18:20:38 2019 : Debug: } # server radius-status Sat Aug 17 18:20:38 2019 : Debug: Created signal pipe. Read end FD 13, write end FD 14 Sat Aug 17 18:20:38 2019 : Debug: radiusd: #### Opening IP addresses and Ports #### Sat Aug 17 18:20:38 2019 : Debug: Loading proto_auth with path: /usr/lib/freeradius/proto_auth.so Sat Aug 17 18:20:38 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 Sat Aug 17 18:20:38 2019 : Debug: Loading library using linker search path(s) Sat Aug 17 18:20:38 2019 : Debug: Defaults : /lib:/usr/lib Sat Aug 17 18:20:38 2019 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Sat Aug 17 18:20:38 2019 : Debug: listen { Sat Aug 17 18:20:38 2019 : Debug: type = "auth" Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 172.16.0.12 Sat Aug 17 18:20:38 2019 : Debug: port = 1812 Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading proto_acct with path: /usr/lib/freeradius/proto_acct.so Sat Aug 17 18:20:38 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 Sat Aug 17 18:20:38 2019 : Debug: Loading library using linker search path(s) Sat Aug 17 18:20:38 2019 : Debug: Defaults : /lib:/usr/lib Sat Aug 17 18:20:38 2019 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Sat Aug 17 18:20:38 2019 : Debug: listen { Sat Aug 17 18:20:38 2019 : Debug: type = "acct" Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 172.16.0.12 Sat Aug 17 18:20:38 2019 : Debug: port = 1813 Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading proto_auth with path: /usr/lib/freeradius/proto_auth.so Sat Aug 17 18:20:38 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 Sat Aug 17 18:20:38 2019 : Debug: Loading library using linker search path(s) Sat Aug 17 18:20:38 2019 : Debug: Defaults : /lib:/usr/lib Sat Aug 17 18:20:38 2019 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Sat Aug 17 18:20:38 2019 : Debug: listen { Sat Aug 17 18:20:38 2019 : Debug: type = "auth" Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 127.0.0.1 Sat Aug 17 18:20:38 2019 : Debug: port = 18120 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Loading proto_status with path: /usr/lib/freeradius/proto_status.so Sat Aug 17 18:20:38 2019 : Debug: Loading proto_status failed: /usr/lib/freeradius/proto_status.so: cannot open shared object file: No such file or directory - No such file or directory Sat Aug 17 18:20:38 2019 : Debug: Loading library using linker search path(s) Sat Aug 17 18:20:38 2019 : Debug: Defaults : /lib:/usr/lib Sat Aug 17 18:20:38 2019 : Debug: Failed with error: proto_status.so: cannot open shared object file: No such file or directory Sat Aug 17 18:20:38 2019 : Debug: listen { Sat Aug 17 18:20:38 2019 : Debug: type = "status" Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 127.0.0.1 Sat Aug 17 18:20:38 2019 : Debug: port = 18121 Sat Aug 17 18:20:38 2019 : Debug: client admin { Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 127.0.0.1 Sat Aug 17 18:20:38 2019 : Debug: require_message_authenticator = no Sat Aug 17 18:20:38 2019 : Debug: secret = "Ametyst3" Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: client router { Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 172.16.0.1 Sat Aug 17 18:20:38 2019 : Debug: require_message_authenticator = no Sat Aug 17 18:20:38 2019 : Debug: secret = "Ametyst3" Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.1/32 (172.16.0.1) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: client switch { Sat Aug 17 18:20:38 2019 : Debug: ipaddr = 172.16.0.2 Sat Aug 17 18:20:38 2019 : Debug: require_message_authenticator = no Sat Aug 17 18:20:38 2019 : Debug: secret = "Ametyst3" Sat Aug 17 18:20:38 2019 : Debug: limit { Sat Aug 17 18:20:38 2019 : Debug: max_connections = 16 Sat Aug 17 18:20:38 2019 : Debug: lifetime = 0 Sat Aug 17 18:20:38 2019 : Debug: idle_timeout = 30 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Adding client 172.16.0.2/32 (172.16.0.2) to prefix tree 32 Sat Aug 17 18:20:38 2019 : Debug: } Sat Aug 17 18:20:38 2019 : Debug: Listening on auth address 172.16.0.12 port 1812 bound to server DOM Sat Aug 17 18:20:38 2019 : Debug: Listening on acct address 172.16.0.12 port 1813 bound to server DOM Sat Aug 17 18:20:38 2019 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Sat Aug 17 18:20:38 2019 : Debug: Listening on status address 127.0.0.1 port 18121 bound to server radius-status Sat Aug 17 18:20:38 2019 : Debug: Opened new proxy socket 'proxy address * port 44003' Sat Aug 17 18:20:38 2019 : Debug: Listening on proxy address * port 44003 Sat Aug 17 18:20:38 2019 : Info: Ready to process requests

—————————————

On top of that I have a problems with accounting, it seems like NAS doesn’t like Gigawords - quite often reports 4GB up and down. More often it happens when session is longer than shorter. Is there any any fix available on Freeradius side? Ubiquiti claims https://help.ubnt.com/hc/en-us/articles/115005255907-UniFi-Hotspot-RADIUS-At... their APs should be working with this attribute. NAS it is Unifi AP AC Pro.

So, where do I need to troubleshoot, Freeradius or NAS? While looking at tcpdump on port 1812 I can see lengthy negotiation: multiple access requests and access challenges (12 times) followed finally by access accept... I don't know how many requests and challenges should be there. Thanks in advance!

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

There's no need to test. If you read the documentation about how Post-Auth-Type works, you will understand how it works.

You are right, but this seems to work; maybe for not all the cases but at least in mine case. if (&reply:EAP-Session-Id) { } else { sql } Suggestions for improvement?

And PLEASE edit your posts to the list. There is no need to quote hundreds of lines of text when replying to a message. The list guideline page on the Wiki says this:

I’ve read it and there’s only info about (not) reposting and I didn’t. My bad, since my email client automatically wraps previous messages and I didn’t notice them.

Thanks Alan D, I knew I won’t be perfect.

We need "radiusd -X". Not "radiusd -Xxxxxxxxxxx". Among a few other issues.

Read this: http://wiki.freeradius.org/list-help

I’ve read wiki but I sent more detailed debug info because I hadn’t seen sql entry in standard debug. Gigawords

Ask the NAS vendor how there equipment works.

I did ask Ubiquiti but unfortunately without any result/reply. That’s why I’m trying to figure it out somewhere else.

If you get an Access-Accept, why you do care how many packets there are?

Because I wasn’t sure whether it may affect accounting/problems with gigawords. I did read info about EAP protocol but I couldn’t find details about packets exchange. I need only push in the right direction. Regards Martin

Wiadomość napisana przez Alan DeKok <aland@deployingradius.com> w dniu 18.08.2019, o godz. 13:49:

On Aug 18, 2019, at 3:33 AM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:

...

I’m newbie to Freeradius and have been pulling my hair out… Installed Freeradius 3.16 with mysql and Daloradius. Autheticating and authorizing work (I think so). But I might have something misconfigured - radpostauth table is full of duplicated/always double entries with the same timestamp. And it happens only for EAP auth., PAP (radtest) and MD5 (MAC based auth.) are not affected. Does it may affect accounting?

It doesn't affect accounting. You can *read* the debug log to verify this.

The "double entries" are how PEAP works. There is an outer identity, and an inner one. They can be different.

...

Following is request debug where double input to radpostauth is visible: ———————————————— Sat Aug 17 18:23:36 2019 : Debug: (10) Received Access-Request Id 248 from 172.16.0.5:48453 to 172.16.0.12:1812 length 242 Sat Aug 17 18:23:36 2019 : Debug: (10) User-Name = "Robert" Sat Aug 17 18:23:36 2019 : Debug: (10) NAS-Identifier = "feec3a9aeda5"

<sigh> Is it *really* that hard to read the documentation? Where should we put the documentation where you will *read* it?

We need "radiusd -X". Not "radiusd -Xxxxxxxxxxx". Among a few other issues.

Read this: http://wiki.freeradius.org/list-help

When you joined the mailing list, you were sent an email giving you that URL, and telling you what to post. The "man radiusd" page tells you to run "radiusd -X". The documentation on the main web site tells you do use "radiusd -X". We say this almost daily on the mailing list.

So... WHY are you ignoring all of the documentation?

...

On top of that I have a problems with accounting, it seems like NAS doesn’t like Gigawords - quite often reports 4GB up and down. More often it happens when session is longer than shorter. Is there any any fix available on Freeradius side? Ubiquiti claims https://help.ubnt.com/hc/en-us/articles/115005255907-UniFi-Hotspot-RADIUS-At... their APs should be working with this attribute. NAS it is Unifi AP AC Pro.

Ask the NAS vendor how there equipment works.

...

So, where do I need to troubleshoot, Freeradius or NAS? While looking at tcpdump on port 1812 I can see lengthy negotiation: multiple access requests and access challenges (12 times) followed finally by access accept... I don't know how many requests and challenges should be there.

If you get an Access-Accept, why you do care how many packets there are?

If you really want to know how many packets there *should* be, then read the documentation / specifications for EAP. But given the avoidance of all documentation. I guess that won't happen.

Alan DeKok.

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html