Sun Jul 26 18:20:01 2020 : Debug: (1) ntlm_auth_vpn_hb: Program returned code (0) and output 'NT_STATUS_OK: The operation completed successfully. (0x0)' Sun Jul 26 18:20:01 2020 : Debug: (1) ntlm_auth_vpn_hb: Program executed successfully Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: returned from ntlm_auth_vpn_hb (rlm_exec) Sun Jul 26 18:20:01 2020 : Debug: (1) [ntlm_auth_vpn_hb] = ok Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: calling smsotp (rlm_smsotp) Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp (smsotp): Reserved connection (0) Sun Jul 26 18:20:01 2020 : Debug: (1) smsotp: Generating OTP Sun Jul 26 18:20:01 2020 : Debug: (1) smsotp: Unique ID is 8475108159 Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp: Sending Access-Challenge Sun Jul 26 18:20:01 2020 : Debug: rlm_smsotp (smsotp): Released connection (0) Sun Jul 26 18:20:01 2020 : Info: rlm_smsotp (smsotp): Closing connection (1), from 4 unused connections Sun Jul 26 18:20:01 2020 : Debug: (1) modsingle[authenticate]: returned from smsotp (rlm_smsotp) Sun Jul 26 18:20:01 2020 : Debug: (1) [smsotp] = handled Sun Jul 26 18:20:01 2020 : Debug: (1) } # Auth-Type smsotp = handled Sun Jul 26 18:20:01 2020 : Debug: (1) Using Post-Auth-Type Challenge Sun Jul 26 18:20:01 2020 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default Sun Jul 26 18:20:01 2020 : Debug: (1) Challenge { ... } # empty sub-section is ignored Sun Jul 26 18:20:01 2020 : Debug: (1) session-state: Nothing to cache Sun Jul 26 18:20:01 2020 : Debug: (1) Sent Access-Challenge Id 200 from 10.100.x.60:1812 to 10.100.x.3:17138 length 0 Sun Jul 26 18:20:01 2020 : Debug: (1) Framed-IP-Address = 10.100.x.112 Sun Jul 26 18:20:01 2020 : Debug: (1) Reply-Message = "Enter Mobile PIN:" Sun Jul 26 18:20:01 2020 : Debug: (1) State = 0x38343735313038313539 Sun Jul 26 18:20:01 2020 : Debug: (1) Finished request Sun Jul 26 18:20:01 2020 : Debug: Waking up in 4.9 seconds. Sun Jul 26 18:20:06 2020 : Debug: (1) Cleaning up request packet ID 200 with timestamp +83 Sun Jul 26 18:20:06 2020 : Info: Ready to process requests Sun Jul 26 18:20:16 2020 : Debug: (2) Received Access-Request Id 201 from 10.100.x.3:17138 to 10.100.x.60:1812 length 627 Sun Jul 26 18:20:16 2020 : Debug: (2) User-Name = "milovan.kotlica" Sun Jul 26 18:20:16 2020 : Debug: (2) User-Password = "02987" Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-Port = 37847040 Sun Jul 26 18:20:16 2020 : Debug: (2) Called-Station-Id = "x.x.x.x" Sun Jul 26 18:20:16 2020 : Debug: (2) Calling-Station-Id = "109.228.125.82" Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-Port-Type = Virtual Sun Jul 26 18:20:16 2020 : Debug: (2) Tunnel-Client-Endpoint:0 = "109.228.125.82" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-phone-id=unknown" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-platform=android" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-platform-version=10" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-mac=aa-02-36-c3-b3-aa" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-type=samsung SM-A715F" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=ac-user-agent=AnyConnect Android 4.8.03651" Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "mdm-tlv=device-uid=8137C81B06B9A4D33B3B673C1BFA077AF83273B03ADA995C4276C4F534E349EF" Sun Jul 26 18:20:16 2020 : Debug: (2) NAS-IP-Address = 10.100.x.3 Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "audit-session-id=0a64c803024180005f1db0f4" Sun Jul 26 18:20:16 2020 : Debug: (2) State = 0x38343735313038313539 Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "ip:source-ip=109.228.125.82" Sun Jul 26 18:20:16 2020 : Debug: (2) ASA-TunnelGroupName = "XXXXXXX" Sun Jul 26 18:20:16 2020 : Debug: (2) ASA-ClientType = AnyConnect-Client-SSL-VPN Sun Jul 26 18:20:16 2020 : Debug: (2) Cisco-AVPair = "coa-push=true" Sun Jul 26 18:20:16 2020 : Debug: (2) session-state: No cached attributes Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default Sun Jul 26 18:20:16 2020 : Debug: (2) authorize { Sun Jul 26 18:20:16 2020 : Debug: (2) policy filter_username { Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) { Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) -> TRUE Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name) { Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ / /) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ / /) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.\./ ) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.\./ ) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.$/) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /\.$/) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@\./) { Sun Jul 26 18:20:16 2020 : Debug: No matches Sun Jul 26 18:20:16 2020 : Debug: (2) if (&User-Name =~ /@\./) -> FALSE Sun Jul 26 18:20:16 2020 : Debug: (2) } # if (&User-Name) = notfound Sun Jul 26 18:20:16 2020 : Debug: (2) } # policy filter_username = notfound Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sun Jul 26 18:20:16 2020 : Debug: (2) [preprocess] = ok Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling auth_log (rlm_detail) Sun Jul 26 18:20:16 2020 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> /var/log/radius/radacct/ Sun Jul 26 18:20:16 2020 : Debug: XLAT-IF { Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Src-IP-Address Sun Jul 26 18:20:16 2020 : Debug: } Sun Jul 26 18:20:16 2020 : Debug: XLAT-ELSE { Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Src-IPv6-Address Sun Jul 26 18:20:16 2020 : Debug: } Sun Jul 26 18:20:16 2020 : Debug: literal --> /auth-detail- Sun Jul 26 18:20:16 2020 : Debug: percent --> Y Sun Jul 26 18:20:16 2020 : Debug: percent --> m Sun Jul 26 18:20:16 2020 : Debug: percent --> d Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: --> /var/log/radius/radacct/10.100.x.3/auth-detail-20200726 Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.100.x.3/auth-detail-20200726 Sun Jul 26 18:20:16 2020 : Debug: %t Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: percent --> t Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: EXPAND %t Sun Jul 26 18:20:16 2020 : Debug: (2) auth_log: --> Sun Jul 26 18:20:16 2020 Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from auth_log (rlm_detail) Sun Jul 26 18:20:16 2020 : Debug: (2) [auth_log] = ok Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling chap (rlm_chap) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from chap (rlm_chap) Sun Jul 26 18:20:16 2020 : Debug: (2) [chap] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap) Sun Jul 26 18:20:16 2020 : Debug: (2) [mschap] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling digest (rlm_digest) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from digest (rlm_digest) Sun Jul 26 18:20:16 2020 : Debug: (2) [digest] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm) Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: Checking for suffix after "@" Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: No '@' in User-Name = "milovan.kotlica", looking up realm NULL Sun Jul 26 18:20:16 2020 : Debug: (2) suffix: No such realm "NULL" Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm) Sun Jul 26 18:20:16 2020 : Debug: (2) [suffix] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) Sun Jul 26 18:20:16 2020 : Debug: (2) eap: No EAP-Message, not doing EAP Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) Sun Jul 26 18:20:16 2020 : Debug: (2) [eap] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling files (rlm_files) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from files (rlm_files) Sun Jul 26 18:20:16 2020 : Debug: (2) [files] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling sql (rlm_sql) Sun Jul 26 18:20:16 2020 : Debug: %{User-Name} Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: attribute --> User-Name Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND %{User-Name} Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> milovan.kotlica Sun Jul 26 18:20:16 2020 : Debug: (2) sql: SQL-User-Name set to 'milovan.kotlica' Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 75 seconds Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 75 seconds Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): You probably need to lower "min" Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Reserved connection (1) Sun Jul 26 18:20:16 2020 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'milovan.kotlica' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'milovan.kotlica' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User found in radcheck table Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Conditional check items matched, merging assignment check items Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Auth-Type := smsotp Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: Examining Auth-Type Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: APPENDING Auth-Type FROM 0 TO 0 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: TO in 0 out 0 Sun Jul 26 18:20:16 2020 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = ' Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'milovan.kotlica' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'milovan.kotlica' ORDER BY id Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User found in radreply table, merging reply items Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Framed-IP-Address = 10.100.x.112 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: Examining Framed-IP-Address Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: APPENDING Framed-IP-Address FROM 0 TO 0 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ::: TO in 0 out 0 Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ... falling-through to group processing Sun Jul 26 18:20:16 2020 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name Sun Jul 26 18:20:16 2020 : Debug: literal --> ' ORDER BY priority Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> SELECT groupname FROM radusergroup WHERE username = 'milovan.kotlica' ORDER BY priority Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'milovan.kotlica' ORDER BY priority Sun Jul 26 18:20:16 2020 : Debug: (2) sql: User not found in any groups Sun Jul 26 18:20:16 2020 : Debug: (2) sql: ... falling-through to profile processing Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Released connection (1) Sun Jul 26 18:20:16 2020 : Info: Need 1 more connections to reach min connections (3) Sun Jul 26 18:20:16 2020 : Info: rlm_sql (sql): Opening additional connection (8), 1 of 30 pending slots used Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sun Jul 26 18:20:16 2020 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.3.17-MariaDB, protocol version 10 Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from sql (rlm_sql) Sun Jul 26 18:20:16 2020 : Debug: (2) [sql] = ok Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling smsotp (rlm_smsotp) Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp: Found reply to access challenge (AUTZ), Adding Auth-Type 'smsotp-reply' Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from smsotp (rlm_smsotp) Sun Jul 26 18:20:16 2020 : Debug: (2) [smsotp] = ok Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling expiration (rlm_expiration) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from expiration (rlm_expiration) Sun Jul 26 18:20:16 2020 : Debug: (2) [expiration] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling logintime (rlm_logintime) Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from logintime (rlm_logintime) Sun Jul 26 18:20:16 2020 : Debug: (2) [logintime] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: calling pap (rlm_pap) Sun Jul 26 18:20:16 2020 : WARNING: (2) pap: No "known good" password found for the user. Not setting Auth-Type Sun Jul 26 18:20:16 2020 : WARNING: (2) pap: Authentication will fail unless a "known good" password is available Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authorize]: returned from pap (rlm_pap) Sun Jul 26 18:20:16 2020 : Debug: (2) [pap] = noop Sun Jul 26 18:20:16 2020 : Debug: (2) } # authorize = ok Sun Jul 26 18:20:16 2020 : Debug: (2) Found Auth-Type = smsotp-reply Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default Sun Jul 26 18:20:16 2020 : Debug: (2) Auth-Type smsotp-reply { Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authenticate]: calling smsotp (rlm_smsotp) Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp (smsotp): Reserved connection (2) Sun Jul 26 18:20:16 2020 : Debug: (2) smsotp: Found reply to access challenge Sun Jul 26 18:20:16 2020 : Debug: (2) smsotp: answer is FAILED Sun Jul 26 18:20:16 2020 : Debug: rlm_smsotp (smsotp): Released connection (2) Sun Jul 26 18:20:16 2020 : Info: rlm_smsotp (smsotp): Closing connection (3), from 3 unused connections Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[authenticate]: returned from smsotp (rlm_smsotp) Sun Jul 26 18:20:16 2020 : Debug: (2) [smsotp] = fail Sun Jul 26 18:20:16 2020 : Debug: (2) } # Auth-Type smsotp-reply = fail Sun Jul 26 18:20:16 2020 : Debug: (2) Failed to authenticate the user Sun Jul 26 18:20:16 2020 : Debug: (2) Using Post-Auth-Type Reject Sun Jul 26 18:20:16 2020 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default Sun Jul 26 18:20:16 2020 : Debug: (2) Post-Auth-Type REJECT { Sun Jul 26 18:20:16 2020 : Debug: (2) modsingle[post-auth]: calling sql (rlm_sql) Sun Jul 26 18:20:16 2020 : Debug: .query Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> .query Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND .query Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> .query Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Using query template 'query' Sun Jul 26 18:20:16 2020 : Debug: rlm_sql (sql): Reserved connection (7) Sun Jul 26 18:20:16 2020 : Debug: %{User-Name} Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: attribute --> User-Name Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND %{User-Name} Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> milovan.kotlica Sun Jul 26 18:20:16 2020 : Debug: (2) sql: SQL-User-Name set to 'milovan.kotlica' Sun Jul 26 18:20:16 2020 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', 'xxxxxxx', '%{reply:Packet-Type}', '%S') Sun Jul 26 18:20:16 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:16 2020 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Sun Jul 26 18:20:16 2020 : Debug: attribute --> SQL-User-Name Sun Jul 26 18:20:16 2020 : Debug: literal --> ', 'xxxxxxx', ' Sun Jul 26 18:20:16 2020 : Debug: attribute --> Packet-Type Sun Jul 26 18:20:16 2020 : Debug: literal --> ', ' Sun Jul 26 18:20:16 2020 : Debug: percent --> S Sun Jul 26 18:20:16 2020 : Debug: literal --> ') Sun Jul 26 18:20:16 2020 : Debug: (2) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', 'xxxxxxx', '%{reply:Packet-Type}', '%S') Sun Jul 26 18:20:16 2020 : Debug: (2) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'milovan.kotlica', 'xxxxxxx', 'Access-Reject', '2020-07-26 18:20:16') Sun Jul 26 18:20:16 2020 : Debug: (2) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'milovan.kotlica', 'xxxxxxx', 'Access-Reject', '2020-07-26 18:20:16') Sun Jul 26 18:20:17 2020 : Debug: (2) sql: SQL query returned: success Sun Jul 26 18:20:17 2020 : Debug: (2) sql: 1 record(s) updated Sun Jul 26 18:20:17 2020 : Debug: rlm_sql (sql): Released connection (7) Sun Jul 26 18:20:17 2020 : Info: Need 7 more connections to reach 10 spares Sun Jul 26 18:20:17 2020 : Info: rlm_sql (sql): Opening additional connection (9), 1 of 29 pending slots used Sun Jul 26 18:20:17 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sun Jul 26 18:20:17 2020 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.3.17-MariaDB, protocol version 10 Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from sql (rlm_sql) Sun Jul 26 18:20:17 2020 : Debug: (2) [sql] = ok Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) Sun Jul 26 18:20:17 2020 : Debug: %{User-Name} Sun Jul 26 18:20:17 2020 : Debug: Parsed xlat tree: Sun Jul 26 18:20:17 2020 : Debug: attribute --> User-Name Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: EXPAND %{User-Name} Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: --> milovan.kotlica Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: Matched entry DEFAULT at line 11 Sun Jul 26 18:20:17 2020 : Debug: (2) attr_filter.access_reject: Attribute "Framed-IP-Address" allowed by 0 rules, disallowed by 0 rules Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) Sun Jul 26 18:20:17 2020 : Debug: (2) [attr_filter.access_reject] = updated Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling eap (rlm_eap) Sun Jul 26 18:20:17 2020 : Debug: (2) eap: Request didn't contain an EAP-Message, not inserting EAP-Failure Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from eap (rlm_eap) Sun Jul 26 18:20:17 2020 : Debug: (2) [eap] = noop Sun Jul 26 18:20:17 2020 : Debug: (2) policy remove_reply_message_if_eap { Sun Jul 26 18:20:17 2020 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) { Sun Jul 26 18:20:17 2020 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Sun Jul 26 18:20:17 2020 : Debug: (2) else { Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: calling noop (rlm_always) Sun Jul 26 18:20:17 2020 : Debug: (2) modsingle[post-auth]: returned from noop (rlm_always) Sun Jul 26 18:20:17 2020 : Debug: (2) [noop] = noop Sun Jul 26 18:20:17 2020 : Debug: (2) } # else = noop Sun Jul 26 18:20:17 2020 : Debug: (2) } # policy remove_reply_message_if_eap = noop Sun Jul 26 18:20:17 2020 : Debug: (2) } # Post-Auth-Type REJECT = updated Sun Jul 26 18:20:17 2020 : Debug: (2) Delaying response for 1.000000 seconds Sun Jul 26 18:20:17 2020 : Debug: Waking up in 0.3 seconds. Sun Jul 26 18:20:17 2020 : Debug: Waking up in 0.6 seconds. Sun Jul 26 18:20:18 2020 : Debug: (2) Sending delayed response Sun Jul 26 18:20:18 2020 : Debug: (2) Sent Access-Reject Id 201 from 10.100.x.60:1812 to 10.100.x.3:17138 length 20 Sun Jul 26 18:20:18 2020 : Debug: Waking up in 3.9 seconds. Sun Jul 26 18:20:22 2020 : Debug: (2) Cleaning up request packet ID 201 with timestamp +98 Sun Jul 26 18:20:22 2020 : Info: Ready to process requests