SQL module mixes up packets when putting it to database

Khalukhin Alexander khalukhin at gmail.com
Thu Jul 24 19:53:23 CEST 2008


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"
        h323-setup-time = ".09:48:16.191 MSD Thu Jul 24 2008"
        h323-gw-id = "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
        Acct-Delay-Time = 0
        call-id = "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
        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"
        h323-setup-time = ".09:48:16.191 MSD Thu Jul 24 2008"
        h323-gw-id = "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"
        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
        Acct-Delay-Time = 0
        call-id = "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
        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', 'originate',
'74955891937', '4959636156', '57000000000008F7', '
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', 'originate',
'74955891937', '4959636156', '57000000000008F7', '
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      F0FF23AA 587A11DD
B8009A2D 9B5B4497
   1134862 Start
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

Server info:
FreeRADIUS Version 1.1.7, for host x86_64-redhat-linux-gnu, built on Jan 31
2008 at 18:32:53
CentOS release 5.2 (Final)
Linux Registrar 2.6.18-53.1.21.el5 #1 SMP Tue May 20 09:35:07 EDT 2008
x86_64 x86_64 x86_64 GNU/Linux
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20080724/4b12ec01/attachment.html>


More information about the Freeradius-Users mailing list