Freeradius 3.16 and mysql - duplicated entries in radpostauth
Alan Buxey
alan.buxey at gmail.com
Sun Aug 18 13:39:20 CEST 2019
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
More information about the Freeradius-Users
mailing list