Problem with sql entry

[Fajar A. Nugraha]

On Tue, Dec 20, 2011 at 3:55 PM, Miha Zoubek <miha at softnet.si> wrote:
> Hi,
>
> please help me out why I am getting two entries in mysql table (radacct) for
> outgoing call. If the call is answered I get two entries and one entry if
> the call is not answered (this is ok).
>
> Reason that I am asking this is that I do not see that my NAS is sending two
> start packet and to stop packet for answered call (you can see below).
>
> Please help me out understand why radius add two entries for stop packet if
> only one is send from NAS.

First of all, if you're going to trim the debug log anyway, make sure
you include debug from a full sesssion to make it easier to diagnose.

> 2. Call is answered.
> 3142.992787 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Accounting-Request(4)
> (id=195, l=265)
> 3142.994570 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Accounting-Response(5)
> (id=195, l=20)

those two above most likely belong to a previous session. Accounting
usually comes after Access-Request. So I don't think you need to
include those. UNLESS your NAS is doing something funny, and it REALLY
sends Accounting - Access Request - Accounting for a session.

> rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx port 48752,
> id=198, length=265
>         Acct-Status-Type = Start
>         Acct-Session-Id = "d446d20a-6d1c-4ffd-9b59-1aedbf63b74c"

I'd note Acct-Session-Id lines ...

> rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx port 35569,
> id=200, length=401
>         Acct-Status-Type = Stop
>         Acct-Session-Id = "68507972-f9d9-46c7-bf22-59020602ffe2"

... and compare it with the next one. That's a different
Acct-Session-Id, so it's two different sessions.

Are you SURE you have two entries in radacct with Acct-Session-Id =
"68507972-f9d9-46c7-bf22-59020602ffe2"?

> [sql]   expand:            UPDATE radacct SET           acctstarttime   =
> '%{Freeswitch-Callanswerdate}',           acctstoptime       =
> '%S',              acctsessiontime    = '%{Acct-Session-Time}',
> acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32
> |
> '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   =
> '%{%{Acct-Output-Gigawords}:-0}' << 32 |
> '%{%{Acct-Output-Octets}:-0}',              acctterminatecause =
> '%{Acct-Terminate-Cause}',              acctstopdelay      =
> '%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   =
> '%{Connect-Info}'           WHERE acctsessionid   =
> '%{Acct-Session-Id}'           AND username          =
> '%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}'
> ->            UPDATE radacct SET               acctstarttime   =
> '2011-12-20T09:49:30.669405=2B0100',      acctstoptime       = '2011-12-20
> 09:49:49',              acctsessiontime    = '3',
> acctinputoctets    = '0' <<

hmmm ... that query doesn't look right.

"
UPDATE radacct SET               acctstarttime   =
'2011-12-20T09:49:30.669405=2B0100',      acctstoptime       = '2011-12-20
09:49:49',              acctsessiontime    = '3',
acctinputoctets    = '0' <<
"

seriously? Are you sure you didn't mess up the query while editing it
manually? Or was it copy-and-paste error?
Even acctstarttime looks wrong.


> [sql]   expand:            INSERT INTO radacct             (acctsessionid,
> acctuniqueid, username,              realm, nasipaddress,
> nasportid,              nasporttype, acctstarttime,
> acctstoptime,              acctsessiontime, acctauthentic,
> connectinfo_start,              connectinfo_stop, acctinputoctets,
> acctoutputoctets,              calledstationid, callingstationid,
> acctterminatecause,              servicetype, framedprotocol,
> framedipaddress,              acctstartdelay, acctstopdelay)
> VALUES             ('%{Acct-Session-Id}',
> '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',
> '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
> '%{NAS-Port-Type}',              DATE_SUB('%S',                  INTERVAL
> (%{%{Acct-Session-Time}:-0} +                  %{%{Acct-Delay-Time}:-0})
> SECOND),              '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}',
> '',              '%{Connect-Info}',
> '%{%{Acct-Input-Gigawords}:-0}' << 32 |              '%{%{Acct-Inpu

Same thing here. It should print what the actual sql statement executed

My best guess so far:
- the double lines you see are from different session (i.e. different
Acct-Session-Id). If so, the NAS sends two different accounting
request. Ask the NAS why it does that. OR
- you edit the default query and broke it.

In any case:
- check whether the records have the same Acct-Session-Id
- check that your queries are OK. Get a DBA to help you if necessary.
- get the full sql query executed somehow. It should be available in
the debug log, but the db might be able to provide it as well (e.g.
http://dev.mysql.com/doc/refman/5.5/en/query-log.html). Again, get a
DBA to help you if necessary.

-- 
Fajar