Freeradius + MySQL wrong Timestamps
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@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@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@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@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@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@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@192.168.1.5', nas '127.0.0.1'] Tue Aug 12 22:46:20 2014 : Info: [sql] stop packet with zero session length. [user '2002@192.168.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)
Satish Patel wrote:
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 ).
The SIP server is supposed to send an accounting stop packet. This isn't a FreeRADIUS issue. Fix the SIP server so that it sends the packet. < 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)
That isn't a FreeRADIUS config file, so we can't help you. Ask the authors of the SIP software how to configure it. Alan DeKok.
If you check log sip sending stop packet but and freeradius able to update start accounting but not stop. Check my log even MySQL date time stamps are wrong also. Sent from my iPhone On Aug 13, 2014, at 1:10 PM, Alan DeKok <aland@deployingradius.com> wrote:
Satish Patel wrote:
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 ).
The SIP server is supposed to send an accounting stop packet. This isn't a FreeRADIUS issue. Fix the SIP server so that it sends the packet.
< 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)
That isn't a FreeRADIUS config file, so we can't help you.
Ask the authors of the SIP software how to configure it.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Satish Patel wrote:
If you check log sip sending stop packet but and freeradius able to update start accounting but not stop.
Because the NAS is broken. 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@192.168.1.5', nas '127.0.0.1'] Tue Aug 12 22:46:20 2014 : Info: [sql] stop packet with zero session length. [user '2002@192.168.1.5', nas '127.0.0.1'] A Stop packet with zero session length is *stupid*. The server tosses those. Because they're stupid, and don't mean anything.
Check my log even MySQL date time stamps are wrong also.
No. The server doesn't invent timestamps. It uses the timestamps it gets from the NAS. If the timestamps are wrong, blame the NAS. Alan DeKok.
Hi,
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
FreeRADIUS does what you tell it to do. you are getting Stop packets...okay... but look at the SQL that you are telling it to run when you get such packets...if you want your Connect Start/End toimes to be populated then you need to adjust the Start/Stop SQL queries as you require them... you have a DB schema..ensur eit gets used as you want it to be used. alan
participants (3)
-
A.L.M.Buxey@lboro.ac.uk -
Alan DeKok -
Satish Patel