Freeradius 3.16 and mysql - duplicated entries in radpostauth
Marcin Marszałkowski
m.marszal at wp.pl
Sun Aug 18 09:33:50 CEST 2019
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!
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1633 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20190818/33fd51d2/attachment-0001.bin>
More information about the Freeradius-Users
mailing list