[sr-dev] [kamailio 3.1.0]PostgreSQL + Permissions + DRouting: Concurrent db access fault on returning result set

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


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 at 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 at 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 at 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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-dev/attachments/20101130/4d662932/attachment-0001.htm>


More information about the sr-dev mailing list