[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
Wed Dec 1 22:21:58 CET 2010
Hello,
I did a fix for drouting module which opened a connection to DB in a
wrong way. Can you fetch the latest version of branch 3.1 and try again?
Tomorrow is planned 3.1.1 which will contain the fix as well.
Thanks,
Daniel
On 11/30/10 10:03 PM, Daniel-Constantin Mierla wrote:
> 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