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