"invalid version 1 for table trusted found, expected 5" while trying to load permissions and drouting modules togheter
29 Nov
2010
29 Nov
'10
5:22 p.m.
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(a)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(a)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
30 Nov
30 Nov
11:03 p.m.
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(a)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(a)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(a)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
1 Dec
1 Dec
11:21 p.m.
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:
--
Daniel-Constantin Mierla
Kamailio (OpenSER) Advanced Training
Jan 24-26, 2011, Irvine, CA, USA
http://www.asipto.com
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(a)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(a)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(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
5107
days inactive
5109
days old
2 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Pierpaolo Culurciello