[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