Re: FreeRadius 3.0.15 - Help with accounting

9 Aug 2017


      Hi Alan,

     Problem Output:

(28461) Received Access-Request Id 185 from 172.17.43.2:54246 to 
187.120.197.140:1812 length 188
(28461)   Service-Type = Framed-User
(28461)   Framed-Protocol = PPP
(28461)   NAS-Port = 15791968
(28461)   NAS-Port-Type = Ethernet
(28461)   User-Name = "waldemarjunior"
(28461)   Calling-Station-Id = "C4:6E:1F:F3:A1:E7"
(28461)   Called-Station-Id = "CE - POP SM9"
(28461)   NAS-Port-Id = "ether9"
(28461)   MS-CHAP-Challenge = 0x2e08483252d28f89
(28461)   MS-CHAP-Response = 
0x0101000000000000000000000000000000000000000000000000d1129355aac1e4cf1c152517f5251a854ea7e18c06bb71a4
(28461)   NAS-Identifier = "CE-SM"
(28461)   NAS-IP-Address = 172.17.43.2
(28461) # Executing section authorize from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   authorize {
(28461)     [preprocess] = ok
(28461)     [chap] = noop
(28461) mschap: Found MS-CHAP attributes.  Setting 'Auth-Type  = mschap'
(28461)     [mschap] = ok
(28461) sql: EXPAND %{User-Name}
(28461) sql:    --> waldemarjunior
(28461) sql: SQL-User-Name set to 'waldemarjunior'
rlm_sql (sql): Reserved connection (0)
(28461) sql: EXPAND SELECT DISTINCT (R.id), R.username, R.attribute, 
R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'%{SQL-User-Name}'                                  AND M.usuario_login 
=  BINARY '%{SQL-User-Name}'                                  AND 
N.nasname =  '%{Nas-IP-Address}'                                  AND 
N.gw_id = (SELECT gateway_id FROM mpc_lw.maclist WHERE usuario_login =  
BINARY '%{SQL-User-Name}' AND plano_id NOT IN (8,9,793) AND gateway_id = 
( SELECT gw_id FROM mpc_freeradius.nas WHERE nasname = 
'%{Nas-IP-Address}' )                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'%{SQL-User-Name}'                                  AND M.usuario_login 
=  BINARY '%{SQL-User-Name}'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql:    --> SELECT DISTINCT (R.id), R.username, R.attribute, 
R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND N.nasname = 
'172.17.43.2'                                  AND N.gw_id = (SELECT 
gateway_id FROM mpc_lw.maclist WHERE usuario_login =  BINARY 
'waldemarjunior' AND plano_id NOT IN (8,9,793) AND gateway_id = ( SELECT 
gw_id FROM mpc_freeradius.nas WHERE nasname = '172.17.43.2' 
)                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql: Executing select query: SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND N.nasname = 
'172.17.43.2'                                  AND N.gw_id = (SELECT 
gateway_id FROM mpc_lw.maclist WHERE usuario_login =  BINARY 
'waldemarjunior' AND plano_id NOT IN (8,9,793) AND gateway_id = ( SELECT 
gw_id FROM mpc_freeradius.nas WHERE nasname = '172.17.43.2' 
)                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql: User found in radcheck table
(28461) sql: Conditional check items matched, merging assignment check items
(28461) sql:   Simultaneous-Use := 1
(28461) sql:   Pool-Name := "main_pool"
(28461) sql:   Cleartext-Password := "32000"
(28461) sql: EXPAND SELECT DISTINCT (R.id), R.username, R.attribute, 
R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'%{SQL-User-Name}'                                  AND M.usuario_login 
=  BINARY '%{SQL-User-Name}'                                  AND 
N.nasname =  '%{Nas-IP-Address}'                                  AND 
N.gw_id = (SELECT gateway_id FROM mpc_lw.maclist WHERE usuario_login =  
BINARY '%{SQL-User-Name}' AND plano_id NOT IN (8,9,793) AND gateway_id = 
( SELECT gw_id FROM mpc_freeradius.nas WHERE nasname = 
'%{Nas-IP-Address}' )                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'%{SQL-User-Name}'                                  AND M.usuario_login 
=  BINARY '%{SQL-User-Name}'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql:    --> SELECT DISTINCT (R.id), R.username, R.attribute, 
R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND N.nasname = 
'172.17.43.2'                                  AND N.gw_id = (SELECT 
gateway_id FROM mpc_lw.maclist WHERE usuario_login =  BINARY 
'waldemarjunior' AND plano_id NOT IN (8,9,793) AND gateway_id = ( SELECT 
gw_id FROM mpc_freeradius.nas WHERE nasname = '172.17.43.2' 
)                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql: Executing select query: SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND N.nasname = 
'172.17.43.2'                                  AND N.gw_id = (SELECT 
gateway_id FROM mpc_lw.maclist WHERE usuario_login =  BINARY 
'waldemarjunior' AND plano_id NOT IN (8,9,793) AND gateway_id = ( SELECT 
gw_id FROM mpc_freeradius.nas WHERE nasname = '172.17.43.2' 
)                                  ORDER BY 
ID)                                  UNION 
ALL                                  SELECT DISTINCT (R.id), R.username, 
R.attribute, R.value, R.op                                  FROM 
mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist 
M                                  WHERE R.username =  BINARY 
'waldemarjunior'                                  AND M.usuario_login =  
BINARY 'waldemarjunior'                                  AND 
M.grupocliente = 'ALL-POPS'
(28461) sql: User found in radreply table, merging reply items
(28461) sql:   Simultaneous-Use := 1
(28461) sql:   Pool-Name := "main_pool"
(28461) sql:   Cleartext-Password := "32000"
(28461) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = 
'%{SQL-User-Name}' ORDER BY priority
(28461) sql:    --> SELECT groupname FROM radusergroup WHERE username = 
'waldemarjunior' ORDER BY priority
(28461) sql: Executing select query: SELECT groupname FROM radusergroup 
WHERE username = 'waldemarjunior' ORDER BY priority
(28461) sql: User found in the group table
(28461) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM 
radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id
(28461) sql:    --> SELECT id, groupname, attribute, Value, op FROM 
radgroupcheck WHERE groupname = '716' ORDER BY id
(28461) sql: Executing select query: SELECT id, groupname, attribute, 
Value, op FROM radgroupcheck WHERE groupname = '716' ORDER BY id
(28461) sql: Group "716": Conditional check items matched
(28461) sql: Group "716": Merging assignment check items
(28461) sql: EXPAND SELECT id, groupname, attribute, value, op FROM 
radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id
(28461) sql:    --> SELECT id, groupname, attribute, value, op FROM 
radgroupreply WHERE groupname = '716' ORDER BY id
(28461) sql: Executing select query: SELECT id, groupname, attribute, 
value, op FROM radgroupreply WHERE groupname = '716' ORDER BY id
(28461) sql: Group "716": Merging reply items
(28461) sql:   Framed-Compression := Van-Jacobson-TCP-IP
(28461) sql:   Framed-Protocol := PPP
(28461) sql:   Framed-Routing := Broadcast-Listen
(28461) sql:   Framed-MTU := 1500
(28461) sql:   Service-Type := Framed-User
(28461) sql:   Mikrotik-Rate-Limit := "1024k/4096k 1126k/11264k 
1075k/8192k 108/108"
rlm_sql (sql): Released connection (0)
(28461)     [sql] = ok
(28461)     [expiration] = noop
(28461)     [logintime] = noop
(28461) pap: WARNING: Auth-Type already set.  Not setting to PAP
(28461)     [pap] = noop
(28461)   } # authorize = ok
(28461) Found Auth-Type = MS-CHAP
(28461) # Executing group from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   Auth-Type MS-CHAP {
(28461) mschap: Found Cleartext-Password, hashing to create NT-Password
(28461) mschap: Found Cleartext-Password, hashing to create LM-Password
(28461) mschap: Client is using MS-CHAPv1 with NT-Password
(28461) mschap: adding MS-CHAPv1 MPPE keys
(28461)     [mschap] = ok
(28461)     if (reject) {
(28461)     if (reject)  -> FALSE
(28461)   } # Auth-Type MS-CHAP = ok
(28461) # Executing section session from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   session {
(28461) sql: EXPAND %{User-Name}
(28461) sql:    --> waldemarjunior
(28461) sql: SQL-User-Name set to 'waldemarjunior'
(28461) sql: EXPAND SELECT COUNT(*) FROM 
radacct                              WHERE username = 
'%{SQL-User-Name}'                              AND acctstoptime IS 
NULL                              AND framedipaddress NOT REGEXP '^10\.'
(28461) sql:    --> SELECT COUNT(*)                              FROM 
radacct                              WHERE username = 
'waldemarjunior'                              AND acctstoptime IS 
NULL                              AND framedipaddress NOT REGEXP '^10\.'
rlm_sql (sql): Reserved connection (17)
(28461) sql: Executing select query: SELECT 
COUNT(*)                              FROM 
radacct                              WHERE username = 
'waldemarjunior'                              AND acctstoptime IS 
NULL                              AND framedipaddress NOT REGEXP '^10\.'
(28461) sql: EXPAND SELECT radacctid, acctsessionid, 
username,                                nasipaddress, nasportid, 
framedipaddress,                                callingstationid, 
framedprotocol                                FROM 
radacct                                WHERE username = 
'%{SQL-User-Name}'                                AND acctstoptime IS 
NULL                                AND framedipaddress NOT REGEXP '^10\.'
(28461) sql:    --> SELECT radacctid, acctsessionid, 
username,                                nasipaddress, nasportid, 
framedipaddress,                                callingstationid, 
framedprotocol                                FROM 
radacct                                WHERE username = 
'waldemarjunior'                                AND acctstoptime IS 
NULL                                AND framedipaddress NOT REGEXP '^10\.'
(28461) sql: Executing select query: SELECT radacctid, acctsessionid, 
username, nasipaddress, nasportid, 
framedipaddress,                                callingstationid, 
framedprotocol                                FROM 
radacct                                WHERE username = 
'waldemarjunior'                                AND acctstoptime IS 
NULL                                AND framedipaddress NOT REGEXP '^10\.'
Timeout: No Response from 172.17.43.2
(28461) sql: Running Accounting section for automatically created 
accounting 'stop'
(28461) sql:   Service-Type = Framed-User
(28461) sql:   Framed-Protocol = PPP
(28461) sql:   NAS-Port = 15791968
(28461) sql:   NAS-Port-Type = Ethernet
(28461) sql:   User-Name = "waldemarjunior"
(28461) sql:   Calling-Station-Id = "C4:6E:1F:F3:A1:E7"
(28461) sql:   Called-Station-Id = "CE - POP SM9"
(28461) sql:   NAS-Port-Id = "ether9"
(28461) sql:   MS-CHAP-Challenge = 0x2e08483252d28f89
(28461) sql:   MS-CHAP-Response = 
0x0101000000000000000000000000000000000000000000000000d1129355aac1e4cf1c152517f5251a854ea7e18c06bb71a4
(28461) sql:   NAS-Identifier = "CE-SM"
(28461) sql:   NAS-IP-Address = 172.17.43.2
(28461) sql:   Event-Timestamp = "Aug  9 2017 13:41:58 BRT"
(28461) sql:   SQL-User-Name := "waldemarjunior"
(28461) # Executing section preacct from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   preacct {
(28461)     [preprocess] = ok
(28461)     policy acct_unique {
(28461)       update request {
(28461)         &Tmp-String-9 := "ai:"
(28461)       } # update request = noop
(28461)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && 
("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(28461)       EXPAND %{hex:&Class}
(28461)          -->
(28461)       EXPAND ^%{hex:&Tmp-String-9}
(28461)          --> ^61693a
(28461)       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && 
("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
(28461)       else {
(28461)         update request {
(28461)           EXPAND 
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(28461)              --> 6d3eb9c3ffe04efb05453582256f179a
(28461)           &Acct-Unique-Session-Id := 
6d3eb9c3ffe04efb05453582256f179a
(28461)         } # update request = noop
(28461)       } # else = noop
(28461)     } # policy acct_unique = noop
(28461)     [files] = noop
(28461)   } # preacct = ok
(28461) # Executing section accounting from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   accounting {
rlm_sql (sql): Reserved connection (28)
(28461) sqlippool: EXPAND %{User-Name}
(28461) sqlippool:    --> waldemarjunior
(28461) sqlippool: SQL-User-Name set to 'waldemarjunior'
(28461) sqlippool: EXPAND START TRANSACTION
(28461) sqlippool:    --> START TRANSACTION
(28461) sqlippool: Executing query: START TRANSACTION
(28461) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', 
pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE nasipaddress = '%{Nas-IP-Address}' AND 
pool_key = '%{Calling-Station-Id}' AND username = '%{User-Name}' AND 
callingstationid = '%{Calling-Station-Id}' AND framedipaddress = 
'%{Framed-IP-Address}'
(28461) sqlippool:    --> UPDATE radippool SET nasipaddress = '', 
pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE nasipaddress = '172.17.43.2' AND pool_key = 
'' AND username = 'waldemarjunior' AND callingstationid = '' AND 
framedipaddress = '187.120.206.111'
(28461) sqlippool: Executing query: UPDATE radippool SET nasipaddress = 
'', pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE nasipaddress = '172.17.43.2' AND pool_key = 
'' AND username = 'waldemarjunior' AND callingstationid = '' AND 
framedipaddress = '187.120.206.111'
rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
(28461) sqlippool: EXPAND COMMIT
(28461) sqlippool:    --> COMMIT
(28461) sqlippool: Executing query: COMMIT
(28461) sqlippool: EXPAND Released IP %{Framed-IP-Address} (did 
%{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name})
(28461) sqlippool:    --> Released IP 187.120.206.111 (did cli  user 
waldemarjunior)
rlm_sql (sql): Released connection (28)
Need 1 more connections to reach 35 spares
rlm_sql (sql): Opening additional connection (38), 1 of 29 pending slots 
used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'mpc_freeradius' on 
mysql.mpc.com.br via TCP/IP, server version 5.5.57-0ubuntu0.14.04.1-log, 
protocol version 10
(28461)     [sqlippool] = ok
(28461) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(28461) sql:    --> type.stop.query
(28461) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (22)
(28461) sql: EXPAND %{User-Name}
(28461) sql:    --> waldemarjunior
(28461) sql: SQL-User-Name set to 'waldemarjunior'
(28461) sql: EXPAND UPDATE radacct SET acctstoptime    = NOW(), 
acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = 
'%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', 
acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | 
'%{%{Acct-Output-Octets}:-0}', acctterminatecause = 
'%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connect-Info}' WHERE 
AcctUniqueId = '%{Acct-Unique-Session-Id}'
(28461) sql:    --> UPDATE radacct SET acctstoptime    = NOW(), 
acctsessiontime = 0, acctinputoctets = '0' << 32 | '0', acctoutputoctets 
= '0' << 32 | '0', acctterminatecause = '', connectinfo_stop = '' WHERE 
AcctUniqueId = '6d3eb9c3ffe04efb05453582256f179a'
(28461) sql: Executing query: UPDATE radacct SET acctstoptime    = 
NOW(), acctsessiontime = 0, acctinputoctets = '0' << 32 | '0', 
acctoutputoctets = '0' << 32 | '0', acctterminatecause = '', 
connectinfo_stop = '' WHERE AcctUniqueId = 
'6d3eb9c3ffe04efb05453582256f179a'
rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
(28461) sql: SQL query returned: success
(28461) sql: 0 record(s) updated
(28461) sql: Trying next query...
(28461) sql: EXPAND INSERT INTO radacct 
(acctsessionid,acctuniqueid,username, realm,nasipaddress,nasportid, 
nasporttype,acctstarttime,acctupdatetime, acctstoptime,acctsessiontime, 
acctauthentic, connectinfo_start,connectinfo_stop, acctinputoctets, 
acctoutputoctets,calledstationid, callingstationid, 
acctterminatecause,servicetype,framedprotocol, framedipaddress) VALUES 
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', 
'%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', 
(NOW() - %{%{Acct-Session-Time}:-0}), NOW(), NOW(), 
%{%{Acct-Session-Time}:-NULL}, '%{Acct-Authentic}', '', 
'%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | 
'%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | 
'%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', 
'%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', 
'%{Framed-Protocol}', '%{Framed-IP-Address}')
(28461) sql:    --> INSERT INTO radacct 
(acctsessionid,acctuniqueid,username, realm,nasipaddress,nasportid, 
nasporttype,acctstarttime,acctupdatetime, acctstoptime,acctsessiontime, 
acctauthentic, connectinfo_start,connectinfo_stop, acctinputoctets, 
acctoutputoctets,calledstationid, callingstationid, 
acctterminatecause,servicetype,framedprotocol, framedipaddress) VALUES 
('81b0eef6', '6d3eb9c3ffe04efb05453582256f179a', 'waldemarjunior', '', 
'172.17.43.2', '15791967', '', (NOW() - 0), NOW(), NOW(), 0, '', '', '', 
'0' << 32 | '0', '0' << 32 | '0', '', '', '', 'Framed-User', 'PPP', 
'187.120.206.111')
(28461) sql: Executing query: INSERT INTO radacct 
(acctsessionid,acctuniqueid,username, realm,nasipaddress,nasportid, 
nasporttype,acctstarttime,acctupdatetime, acctstoptime,acctsessiontime, 
acctauthentic, connectinfo_start,connectinfo_stop, acctinputoctets, 
acctoutputoctets,calledstationid, callingstationid, 
acctterminatecause,servicetype,framedprotocol, framedipaddress) VALUES 
('81b0eef6', '6d3eb9c3ffe04efb05453582256f179a', 'waldemarjunior', '', 
'172.17.43.2', '15791967', '', (NOW() - 0), NOW(), NOW(), 0, '', '', '', 
'0' << 32 | '0', '0' << 32 | '0', '', '', '', 'Framed-User', 'PPP', 
'187.120.206.111')
(28461) sql: SQL query returned: success
(28461) sql: 1 record(s) updated
rlm_sql (sql): Released connection (22)
(28461)     [sql] = ok
(28461)     [exec] = noop
(28461) attr_filter.accounting_response: EXPAND %{User-Name}
(28461) attr_filter.accounting_response:    --> waldemarjunior
(28461) attr_filter.accounting_response: Matched entry DEFAULT at line 12
(28461)     [attr_filter.accounting_response] = updated
(28461) log_accounting: EXPAND 
Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(28461) log_accounting:    --> Accounting-Request.Stop
(28461) log_accounting: EXPAND %t : Info: Released IP 
%{Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} 
user %{User-Name})
(28461) log_accounting:    --> Wed Aug  9 13:41:58 2017 : Info: Released 
IP 187.120.206.111 (did  cli  user waldemarjunior)
(28461) log_accounting: EXPAND /var/log/radius.log
(28461) log_accounting:    --> /var/log/radius.log
(28461)     [log_accounting] = ok
(28461)   } # accounting = updated
rlm_sql (sql): Released connection (17)
(28461)     [sql] = ok
(28461)   } # session = ok
(28461) # Executing section post-auth from file 
/usr/local/etc/raddb/sites-enabled/default
(28461)   post-auth {
(28461)     update {
(28461)       No attributes updated
(28461)     } # update = noop
rlm_sql (sql): Reserved connection (7)
(28461) sqlippool: EXPAND %{User-Name}
(28461) sqlippool:    --> waldemarjunior
(28461) sqlippool: SQL-User-Name set to 'waldemarjunior'
(28461) sqlippool: EXPAND START TRANSACTION
(28461) sqlippool:    --> START TRANSACTION
(28461) sqlippool: Executing query: START TRANSACTION
(28461) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', 
pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND 
pool_key = '%{Calling-Station-Id}'
(28461) sqlippool:    --> UPDATE radippool SET nasipaddress = '', 
pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND 
pool_key = 'C4:6E:1F:F3:A1:E7'
(28461) sqlippool: Executing query: UPDATE radippool SET nasipaddress = 
'', pool_key = 0, callingstationid = '', username = '', expiry_time = 
'0000-00-00 00:00:00' WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND 
pool_key = 'C4:6E:1F:F3:A1:E7'
rlm_sql_mysql: Rows matched: 0  Changed: 0  Warnings: 0
(28461) sqlippool: EXPAND COMMIT
(28461) sqlippool:    --> COMMIT
(28461) sqlippool: Executing query: COMMIT
(28461) sqlippool: EXPAND START TRANSACTION
(28461) sqlippool:    --> START TRANSACTION
(28461) sqlippool: Executing query: START TRANSACTION
(28461) sqlippool: EXPAND SELECT framedipaddress FROM radippool WHERE 
pool_name = '%{control:Pool-Name}' AND  expiry_time = '0000-00-00 
00:00:00' ORDER BY (username <> '%{User-Name}'), (callingstationid <> 
'%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE
(28461) sqlippool:    --> SELECT framedipaddress FROM radippool WHERE 
pool_name = 'main_pool' AND  expiry_time = '0000-00-00 00:00:00' ORDER 
BY (username <> 'waldemarjunior'), (callingstationid <> 
'C4:6E:1F:F3:A1:E7'), expiry_time LIMIT 1 FOR UPDATE
(28461) sqlippool: Executing select query: SELECT framedipaddress FROM 
radippool WHERE pool_name = 'main_pool' AND  expiry_time = '0000-00-00 
00:00:00' ORDER BY (username <> 'waldemarjunior'), (callingstationid <> 
'C4:6E:1F:F3:A1:E7'), expiry_time LIMIT 1 FOR UPDATE
(28461) sqlippool: Allocated IP 187.120.205.26
(28461) sqlippool: EXPAND UPDATE radippool SET nasipaddress = 
'%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', 
callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', 
expiry_time = NOW() + INTERVAL 330 SECOND WHERE framedipaddress = 
'187.120.205.26' AND expiry_time = '0000-00-00 00:00:00'
(28461) sqlippool:    --> UPDATE radippool SET nasipaddress = 
'172.17.43.2', pool_key = 'C4:6E:1F:F3:A1:E7', callingstationid = 
'C4:6E:1F:F3:A1:E7', username = 'waldemarjunior', expiry_time = NOW() + 
INTERVAL 330 SECOND WHERE framedipaddress = '187.120.205.26' AND 
expiry_time = '0000-00-00 00:00:00'
(28461) sqlippool: Executing query: UPDATE radippool SET nasipaddress = 
'172.17.43.2', pool_key = 'C4:6E:1F:F3:A1:E7', callingstationid = 
'C4:6E:1F:F3:A1:E7', username = 'waldemarjunior', expiry_time = NOW() + 
INTERVAL 330 SECOND WHERE framedipaddress = '187.120.205.26' AND 
expiry_time = '0000-00-00 00:00:00'
rlm_sql_mysql: Rows matched: 1  Changed: 1  Warnings: 0
(28461) sqlippool: EXPAND COMMIT
(28461) sqlippool:    --> COMMIT
(28461) sqlippool: Executing query: COMMIT
rlm_sql (sql): Released connection (7)
(28461) sqlippool: EXPAND Allocated IP: %{reply:Framed-IP-Address} from 
%{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} 
port %{NAS-Port} user %{User-Name})
(28461) sqlippool:    --> Allocated IP: 187.120.205.26 from main_pool 
(did CE - POP SM9 cli C4:6E:1F:F3:A1:E7 port 15791968 user waldemarjunior)
(28461)     [sqlippool] = ok
(28461)     [exec] = noop
(28461) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default}
(28461) linelog:    --> messages.Access-Accept
(28461) linelog: EXPAND %t : Auth: Login OK: [%{User-Name}] (from client 
%{Called-Station-Id} port %{NAS-Port} cli %{Calling-Station-Id})
(28461) linelog:    --> Wed Aug  9 13:41:58 2017 : Auth: Login OK: 
[waldemarjunior] (from client CE - POP SM9 port 15791968 cli 
C4:6E:1F:F3:A1:E7)
(28461) linelog: EXPAND /var/log/radius.log
(28461) linelog:    --> /var/log/radius.log
(28461)     [linelog] = ok
(28461)   } # post-auth = ok
(28461) Login OK: [waldemarjunior] (from client ce-popsm-rb port 
15791968 cli C4:6E:1F:F3:A1:E7)
(28461) Sent Access-Accept Id 185 from 187.120.197.140:1812 to 
172.17.43.2:54246 length 0
(28461)   Framed-Compression = Van-Jacobson-TCP-IP
(28461)   Framed-Protocol = PPP
(28461)   Framed-Routing = Broadcast-Listen
(28461)   Framed-MTU = 1500
(28461)   Service-Type = Framed-User
(28461)   Mikrotik-Rate-Limit = "1024k/4096k 1126k/11264k 1075k/8192k 
108/108"
(28461)   MS-CHAP-MPPE-Keys = 
0x4147ceeab03cfcd0aa376984106901b2657866f8bd83948f
(28461)   MS-MPPE-Encryption-Policy = Encryption-Allowed
(28461)   MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(28461)   Framed-IP-Address = 187.120.205.26
(28461) Finished request


     Thanks

Aurelio


Em 08/08/2017 17:32, Alan Buxey escreveu:
...
Provide the output, that's why we ask you to run out that way. We can't
just work on guesswork and if you've read, seen and understood the output
then you don't need our help ;)
alan
On 8 Aug 2017 9:21 pm, "Aurélio de Souza Ribeiro Neto" <
netolistas@mpc.com.br> wrote:
Fajar,
I use  -X mode and my NAS send a complete information.
In the same request I got an "invalid" insert and the I receive a valid
insert.
In the same NAS I have about 400 users and one or other have a "wrong"
insert!!
In FreeRadius 2.2.9 I don't have this problem.
I know.... this is not a FreeRadius problem, but I want a hint  to
solve this!
Thanks
Em 08/08/2017 12:11, Fajar A. Nugraha escreveu:
...
On Tue, Aug 8, 2017 at 8:04 PM, Aurélio de Souza Ribeiro Neto
<netolistas@mpc.com.br> wrote:
...
Fajar,
I did and not appear to be a Query problem.
Look the first and the second insert:
INSERT INTO radacct (acctsessionid, acctuniqueid,           username,
realm,
nasipaddress,           nasportid, nasporttype,
                  acctstarttime,          acctupdatetime, acctstoptime,
acctsessiontime,        acctauthentic, connectinfo_start,
connectinfo_stop,
          acctinputoctets, acctoutputoctets, calledstationid,
callingstationid, acctterminatecause, servicetype,
framedprotocol, framedipaddress)
VALUES ('81b0ec6b', '1e485bcb3cfbe8526b33e4d1fb50fecd', 'katiasantos',
'',
'172.17.43.2', '15791310', '', (NOW() - 0), NOW(), NOW(), 0, '', '', '',
'0'
<< 32 | '0', '0'
'Framed-User', 'PPP', '187.120.203.169');
INSERT INTO radacct (acctsessionid, acctuniqueid,           username,
realm,
nasipaddress,           nasportid, nasporttype,
                  acctstarttime,          acctupdatetime, acctstoptime,
acctsessiontime,        acctauthentic, connectinfo_start,
connectinfo_stop,
          acctinputoctets, acctoutputoctets, calledstationid,
callingstationid, acctterminatecause, servicetype,
framedprotocol, framedipaddress)
   VALUES ('81b0ecc1', '5b68881f4438da10588f26dbe616c917', 'katiasantos',
'',
'172.17.43.2', '15791396', 'Ethernet', NOW(), NOW(), NULL, '0', 'RADIUS',
'', '', '0', '0',
   'CE - POP SM8', '1C:7E:E5:C4:2E:73', '', 'Framed-User', 'PPP',
'187.120.203.169');
What I can do?
Then you need to capture what the NAS send when this happens. On the
first insert, FR believes that the NAS is not sending nasporttype and
callingstationid. 'freeradius -X' can show you what FR receives (I did
not see accounting request on your original dump, only
Access-Request).
Again, my GUESS is the NAS sends it that way. In which case you need
to ask whoever configured the NAS (or its creators) why it sends that.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list
/users.html
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html