Freeradius Not working with Bits limit for Hotspots

Jahans Solutions jahans.solutions at gmail.com
Mon Jul 5 17:49:37 CEST 2021


Hi
I have acquired a freeradius server which i currently manage. I am facing
some issues with it. All hotspot users are getting disconnected after using
2gb. As per debug what i have seen is that freeradius is receiving an
attribute Mikrotik-Total-Limit with 2147483648  I cannot find where this
attribute is coming from.. Also there is no Mikrotik-Total-Limit  on
radgroupreply. It is driving me crazy. Can someone help me with this? I
have attached three debug reports. Thanks in advance. Regards
-------------- next part --------------
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
-------------- next part --------------
Mon Jul  5 17:54:43 2021 : Info: Ready to process requests
Mon Jul  5 17:56:17 2021 : Debug: (4) Received Accounting-Request Id 45 from 103.136.                                                                                                        204.45:43532 to 172.26.11.27:1813 length 202
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Status-Type = Stop
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Terminate-Cause = NAS-Request
Mon Jul  5 17:56:17 2021 : Debug: (4)   NAS-Port-Type = Wireless-802.11
Mon Jul  5 17:56:17 2021 : Debug: (4)   Calling-Station-Id = "00:0C:29:D6:B8:A6"
Mon Jul  5 17:56:17 2021 : Debug: (4)   Called-Station-Id = "hotspot1"
Mon Jul  5 17:56:17 2021 : Debug: (4)   NAS-Port-Id = "ether3-LAN"
Mon Jul  5 17:56:17 2021 : Debug: (4)   User-Name = "06767"
Mon Jul  5 17:56:17 2021 : Debug: (4)   NAS-Port = 2149580826
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Session-Id = "8020001a"
Mon Jul  5 17:56:17 2021 : Debug: (4)   Framed-IP-Address = 192.168.251.117
Mon Jul  5 17:56:17 2021 : Debug: (4)   Mikrotik-Host-IP = 192.168.251.117
Mon Jul  5 17:56:17 2021 : Debug: (4)   Event-Timestamp = "Jul  5 2021 17:56:17 +04"
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Input-Octets = 21740756
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Output-Octets = 2125744426
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Input-Gigawords = 0
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Output-Gigawords = 0
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Input-Packets = 498913
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Output-Packets = 487557
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Session-Time = 694
Mon Jul  5 17:56:17 2021 : Debug: (4)   NAS-Identifier = "Nayeem-R1-CoreRouter"
Mon Jul  5 17:56:17 2021 : Debug: (4)   Acct-Delay-Time = 0
Mon Jul  5 17:56:17 2021 : Debug: (4)   NAS-IP-Address = 192.168.31.77
Mon Jul  5 17:56:17 2021 : Debug: (4) # Executing section preacct from file /etc/free                                                                                                        radius/3.0/sites-enabled/default
Mon Jul  5 17:56:17 2021 : Debug: (4)   preacct {
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: calling preprocess (rlm                                                                                                        _preprocess)
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: returned from preproces                                                                                                        s (rlm_preprocess)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [preprocess] = ok
Mon Jul  5 17:56:17 2021 : Debug: (4)     policy acct_unique {
Mon Jul  5 17:56:17 2021 : Debug: (4)       update request {
Mon Jul  5 17:56:17 2021 : Debug: (4)         &Tmp-String-9 := "ai:"
Mon Jul  5 17:56:17 2021 : Debug: (4)       } # update request = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-Stri                                                                                                        ng-9}/) &&          ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{hex:&Class}
Mon Jul  5 17:56:17 2021 : Debug: (4)          -->
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND ^%{hex:&Tmp-String-9}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> ^61693a
Mon Jul  5 17:56:17 2021 : Debug: No matches
Mon Jul  5 17:56:17 2021 : Debug: (4)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-Stri                                                                                                        ng-9}/) &&          ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
Mon Jul  5 17:56:17 2021 : Debug: (4)       else {
Mon Jul  5 17:56:17 2021 : Debug: (4)         update request {
Mon Jul  5 17:56:17 2021 : Debug: (4)           EXPAND %{md5:%{User-Name},%{Acct-Sess                                                                                                        ion-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{                                                                                                        NAS-Port}}
Mon Jul  5 17:56:17 2021 : Debug: (4)              --> 3f74fa78ccd63a57e895ef24572721                                                                                                        40
Mon Jul  5 17:56:17 2021 : Debug: (4)           &Acct-Unique-Session-Id := 3f74fa78cc                                                                                                        d63a57e895ef2457272140
Mon Jul  5 17:56:17 2021 : Debug: (4)         } # update request = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)       } # else = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)     } # policy acct_unique = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: calling suffix (rlm_rea                                                                                                        lm)
Mon Jul  5 17:56:17 2021 : Debug: (4) suffix: Checking for suffix after "@"
Mon Jul  5 17:56:17 2021 : Debug: (4) suffix: No '@' in User-Name = "06767", looking                                                                                                         up realm NULL
Mon Jul  5 17:56:17 2021 : Debug: (4) suffix: No such realm "NULL"
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: returned from suffix (r                                                                                                        lm_realm)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [suffix] = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: calling files (rlm_file                                                                                                        s)
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[preacct]: returned from files (rl                                                                                                        m_files)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [files] = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)   } # preacct = ok
Mon Jul  5 17:56:17 2021 : Debug: (4) # Executing section accounting from file /etc/f                                                                                                        reeradius/3.0/sites-enabled/default
Mon Jul  5 17:56:17 2021 : Debug: (4)   accounting {
Mon Jul  5 17:56:17 2021 : Debug: (4)     update control {
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4)       SQL-User-Name set to '06767'
Mon Jul  5 17:56:17 2021 : Info: rlm_sql (sql): Closing connection (9): Hit idle_time                                                                                                        out, was idle for 94 seconds
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): You probably need to lower "min"
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Socket destructor called, closing so                                                                                                        cket
Mon Jul  5 17:56:17 2021 : Info: rlm_sql (sql): Closing connection (10): Hit idle_tim                                                                                                        eout, was idle for 94 seconds
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): You probably need to lower "min"
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Socket destructor called, closing so                                                                                                        cket
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): 0 of 0 connections in use.  You  may                                                                                                         need to increase "spare"
Mon Jul  5 17:56:17 2021 : Info: rlm_sql (sql): Opening additional connection (11), 1                                                                                                         of 32 pending slots used
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Connected to database 'radius' on Lo                                                                                                        calhost via UNIX socket, server version 5.7.34-0ubuntu0.18.04.1, protocol version 10
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Reserved connection (11)
Mon Jul  5 17:56:17 2021 : Debug: (4)       Executing select query: SELECT (SUM(accti                                                                                                        nputOctets)+SUM(acctoutputoctets)) AS Total FROM radacct WHERE radacct.username='0676                                                                                                        7'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Released connection (11)
Mon Jul  5 17:56:17 2021 : Info: Need 2 more connections to reach min connections (3)
Mon Jul  5 17:56:17 2021 : Info: rlm_sql (sql): Opening additional connection (12), 1                                                                                                         of 31 pending slots used
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Connected to database 'radius' on Lo                                                                                                        calhost via UNIX socket, server version 5.7.34-0ubuntu0.18.04.1, protocol version 10
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{sql:SELECT (SUM(acctinputOctets)                                                                                                        +SUM(acctoutputoctets)) AS Total FROM radacct WHERE radacct.username='%{User-Name}'}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 1802278260
Mon Jul  5 17:56:17 2021 : Debug: (4)       Tmp-Integer-0 := 1802278260
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4)       SQL-User-Name set to '06767'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Reserved connection (11)
Mon Jul  5 17:56:17 2021 : Debug: (4)       Executing select query:  SELECT value FRO                                                                                                        M radcheck WHERE attribute='Max-All-MB’ AND username='06767'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: No additional diagnostic info on ser                                                                                                        ver
Mon Jul  5 17:56:17 2021 : ERROR: (4)       rlm_sql_mysql: ERROR 1064 (You have an er                                                                                                        ror in your SQL syntax; check the manual that corresponds to your MySQL server versio                                                                                                        n for the right syntax to use near '06767'' at line 1): 42000
Mon Jul  5 17:56:17 2021 : ERROR: (4)       SQL query failed: server error
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Released connection (11)
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{sql: SELECT value FROM radcheck                                                                                                         WHERE attribute='Max-All-MB’ AND username='%{User-Name}'}
Mon Jul  5 17:56:17 2021 : Debug: (4)          -->
Mon Jul  5 17:56:17 2021 : Debug: (4)       Tmp-String-1 :=
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4)       SQL-User-Name set to '06767'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Reserved connection (12)
Mon Jul  5 17:56:17 2021 : Debug: (4)       Executing select query:  SELECT value FRO                                                                                                        M radgroupcheck WHERE attribute='Max-All-MB'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Released connection (12)
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{sql: SELECT value FROM radgroupc                                                                                                        heck WHERE attribute='Max-All-MB'}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 10737418240
Mon Jul  5 17:56:17 2021 : Debug: (4)       Tmp-String-1 := 10737418240
Mon Jul  5 17:56:17 2021 : Debug: (4)       Overwriting value "" with "10737418240"
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4)       SQL-User-Name set to '06767'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Reserved connection (11)
Mon Jul  5 17:56:17 2021 : Debug: (4)       Executing select query: select calledstat                                                                                                        ionid from radacct where acctsessionid='8020001a'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Released connection (11)
Mon Jul  5 17:56:17 2021 : Debug: (4)       EXPAND %{sql:select calledstationid from                                                                                                         radacct where acctsessionid='%{Acct-Session-Id}'}
Mon Jul  5 17:56:17 2021 : Debug: (4)          --> hotspot1
Mon Jul  5 17:56:17 2021 : Debug: (4)       Tmp-String-3 := hotspot1
Mon Jul  5 17:56:17 2021 : Debug: (4)     } # update control = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)     if ("%{control:Tmp-Integer-0}" > "%{control                                                                                                        :Tmp-String-1}"){
Mon Jul  5 17:56:17 2021 : Debug: (4)     EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:56:17 2021 : Debug: (4)     EXPAND %{control:Tmp-Integer-0}
Mon Jul  5 17:56:17 2021 : Debug: (4)        --> 1802278260
Mon Jul  5 17:56:17 2021 : Debug: (4)     EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:56:17 2021 : Debug: (4)     EXPAND %{control:Tmp-String-1}
Mon Jul  5 17:56:17 2021 : Debug: (4)        --> 10737418240
Mon Jul  5 17:56:17 2021 : Debug: (4)     if ("%{control:Tmp-Integer-0}" > "%{control                                                                                                        :Tmp-String-1}") -> FALSE
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: calling detail (rlm_                                                                                                        detail)
Mon Jul  5 17:56:17 2021 : Debug: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Addre                                                                                                        ss}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: literal --> /var/log/freeradius/radacct/
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Packet-Src-IP-Address
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Packet-Src-IPv6-Address
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> /detail-
Mon Jul  5 17:56:17 2021 : Debug: percent --> Y
Mon Jul  5 17:56:17 2021 : Debug: percent --> m
Mon Jul  5 17:56:17 2021 : Debug: percent --> d
Mon Jul  5 17:56:17 2021 : Debug: (4) detail: EXPAND /var/log/freeradius/radacct/%{%{                                                                                                        Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Mon Jul  5 17:56:17 2021 : Debug: (4) detail:    --> /var/log/freeradius/radacct/103.                                                                                                        136.204.45/detail-20210705
Mon Jul  5 17:56:17 2021 : Debug: (4) detail: /var/log/freeradius/radacct/%{%{Packet-                                                                                                        Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freera                                                                                                        dius/radacct/103.136.204.45/detail-20210705
Mon Jul  5 17:56:17 2021 : Debug: %t
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: percent --> t
Mon Jul  5 17:56:17 2021 : Debug: (4) detail: EXPAND %t
Mon Jul  5 17:56:17 2021 : Debug: (4) detail:    --> Mon Jul  5 17:56:17 2021
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: returned from detail                                                                                                         (rlm_detail)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [detail] = ok
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: calling unix (rlm_un                                                                                                        ix)
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: returned from unix (                                                                                                        rlm_unix)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [unix] = ok
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: calling sql (rlm_sql                                                                                                        )
Mon Jul  5 17:56:17 2021 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: xlat --> tolower
Mon Jul  5 17:56:17 2021 : Debug: {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> type.
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Status-Type
Mon Jul  5 17:56:17 2021 : Debug:       literal --> .query
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.                                                                                                        query}
Mon Jul  5 17:56:17 2021 : Debug: (4) sql:    --> type.stop.query
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: Using query template 'query'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Reserved connection (12)
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: EXPAND %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: (4) sql:    --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: SQL-User-Name set to '06767'
Mon Jul  5 17:56:17 2021 : Debug: UPDATE radacct SET acctstoptime       = FROM_UNIXTI                                                                                                        ME(%{integer:Event-Timestamp}), acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acct                                                                                                        inputoctets     = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}                                                                                                        ', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octet                                                                                                        s}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connec                                                                                                        t-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: literal --> UPDATE radacct SET acctstoptime   = FRO                                                                                                        M_UNIXTIME(
Mon Jul  5 17:56:17 2021 : Debug: xlat --> integer
Mon Jul  5 17:56:17 2021 : Debug: {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> Event-Timestamp
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> ), acctsessiontime        =
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Session-Time
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> NULL
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> , acctinputoctets = '
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Input-Gigawords
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> 0
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> ' << 32 | '
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Input-Octets
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> 0
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> ', acctoutputoctets = '
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Output-Gigawords
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> 0
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> ' << 32 | '
Mon Jul  5 17:56:17 2021 : Debug: XLAT-IF {
Mon Jul  5 17:56:17 2021 : Debug:       attribute --> Acct-Output-Octets
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:56:17 2021 : Debug:       literal --> 0
Mon Jul  5 17:56:17 2021 : Debug: }
Mon Jul  5 17:56:17 2021 : Debug: literal --> ', acctterminatecause = '
Mon Jul  5 17:56:17 2021 : Debug: attribute --> Acct-Terminate-Cause
Mon Jul  5 17:56:17 2021 : Debug: literal --> ', connectinfo_stop = '
Mon Jul  5 17:56:17 2021 : Debug: attribute --> Connect-Info
Mon Jul  5 17:56:17 2021 : Debug: literal --> ' WHERE AcctUniqueId = '
Mon Jul  5 17:56:17 2021 : Debug: attribute --> Acct-Unique-Session-Id
Mon Jul  5 17:56:17 2021 : Debug: literal --> '
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: EXPAND UPDATE radacct SET acctstoptime   =                                                                                                         FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime     = %{%{Acct-Session-Ti                                                                                                        me}:-NULL}, acctinputoctets     = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-I                                                                                                        nput-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{A                                                                                                        cct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', connectinfo_                                                                                                        stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
Mon Jul  5 17:56:17 2021 : Debug: (4) sql:    --> UPDATE radacct SET acctstoptime   =                                                                                                         FROM_UNIXTIME(1625493377), acctsessiontime     = 694, acctinputoctets  = '0' << 32 |                                                                                                         '21740756', acctoutputoctets = '0' << 32 | '2125744426', acctterminatecause = 'NAS-R                                                                                                        equest', connectinfo_stop = '' WHERE AcctUniqueId = '3f74fa78ccd63a57e895ef2457272140                                                                                                        '
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: Executing query: UPDATE radacct SET acctst                                                                                                        optime  = FROM_UNIXTIME(1625493377), acctsessiontime    = 694, acctinputoctets  = '0'                                                                                                         << 32 | '21740756', acctoutputoctets = '0' << 32 | '2125744426', acctterminatecause                                                                                                         = 'NAS-Request', connectinfo_stop = '' WHERE AcctUniqueId = '3f74fa78ccd63a57e895ef24                                                                                                        57272140'
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql_mysql: Rows matched: 1  Changed: 1  Warning                                                                                                        s: 0
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: SQL query returned: success
Mon Jul  5 17:56:17 2021 : Debug: (4) sql: 1 record(s) updated
Mon Jul  5 17:56:17 2021 : Debug: rlm_sql (sql): Released connection (12)
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: returned from sql (r                                                                                                        lm_sql)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [sql] = ok
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: calling exec (rlm_ex                                                                                                        ec)
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: returned from exec (                                                                                                        rlm_exec)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [exec] = noop
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: calling attr_filter.                                                                                                        accounting_response (rlm_attr_filter)
Mon Jul  5 17:56:17 2021 : Debug: %{User-Name}
Mon Jul  5 17:56:17 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:56:17 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:56:17 2021 : Debug: (4) attr_filter.accounting_response: EXPAND %{User-                                                                                                        Name}
Mon Jul  5 17:56:17 2021 : Debug: (4) attr_filter.accounting_response:    --> 06767
Mon Jul  5 17:56:17 2021 : Debug: (4) attr_filter.accounting_response: Matched entry                                                                                                         DEFAULT at line 12
Mon Jul  5 17:56:17 2021 : Debug: (4)     modsingle[accounting]: returned from attr_f                                                                                                        ilter.accounting_response (rlm_attr_filter)
Mon Jul  5 17:56:17 2021 : Debug: (4)     [attr_filter.accounting_response] = updated
Mon Jul  5 17:56:17 2021 : Debug: (4)   } # accounting = updated
Mon Jul  5 17:56:17 2021 : Debug: (4) Sent Accounting-Response Id 45 from 172.26.11.2                                                                                                        7:1813 to 103.136.204.45:43532 length 0
Mon Jul  5 17:56:17 2021 : Debug: (4) Finished request
Mon Jul  5 17:56:17 2021 : Debug: (4) Cleaning up request packet ID 45 with timestamp                                                                                                         +752
Mon Jul  5 17:56:17 2021 : Info: Ready to process requests
-------------- next part --------------
Mon Jul  5 17:43:45 2021 : Info: Ready to process requests
Mon Jul  5 17:44:43 2021 : Debug: (0) Received Access-Request Id 41 from 103.136                                                                                                             .204.45:47019 to 172.26.11.27:1812 length 216
Mon Jul  5 17:44:43 2021 : Debug: (0)   NAS-Port-Type = Wireless-802.11
Mon Jul  5 17:44:43 2021 : Debug: (0)   Calling-Station-Id = "00:0C:29:D6:B8:A6"
Mon Jul  5 17:44:43 2021 : Debug: (0)   Called-Station-Id = "hotspot1"
Mon Jul  5 17:44:43 2021 : Debug: (0)   NAS-Port-Id = "ether3-LAN"
Mon Jul  5 17:44:43 2021 : Debug: (0)   User-Name = "06767"
Mon Jul  5 17:44:43 2021 : Debug: (0)   NAS-Port = 2149580826
Mon Jul  5 17:44:43 2021 : Debug: (0)   Acct-Session-Id = "8020001a"
Mon Jul  5 17:44:43 2021 : Debug: (0)   Framed-IP-Address = 192.168.251.117
Mon Jul  5 17:44:43 2021 : Debug: (0)   Mikrotik-Host-IP = 192.168.251.117
Mon Jul  5 17:44:43 2021 : Debug: (0)   CHAP-Challenge = 0xca3c9573001464eb300f0                                                                                                             d8c3ebe7a79
Mon Jul  5 17:44:43 2021 : Debug: (0)   CHAP-Password = 0x53366b5b1a6f407af389df                                                                                                             013e65f0b10a
Mon Jul  5 17:44:43 2021 : Debug: (0)   Service-Type = Login-User
Mon Jul  5 17:44:43 2021 : Debug: (0)   WISPr-Logoff-URL = "http://192.168.251.2                                                                                                             54/logout"
Mon Jul  5 17:44:43 2021 : Debug: (0)   NAS-Identifier = "Nayeem-R1-CoreRouter"
Mon Jul  5 17:44:43 2021 : Debug: (0)   NAS-IP-Address = 192.168.31.77
Mon Jul  5 17:44:43 2021 : Debug: (0) session-state: No State attribute
Mon Jul  5 17:44:43 2021 : Debug: (0) # Executing section authorize from file /e                                                                                                             tc/freeradius/3.0/sites-enabled/default
Mon Jul  5 17:44:43 2021 : Debug: (0)   authorize {
Mon Jul  5 17:44:43 2021 : Debug: (0)     policy filter_username {
Mon Jul  5 17:44:43 2021 : Debug: (0)       if (&User-Name) {
Mon Jul  5 17:44:43 2021 : Debug: (0)       if (&User-Name)  -> TRUE
Mon Jul  5 17:44:43 2021 : Debug: (0)       if (&User-Name)  {
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ / /) {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ / /)  -> FALSE
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ ) {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /@[^@]*@/ )  ->                                                                                                              FALSE
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /\.\./ ) {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /\.\./ )  -> FAL                                                                                                             SE
Mon Jul  5 17:44:43 2021 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-                                                                                                             Name !~ /@(.+)\.(.+)$/))  {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if ((&User-Name =~ /@/) && (&User-                                                                                                             Name !~ /@(.+)\.(.+)$/))   -> FALSE
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /\.$/)  {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /\.$/)   -> FALS                                                                                                             E
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /@\./)  {
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (0)         if (&User-Name =~ /@\./)   -> FALS                                                                                                             E
Mon Jul  5 17:44:43 2021 : Debug: (0)       } # if (&User-Name)  = notfound
Mon Jul  5 17:44:43 2021 : Debug: (0)     } # policy filter_username = notfound
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling preproce                                                                                                             ss (rlm_preprocess)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from pr                                                                                                             eprocess (rlm_preprocess)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [preprocess] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling chap (rl                                                                                                             m_chap)
Mon Jul  5 17:44:43 2021 : Debug: (0) chap:   &control:Auth-Type := CHAP
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ch                                                                                                             ap (rlm_chap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [chap] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling mschap (                                                                                                             rlm_mschap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ms                                                                                                             chap (rlm_mschap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [mschap] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling digest (                                                                                                             rlm_digest)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from di                                                                                                             gest (rlm_digest)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [digest] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling suffix (                                                                                                             rlm_realm)
Mon Jul  5 17:44:43 2021 : Debug: (0) suffix: Checking for suffix after "@"
Mon Jul  5 17:44:43 2021 : Debug: (0) suffix: No '@' in User-Name = "06767", loo                                                                                                             king up realm NULL
Mon Jul  5 17:44:43 2021 : Debug: (0) suffix: No such realm "NULL"
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from su                                                                                                             ffix (rlm_realm)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [suffix] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling eap (rlm                                                                                                             _eap)
Mon Jul  5 17:44:43 2021 : Debug: (0) eap: No EAP-Message, not doing EAP
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ea                                                                                                             p (rlm_eap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [eap] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling files (r                                                                                                             lm_files)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from fi                                                                                                             les (rlm_files)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [files] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling sql (rlm                                                                                                             _sql)
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (1)
Mon Jul  5 17:44:43 2021 : Debug: SELECT id, username, attribute, value, op FROM                                                                                                              radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> SELECT id, username, attribute, va                                                                                                             lue, op FROM radcheck WHERE username = '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-User-Name
Mon Jul  5 17:44:43 2021 : Debug: literal --> ' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND SELECT id, username, attribute                                                                                                             , value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> SELECT id, username, attribute                                                                                                             , value, op FROM radcheck WHERE username = '06767' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing select query: SELECT id, us                                                                                                             ername, attribute, value, op FROM radcheck WHERE username = '06767' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: User found in radcheck table
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Conditional check items matched, merg                                                                                                             ing assignment check items
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Cleartext-Password := "12411"
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: FROM 1 TO 1 MAX 2
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Cleartext-Password
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Cleartext-Password FROM                                                                                                              0 TO 1
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: TO in 1 out 1
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: to[0] = Auth-Type
Mon Jul  5 17:44:43 2021 : Debug: SELECT id, username, attribute, value, op FROM                                                                                                              radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> SELECT id, username, attribute, va                                                                                                             lue, op FROM radreply WHERE username = '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-User-Name
Mon Jul  5 17:44:43 2021 : Debug: literal --> ' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND SELECT id, username, attribute                                                                                                             , value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> SELECT id, username, attribute                                                                                                             , value, op FROM radreply WHERE username = '06767' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing select query: SELECT id, us                                                                                                             ername, attribute, value, op FROM radreply WHERE username = '06767' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ... falling-through to group processi                                                                                                             ng
Mon Jul  5 17:44:43 2021 : Debug: SELECT groupname FROM radusergroup WHERE usern                                                                                                             ame = '%{SQL-User-Name}' ORDER BY priority
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> SELECT groupname FROM radusergroup                                                                                                              WHERE username = '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-User-Name
Mon Jul  5 17:44:43 2021 : Debug: literal --> ' ORDER BY priority
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND SELECT groupname FROM raduserg                                                                                                             roup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> SELECT groupname FROM raduserg                                                                                                             roup WHERE username = '06767' ORDER BY priority
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing select query: SELECT groupn                                                                                                             ame FROM radusergroup WHERE username = '06767' ORDER BY priority
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: User found in the group table
Mon Jul  5 17:44:43 2021 : Debug: SELECT id, groupname, attribute, Value, op FRO                                                                                                             M radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> SELECT id, groupname, attribute, V                                                                                                             alue, op FROM radgroupcheck WHERE groupname = '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-Group
Mon Jul  5 17:44:43 2021 : Debug: literal --> ' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND SELECT id, groupname, attribut                                                                                                             e, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> SELECT id, groupname, attribut                                                                                                             e, Value, op FROM radgroupcheck WHERE groupname = 'HSP6G-20day' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing select query: SELECT id, gr                                                                                                             oupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'HSP6G-20day'                                                                                                              ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Group "HSP6G-20day": Conditional chec                                                                                                             k items matched
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Group "HSP6G-20day": Merging assignme                                                                                                             nt check items
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Max-All-MB := 2147483648
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Max-All-Session := 1728000
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: FROM 2 TO 2 MAX 4
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Max-All-MB
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Max-All-MB FROM 0 TO 2
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Max-All-Session
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Max-All-Session FROM 1                                                                                                              TO 2
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: TO in 2 out 2
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: to[0] = Auth-Type
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: to[1] = Cleartext-Password
Mon Jul  5 17:44:43 2021 : Debug: SELECT id, groupname, attribute, value, op FRO                                                                                                             M radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> SELECT id, groupname, attribute, v                                                                                                             alue, op FROM radgroupreply WHERE groupname = '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-Group
Mon Jul  5 17:44:43 2021 : Debug: literal --> ' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND SELECT id, groupname, attribut                                                                                                             e, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> SELECT id, groupname, attribut                                                                                                             e, value, op FROM radgroupreply WHERE groupname = 'HSP6G-20day' ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing select query: SELECT id, gr                                                                                                             oupname, attribute, value, op FROM radgroupreply WHERE groupname = 'HSP6G-20day'                                                                                                              ORDER BY id
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Group "HSP6G-20day": Merging reply it                                                                                                             ems
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   WISPr-Bandwidth-Max-Down := 5242880                                                                                                             0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   WISPr-Bandwidth-Max-Up := 52428800
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Simultaneous-Use := 1
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Max-All-Session := 1728000
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:   Max-All-MB := 2147483648
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: FROM 5 TO 0 MAX 5
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining WISPr-Bandwidth-Max-Dow                                                                                                             n
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING WISPr-Bandwidth-Max-Dow                                                                                                             n FROM 0 TO 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining WISPr-Bandwidth-Max-Up
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING WISPr-Bandwidth-Max-Up                                                                                                              FROM 1 TO 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Simultaneous-Use
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Simultaneous-Use FROM 2                                                                                                              TO 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Max-All-Session
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Max-All-Session FROM 3                                                                                                              TO 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: Examining Max-All-MB
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: APPENDING Max-All-MB FROM 4 TO 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ::: TO in 0 out 0
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: ... falling-through to profile proces                                                                                                             sing
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (1)
Mon Jul  5 17:44:43 2021 : Info: Need 4 more connections to reach 10 spares
Mon Jul  5 17:44:43 2021 : Info: rlm_sql (sql): Opening additional connection (6                                                                                                             ), 1 of 26 pending slots used
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql_mysql: Starting connect to MySQL serve                                                                                                             r
Mon Jul  5 17:44:43 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:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from sq                                                                                                             l (rlm_sql)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [sql] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling maximum_                                                                                                             mbs (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: sqlcounter_expand: 'SELECT IFNULL((SUM(AcctInp                                                                                                             utOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName='%{User-Name}''
Mon Jul  5 17:44:43 2021 : Debug: %{sql:SELECT IFNULL((SUM(AcctInputOctets)+SUM(                                                                                                             AcctOutputOctets)),0) FROM radacct WHERE UserName='%{User-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: xlat --> sql
Mon Jul  5 17:44:43 2021 : Debug: {
Mon Jul  5 17:44:43 2021 : Debug:       literal --> SELECT IFNULL((SUM(AcctInput                                                                                                             Octets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName='
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug:       literal --> '
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs:    --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (2)
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: Executing select query: SELEC                                                                                                             T IFNULL((SUM(AcctInputOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE User                                                                                                             Name='06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (2)
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: EXPAND %{sql:SELECT IFNULL((S                                                                                                             UM(AcctInputOctets)+SUM(AcctOutputOctets)),0) FROM radacct WHERE UserName='%{Use                                                                                                             r-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs:    --> 0
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: Allowing user, &control:Max-A                                                                                                             ll-MB value (2147483648) is greater than counter value (0)
Mon Jul  5 17:44:43 2021 : Debug: (0) maximum_mbs: Setting &reply:Mikrotik-Total                                                                                                             -Limit value to 2147483648
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ma                                                                                                             ximum_mbs (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [maximum_mbs] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling expire_o                                                                                                             n_login (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : WARNING: (0) expire_on_login: Couldn't find check att                                                                                                             ribute, control:Expire-After, doing nothing...
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ex                                                                                                             pire_on_login (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [expire_on_login] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling accesspe                                                                                                             riod (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : WARNING: (0) accessperiod: Couldn't find check attrib                                                                                                             ute, control:Access-Period, doing nothing...
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ac                                                                                                             cessperiod (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [accessperiod] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling noresetc                                                                                                             ounter (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: sqlcounter_expand: 'SELECT IFNULL(SUM(AcctSess                                                                                                             ionTime),0) FROM radacct WHERE UserName='%{User-Name}''
Mon Jul  5 17:44:43 2021 : Debug: %{sql:SELECT IFNULL(SUM(AcctSessionTime),0) FR                                                                                                             OM radacct WHERE UserName='%{User-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: xlat --> sql
Mon Jul  5 17:44:43 2021 : Debug: {
Mon Jul  5 17:44:43 2021 : Debug:       literal --> SELECT IFNULL(SUM(AcctSessio                                                                                                             nTime),0) FROM radacct WHERE UserName='
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug:       literal --> '
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter:    --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: SQL-User-Name set to '0676                                                                                                             7'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (3)
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: Executing select query: SE                                                                                                             LECT IFNULL(SUM(AcctSessionTime),0) FROM radacct WHERE UserName='06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (3)
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: EXPAND %{sql:SELECT IFNULL                                                                                                             (SUM(AcctSessionTime),0) FROM radacct WHERE UserName='%{User-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter:    --> 0
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: Allowing user, &control:Ma                                                                                                             x-All-Session value (1728000) is greater than counter value (0)
Mon Jul  5 17:44:43 2021 : Debug: (0) noresetcounter: Setting &reply:Session-Tim                                                                                                             eout value to 1728000
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from no                                                                                                             resetcounter (rlm_sqlcounter)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [noresetcounter] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling expirati                                                                                                             on (rlm_expiration)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from ex                                                                                                             piration (rlm_expiration)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [expiration] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling logintim                                                                                                             e (rlm_logintime)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from lo                                                                                                             gintime (rlm_logintime)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [logintime] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: calling pap (rlm                                                                                                             _pap)
Mon Jul  5 17:44:43 2021 : WARNING: (0) pap: Auth-Type already set.  Not setting                                                                                                              to PAP
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authorize]: returned from pa                                                                                                             p (rlm_pap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [pap] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)   } # authorize = ok
Mon Jul  5 17:44:43 2021 : Debug: (0) Found Auth-Type = CHAP
Mon Jul  5 17:44:43 2021 : Debug: (0) # Executing group from file /etc/freeradiu                                                                                                             s/3.0/sites-enabled/default
Mon Jul  5 17:44:43 2021 : Debug: (0)   Auth-Type CHAP {
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authenticate]: calling chap                                                                                                              (rlm_chap)
Mon Jul  5 17:44:43 2021 : Debug: (0) chap: Comparing with "known good" &control                                                                                                             :Cleartext-Password value "12411"
Mon Jul  5 17:44:43 2021 : Debug: (0) chap: Using challenge from &request:CHAP-C                                                                                                             hallenge
Mon Jul  5 17:44:43 2021 : Debug: (0) chap:   CHAP challenge : ca3c9573001464eb3                                                                                                             00f0d8c3ebe7a79
Mon Jul  5 17:44:43 2021 : Debug: (0) chap:   Client sent    : 366b5b1a6f407af38                                                                                                             9df013e65f0b10a
Mon Jul  5 17:44:43 2021 : Debug: (0) chap:   We calculated  : 366b5b1a6f407af38                                                                                                             9df013e65f0b10a
Mon Jul  5 17:44:43 2021 : Debug: (0) chap: CHAP user "06767" authenticated succ                                                                                                             essfully
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[authenticate]: returned from                                                                                                              chap (rlm_chap)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [chap] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)   } # Auth-Type CHAP = ok
Mon Jul  5 17:44:43 2021 : Debug: (0) # Executing section post-auth from file /e                                                                                                             tc/freeradius/3.0/sites-enabled/default
Mon Jul  5 17:44:43 2021 : Debug: (0)   post-auth {
Mon Jul  5 17:44:43 2021 : Debug: (0)     update {
Mon Jul  5 17:44:43 2021 : Debug: (0)       No attributes updated
Mon Jul  5 17:44:43 2021 : Debug: (0)     } # update = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[post-auth]: calling sql (rlm                                                                                                             _sql)
Mon Jul  5 17:44:43 2021 : Debug: .query
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> .query
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND .query
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> .query
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Using query template 'query'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (4)
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (0) sql:    --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 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:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> INSERT INTO radpostauth (username,                                                                                                              pass, reply, authdate) VALUES ( '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-User-Name
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: XLAT-IF {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> User-Password
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> CHAP-Password
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Packet-Type
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: percent --> S
Mon Jul  5 17:44:43 2021 : Debug: literal --> ')
Mon Jul  5 17:44:43 2021 : Debug: (0) 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:44:43 2021 : Debug: (0) sql:    --> INSERT INTO radpostauth (usern                                                                                                             ame, pass, reply, authdate) VALUES ( '06767', '0x53366b5b1a6f407af389df013e65f0b                                                                                                             10a', 'Access-Accept', '2021-07-05 17:44:43')
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: Executing query: INSERT INTO radposta                                                                                                             uth (username, pass, reply, authdate) VALUES ( '06767', '0x53366b5b1a6f407af389d                                                                                                             f013e65f0b10a', 'Access-Accept', '2021-07-05 17:44:43')
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: SQL query returned: success
Mon Jul  5 17:44:43 2021 : Debug: (0) sql: 1 record(s) updated
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (4)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[post-auth]: returned from sq                                                                                                             l (rlm_sql)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [sql] = ok
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[post-auth]: calling exec (rl                                                                                                             m_exec)
Mon Jul  5 17:44:43 2021 : Debug: (0)     modsingle[post-auth]: returned from ex                                                                                                             ec (rlm_exec)
Mon Jul  5 17:44:43 2021 : Debug: (0)     [exec] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     policy remove_reply_message_if_eap {
Mon Jul  5 17:44:43 2021 : Debug: (0)       if (&reply:EAP-Message && &reply:Rep                                                                                                             ly-Message) {
Mon Jul  5 17:44:43 2021 : Debug: (0)       if (&reply:EAP-Message && &reply:Rep                                                                                                             ly-Message)  -> FALSE
Mon Jul  5 17:44:43 2021 : Debug: (0)       else {
Mon Jul  5 17:44:43 2021 : Debug: (0)         modsingle[post-auth]: calling noop                                                                                                              (rlm_always)
Mon Jul  5 17:44:43 2021 : Debug: (0)         modsingle[post-auth]: returned fro                                                                                                             m noop (rlm_always)
Mon Jul  5 17:44:43 2021 : Debug: (0)         [noop] = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)       } # else = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)     } # policy remove_reply_message_if_eap                                                                                                              = noop
Mon Jul  5 17:44:43 2021 : Debug: (0)   } # post-auth = ok
Mon Jul  5 17:44:43 2021 : Debug: (0) Sent Access-Accept Id 41 from 172.26.11.27                                                                                                             :1812 to 103.136.204.45:47019 length 0
Mon Jul  5 17:44:43 2021 : Debug: (0)   WISPr-Bandwidth-Max-Down = 52428800
Mon Jul  5 17:44:43 2021 : Debug: (0)   WISPr-Bandwidth-Max-Up = 52428800
Mon Jul  5 17:44:43 2021 : Debug: (0)   Mikrotik-Total-Limit = 2147483648
Mon Jul  5 17:44:43 2021 : Debug: (0)   Session-Timeout = 1728000
Mon Jul  5 17:44:43 2021 : Debug: (0) Finished request
Mon Jul  5 17:44:43 2021 : Debug: Waking up in 4.9 seconds.
Mon Jul  5 17:44:43 2021 : Debug: (1) Received Accounting-Request Id 42 from 103                                                                                                             .136.204.45:60317 to 172.26.11.27:1813 length 154
Mon Jul  5 17:44:43 2021 : Debug: (1)   Acct-Status-Type = Start
Mon Jul  5 17:44:43 2021 : Debug: (1)   NAS-Port-Type = Wireless-802.11
Mon Jul  5 17:44:43 2021 : Debug: (1)   Calling-Station-Id = "00:0C:29:D6:B8:A6"
Mon Jul  5 17:44:43 2021 : Debug: (1)   Called-Station-Id = "hotspot1"
Mon Jul  5 17:44:43 2021 : Debug: (1)   NAS-Port-Id = "ether3-LAN"
Mon Jul  5 17:44:43 2021 : Debug: (1)   User-Name = "06767"
Mon Jul  5 17:44:43 2021 : Debug: (1)   NAS-Port = 2149580826
Mon Jul  5 17:44:43 2021 : Debug: (1)   Acct-Session-Id = "8020001a"
Mon Jul  5 17:44:43 2021 : Debug: (1)   Framed-IP-Address = 192.168.251.117
Mon Jul  5 17:44:43 2021 : Debug: (1)   Mikrotik-Host-IP = 192.168.251.117
Mon Jul  5 17:44:43 2021 : Debug: (1)   Event-Timestamp = "Jul  5 2021 17:44:42                                                                                                              +04"
Mon Jul  5 17:44:43 2021 : Debug: (1)   NAS-Identifier = "Nayeem-R1-CoreRouter"
Mon Jul  5 17:44:43 2021 : Debug: (1)   Acct-Delay-Time = 0
Mon Jul  5 17:44:43 2021 : Debug: (1)   NAS-IP-Address = 192.168.31.77
Mon Jul  5 17:44:43 2021 : Debug: (1) # Executing section preacct from file /etc                                                                                                             /freeradius/3.0/sites-enabled/default
Mon Jul  5 17:44:43 2021 : Debug: (1)   preacct {
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: calling preprocess                                                                                                              (rlm_preprocess)
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: returned from prep                                                                                                             rocess (rlm_preprocess)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [preprocess] = ok
Mon Jul  5 17:44:43 2021 : Debug: (1)     policy acct_unique {
Mon Jul  5 17:44:43 2021 : Debug: (1)       update request {
Mon Jul  5 17:44:43 2021 : Debug: (1)         &Tmp-String-9 := "ai:"
Mon Jul  5 17:44:43 2021 : Debug: (1)       } # update request = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp                                                                                                             -String-9}/) &&             ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{hex:&Class}
Mon Jul  5 17:44:43 2021 : Debug: (1)          -->
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND ^%{hex:&Tmp-String-9}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> ^61693a
Mon Jul  5 17:44:43 2021 : Debug: No matches
Mon Jul  5 17:44:43 2021 : Debug: (1)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp                                                                                                             -String-9}/) &&             ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> F                                                                                                             ALSE
Mon Jul  5 17:44:43 2021 : Debug: (1)       else {
Mon Jul  5 17:44:43 2021 : Debug: (1)         update request {
Mon Jul  5 17:44:43 2021 : Debug: (1)           EXPAND %{md5:%{User-Name},%{Acct                                                                                                             -Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-P                                                                                                             ort-ID},%{NAS-Port}}
Mon Jul  5 17:44:43 2021 : Debug: (1)              --> 3f74fa78ccd63a57e895ef245                                                                                                             7272140
Mon Jul  5 17:44:43 2021 : Debug: (1)           &Acct-Unique-Session-Id := 3f74f                                                                                                             a78ccd63a57e895ef2457272140
Mon Jul  5 17:44:43 2021 : Debug: (1)         } # update request = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)       } # else = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)     } # policy acct_unique = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: calling suffix (rl                                                                                                             m_realm)
Mon Jul  5 17:44:43 2021 : Debug: (1) suffix: Checking for suffix after "@"
Mon Jul  5 17:44:43 2021 : Debug: (1) suffix: No '@' in User-Name = "06767", loo                                                                                                             king up realm NULL
Mon Jul  5 17:44:43 2021 : Debug: (1) suffix: No such realm "NULL"
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: returned from suff                                                                                                             ix (rlm_realm)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [suffix] = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: calling files (rlm                                                                                                             _files)
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[preacct]: returned from file                                                                                                             s (rlm_files)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [files] = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)   } # preacct = ok
Mon Jul  5 17:44:43 2021 : Debug: (1) # Executing section accounting from file /                                                                                                             etc/freeradius/3.0/sites-enabled/default
Mon Jul  5 17:44:43 2021 : Debug: (1)   accounting {
Mon Jul  5 17:44:43 2021 : Debug: (1)     update control {
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (1)       SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (0)
Mon Jul  5 17:44:43 2021 : Debug: (1)       Executing select query: SELECT (SUM(                                                                                                             acctinputOctets)+SUM(acctoutputoctets)) AS Total FROM radacct WHERE radacct.user                                                                                                             name='06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (0)
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{sql:SELECT (SUM(acctinputOc                                                                                                             tets)+SUM(acctoutputoctets)) AS Total FROM radacct WHERE radacct.username='%{Use                                                                                                             r-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: (1)          -->
Mon Jul  5 17:44:43 2021 : Debug: (1)       Tmp-Integer-0 := 0
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (1)       SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (5)
Mon Jul  5 17:44:43 2021 : Debug: (1)       Executing select query:  SELECT valu                                                                                                             e FROM radcheck WHERE attribute='Max-All-MB’ AND username='06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql_mysql: No additional diagnostic info o                                                                                                             n server
Mon Jul  5 17:44:43 2021 : ERROR: (1)       rlm_sql_mysql: ERROR 1064 (You have                                                                                                              an error in your SQL syntax; check the manual that corresponds to your MySQL ser                                                                                                             ver version for the right syntax to use near '06767'' at line 1): 42000
Mon Jul  5 17:44:43 2021 : ERROR: (1)       SQL query failed: server error
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (5)
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{sql: SELECT value FROM radc                                                                                                             heck WHERE attribute='Max-All-MB’ AND username='%{User-Name}'}
Mon Jul  5 17:44:43 2021 : Debug: (1)          -->
Mon Jul  5 17:44:43 2021 : Debug: (1)       Tmp-String-1 :=
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (1)       SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (1)
Mon Jul  5 17:44:43 2021 : Debug: (1)       Executing select query:  SELECT valu                                                                                                             e FROM radgroupcheck WHERE attribute='Max-All-MB'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (1)
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{sql: SELECT value FROM radg                                                                                                             roupcheck WHERE attribute='Max-All-MB'}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> 10737418240
Mon Jul  5 17:44:43 2021 : Debug: (1)       Tmp-String-1 := 10737418240
Mon Jul  5 17:44:43 2021 : Debug: (1)       Overwriting value "" with "107374182                                                                                                             40"
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1)          --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (1)       SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (6)
Mon Jul  5 17:44:43 2021 : Debug: (1)       Executing select query: select calle                                                                                                             dstationid from radacct where acctsessionid='8020001a'
Mon Jul  5 17:44:43 2021 : Debug: (1)       SQL query returned no results
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (6)
Mon Jul  5 17:44:43 2021 : Debug: (1)       EXPAND %{sql:select calledstationid                                                                                                              from radacct where acctsessionid='%{Acct-Session-Id}'}
Mon Jul  5 17:44:43 2021 : Debug: (1)          -->
Mon Jul  5 17:44:43 2021 : Debug: (1)       Tmp-String-3 :=
Mon Jul  5 17:44:43 2021 : Debug: (1)     } # update control = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)     if ("%{control:Tmp-Integer-0}" > "%{co                                                                                                             ntrol:Tmp-String-1}"){
Mon Jul  5 17:44:43 2021 : Debug: (1)     EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:44:43 2021 : Debug: (1)     EXPAND %{control:Tmp-Integer-0}
Mon Jul  5 17:44:43 2021 : Debug: (1)        --> 0
Mon Jul  5 17:44:43 2021 : Debug: (1)     EXPAND TMPL XLAT STRUCT
Mon Jul  5 17:44:43 2021 : Debug: (1)     EXPAND %{control:Tmp-String-1}
Mon Jul  5 17:44:43 2021 : Debug: (1)        --> 10737418240
Mon Jul  5 17:44:43 2021 : Debug: (1)     if ("%{control:Tmp-Integer-0}" > "%{co                                                                                                             ntrol:Tmp-String-1}") -> FALSE
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: calling detail                                                                                                              (rlm_detail)
Mon Jul  5 17:44:43 2021 : Debug: /var/log/freeradius/radacct/%{%{Packet-Src-IP-                                                                                                             Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> /var/log/freeradius/radacct/
Mon Jul  5 17:44:43 2021 : Debug: XLAT-IF {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> Packet-Src-IP-Address
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> Packet-Src-IPv6-Address
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: literal --> /detail-
Mon Jul  5 17:44:43 2021 : Debug: percent --> Y
Mon Jul  5 17:44:43 2021 : Debug: percent --> m
Mon Jul  5 17:44:43 2021 : Debug: percent --> d
Mon Jul  5 17:44:43 2021 : Debug: (1) detail: EXPAND /var/log/freeradius/radacct                                                                                                             /%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
Mon Jul  5 17:44:43 2021 : Debug: (1) detail:    --> /var/log/freeradius/radacct                                                                                                             /103.136.204.45/detail-20210705
Mon Jul  5 17:44:43 2021 : Debug: (1) detail: /var/log/freeradius/radacct/%{%{Pa                                                                                                             cket-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/                                                                                                             log/freeradius/radacct/103.136.204.45/detail-20210705
Mon Jul  5 17:44:43 2021 : Debug: %t
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: percent --> t
Mon Jul  5 17:44:43 2021 : Debug: (1) detail: EXPAND %t
Mon Jul  5 17:44:43 2021 : Debug: (1) detail:    --> Mon Jul  5 17:44:43 2021
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: returned from d                                                                                                             etail (rlm_detail)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [detail] = ok
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: calling unix (r                                                                                                             lm_unix)
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: returned from u                                                                                                             nix (rlm_unix)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [unix] = ok
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: calling sql (rl                                                                                                             m_sql)
Mon Jul  5 17:44:43 2021 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: xlat --> tolower
Mon Jul  5 17:44:43 2021 : Debug: {
Mon Jul  5 17:44:43 2021 : Debug:       literal --> type.
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> Acct-Status-Type
Mon Jul  5 17:44:43 2021 : Debug:       literal --> .query
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: EXPAND %{tolower:type.%{Acct-Status-T                                                                                                             ype}.query}
Mon Jul  5 17:44:43 2021 : Debug: (1) sql:    --> type.start.query
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: Using query template 'query'
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Reserved connection (2)
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: EXPAND %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1) sql:    --> 06767
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: SQL-User-Name set to '06767'
Mon Jul  5 17:44:43 2021 : Debug: INSERT INTO radacct (acctsessionid,          a                                                                                                             cctuniqueid,            username, realm,                        nasipaddress,  n                                                                                                             asportid, nasporttype,          acctstarttime,          acctupdatetime, acctstop                                                                                                             time,           acctsessiontime,        acctauthentic, connectinfo_start,      c                                                                                                             onnectinfo_stop,        acctinputoctets, acctoutputoctets,      calledstationid,                                                                                                                     callingstationid, acctterminatecause,   servicetype,            framedpr                                                                                                             otocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id                                                                                                             }', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NA                                                                                                             S-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_U                                                                                                             NIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-                                                                                                             Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Se                                                                                                             rvice-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: literal --> INSERT INTO radacct (acctsessionid                                                                                                             ,               acctuniqueid,           username, realm,                       n                                                                                                             asipaddress,            nasportid, nasporttype,         acctstarttime,         a                                                                                                             cctupdatetime, acctstoptime,            acctsessiontime,        acctauthentic, c                                                                                                             onnectinfo_start,       connectinfo_stop,       acctinputoctets, acctoutputoctet                                                                                                             s,      calledstationid,        callingstationid, acctterminatecause,   servicet                                                                                                             ype,            framedprotocol, framedipaddress) VALUES ('
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Acct-Session-Id
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Acct-Unique-Session-Id
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> SQL-User-Name
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Realm
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> NAS-IP-Address
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: XLAT-IF {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> NAS-Port-Id
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: XLAT-ELSE {
Mon Jul  5 17:44:43 2021 : Debug:       attribute --> NAS-Port
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> NAS-Port-Type
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', FROM_UNIXTIME(
Mon Jul  5 17:44:43 2021 : Debug: xlat --> integer
Mon Jul  5 17:44:43 2021 : Debug: {
Mon Jul  5 17:44:43 2021 : Debug:       literal --> Event-Timestamp
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: literal --> ), FROM_UNIXTIME(
Mon Jul  5 17:44:43 2021 : Debug: xlat --> integer
Mon Jul  5 17:44:43 2021 : Debug: {
Mon Jul  5 17:44:43 2021 : Debug:       literal --> Event-Timestamp
Mon Jul  5 17:44:43 2021 : Debug: }
Mon Jul  5 17:44:43 2021 : Debug: literal --> ), NULL, '0', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Acct-Authentic
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Connect-Info
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '', '0', '0', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Called-Station-Id
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Calling-Station-Id
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Service-Type
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Framed-Protocol
Mon Jul  5 17:44:43 2021 : Debug: literal --> ', '
Mon Jul  5 17:44:43 2021 : Debug: attribute --> Framed-IP-Address
Mon Jul  5 17:44:43 2021 : Debug: literal --> ')
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: EXPAND INSERT INTO radacct (acctsessi                                                                                                             onid,           acctuniqueid,           username, realm,                       n                                                                                                             asipaddress,            nasportid, nasporttype,         acctstarttime,         a                                                                                                             cctupdatetime, acctstoptime,            acctsessiontime,        acctauthentic, c                                                                                                             onnectinfo_start,       connectinfo_stop,       acctinputoctets, acctoutputoctet                                                                                                             s,      calledstationid,        callingstationid, acctterminatecause,   servicet                                                                                                             ype,            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:E                                                                                                             vent-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                                                                                                             }')
Mon Jul  5 17:44:43 2021 : Debug: (1) sql:    --> INSERT INTO radacct (acctsessi                                                                                                             onid,           acctuniqueid,           username, realm,                       n                                                                                                             asipaddress,            nasportid, nasporttype,         acctstarttime,         a                                                                                                             cctupdatetime, acctstoptime,            acctsessiontime,        acctauthentic, c                                                                                                             onnectinfo_start,       connectinfo_stop,       acctinputoctets, acctoutputoctet                                                                                                             s,      calledstationid,        callingstationid, acctterminatecause,   servicet                                                                                                             ype,            framedprotocol, framedipaddress) VALUES ('8020001a', '3f74fa78cc                                                                                                             d63a57e895ef2457272140', '06767', '', '192.168.31.77', 'ether3-LAN', 'Wireless-8                                                                                                             02.11', FROM_UNIXTIME(1625492682), FROM_UNIXTIME(1625492682), NULL, '0', '', '',                                                                                                              '', '0', '0', 'hotspot1', '00:0C:29:D6:B8:A6', '', '', '', '192.168.251.117')
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: Executing query: INSERT INTO radacct                                                                                                              (acctsessionid,         acctuniqueid,           username, realm,               n                                                                                                             asipaddress,            nasportid, nasporttype,         acctstarttime,         a                                                                                                             cctupdatetime, acctstoptime,            acctsessiontime,        acctauthentic, c                                                                                                             onnectinfo_start,       connectinfo_stop,       acctinputoctets, acctoutputoctet                                                                                                             s,      calledstationid,        callingstationid, acctterminatecause,   servicet                                                                                                             ype,            framedprotocol, framedipaddress) VALUES ('8020001a', '3f74fa78cc                                                                                                             d63a57e895ef2457272140', '06767', '', '192.168.31.77', 'ether3-LAN', 'Wireless-8                                                                                                             02.11', FROM_UNIXTIME(1625492682), FROM_UNIXTIME(1625492682), NULL, '0', '', '',                                                                                                              '', '0', '0', 'hotspot1', '00:0C:29:D6:B8:A6', '', '', '', '192.168.251.117')
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: SQL query returned: success
Mon Jul  5 17:44:43 2021 : Debug: (1) sql: 1 record(s) updated
Mon Jul  5 17:44:43 2021 : Debug: rlm_sql (sql): Released connection (2)
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: returned from s                                                                                                             ql (rlm_sql)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [sql] = ok
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: calling exec (r                                                                                                             lm_exec)
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: returned from e                                                                                                             xec (rlm_exec)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [exec] = noop
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: calling attr_fi                                                                                                             lter.accounting_response (rlm_attr_filter)
Mon Jul  5 17:44:43 2021 : Debug: %{User-Name}
Mon Jul  5 17:44:43 2021 : Debug: Parsed xlat tree:
Mon Jul  5 17:44:43 2021 : Debug: attribute --> User-Name
Mon Jul  5 17:44:43 2021 : Debug: (1) attr_filter.accounting_response: EXPAND %{                                                                                                             User-Name}
Mon Jul  5 17:44:43 2021 : Debug: (1) attr_filter.accounting_response:    --> 06                                                                                                             767
Mon Jul  5 17:44:43 2021 : Debug: (1) attr_filter.accounting_response: Matched e                                                                                                             ntry DEFAULT at line 12
Mon Jul  5 17:44:43 2021 : Debug: (1)     modsingle[accounting]: returned from a                                                                                                             ttr_filter.accounting_response (rlm_attr_filter)
Mon Jul  5 17:44:43 2021 : Debug: (1)     [attr_filter.accounting_response] = up                                                                                                             dated
Mon Jul  5 17:44:43 2021 : Debug: (1)   } # accounting = updated
Mon Jul  5 17:44:43 2021 : Debug: (1) Sent Accounting-Response Id 42 from 172.26                                                                                                             .11.27:1813 to 103.136.204.45:60317 length 0
Mon Jul  5 17:44:43 2021 : Debug: (1) Finished request
Mon Jul  5 17:44:43 2021 : Debug: (1) Cleaning up request packet ID 42 with time                                                                                                             stamp +58
Mon Jul  5 17:44:43 2021 : Debug: Waking up in 4.8 seconds.
Mon Jul  5 17:44:48 2021 : Debug: (0) Cleaning up request packet ID 41 with time                                                                                                             stamp +58
Mon Jul  5 17:44:48 2021 : Info: Ready to process requests


More information about the Freeradius-Users mailing list