Freeradius 3.16 and mysql - duplicated entries in radpostauth

Marcin Marszałkowski m.marszal at wp.pl
Sun Aug 18 15:47:25 CEST 2019




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-Attributes 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 at 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-eap-protocol
> 
> alan
> 
> On Sun, 18 Aug 2019 at 08:36, Marcin Marszałkowski <m.marszal at 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-Attributes 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



More information about the Freeradius-Users mailing list