[SR-Users] Kamailio + FreeRadius + MySQL Accounting STOP not updating

I have install Kamailio 4.1 with MySQL database so all users stored in MySQL (authentication), Later I have installed FreeRadius for accounting only, Just accounting (Invite/Bye). In short MySQL for authentication and FreeRadius for accounting ( CDRTool). Problems: If i register user using SIP phone and call other SIP extension then freeradius start accounting and insert entry in MySQL/radaccts tables if i end call then it doesn't update END accounting ( Bye ). I have google it everywhere but didn't get single clue so i hope i get something here from you guys -- kamailio.cfg ( default file i just add following radius section) loadmodule "acc.so" loadmodule "acc_radius.so" ... ... # ------- FreeRadius Accounting ------- modparam("acc_radius", "radius_flag", 1) modparam("acc_radius", "radius_missed_flag", 2) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "service_type", 15) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") modparam("acc_radius", "radius_extra", "User-Name=$Au") -- /etc/freeradius/sql.conf sql { driver = "rlm_sql_mysql" server = "localhost" login = "radius" password = "radius" radius_db = "radius" sqltrace = no sqltracefile = ${logdir}/sqltrace-%Y%m%d.log num_sql_socks = 25 connect_failure_retry_delay = 60 accounting_start_query = "\ CALL insert_radacct_record( \ 'radius', \ '%{Acct-Session-Id}', \ '%{Acct-Unique-Session-Id}', \ '%{Billing-Party}', \ '%{Billing-Party}', \ '%{SIP-Proxy-IP}', \ '%{NAS-Port}', \ FROM_UNIXTIME('%S'), \ '0', \ '0', \ '0', \ '0', \ '%{Called-Station-Id}', \ '%{Calling-Station-Id}', \ '%{Sip-Response-Code}', \ '%{Service-Type}', \ '%{ENUM-TLD}', \ '%{Framed-IP-Address}', \ UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', \ UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', \ '%{Sip-Response-Code}', \ '%{Sip-Method}', \ '%{Sip-Translated-Request-URI}', \ '%{Sip-To-Tag}', \ '%{Sip-From-Tag}', \ '%{Sip-RPId}', \ '%{Source-IP}', \ '%{Source-Port}', \ '%{Canonical-URI}', \ '', \ '', \ '%{Sip-Application-Type}', \ '%{User-Agent}', \ '%{From-Header}' \ )" accounting_stop_query = "\ CALL update_radacct_record( \ 'radius', \ FROM_UNIXTIME('%S'), \ UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', \ '', \ '%{X-RTP-Stat}', \ '%{Acct-Session-Id}', \ '%{Sip-To-Tag}', \ '%{Sip-From-Tag}' \ )" -- Radius logs rad_recv: Accounting-Request packet from host 127.0.0.1 port 36379, id=11, length=152 Acct-Status-Type = Start Service-Type = Sip-Session Sip-Response-Code = 200 Sip-Method = Invite Event-Timestamp = "Aug 12 2014 22:45:36 EDT" Sip-From-Tag = "59eb1875" Sip-To-Tag = "d443e36e" Acct-Session-Id = "M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ." User-Name = "2002(a)192.168.1.5" NAS-Port = 5060 Acct-Delay-Time = 0 NAS-IP-Address = 127.0.0.1 Tue Aug 12 22:45:36 2014 : Info: # Executing section preacct from file /etc/freeradius/sites-enabled/default Tue Aug 12 22:45:36 2014 : Info: +- entering group preacct {...} Tue Aug 12 22:45:36 2014 : Info: ++[preprocess] returns ok Tue Aug 12 22:45:36 2014 : Info: [acct_unique] Hashing 'NAS-Port = 5060,Client-IP-Address = 127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id = "M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ.",User-Name = "2002(a)192.168.1.5 "' Tue Aug 12 22:45:36 2014 : Info: [acct_unique] Acct-Unique-Session-ID = "117c7740de62ba6c". Tue Aug 12 22:45:36 2014 : Info: ++[acct_unique] returns ok Tue Aug 12 22:45:36 2014 : Info: [suffix] Looking up realm "192.168.1.5" for User-Name = "2002(a)192.168.1.5" Tue Aug 12 22:45:36 2014 : Info: [suffix] No such realm "192.168.1.5" Tue Aug 12 22:45:36 2014 : Info: ++[suffix] returns noop Tue Aug 12 22:45:36 2014 : Info: ++[files] returns noop Tue Aug 12 22:45:36 2014 : Info: # Executing section accounting from file /etc/freeradius/radiusd.conf Tue Aug 12 22:45:36 2014 : Info: +- entering group accounting {...} Tue Aug 12 22:45:36 2014 : Info: [detail] expand: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/freeradius/radacct/127.0.0.1/detail-20140812 Tue Aug 12 22:45:36 2014 : Info: [detail] /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/detail-20140812 Tue Aug 12 22:45:36 2014 : Info: [detail] expand: %t -> Tue Aug 12 22:45:36 2014 Tue Aug 12 22:45:36 2014 : Info: ++[detail] returns ok Tue Aug 12 22:45:36 2014 : Info: [sql] expand: CALL insert_radacct_record( 'radius', '%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{Billing-Party}', '%{Billing-Party}', '%{SIP-Proxy-IP}', '%{NAS-Port}', FROM_UNIXTIME('%S'), '0', '0', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Sip-Response-Code}', '%{Service-Type}', '%{ENUM-TLD}', '%{Framed-IP-Address}', UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', '%{Sip-Response-Code}', '%{Sip-Method}', '%{Sip-Translated-Request-URI}', '%{Sip-To-Tag}', '%{Sip-From-Tag}', '%{Sip-RPId}', '%{Source-IP}' Tue Aug 12 22:45:36 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 24 Tue Aug 12 22:45:36 2014 : Debug: rlm_sql (sql): Released sql socket id: 24 Tue Aug 12 22:45:36 2014 : Info: ++[sql] returns ok Sending Accounting-Response of id 11 to 127.0.0.1 port 36379 Tue Aug 12 22:45:36 2014 : Info: Finished request 0. Tue Aug 12 22:45:36 2014 : Info: Cleaning up request 0 ID 11 with timestamp +13 Tue Aug 12 22:45:36 2014 : Debug: Going to the next request Tue Aug 12 22:45:36 2014 : Info: Ready to process requests. rad_recv: Accounting-Request packet from host 127.0.0.1 port 35683, id=149, length=152 Acct-Status-Type = Stop Service-Type = Sip-Session Sip-Response-Code = 200 Sip-Method = Bye Event-Timestamp = "Aug 12 2014 22:46:20 EDT" Sip-From-Tag = "59eb1875" Sip-To-Tag = "d443e36e" Acct-Session-Id = "M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ." User-Name = "2002(a)192.168.1.5" NAS-Port = 5060 Acct-Delay-Time = 0 NAS-IP-Address = 127.0.0.1 Tue Aug 12 22:46:20 2014 : Info: # Executing section preacct from file /etc/freeradius/sites-enabled/default Tue Aug 12 22:46:20 2014 : Info: +- entering group preacct {...} Tue Aug 12 22:46:20 2014 : Info: ++[preprocess] returns ok Tue Aug 12 22:46:20 2014 : Info: [acct_unique] Hashing 'NAS-Port = 5060,Client-IP-Address = 127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id = "M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ.",User-Name = "2002(a)192.168.1.5 "' Tue Aug 12 22:46:20 2014 : Info: [acct_unique] Acct-Unique-Session-ID = "117c7740de62ba6c". Tue Aug 12 22:46:20 2014 : Info: ++[acct_unique] returns ok Tue Aug 12 22:46:20 2014 : Info: [suffix] Looking up realm "192.168.1.5" for User-Name = "2002(a)192.168.1.5" Tue Aug 12 22:46:20 2014 : Info: [suffix] No such realm "192.168.1.5" Tue Aug 12 22:46:20 2014 : Info: ++[suffix] returns noop Tue Aug 12 22:46:20 2014 : Info: ++[files] returns noop Tue Aug 12 22:46:20 2014 : Info: # Executing section accounting from file /etc/freeradius/radiusd.conf Tue Aug 12 22:46:20 2014 : Info: +- entering group accounting {...} Tue Aug 12 22:46:20 2014 : Info: [detail] expand: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/freeradius/radacct/127.0.0.1/detail-20140812 Tue Aug 12 22:46:20 2014 : Info: [detail] /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/detail-20140812 Tue Aug 12 22:46:20 2014 : Info: [detail] expand: %t -> Tue Aug 12 22:46:20 2014 Tue Aug 12 22:46:20 2014 : Info: ++[detail] returns ok Tue Aug 12 22:46:20 2014 : Info: [sql] expand: CALL update_radacct_record( 'radius', FROM_UNIXTIME('%S'), UNIX_TIMESTAMP('%S') - '%{Event-Timestamp}', '', '%{X-RTP-Stat}', '%{Acct-Session-Id}', '%{Sip-To-Tag}', '%{Sip-From-Tag}' ) -> CALL update_radacct_record( 'radius', FROM_UNIXTIME('2014-08-12 22:46:20'), UNIX_TIMESTAMP('2014-08-12 22:46:20') - 'Aug 12 2014 22:46:20 EDT', '', '', 'M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ.', 'd443e36e', '59eb1875' ) Tue Aug 12 22:46:20 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 23 Tue Aug 12 22:46:20 2014 : Info: [sql] expand: stop packet with zero session length. [user '%{User-Name}', nas '%{NAS-IP-Address}'] -> stop packet with zero session length. [user '2002(a)192.168.1.5'1.5', nas '127.0.0.1'] Tue Aug 12 22:46:20 2014 : Info: [sql] stop packet with zero session length. [user '2002(a)192.168.1.5'1.5', nas '127.0.0.1'] Tue Aug 12 22:46:20 2014 : Debug: rlm_sql (sql): Released sql socket id: 23 Tue Aug 12 22:46:20 2014 : Info: ++[sql] returns noop Sending Accounting-Response of id 149 to 127.0.0.1 port 35683 Tue Aug 12 22:46:20 2014 : Info: Finished request 1. Tue Aug 12 22:46:20 2014 : Info: Cleaning up request 1 ID 149 with timestamp +57 Tue Aug 12 22:46:20 2014 : Debug: Going to the next request Tue Aug 12 22:46:20 2014 : Info: Ready to process requests. -- SQL tables ( Time is wired 1969 ) mysql> select * from radacct196912; +-----------+----------------------------------------------+------------------+----------+-------+--------------+-----------+-------------+---------------------+---------------------+-----------------+---------------+-------------------+------------------+-----------------+------------------+-----------------+------------------+--------------------+-------------+---------+-----------------+----------------+---------------+-----------+-----------------+----------+------------+-------------------------+---------------+--------------------+-----------+---------+---------------+----------+------------+--------------+-----------+-----------+---------------+------+-------+------------+-----------+-----------+---------------+------------+-----------+---------+ | RadAcctId | AcctSessionId | AcctUniqueId | UserName | Realm | NASIPAddress | NASPortId | NASPortType | AcctStartTime | AcctStopTime | AcctSessionTime | AcctAuthentic | ConnectInfo_start | ConnectInfo_stop | AcctInputOctets | AcctOutputOctets | CalledStationId | CallingStationId | AcctTerminateCause | ServiceType | ENUMtld | FramedIPAddress | AcctStartDelay | AcctStopDelay | SipMethod | SipResponseCode | SipToTag | SipFromTag | SipTranslatedRequestURI | SipUserAgents | SipApplicationType | SipCodecs | SipRPID | SipRPIDHeader | SourceIP | SourcePort | CanonicalURI | DelayTime | Timestamp | DestinationId | Rate | Price | Normalized | BillingId | MediaInfo | RTPStatistics | FromHeader | UserAgent | Contact | +-----------+----------------------------------------------+------------------+----------+-------+--------------+-----------+-------------+---------------------+---------------------+-----------------+---------------+-------------------+------------------+-----------------+------------------+-----------------+------------------+--------------------+-------------+---------+-----------------+----------------+---------------+-----------+-----------------+----------+------------+-------------------------+---------------+--------------------+-----------+---------+---------------+----------+------------+--------------+-----------+-----------+---------------+------+-------+------------+-----------+-----------+---------------+------------+-----------+---------+ | 1 | Y2ExZjhkMTU4ODRmN2MwMGM1N2Q1Y2E5YTA5ZjAzNjg | e46f9d0439141495 | | | | 5060 | | 1969-12-31 19:00:00 | 1969-12-31 19:00:00 | 0 | NULL | NULL | | 0 | 0 | | | 200 | Sip-Session | | | 1407883391 | 0 | Invite | 200 | 70cc9216 | e2cb1f0c | | | | | | | | | | | 0 | | | NULL | 0 | | NULL | | | | | | 2 | MzYyY2JhM2Q3MzEyN2U1ODJkMDA1NGNiMTMzYmE0OTc | aa9b8bcb6effa2c7 | | | | 5060 | | 1969-12-31 19:00:00 | 1969-12-31 19:00:00 | 0 | NULL | NULL | | 0 | 0 | | | 200 | Sip-Session | | | 0 | 0 | Invite | 200 | c6ea6056 | 407f047e | | | | | | | | | | | 0 | | | NULL | 0 | | NULL | | | | | | 3 | M2IwZTVkY2Y5YTU2ZjdmOTQ5NWMzYzI1NTU3MWMwYjQ. | 117c7740de62ba6c | | | | 5060 | | 1969-12-31 19:33:34 | 1969-12-31 19:33:34 | 0 | NULL | NULL | | 0 | 0 | | | 200 | Sip-Session | | | 1407897936 | 1407897980 | Invite | 200 | d443e36e | 59eb1875 | | | | | | | | | | | 0 | | | NULL | 0 | | NULL | | | | | +-----------+----------------------------------------------+------------------+----------+-------+--------------+-----------+-------------+---------------------+---------------------+-----------------+---------------+-------------------+------------------+-----------------+------------------+-----------------+------------------+--------------------+-------------+---------+-----------------+----------------+---------------+-----------+-----------------+----------+------------+-------------------------+---------------+--------------------+-----------+---------+---------------+----------+------------+--------------+-----------+-----------+---------------+------+-------+------------+-----------+-----------+---------------+------------+-----------+---------+ 3 rows in set (0.00 sec)