Re: FreeRadius 3.0.15 - Help with accounting
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
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
On Thu, Aug 10, 2017 at 3:41 AM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
Hi Alan,
Problem Output:
(28461) Received Access-Request Id 185 from 172.17.43.2:54246 to 187.120.197.140:1812 length 188
- You say you have a problem with accounting entries - This is access request, not accounting start packet
(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\.'
That one looks like simultaneous use check, but it's a customized one (AFAIK the examples don't use REGEXP). Did you create that? Or someone else did, and you simply inherit this machine?
Timeout: No Response from 172.17.43.2
That looks suspicious. And MIGHT be the root cause of your problem.
(28461) sql: Running Accounting section for automatically created accounting 'stop'
This seems to be a new feature introduced by https://github.com/FreeRADIUS/freeradius-server/commit/84e62deae4b4282fe7057... . AFAIK it should only be executed if FR determines you have stale accounting entries, and not something that the NAS sends. Short version: - get a debug log where your NAS is actually sending the problematic accounting package - find out why the NAS does not response (i.e. the 'timeout' above) - take a look at your simultaneous use check, the problem might be there. -- Fajar
Em 09/08/2017 20:54, Fajar A. Nugraha escreveu:
> On Thu, Aug 10, 2017 at 3:41 AM, Aurélio de Souza Ribeiro Neto
> <netolistas@mpc.com.br> wrote:
>> Hi Alan,
>>
>> Problem Output:
>>
>> (28461) Received Access-Request Id 185 from 172.17.43.2:54246 to
>> 187.120.197.140:1812 length 188
> - You say you have a problem with accounting entries
> - This is access request, not accounting start packet
Sorry, you are right.
>
>> (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\.'
> That one looks like simultaneous use check, but it's a customized one
> (AFAIK the examples don't use REGEXP). Did you create that? Or someone
> else did, and you simply inherit this machine?
I did, for iternal purposes and it's ok for me since 2.2.9 verision.
>
>> Timeout: No Response from 172.17.43.2
> That looks suspicious. And MIGHT be the root cause of your problem.
Very suspicious, I'm checking.
>
>> (28461) sql: Running Accounting section for automatically created accounting
>> 'stop'
> This seems to be a new feature introduced by
> https://github.com/FreeRADIUS/freeradius-server/commit/84e62deae4b4282fe70570be6a24be18a7bfe9f7
> . AFAIK it should only be executed if FR determines you have stale
> accounting entries, and not something that the NAS sends.
>
> Short version:
> - get a debug log where your NAS is actually sending the problematic
> accounting package
> - find out why the NAS does not response (i.e. the 'timeout' above)
> - take a look at your simultaneous use check, the problem might be there.
>
Maybe an SNMP failure cause this for me.
No problem for me the zap If the snmp for simultaneous-use fails.
My question is: why the radacct registry is incomplete, without
nasporttype and callingstationid?
Thank You.
Aurélio
On Thu, Aug 10, 2017 at 6:55 PM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
Short version: - get a debug log where your NAS is actually sending the problematic accounting package - find out why the NAS does not response (i.e. the 'timeout' above) - take a look at your simultaneous use check, the problem might be there.
Maybe an SNMP failure cause this for me.
No problem for me the zap If the snmp for simultaneous-use fails.
My question is: why the radacct registry is incomplete, without nasporttype and callingstationid?
As far as I can tell, those are related. You wrote: ' Sometimes I receive a complete Start request, but in my database (MySQL) the data are inserted incomplete, without nasporttype and callingstationid. When this occours I receive an automatic stop and a new start packet and then all is ok. ' When can you 'receive an automatic stop'? The only time I can think of is when session_zap does its thing. Which isn't really 'receive an automatic stop', but rather 'FR generates it'. When does session_zap happen? If it detects that the session is no longer alive. How does FR detect that the session is no longer alive? In your case, it might be SNMP to the NAS. IIRC if it times out, FR decide that the session is no longer alive. Why does session check happens in the first place? Because you configure simultaneous use check. So the key points should be: - Did you REALLY 'receive a complete Start request, but in my database (MySQL) the data are inserted incomplete'? If so, a debug log when THAT happens should tell you why. - Did you REALLY 'receive an automatic stop'? It shouldn't be the case. - Why did you get timeout? My GUESS is if you fix that, it will solve this particular problem. Again, some of what I wrote are guesses. You should be able to determine the actual cause accurately if you can capture the correct debug log, or solve the timeout issue. -- Fajar
Dear ALL, Many thanks for help!! I found my problem. My checkrad was not working. I fixed and then my problem gone away. Aurelio Em 10/08/2017 10:01, Fajar A. Nugraha escreveu:
On Thu, Aug 10, 2017 at 6:55 PM, Aurélio de Souza Ribeiro Neto <netolistas@mpc.com.br> wrote:
Short version: - get a debug log where your NAS is actually sending the problematic accounting package - find out why the NAS does not response (i.e. the 'timeout' above) - take a look at your simultaneous use check, the problem might be there.
Maybe an SNMP failure cause this for me.
No problem for me the zap If the snmp for simultaneous-use fails.
My question is: why the radacct registry is incomplete, without nasporttype and callingstationid? As far as I can tell, those are related. You wrote:
' Sometimes I receive a complete Start request, but in my database (MySQL) the data are inserted incomplete, without nasporttype and callingstationid.
When this occours I receive an automatic stop and a new start packet and then all is ok. '
When can you 'receive an automatic stop'? The only time I can think of is when session_zap does its thing. Which isn't really 'receive an automatic stop', but rather 'FR generates it'.
When does session_zap happen? If it detects that the session is no longer alive.
How does FR detect that the session is no longer alive? In your case, it might be SNMP to the NAS. IIRC if it times out, FR decide that the session is no longer alive.
Why does session check happens in the first place? Because you configure simultaneous use check.
So the key points should be: - Did you REALLY 'receive a complete Start request, but in my database (MySQL) the data are inserted incomplete'? If so, a debug log when THAT happens should tell you why. - Did you REALLY 'receive an automatic stop'? It shouldn't be the case. - Why did you get timeout? My GUESS is if you fix that, it will solve this particular problem.
Again, some of what I wrote are guesses. You should be able to determine the actual cause accurately if you can capture the correct debug log, or solve the timeout issue.
participants (3)
-
Alan Buxey -
Aurélio de Souza Ribeiro Neto -
Fajar A. Nugraha