30 Nov
2010
30 Nov
'10
10:08 p.m.
Hello,
seems to be an issue with sharing db connection, which should not
happen, but it was reported by others. I will look at it, seems that the
trouble is in drouting or permissions, as both were always involved.
Thanks for reporting,
Daniel
On 11/27/10 12:33 PM, Giorgio Maria Santini wrote:
Hello everybody,
We need to deploy kamailio with both drouting and permissions modules
enabled. We are using kamailio 3.1.0 and we found, probably, a bug in
one of the two modules (we don't know where) that cause kamailio to
quit for an invalid table_version founded for table Permissions.
First, I want to say that in table version there is the right record:
kamailio=# select * from version where table_name='trusted';
LOG: statement: select * from version where table_name='trusted';
table_name | table_version
------------+---------------
trusted | 5
(1 row)
Then, debugging I've found that kamailio do the right query, but
returns a wrong recordset. Here a little snapshot of the debug:
1(2615) DEBUG: <core> [db.c:294]: connection 0x82bc910 found in pool
1(2615) DEBUG: db_postgres [km_dbase.c:149]: 0x82bc8f8
PQsendQuery(select gwid,address,strip,pri_prefix,type,attrs from
dr_gateways )
...
....
2(2616) DEBUG: db_postgres [km_dbase.c:149]: 0x82a74e8
PQsendQuery(select table_version from version where table_name='trusted')
2(2616) 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(2616) DEBUG: db_postgres [km_dbase.c:403]: 0x82a74e8
PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x870c010)
2(2616) DEBUG: db_postgres [km_res.c:108]: 6 columns returned from
the query
instead of saying "1 columns returned from the query" it returns the
number of columns of the query launched in the other thread, I think.
In this case
"select gwid,address,strip,pri_prefix,type,attrs from dr_gateway"
but it's not always the same query, sometimes returns the query of the
usrloc, or other else.
The strange is that it's happen only when Permissions and Drouting
modules are enabled together. If I remove one of this, not depending
on which one I choose, everything works ok. We absolutely need both
modules working together, but this errors (a bug??) destroys our
dreams of success :)
Here is the complete log:
0(2614) DEBUG: db_postgres [km_pg_con.c:72]: opening connection:
postgres://xxxx:xxxx@192.168.190.150:5432/kamailio
0(2614) DEBUG: db_postgres [km_pg_con.c:80]: PQsetdbLogin(0x8702520)
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): permissions
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): ldap
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): alias_db
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): domain
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): presence
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): presence_xml
0(2614) DEBUG: presence_xml [presence_xml.c:300]: [-127] pid [2614]
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): nathelper
0(2614) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child
(-127): mediaproxy
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
mi_fifo
1(2615) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (1): tm
1(2615) DEBUG: tm [callid.c:131]: DEBUG: callid:
'5c94ff7d-2615(a)192.168.190.185'
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
avpops
1(2615) DEBUG: <core> [db.c:294]: connection 0x82a7358 found in pool
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
usrloc
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
registrar
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
uri_db
1(2615) DEBUG: <core> [db.c:294]: connection 0x82a7408 found in pool
1(2615) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (1): ctl
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1): acc
1(2615) DEBUG: <core> [db.c:294]: connection 0x82bc668 found in pool
1(2615) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (1):
drouting
1(2615) DEBUG: <core> [db.c:294]: connection 0x82bc910 found in pool
1(2615) DEBUG: db_postgres [km_dbase.c:149]: 0x82bc8f8
PQsendQuery(select gwid,address,strip,pri_prefix,type,attrs from
dr_gateways )
1(2615) DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result
set at 0x82a74e8
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
mi_fifo
2(2616) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (2): tm
2(2616) DEBUG: tm [callid.c:131]: DEBUG: callid:
'5c94ff7d-2616(a)192.168.190.185'
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
avpops
2(2616) DEBUG: <core> [db.c:294]: connection 0x82a7358 found in pool
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
usrloc
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
registrar
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
uri_db
2(2616) DEBUG: <core> [db.c:294]: connection 0x82a7408 found in pool
2(2616) DEBUG: <core> [sr_module.c:791]: DEBUG: init_mod_child (2): ctl
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2): acc
2(2616) DEBUG: <core> [db.c:294]: connection 0x82bc668 found in pool
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
drouting
2(2616) DEBUG: <core> [db.c:294]: connection 0x82bc910 found in pool
2(2616) DEBUG: <core> [sr_module.c:807]: DEBUG: init_mod_child (2):
permissions
2(2616) DEBUG: <core> [db.c:294]: connection 0x82a7500 found in pool
2(2616) DEBUG: db_postgres [km_val.c:158]: PQescapeStringConn: in: 7
chars, out: 7 chars
2(2616) DEBUG: db_postgres [km_dbase.c:149]: 0x82a74e8
PQsendQuery(select table_version from version where table_name='trusted')
2(2616) 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(2616) DEBUG: db_postgres [km_dbase.c:403]: 0x82a74e8
PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x870c010)
2(2616) DEBUG: db_postgres [km_res.c:108]: 6 columns returned from
the query
2(2616) DEBUG: <core> [db_res.c:153]: allocate 24 bytes for result
names at 0x82a75c0
2(2616) DEBUG: <core> [db_res.c:163]: allocate 24 bytes for result
types at 0x82a75e0
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[0] at 0x82a7600
2(2616) DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0x82a7600)[0]=[gwid]
2(2616) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[1] at 0x82a7610
2(2616) DEBUG: db_postgres [km_res.c:133]:
RES_NAMES(0x82a7610)[1]=[address]
2(2616) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[2] at 0x82a7620
2(2616) DEBUG: db_postgres [km_res.c:133]:
RES_NAMES(0x82a7620)[2]=[strip]
2(2616) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[3] at 0x82a7630
2(2616) DEBUG: db_postgres [km_res.c:133]:
RES_NAMES(0x82a7630)[3]=[pri_prefix]
2(2616) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[4] at 0x82a7640
2(2616) DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0x82a7640)[4]=[type]
2(2616) DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type
2(2616) DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for
RES_NAMES[5] at 0x82a7650
2(2616) DEBUG: db_postgres [km_res.c:133]:
RES_NAMES(0x82a7650)[5]=[attrs]
2(2616) DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type
2(2616) DEBUG: db_postgres [km_res.c:222]: allocate for 6 columns 24
bytes in row buffer at 0x82a7660
2(2616) DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at
0x82a7680
2(2616) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,0)=[1]
2(2616) DEBUG: db_postgres [km_res.c:251]: [0][0] Column[gwid]=[1]
2(2616) DEBUG: db_postgres [km_res.c:242]:
PQgetvalue(0x82a74e8,0,1)=[192.168.190.150]
2(2616) DEBUG: db_postgres [km_res.c:251]: [0][1]
Column[address]=[192.168.190.150]
2(2616) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,2)=[2]
2(2616) DEBUG: db_postgres [km_res.c:251]: [0][2] Column[strip]=[2]
2(2616) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,3)=[88]
2(2616) DEBUG: db_postgres [km_res.c:251]: [0][3] Column[pri_prefix]=[88]
2(2616) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,4)=[0]
2(2616) DEBUG: db_postgres [km_res.c:251]: [0][4] Column[type]=[0]
2(2616) DEBUG: db_postgres [km_res.c:242]: PQgetvalue(0x82a74e8,0,5)=[]
2(2616) DEBUG: <core> [db_row.c:119]: allocate 120 bytes for row
values at 0x82c17f8
2(2616) DEBUG: <core> [db_val.c:73]: converting INT [1]
2(2616) DEBUG: <core> [db_val.c:117]: converting STRING [192.168.190.150]
2(2616) DEBUG: <core> [db_val.c:127]: allocate 16 bytes memory for
STRING at 0x82a7690 2(2616) DEBUG: <core> [db_val.c:73]: converting
INT [2]
2(2616) DEBUG: <core> [db_val.c:117]: converting STRING [88]
2(2616) DEBUG: <core> [db_val.c:127]: allocate 3 bytes memory for
STRING at 0x82c1878 2(2616) DEBUG: <core> [db_val.c:73]: converting
INT [0]
2(2616) DEBUG: <core> [db_val.c:56]: converting NULL value 2(2616)
DEBUG: db_postgres [km_res.c:266]: freeing row buffer at 0x82a7660
2(2616) DEBUG: db_postgres [km_dbase.c:302]: PQclear(0x870c010)
result set
2(2616) DEBUG: <core> [db_res.c:79]: freeing 6 columns
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82a7600
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82a7610
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82a7620
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[3] at 0x82a7630
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[4] at 0x82a7640
2(2616) DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[5] at 0x82a7650
2(2616) DEBUG: <core> [db_res.c:92]: freeing result names at 0x82a75c0
2(2616) DEBUG: <core> [db_res.c:97]: freeing result types at 0x82a75e0
2(2616) DEBUG: <core> [db_res.c:52]: freeing 1 rows
2(2616) DEBUG: <core> [db_row.c:68]: free VAL_STRING[1]
'192.168.190.150' at 0x82a7690
2(2616) DEBUG: <core> [db_row.c:68]: free VAL_STRING[3] '88' at 0x82c1878
2(2616) DEBUG: <core> [db_row.c:97]: freeing row values at 0x82c17f8
2(2616) DEBUG: <core> [db_res.c:60]: freeing rows at 0x82a7680
2(2616) DEBUG: <core> [db_res.c:134]: freeing result set at 0x82a7598
2(2616) ERROR: <core> [db.c:408]: invalid version 1 for table trusted
found, expected 5 (check table structure and table "version")
2(2616) ERROR: permissions [trusted.c:249]: error during table
version check.
2(2616) DEBUG: <core> [db_pool.c:97]: connection still kept in the pool
2(2616) ERROR: <core> [sr_module.c:811]: init_mod_child(): Error
while initializing module permissions
2(2616) ERROR: <core> [pt.c:332]: ERROR: fork_process(): init_child
failed for process 2, pid 2616, ""
2(2616) : <core> [main.c:1439]: main_loop: Cannot fork
Here is a snapshot of the configuration:
#!ifdef WITH_SQL
loadmodule "db_postgres.so"
#loadmodule "sqlops"
#!endif
loadmodule "mi_fifo.so"
loadmodule "kex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "avpops.so"
loadmodule "maxfwd.so"
loadmodule "usrloc.so"
loadmodule "registrar.so"
loadmodule "textops.so"
loadmodule "uri_db.so"
loadmodule "siputils.so"
loadmodule "xlog.so"
loadmodule "sanity.so"
loadmodule "ctl.so"
loadmodule "mi_rpc.so"
loadmodule "acc.so"
loadmodule "enum.so"
# ----------------- drouting module -------------------------------
loadmodule "drouting.so"
# ----------------- permissions module -------------------------------
loadmodule "permissions.so"
...
...
...
# ----- drouting params -----
modparam("drouting", "sort_order", 0)
modparam("drouting", "use_domain", 1)
modparam("drouting","db_url",
"postgres://XXXX:YYYY@192.168.190.150:5432/kamailio")
# ------ permissions ----
modparam("permissions", "default_allow_file",
"/usr/local/etc/kamailio/permissions.allow")
modparam("permissions", "default_deny_file",
"/usr/local/etc/kamailio/permissions.deny")
modparam("permissions", "db_url",
"postgres://XXXX:YYYY@192.168.190.150:5432/kamailio")
#modparam("permissions", "db_mode", 1)
Commentingloadmodule "drouting.so" orloadmodule "permissions.so"(and
modparam) lets all things work perfectly. Together, the error rise :(
Thanks a Lot,
Giorgio Maria Santini
_______________________________________________
sr-dev mailing list
sr-dev(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla
Kamailio (OpenSER) Advanced Training
Jan 24-26, 2011, Irvine, CA, USA
http://www.asipto.com