[SR-Users] Usrloc reload problem

[Daniel-Constantin Mierla]

  Hello,

On 9/17/10 3:27 PM, Jan Klepal wrote:
> Hello,
>
> I run kamailio 3.0.3 with location table stored in database (PostgreSQL 8.4.2)
> with db_mode 2 (write-back) and upon kamailio restart some contacts from
> database are loaded incorrectly. Messages for those contacts are routed to
> invalid IP addresses.
>
> After some debugging I figured out that it happens only for contacts which
> "received" column value is null. For those contacts value is filled from
> previously loaded contact having non-null value in "received" column.
>
> Here is sample debug, which shows contact (row #97 in result set) with IP
> 10.3.71.1 is later used for contact without "received" value (row #172):
>
> db_postgres [km_dbase.c:149]: 0x888e00 PQsendQuery(select
> username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
> from location )
> ...
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,79,9)=[sip:10.3.71.1:5060]
> db_postgres [km_res.c:251]: [79][9] Column[received]=[sip:10.3.71.1:5060]
> ...
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,9)=[]
> ...
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,0)=[222333444]
> db_postgres [km_res.c:251]: [172][0] Column[username]=[222333444]
> db_postgres [km_res.c:242]:
> PQgetvalue(0x888e00,172,1)=[sip:222333444 at 195.70.1.200]
> db_postgres [km_res.c:251]: [172][1]
> Column[contact]=[sip:222333444 at 195.70.1.200]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,2)=[2010-09-16 00:21:04]
> db_postgres [km_res.c:251]: [172][2] Column[expires]=[2010-09-16 00:21:04]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,3)=[-1]
> db_postgres [km_res.c:251]: [172][3] Column[q]=[-1]
> db_postgres [km_res.c:242]:
> PQgetvalue(0x888e00,172,4)=[0fc6692b6570aaac04b3c85a3b9496c0 at sipxsip.cz]
> db_postgres [km_res.c:251]: [172][4]
> Column[callid]=[0fc6692b6570aaac04b3c85a3b9496c0 at sipxsip.cz]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,5)=[397]
> db_postgres [km_res.c:251]: [172][5] Column[cseq]=[397]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,6)=[0]
> db_postgres [km_res.c:251]: [172][6] Column[flags]=[0]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,7)=[0]
> db_postgres [km_res.c:251]: [172][7] Column[cflags]=[0]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,8)=[Asterisk SIPXSIP]
> db_postgres [km_res.c:251]: [172][8] Column[user_agent]=[Asterisk SIPXSIP]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,9)=[]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,10)=[]
> db_postgres [km_res.c:242]:
> PQgetvalue(0x888e00,172,11)=[udp:80.200.1.100:5060]
> db_postgres [km_res.c:251]: [172][11] Column[socket]=[udp:80.200.1.100:5060]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,12)=[]
> db_postgres [km_res.c:242]: PQgetvalue(0x888e00,172,13)=[2010-09-16 00:11:04]
> db_postgres [km_res.c:251]: [172][13] Column[last_modified]=[2010-09-16
> 00:11:04]
> <core>  [db_row.c:119]: allocate 448 bytes for row values at 0x998120
> <core>  [db_val.c:117]: converting STRING [222333444]
> <core>  [db_val.c:127]: allocate 10 bytes memory for STRING at 0x944008
> <core>  [db_val.c:117]: converting STRING [sip:222333444 at 195.70.1.200]
> <core>  [db_val.c:127]: allocate 27 bytes memory for STRING at 0x9378d8
> <core>  [db_val.c:157]: converting DATETIME [2010-09-16 00:21:04]
> <core>  [db_val.c:106]: converting DOUBLE [-1]
> <core>  [db_val.c:117]: converting STRING
> [0fc6692b6570aaac04b3c85a3b9496c0 at sipxsip.cz]
> <core>  [db_val.c:127]: allocate 44 bytes memory for STRING at 0x925cd8
> <core>  [db_val.c:73]: converting INT [397]
> <core>  [db_val.c:73]: converting INT [0]
> <core>  [db_val.c:73]: converting INT [0]
> <core>  [db_val.c:117]: converting STRING [Asterisk SIPXSIP]
> <core>  [db_val.c:127]: allocate 17 bytes memory for STRING at 0x9061e8
> <core>  [db_val.c:117]: converting STRING [sip:10.3.71.1:5060]
> <core>  [db_val.c:127]: allocate 19 bytes memory for STRING at 0x905fc8
> <core>  [db_val.c:56]: converting NULL value
> <core>  [db_val.c:117]: converting STRING [udp:80.200.1.100:5060]
> <core>  [db_val.c:127]: allocate 22 bytes memory for STRING at 0x905da8
> <core>  [db_val.c:73]: converting INT [4767]
> <core>  [db_val.c:157]: converting DATETIME [2010-09-16 00:11:04]
>
> To make things clear, all rows after row #97 had "received" value null, and
> row #172 was UA I ran tests on... in the other words contact with null
> "received" value is filled with previous non-null value as long next non-null
> row is fetched from DB and following null contacts are filled with its value
> and so on.
>
> When the contact having invalid "registered" re-register it will overwrite
> value in memory and calls are routed to proper IP address. This query is sent
> to database then:
>
> db_postgres [km_dbase.c:149]: 0x888e00 PQsendQuery(update location set
> expires='2010-09-16 00:30:58',q=-1.00
> ,cseq=103,flags=0,cflags=0,user_agent='Asterisk
> SIPXSIP',received=NULL,path=NULL,socket='udp:80.200.1.100:5
> 060',methods=NULL,last_modified='2010-09-16 00:20:58' where
> username='222333444' AND contact='sip:222333444 at 195.70.1.200' AND
> callid='0fc6692b6570aaac04b3c85a3b9496c0 at sipxsip.cz')
>
> I've also checked status of this record in usrloc by "kamctl ul show"... both
> before and after kamailio restart state was CS_SYNC.
>
> Is this bug or should I somehow force kamailio to store "received" into
> database?
it was a bug, hopefully fixed. Inside the postgres module, an internal 
buffer was not reset.

Test with master branch or take the patch from commit (it is small) and 
do it with 3.0.x:
http://lists.sip-router.org/pipermail/sr-dev/2010-September/008994.html

Since I have no pg server at hand, couldn't actually test it, so when 
you report is working fine, I will backport to 3.0.x.

Thanks,
Daniel


-- 
Daniel-Constantin Mierla
http://www.asipto.com