Mon Jul 5 17:56:17 2021 : Info: Ready to process requests Mon Jul 5 17:58:42 2021 : Debug: (5) Received Access-Request Id 46 from 103.136 .204.45:49215 to 172.26.11.27:1812 length 216 Mon Jul 5 17:58:42 2021 : Debug: (5) NAS-Port-Type = Wireless-802.11 Mon Jul 5 17:58:42 2021 : Debug: (5) Calling-Station-Id = "00:0C:29:D6:B8:A6" Mon Jul 5 17:58:42 2021 : Debug: (5) Called-Station-Id = "hotspot1" Mon Jul 5 17:58:42 2021 : Debug: (5) NAS-Port-Id = "ether3-LAN" Mon Jul 5 17:58:42 2021 : Debug: (5) User-Name = "06767" Mon Jul 5 17:58:42 2021 : Debug: (5) NAS-Port = 2149580827 Mon Jul 5 17:58:42 2021 : Debug: (5) Acct-Session-Id = "8020001b" Mon Jul 5 17:58:42 2021 : Debug: (5) Framed-IP-Address = 192.168.251.117 Mon Jul 5 17:58:42 2021 : Debug: (5) Mikrotik-Host-IP = 192.168.251.117 Mon Jul 5 17:58:42 2021 : Debug: (5) CHAP-Challenge = 0x0aef2a23b7227cc495ba3 4eef3a51d23 Mon Jul 5 17:58:42 2021 : Debug: (5) CHAP-Password = 0x8d3594bf6b78b066c3cef4 270b0505695a Mon Jul 5 17:58:42 2021 : Debug: (5) Service-Type = Login-User Mon Jul 5 17:58:42 2021 : Debug: (5) WISPr-Logoff-URL = "http://192.168.251.2 54/logout" Mon Jul 5 17:58:42 2021 : Debug: (5) NAS-Identifier = "Nayeem-R1-CoreRouter" Mon Jul 5 17:58:42 2021 : Debug: (5) NAS-IP-Address = 192.168.31.77 Mon Jul 5 17:58:42 2021 : Debug: (5) session-state: No State attribute Mon Jul 5 17:58:42 2021 : Debug: (5) # Executing section authorize from file /e tc/freeradius/3.0/sites-enabled/default Mon Jul 5 17:58:42 2021 : Debug: (5) authorize { Mon Jul 5 17:58:42 2021 : Debug: (5) policy filter_username { Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name) { Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name) -> TRUE Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name) { Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ / /) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ / /) -> FALSE Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /\.\./ ) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /\.\./ ) -> FAL SE Mon Jul 5 17:58:42 2021 : Debug: (5) if ((&User-Name =~ /@/) && (&User- Name !~ /@(.+)\.(.+)$/)) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if ((&User-Name =~ /@/) && (&User- Name !~ /@(.+)\.(.+)$/)) -> FALSE Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /\.$/) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /\.$/) -> FALS E Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /@\./) { Mon Jul 5 17:58:42 2021 : Debug: No matches Mon Jul 5 17:58:42 2021 : Debug: (5) if (&User-Name =~ /@\./) -> FALS E Mon Jul 5 17:58:42 2021 : Debug: (5) } # if (&User-Name) = notfound Mon Jul 5 17:58:42 2021 : Debug: (5) } # policy filter_username = notfound Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling preproce ss (rlm_preprocess) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from pr eprocess (rlm_preprocess) Mon Jul 5 17:58:42 2021 : Debug: (5) [preprocess] = ok Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling chap (rl m_chap) Mon Jul 5 17:58:42 2021 : Debug: (5) chap: &control:Auth-Type := CHAP Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from ch ap (rlm_chap) Mon Jul 5 17:58:42 2021 : Debug: (5) [chap] = ok Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling mschap ( rlm_mschap) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from ms chap (rlm_mschap) Mon Jul 5 17:58:42 2021 : Debug: (5) [mschap] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling digest ( rlm_digest) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from di gest (rlm_digest) Mon Jul 5 17:58:42 2021 : Debug: (5) [digest] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling suffix ( rlm_realm) Mon Jul 5 17:58:42 2021 : Debug: (5) suffix: Checking for suffix after "@" Mon Jul 5 17:58:42 2021 : Debug: (5) suffix: No '@' in User-Name = "06767", loo king up realm NULL Mon Jul 5 17:58:42 2021 : Debug: (5) suffix: No such realm "NULL" Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from su ffix (rlm_realm) Mon Jul 5 17:58:42 2021 : Debug: (5) [suffix] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling eap (rlm _eap) Mon Jul 5 17:58:42 2021 : Debug: (5) eap: No EAP-Message, not doing EAP Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from ea p (rlm_eap) Mon Jul 5 17:58:42 2021 : Debug: (5) [eap] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling files (r lm_files) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from fi les (rlm_files) Mon Jul 5 17:58:42 2021 : Debug: (5) [files] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling sql (rlm _sql) Mon Jul 5 17:58:42 2021 : Debug: %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Name Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> 06767 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: SQL-User-Name set to '06767' Mon Jul 5 17:58:42 2021 : Info: rlm_sql (sql): Closing connection (11): Hit idl e_timeout, was idle for 145 seconds Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): You probably need to lower "min " Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Socket destructor called, closi ng socket Mon Jul 5 17:58:42 2021 : Info: rlm_sql (sql): Closing connection (12): Hit idl e_timeout, was idle for 145 seconds Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): You probably need to lower "min " Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Socket destructor called, closi ng socket Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare" Mon Jul 5 17:58:42 2021 : Info: rlm_sql (sql): Opening additional connection (1 3), 1 of 32 pending slots used Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Starting connect to MySQL serve r Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.34-0ubuntu0.18.04.1, protocol v ersion 10 Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Reserved connection (13) Mon Jul 5 17:58:42 2021 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT id, username, attribute, va lue, op FROM radcheck WHERE username = ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-User-Name Mon Jul 5 17:58:42 2021 : Debug: literal --> ' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND SELECT id, username, attribute , value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> SELECT id, username, attribute , value, op FROM radcheck WHERE username = '06767' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing select query: SELECT id, us ername, attribute, value, op FROM radcheck WHERE username = '06767' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: User found in radcheck table Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Conditional check items matched, merg ing assignment check items Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Cleartext-Password := "12411" Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: FROM 1 TO 1 MAX 2 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Cleartext-Password Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Cleartext-Password FROM 0 TO 1 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: TO in 1 out 1 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: to[0] = Auth-Type Mon Jul 5 17:58:42 2021 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT id, username, attribute, va lue, op FROM radreply WHERE username = ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-User-Name Mon Jul 5 17:58:42 2021 : Debug: literal --> ' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND SELECT id, username, attribute , value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> SELECT id, username, attribute , value, op FROM radreply WHERE username = '06767' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing select query: SELECT id, us ername, attribute, value, op FROM radreply WHERE username = '06767' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ... falling-through to group processi ng Mon Jul 5 17:58:42 2021 : Debug: SELECT groupname FROM radusergroup WHERE usern ame = '%{SQL-User-Name}' ORDER BY priority Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-User-Name Mon Jul 5 17:58:42 2021 : Debug: literal --> ' ORDER BY priority Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND SELECT groupname FROM raduserg roup WHERE username = '%{SQL-User-Name}' ORDER BY priority Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> SELECT groupname FROM raduserg roup WHERE username = '06767' ORDER BY priority Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing select query: SELECT groupn ame FROM radusergroup WHERE username = '06767' ORDER BY priority Mon Jul 5 17:58:42 2021 : Debug: (5) sql: User found in the group table Mon Jul 5 17:58:42 2021 : Debug: SELECT id, groupname, attribute, Value, op FRO M radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT id, groupname, attribute, V alue, op FROM radgroupcheck WHERE groupname = ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-Group Mon Jul 5 17:58:42 2021 : Debug: literal --> ' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND SELECT id, groupname, attribut e, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> SELECT id, groupname, attribut e, Value, op FROM radgroupcheck WHERE groupname = 'HSP6G-20day' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing select query: SELECT id, gr oupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'HSP6G-20day' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Group "HSP6G-20day": Conditional chec k items matched Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Group "HSP6G-20day": Merging assignme nt check items Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Max-All-MB := 2147483648 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Max-All-Session := 1728000 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: FROM 2 TO 2 MAX 4 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Max-All-MB Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Max-All-MB FROM 0 TO 2 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Max-All-Session Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Max-All-Session FROM 1 TO 2 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: TO in 2 out 2 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: to[0] = Auth-Type Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: to[1] = Cleartext-Password Mon Jul 5 17:58:42 2021 : Debug: SELECT id, groupname, attribute, value, op FRO M radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT id, groupname, attribute, v alue, op FROM radgroupreply WHERE groupname = ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-Group Mon Jul 5 17:58:42 2021 : Debug: literal --> ' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND SELECT id, groupname, attribut e, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> SELECT id, groupname, attribut e, value, op FROM radgroupreply WHERE groupname = 'HSP6G-20day' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing select query: SELECT id, gr oupname, attribute, value, op FROM radgroupreply WHERE groupname = 'HSP6G-20day' ORDER BY id Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Group "HSP6G-20day": Merging reply it ems Mon Jul 5 17:58:42 2021 : Debug: (5) sql: WISPr-Bandwidth-Max-Down := 5242880 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: WISPr-Bandwidth-Max-Up := 52428800 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Simultaneous-Use := 1 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Max-All-Session := 1728000 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Max-All-MB := 2147483648 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: FROM 5 TO 0 MAX 5 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining WISPr-Bandwidth-Max-Dow n Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING WISPr-Bandwidth-Max-Dow n FROM 0 TO 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining WISPr-Bandwidth-Max-Up Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING WISPr-Bandwidth-Max-Up FROM 1 TO 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Simultaneous-Use Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Simultaneous-Use FROM 2 TO 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Max-All-Session Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Max-All-Session FROM 3 TO 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: Examining Max-All-MB Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: APPENDING Max-All-MB FROM 4 TO 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ::: TO in 0 out 0 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: ... falling-through to profile proces sing Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Released connection (13) Mon Jul 5 17:58:42 2021 : Info: Need 2 more connections to reach min connection s (3) Mon Jul 5 17:58:42 2021 : Info: rlm_sql (sql): Opening additional connection (1 4), 1 of 31 pending slots used Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Starting connect to MySQL serve r Mon Jul 5 17:58:42 2021 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.7.34-0ubuntu0.18.04.1, protocol v ersion 10 Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from sq l (rlm_sql) Mon Jul 5 17:58:42 2021 : Debug: (5) [sql] = ok Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: calling maximum_ mbs (rlm_sqlcounter) Mon Jul 5 17:58:42 2021 : Debug: sqlcounter_expand: 'SELECT IFNULL((SUM(AcctInp utOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName='%{User-Name}'' Mon Jul 5 17:58:42 2021 : Debug: %{sql:SELECT IFNULL((SUM(AcctInputOctets)+SUM( AcctOutputOctets)),0) FROM radacct WHERE UserName='%{User-Name}'} Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: xlat --> sql Mon Jul 5 17:58:42 2021 : Debug: { Mon Jul 5 17:58:42 2021 : Debug: literal --> SELECT IFNULL((SUM(AcctInput Octets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName=' Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Name Mon Jul 5 17:58:42 2021 : Debug: literal --> ' Mon Jul 5 17:58:42 2021 : Debug: } Mon Jul 5 17:58:42 2021 : Debug: %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Name Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: EXPAND %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: --> 06767 Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: SQL-User-Name set to '06767' Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Reserved connection (13) Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: Executing select query: SELEC T IFNULL((SUM(AcctInputOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE User Name='06767' Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Released connection (13) Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: EXPAND %{sql:SELECT IFNULL((S UM(AcctInputOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName='%{Use r-Name}'} Mon Jul 5 17:58:42 2021 : Debug: (5) maximum_mbs: --> 2147485182 Mon Jul 5 17:58:42 2021 : ERROR: (5) maximum_mbs: Maximum never usage time reac hed Mon Jul 5 17:58:42 2021 : ERROR: (5) maximum_mbs: Rejecting user, &control:Max- All-MB value (2147483648) is less than counter value (2147485182) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[authorize]: returned from ma ximum_mbs (rlm_sqlcounter) Mon Jul 5 17:58:42 2021 : Debug: (5) [maximum_mbs] = reject Mon Jul 5 17:58:42 2021 : Debug: (5) } # authorize = reject Mon Jul 5 17:58:42 2021 : Debug: (5) Using Post-Auth-Type Reject Mon Jul 5 17:58:42 2021 : Debug: (5) # Executing group from file /etc/freeradiu s/3.0/sites-enabled/default Mon Jul 5 17:58:42 2021 : Debug: (5) Post-Auth-Type REJECT { Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: calling sql (rlm _sql) Mon Jul 5 17:58:42 2021 : Debug: .query Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> .query Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND .query Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> .query Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Using query template 'query' Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Reserved connection (14) Mon Jul 5 17:58:42 2021 : Debug: %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Name Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> 06767 Mon Jul 5 17:58:42 2021 : Debug: (5) sql: SQL-User-Name set to '06767' Mon Jul 5 17:58:42 2021 : Debug: INSERT INTO radpostauth (username, pass, reply , authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}' , '%{reply:Packet-Type}', '%S') Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> SQL-User-Name Mon Jul 5 17:58:42 2021 : Debug: literal --> ', ' Mon Jul 5 17:58:42 2021 : Debug: XLAT-IF { Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Password Mon Jul 5 17:58:42 2021 : Debug: } Mon Jul 5 17:58:42 2021 : Debug: XLAT-ELSE { Mon Jul 5 17:58:42 2021 : Debug: attribute --> CHAP-Password Mon Jul 5 17:58:42 2021 : Debug: } Mon Jul 5 17:58:42 2021 : Debug: literal --> ', ' Mon Jul 5 17:58:42 2021 : Debug: attribute --> Packet-Type Mon Jul 5 17:58:42 2021 : Debug: literal --> ', ' Mon Jul 5 17:58:42 2021 : Debug: percent --> S Mon Jul 5 17:58:42 2021 : Debug: literal --> ') Mon Jul 5 17:58:42 2021 : Debug: (5) sql: EXPAND INSERT INTO radpostauth (usern ame, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{ Chap-Password}}', '%{reply:Packet-Type}', '%S') Mon Jul 5 17:58:42 2021 : Debug: (5) sql: --> INSERT INTO radpostauth (usern ame, pass, reply, authdate) VALUES ( '06767', '0x8d3594bf6b78b066c3cef4270b05056 95a', 'Access-Reject', '2021-07-05 17:58:42') Mon Jul 5 17:58:42 2021 : Debug: (5) sql: Executing query: INSERT INTO radposta uth (username, pass, reply, authdate) VALUES ( '06767', '0x8d3594bf6b78b066c3cef 4270b0505695a', 'Access-Reject', '2021-07-05 17:58:42') Mon Jul 5 17:58:42 2021 : Debug: (5) sql: SQL query returned: success Mon Jul 5 17:58:42 2021 : Debug: (5) sql: 1 record(s) updated Mon Jul 5 17:58:42 2021 : Debug: rlm_sql (sql): Released connection (14) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: returned from sq l (rlm_sql) Mon Jul 5 17:58:42 2021 : Debug: (5) [sql] = ok Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: calling attr_fil ter.access_reject (rlm_attr_filter) Mon Jul 5 17:58:42 2021 : Debug: %{User-Name} Mon Jul 5 17:58:42 2021 : Debug: Parsed xlat tree: Mon Jul 5 17:58:42 2021 : Debug: attribute --> User-Name Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: EXPAND %{User-N ame} Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: --> 06767 Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Matched entry D EFAULT at line 11 Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "WISP r-Bandwidth-Max-Down" allowed by 0 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "WISP r-Bandwidth-Max-Up" allowed by 0 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "Simu ltaneous-Use" allowed by 0 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "Max- All-Session" allowed by 0 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "Max- All-MB" allowed by 0 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Reply-Message = "Your maximum never usage time has been reached" allowed by Reply-Message =* "" Mon Jul 5 17:58:42 2021 : Debug: (5) attr_filter.access_reject: Attribute "Repl y-Message" allowed by 1 rules, disallowed by 0 rules Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: returned from at tr_filter.access_reject (rlm_attr_filter) Mon Jul 5 17:58:42 2021 : Debug: (5) [attr_filter.access_reject] = updated Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: calling eap (rlm _eap) Mon Jul 5 17:58:42 2021 : Debug: (5) eap: Request didn't contain an EAP-Message , not inserting EAP-Failure Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: returned from ea p (rlm_eap) Mon Jul 5 17:58:42 2021 : Debug: (5) [eap] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) policy remove_reply_message_if_eap { Mon Jul 5 17:58:42 2021 : Debug: (5) if (&reply:EAP-Message && &reply:Rep ly-Message) { Mon Jul 5 17:58:42 2021 : Debug: (5) if (&reply:EAP-Message && &reply:Rep ly-Message) -> FALSE Mon Jul 5 17:58:42 2021 : Debug: (5) else { Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: calling noop (rlm_always) Mon Jul 5 17:58:42 2021 : Debug: (5) modsingle[post-auth]: returned fro m noop (rlm_always) Mon Jul 5 17:58:42 2021 : Debug: (5) [noop] = noop Mon Jul 5 17:58:42 2021 : Debug: (5) } # else = noop Mon Jul 5 17:58:42 2021 : Debug: (5) } # policy remove_reply_message_if_eap = noop Mon Jul 5 17:58:42 2021 : Debug: (5) } # Post-Auth-Type REJECT = updated Mon Jul 5 17:58:42 2021 : Debug: (5) Delaying response for 1.000000 seconds Mon Jul 5 17:58:42 2021 : Debug: Waking up in 0.3 seconds. Mon Jul 5 17:58:43 2021 : Debug: (5) (5) Discarding duplicate request from clie nt port 49215 - ID: 46 due to delayed response Mon Jul 5 17:58:43 2021 : Debug: Waking up in 0.6 seconds. Mon Jul 5 17:58:43 2021 : Debug: (5) (5) Discarding duplicate request from clie nt port 49215 - ID: 46 due to delayed response Mon Jul 5 17:58:43 2021 : Debug: Waking up in 0.4 seconds. Mon Jul 5 17:58:43 2021 : Debug: (5) Sending delayed response Mon Jul 5 17:58:43 2021 : Debug: (5) Sent Access-Reject Id 46 from 172.26.11.27 :1812 to 103.136.204.45:49215 length 68 Mon Jul 5 17:58:43 2021 : Debug: (5) Reply-Message = "Your maximum never usag e time has been reached" Mon Jul 5 17:58:43 2021 : Debug: Waking up in 3.9 seconds. Mon Jul 5 17:58:47 2021 : Debug: (5) Cleaning up request packet ID 46 with timestamp +897 Mon Jul 5 17:58:47 2021 : Info: Ready to process requests