SQL module mixes up packets when putting it to database

Khalukhin Alexander khalukhin at gmail.com
Thu Jul 24 20:16:23 CEST 2008


On Thu, Jul 24, 2008 at 10:01 PM, Phil Mayers <p.mayers at imperial.ac.uk>
wrote:

> Khalukhin Alexander wrote:
>
>> Hi all! I'm using 'sql' module in accounting to log all the radius packets
>> from remote radius client (cisco 2600). I've investigated, that accounting
>> packets are received in right order ("Start" then "Stop"), but putted into
>> DB log table in wrong order ("Stop" then "Start"). Here are the logs:
>>
>> ============ /var/log/radius/radacct/x.y.z.a/detail-20080724
>> =================
>>
>> Thu Jul 24 09:48:26 2008
>>        Acct-Session-Id = "57000000000008F7"
>>        Calling-Station-Id = "4959636156"
>>        Called-Station-Id = "74955891937"
>>        Cisco-AVPair = "call-id=
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>"
>>        h323-setup-time = ".09:48:16.191 MSD Thu Jul 24 2008"
>>        h323-gw-id = "voice5.di-net.ru <http://voice5.di-net.ru>"
>>        h323-conf-id = "F0FF23AA 587A11DD B8009A2D 9B5B4497"
>>        h323-call-origin = "originate"
>>        h323-call-type = "VoIP"
>>        Cisco-AVPair = "h323-incoming-conf-id=F0FF23AA 587A11DD B8009A2D
>> 9B5B4497"
>>        Cisco-AVPair = "subscriber=Unknown"
>>        Cisco-AVPair = "session-protocol=sipv2"
>>        Cisco-AVPair = "gw-rxd-cdn=ton:0,npi:0,#:74955891937"
>>        User-Name = "4959636156"
>>        Cisco-AVPair = "connect-progress=Call Up"
>>        Acct-Status-Type = *Start*
>>        Service-Type = Login-User
>>        NAS-IP-Address = 89.208.190.6 <http://89.208.190.6>
>>        Acct-Delay-Time = 0
>>        call-id = "F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6<mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>"
>>        h323-incoming-conf-id = "F0FF23AA 587A11DD B8009A2D 9B5B4497"
>>        subscriber = "Unknown"
>>        session-protocol = "sipv2"
>>        gw-rxd-cdn = "ton:0,npi:0,#:74955891937"
>>        Client-IP-Address = 89.208.190.6 <http://89.208.190.6>
>>        Acct-Unique-Session-Id = "51b334248c332b3b"
>>        Timestamp = 1216878506
>>
>> Thu Jul 24 09:48:27 2008
>>        Acct-Session-Id = "57000000000008F7"
>>        Calling-Station-Id = "4959636156"
>>        Called-Station-Id = "74955891937"
>>        Cisco-AVPair = "call-id=
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>"
>>        h323-setup-time = ".09:48:16.191 MSD Thu Jul 24 2008"
>>        h323-gw-id = "voice5.di-net.ru <http://voice5.di-net.ru>"
>>        h323-conf-id = "F0FF23AA 587A11DD B8009A2D 9B5B4497"
>>        h323-call-origin = "originate"
>>        h323-call-type = "VoIP"
>>        Cisco-AVPair = "h323-incoming-conf-id=F0FF23AA 587A11DD B8009A2D
>> 9B5B4497"
>>        Cisco-AVPair = "subscriber=Unknown"
>>        Cisco-AVPair = "session-protocol=sipv2"
>>        Cisco-AVPair = "gw-rxd-cdn=ton:0,npi:0,#:74955891937"
>>        Acct-Input-Octets = 0
>>        Acct-Output-Octets = 0
>>        Acct-Input-Packets = 0
>>        Acct-Output-Packets = 0
>>        Acct-Session-Time = 0
>>        h323-connect-time = ".09:48:16.371 MSD Thu Jul 24 2008"
>>        h323-disconnect-time = ".09:48:16.371 MSD Thu Jul 24 2008"
>>        h323-disconnect-cause = "1"
>>        h323-remote-address = "89.208.190.4 <http://89.208.190.4>"
>>        Cisco-AVPair = "release-source=4"
>>        h323-voice-quality = "0"
>>        Cisco-AVPair = "gw-rxd-cgn=ton:0,npi:0,pi:1,si:0,#:4959636156"
>>        Cisco-AVPair = "gw-final-xlated-cdn=ton:0,npi:0,#:74955891937"
>>        Cisco-AVPair =
>> "gw-final-xlated-cgn=ton:0,npi:0,pi:1,si:0,#:4959636156"
>>        User-Name = "4959636156"
>>        Acct-Status-Type = *Stop*
>>        Service-Type = Login-User
>>        NAS-IP-Address = 89.208.190.6 <http://89.208.190.6>
>>        Acct-Delay-Time = 0
>>        call-id = "F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6<mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>"
>>        h323-incoming-conf-id = "F0FF23AA 587A11DD B8009A2D 9B5B4497"
>>        subscriber = "Unknown"
>>        session-protocol = "sipv2"
>>        gw-rxd-cdn = "ton:0,npi:0,#:74955891937"
>>        release-source = "4"
>>        gw-rxd-cgn = "ton:0,npi:0,pi:1,si:0,#:4959636156"
>>        gw-final-xlated-cdn = "ton:0,npi:0,#:74955891937"
>>        gw-final-xlated-cgn = "ton:0,npi:0,pi:1,si:0,#:4959636156"
>>        Client-IP-Address = 89.208.190.6 <http://89.208.190.6>
>>        Acct-Unique-Session-Id = "51b334248c332b3b"
>>        Timestamp = 1216878507
>>
>> =========== /var/log/radius/sqltrace.sql ================
>>
>> INSERT INTO ACC ("ACCT-STATUS-TYPE", "NAS-IP-ADDRESS", "H323-CALL-ORIGIN",
>> "CALLED-STATION-ID", "CALLING-STATION-ID", "ACCT-SESSION-ID", "CALL-ID",
>> "SIP-TO-TAG", "SIP-FROM-TAG", "SIP-TRANSLATED-REQUEST-URI", "USER-NAME",
>> "SIP-SOURCE-IP-ADDRESS", "SIP-SOURCE-PORT", "ACCT-SESSION-TIME",
>> "H323-CONNECT-TIME", "H323-SETUP-TIME", "H323-DISCONNECT-TIME",
>> "H323-DISCONNECT-CAUSE", "IPHOP-COUNT", "IPHOP1", "IPHOP2", "IPHOP3",
>> "H323-CONF-ID") VALUES ('*Start*', '89.208.190.6 <http://89.208.190.6>',
>> 'originate', '74955891937', '4959636156', '57000000000008F7', '
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>', '', '', '',
>> '4959636156', '', '', '', '', '.09:48:16.191 MSD Thu Jul 24 2008', '', '',
>> '', '', '', '', 'F0FF23AA 587A11DD B8009A2D 9B5B4497');
>>
>> INSERT INTO ACC ("ACCT-STATUS-TYPE", "NAS-IP-ADDRESS", "H323-CALL-ORIGIN",
>> "CALLED-STATION-ID", "CALLING-STATION-ID", "ACCT-SESSION-ID", "CALL-ID",
>> "SIP-TO-TAG", "SIP-FROM-TAG", "SIP-TRANSLATED-REQUEST-URI", "USER-NAME",
>> "SIP-SOURCE-IP-ADDRESS", "SIP-SOURCE-PORT", "ACCT-SESSION-TIME",
>> "H323-CONNECT-TIME", "H323-SETUP-TIME", "H323-DISCONNECT-TIME",
>> "H323-DISCONNECT-CAUSE", "IPHOP-COUNT", "IPHOP1", "IPHOP2", "IPHOP3",
>> "H323-CONF-ID") VALUES ('*Stop*', '89.208.190.6 <http://89.208.190.6>',
>> 'originate', '74955891937', '4959636156', '57000000000008F7', '
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>', '', '', '',
>> '4959636156', '', '', '0', '.09:48:16.371 MSD Thu Jul 24 2008',
>> '.09:48:16.191 MSD Thu Jul 24 2008', '.09:48:16.371 MSD Thu Jul 24 2008',
>> '1', '', '', '', '', 'F0FF23AA 587A11DD B8009A2D 9B5B4497');
>>
>> ========== Data from DB acc table ===========
>>
>>        ID ACCT-STATUS-TYPE   CALL-ID
>>         H323-CONF-ID                       ---------- ------------------
>> -----------------------------------------------------
>> ------------------------------------
>>   1134861 Stop
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>      F0FF23AA 587A11DD
>> B8009A2D 9B5B4497
>>   1134862 Start
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6 <mailto:
>> F217BA24-587A11DD-83D18BF5-E033E9AB at 89.208.190.6>      F0FF23AA 587A11DD
>> B8009A2D 9B5B4497
>>
>> ID here is autoincremented primary key (taked from sequence - DB is Oracle
>> 10gR2). As you can see, right order of packets ("Start" then "Stop") is
>> violated. I need them to appear in database  in right order. This error
>> happens once-twice per day, in hours of medium load average. Maybe I should
>> use only one database connection in oracle_sql (now num_sql_socks=5 in
>> /etc/raddb/oraclesql.conf)? Or what it can be? Give me a clue, please
>>
>
> That's an oracle problem, nothing to do with FreeRadius. Either write your
> SQL queries to sort by the acctstarttime/acctstoptime fields or make oracle
> "work right"
>
> FWIW Postgres does exactly the same with "serial" keys; they're not
> guaranteed to be monotonically increasing if contending threads are talking
> to the database.
>
> Using one SQL connection would probably work but will be slow.
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>


Due to
http://download.oracle.com/docs/cd/B19306_01/server.102/b14220/schema.htm#sthref883
:
*Therefore, the sequence generator reduces serialization where the
statements of two transactions must generate sequential numbers at the same
time.

*It's seems you're right in case, if freeradius using more, than one
connection (isolated transaction) to oracle database (that's my case). I
should have known better this feature. Thanks for help!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20080724/d3c52802/attachment.html>


More information about the Freeradius-Users mailing list