[SR-Users] "invalid version 1 for table trusted found, expected 5" while trying to load permissions and drouting modules togheter

Daniel-Constantin Mierla miconda at gmail.com
Tue Nov 30 22:03:35 CET 2010


Hello,

seems to be an issue with opened connections. Normally, each process 
must have its own database connection, but looks like some are shared. 
Maybe there is some module that does not do it right. I will check 
permissions and drouting.

Thanks for pointing out,
Daniel

On 11/29/10 4:22 PM, Pierpaolo Culurciello wrote:
> Hello to everybody,
>
> I'm facing the following problem while trying to load and use 
> Permissions and Drouting modules togheter: here you are the detailed 
> starting debug of my Kamailio 3.1.0:
>
> 0(2456) DEBUG: db_postgres [km_pg_con.c:72]: opening connection: 
> postgres://xxxx:xxxx@192.168.190.150:5432/kamailio
>  0(2456) DEBUG: db_postgres [km_pg_con.c:80]: PQsetdbLogin(0x93ec520)
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): permissions
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): ldap
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): alias_db
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): domain
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): presence
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): presence_xml
>  0(2456) DEBUG: presence_xml [presence_xml.c:300]: [-127]  pid [2456]
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): nathelper
>  0(2456) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child 
> (-127): mediaproxy
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> mi_fifo
>  1(2457) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (1): tm
>  1(2457) DEBUG: tm [callid.c:131]: DEBUG: callid: 
> '65df7ef6-2457 at 192.168.190.185'
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> avpops
>  1(2457) DEBUG: <core> [db.c:294]: connection 0x82a7358 found in pool
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> usrloc
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> registrar
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> uri_db
>  1(2457) DEBUG: <core> [db.c:294]: connection 0x82a7408 found in pool
>  1(2457) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (1): ctl
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): acc
>  1(2457) DEBUG: <core> [db.c:294]: connection 0x82bc668 found in pool
>  1(2457) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): 
> drouting
>  1(2457) DEBUG: <core> [db.c:294]: connection 0x82bc910 found in pool
>  1(2457) DEBUG: db_postgres [km_dbase.c:149]: 0x82bc8f8 
> PQsendQuery(select gwid,address,strip,pri_prefix,type,attrs from 
> dr_gateways )
>  1(2457) DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result 
> set at 0x82a74e8
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> mi_fifo
>  2(2458) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (2): tm
>  2(2458) DEBUG: tm [callid.c:131]: DEBUG: callid: 
> '65df7ef6-2458 at 192.168.190.185'
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> avpops
>  2(2458) DEBUG: <core> [db.c:294]: connection 0x82a7358 found in pool
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> usrloc
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> registrar
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> uri_db
>  2(2458) DEBUG: <core> [db.c:294]: connection 0x82a7408 found in pool
>  2(2458) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (2): ctl
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): acc
>  2(2458) DEBUG: <core> [db.c:294]: connection 0x82bc668 found in pool
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> drouting
>  2(2458) DEBUG: <core> [db.c:294]: connection 0x82bc910 found in pool
>  2(2458) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): 
> permissions
>  2(2458) DEBUG: <core> [db.c:294]: connection 0x82a7500 found in pool
>  2(2458) DEBUG: db_postgres [km_val.c:158]: PQescapeStringConn: in: 7 
> chars, out: 7 chars
>  2(2458) DEBUG: db_postgres [km_dbase.c:149]: 0x82a74e8 
> PQsendQuery(select table_version from version where table_name='trusted')
>  2(2458) DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result 
> set at 0x82a7598
> LOG:  statement: select gwid,address,strip,pri_prefix,type,attrs from 
> dr_gateways
>  2(2458) DEBUG: db_postgres [km_dbase.c:403]: 0x82a74e8 
> PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x93f6010)
>  2(2458) DEBUG: db_postgres [km_res.c:108]: 6 columns returned from 
> the query
>  2(2458) DEBUG: <core> [db_res.c:153]: allocate 24 bytes for result 
> names at 0x82a75c0
>  2(2458) DEBUG: <core> [db_res.c:163]: allocate 24 bytes for result 
> types at 0x82a75e0
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[0] at 0x82a7600
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7600)[0]=[gwid]
>  2(2458) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[1] at 0x82a7610
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7610)[1]=[address]
>  2(2458) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[2] at 0x82a7620
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7620)[2]=[strip]
>  2(2458) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[3] at 0x82a7630
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7630)[3]=[pri_prefix]
>  2(2458) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[4] at 0x82a7640
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7640)[4]=[type]
>  2(2458) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
>  2(2458) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for 
> RES_NAMES[5] at 0x82a7650
>  2(2458) DEBUG: db_postgres [km_res.c:133]: 
> RES_NAMES(0x82a7650)[5]=[attrs]
>  2(2458) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
>  2(2458) DEBUG: db_postgres [km_res.c:222]: allocate for 6 columns 24 
> bytes in row buffer at 0x82a7660
>  2(2458) DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 
> 0x82a7680
>  2(2458) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,0)=[1]
>  2(2458) DEBUG: db_postgres [km_res.c:251]: [0][0] Column[gwid]=[1]
>  2(2458) DEBUG: db_postgres [km_res.c:242]: 
> PQgetvalue(0x82a74e8,0,1)=[192.168.190.150]
>  2(2458) DEBUG: db_postgres [km_res.c:251]: [0][1] 
> Column[address]=[192.168.190.150]
>  2(2458) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,2)=[2]
>  2(2458) DEBUG: db_postgres [km_res.c:251]: [0][2] Column[strip]=[2]
>  2(2458) DEBUG: db_postgres [km_res.c:242]: 
> PQgetvalue(0x82a74e8,0,3)=[88]
>  2(2458) DEBUG: db_postgres [km_res.c:251]: [0][3] 
> Column[pri_prefix]=[88]
>  2(2458) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,4)=[0]
>  2(2458) DEBUG: db_postgres [km_res.c:251]: [0][4] Column[type]=[0]
>  2(2458) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,5)=[]
>  2(2458) DEBUG: <core> [db_row.c:119]: allocate 120 bytes for row 
> values at 0x82c17f8
>  2(2458) DEBUG: <core> [db_val.c:73]: converting INT [1]
>  2(2458) DEBUG: <core> [db_val.c:117]: converting STRING 
> [192.168.190.150]
>  2(2458) DEBUG: <core> [db_val.c:127]: allocate 16 bytes memory for 
> STRING at 0x82a7690 2(2458) DEBUG: <core> [db_val.c:73]: converting 
> INT [2]
>  2(2458) DEBUG: <core> [db_val.c:117]: converting STRING [88]
>  2(2458) DEBUG: <core> [db_val.c:127]: allocate 3 bytes memory for 
> STRING at 0x82c1878 2(2458) DEBUG: <core> [db_val.c:73]: converting 
> INT [0]
>  2(2458) DEBUG: <core> [db_val.c:56]: converting NULL value 2(2458) 
> DEBUG: db_postgres [km_res.c:266]: freeing row buffer at 0x82a7660
>  2(2458) DEBUG: db_postgres [km_dbase.c:302]: PQclear(0x93f6010) 
> result set
>  2(2458) DEBUG: <core> [db_res.c:79]: freeing 6 columns
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82a7600
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82a7610
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82a7620
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[3] at 0x82a7630
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[4] at 0x82a7640
>  2(2458) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[5] at 0x82a7650
>  2(2458) DEBUG: <core> [db_res.c:92]: freeing result names at 0x82a75c0
>  2(2458) DEBUG: <core> [db_res.c:97]: freeing result types at 0x82a75e0
>  2(2458) DEBUG: <core> [db_res.c:52]: freeing 1 rows
>  2(2458) DEBUG: <core> [db_row.c:68]: free VAL_STRING[1] 
> '192.168.190.150' at 0x82a7690
>  2(2458) DEBUG: <core> [db_row.c:68]: free VAL_STRING[3] '88' at 
> 0x82c1878
>  2(2458) DEBUG: <core> [db_row.c:97]: freeing row values at 0x82c17f8
>  2(2458) DEBUG: <core> [db_res.c:60]: freeing rows at 0x82a7680
>  2(2458) DEBUG: <core> [db_res.c:134]: freeing result set at 0x82a7598
>  2(2458) ERROR: <core> [db.c:408]: invalid version 1 for table trusted 
> found, expected 5 (check table structure and table "version")
>  2(2458) ERROR: permissions [trusted.c:249]: error during table 
> version check.
>  2(2458) DEBUG: <core> [db_pool.c:97]: connection still kept in the pool
>  2(2458) ERROR: <core> [sr_module.c:811]: init_mod_child(): Error 
> while initializing module permissions
>  2(2458) ERROR: <core> [pt.c:332]: ERROR: fork_process(): init_child 
> failed for  process 2, pid 2458, ""
>  2(2458) : <core> [main.c:1439]: main_loop: Cannot fork
>
> As you can see expecially from the extract reported below, the problem 
> seems to occur when multiple threads run at the same time and placing 
> queries almost at the same time and it happens that the results of 
> those queries are returned back to the other thread.
>
>  2(2458) DEBUG: db_postgres [km_val.c:158]: PQescapeStringConn: in: 7 
> chars, out: 7 chars
>  2(2458) DEBUG: db_postgres [km_dbase.c:149]: 0x82a74e8 
> PQsendQuery(select table_version from version where table_name='trusted')
>  2(2458) DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result 
> set at 0x82a7598
> LOG:  statement: select gwid,address,strip,pri_prefix,type,attrs from 
> dr_gateways
>  2(2458) DEBUG: db_postgres [km_dbase.c:403]: 0x82a74e8 
> PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x93f6010)
>  2(2458) DEBUG: db_postgres [km_res.c:108]: 6 columns returned from 
> the query
>
> Here thread number 2 executes the query "select table_version from 
> version where table_name='trusted'" but then the same thread doesn't 
> evaluate its result but the one of the previous query, "select 
> gwid,address,strip,pri_prefix,type,attrs from dr_gateways"; as a 
> matter of fact you can see in the LOG statement "6 columns returned 
> from the query".
> The strange thing is that this problem occurs only when I try to load 
> Permissions and Drouting modules at the same time: whenever I load 
> anyone of that two modules alone Kamailio starts whitout complaining 
> about anything.
> Obviously I have already checked the value of "table_version" in 
> version table and it's the correct one (5).
> Moreover I have also tried to apply the patch suggested in the 
> following thread for a similar problem, 
> (http://www.mail-archive.com/sr-dev@lists.sip-router.org/msg07551.html) but 
> without any success.
> Please let me know if you have some advice for my problem, I really 
> need to use these two modules at the same time!
>
> Greetings,
> Pierpaolo Culurciello
>
>
>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

-- 
Daniel-Constantin Mierla
Kamailio (OpenSER) Advanced Training
Jan 24-26, 2011, Irvine, CA, USA
http://www.asipto.com




More information about the sr-users mailing list