27 Aug
2011
27 Aug
'11
10:14 p.m.
Hi,
I am using the git version of kamailio, and i am experiencing problem
This message is repeated in log with all kind of mysql query
(insert/delete/select)
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you can't
run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:103]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:570]: db_query failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you can't
run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:186]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[ucontact.c:513]: inserting contact in db failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:474]: failed to insert in database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: registrar
[save.c:430]: failed to insert contact
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you can't
run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:242]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:426]: failed to delete from database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:896]: DB delete failed
I am using stable debian so db_mysql.so linked with libmysqlclient.so.16
I read mysql doc and it is saying about this error the following:
"Commands out of sync; you can't run this command now"
http://dev.mysql.com/doc/refman/5.0/en/commands-out-of-sync.html
So this problem cause it that not freed the last result.
Only one assumption:
Could it related to this change:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commitdiff;h=df…
Any help appreciated.
Regards,
Misi
28 Aug
28 Aug
9:25 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello,
thanks for investigation - this is only on current devel version. For
quick try, can you revert the patch and try? Practically, you have to
replace:
while( mysql_more_results(CON_CONNECTION(_h)) &&
mysql_next_result(CON_CONNECTION(_h)) > 0 ) {
with:
while( mysql_next_result( CON_CONNECTION(_h) ) > 0 ) {
two times in modules/db_mysql/km_dbase.c.
At this moment I do not have a good internet connection to be able to
investigate more and search into documentation of mysql for
mysql_more_results(). It looks like the result was not freed indeed.
Another case for such error is when a mysql connection is shared between
many processes and the access to it is not synchronized -- there were no
changes afaik that could introduce such situation.
Thanks,
Daniel
On 8/27/11 10:14 PM, MÉSZÁROS Mihály wrote:
Hi,
I am using the git version of kamailio, and i am experiencing problem
This message is repeated in log with all kind of mysql query
(insert/delete/select)
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:103]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:570]: db_query failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:186]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[ucontact.c:513]: inserting contact in db failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:474]: failed to insert in database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: registrar
[save.c:430]: failed to insert contact
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:242]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:426]: failed to delete from database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:896]: DB delete failed
I am using stable debian so db_mysql.so linked with libmysqlclient.so.16
I read mysql doc and it is saying about this error the following:
"Commands out of sync; you can't run this command now"
http://dev.mysql.com/doc/refman/5.0/en/commands-out-of-sync.html
So this problem cause it that not freed the last result.
Only one assumption:
Could it related to this change:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commitdiff;h=df…
Any help appreciated.
Regards,
Misi
_______________________________________________
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 -- http://www.asipto.com
Kamailio Advanced Training, Oct 10-13, Berlin: http://asipto.com/u/kat
http://linkedin.com/in/miconda -- http://twitter.com/miconda
10:56 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello,
After reverting back to original this commit, the problem is still
occurring. :(
So not this commit is causing the problem. :(
Misi
2011-08-28 09:25 keltezéssel, Daniel-Constantin Mierla írta:
Hello,
thanks for investigation - this is only on current devel version. For
quick try, can you revert the patch and try? Practically, you have to
replace:
while( mysql_more_results(CON_CONNECTION(_h)) &&
mysql_next_result(CON_CONNECTION(_h)) > 0 ) {
with:
while( mysql_next_result( CON_CONNECTION(_h) ) > 0 ) {
two times in modules/db_mysql/km_dbase.c.
At this moment I do not have a good internet connection to be able to
investigate more and search into documentation of mysql for
mysql_more_results(). It looks like the result was not freed indeed.
Another case for such error is when a mysql connection is shared
between many processes and the access to it is not synchronized --
there were no changes afaik that could introduce such situation.
Thanks,
Daniel
On 8/27/11 10:14 PM, MÉSZÁROS Mihály wrote:
Hi,
I am using the git version of kamailio, and i am experiencing problem
This message is repeated in log with all kind of mysql query
(insert/delete/select)
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:103]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:570]: db_query failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:186]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[ucontact.c:513]: inserting contact in db failed
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:474]: failed to insert in database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: registrar
[save.c:430]: failed to insert contact
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: db_mysql
[km_dbase.c:124]: driver error on query: Commands out of sync; you
can't run this command now
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: <core>
[db_query.c:242]: error while submitting query
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[urecord.c:426]: failed to delete from database
Aug 27 22:04:05 hal /usr/sbin/kamailio[25681]: ERROR: usrloc
[udomain.c:896]: DB delete failed
I am using stable debian so db_mysql.so linked with libmysqlclient.so.16
I read mysql doc and it is saying about this error the following:
"Commands out of sync; you can't run this command now"
http://dev.mysql.com/doc/refman/5.0/en/commands-out-of-sync.html
So this problem cause it that not freed the last result.
Only one assumption:
Could it related to this change:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commitdiff;h=df…
Any help appreciated.
Regards,
Misi
_______________________________________________
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
10:53 a.m.
On Saturday 27 August 2011, MÉSZÁROS Mihály wrote:
I am using the git version of kamailio, and i am
experiencing problem
This message is repeated in log with all kind of mysql query
(insert/delete/select)
http://dev.mysql.com/doc/refman/5.0/en/commands-out-of-sync.html
Can you try to reproduce with attached patch and mail the line with the
mysql error as well as the last couple of loglines with submit_query and
store_result having the same con: as the failing query.
You can anonymize the queries as long as it is still deducable which module
submitted the query.
Also send list of modules using the database please.
Only one assumption:
Could it related to this change:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commitdiff;h=
dfc2834223b7c6b2e799da5a0876b8096cfdae5e
That one can be safely reverted if you don't use the PV $sqlrows. But please
do above test without reverting this.
--
Alex Hermann
12:50 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi
I attached the log file.
If you need detailed log/higher log level, then please let me know.
OK I applied your patch to the git version of km_dbase.c
Thanks,
Misi
Can you try to reproduce with attached patch and mail
the line with the
mysql error as well as the last couple of loglines with submit_query and
store_result having the same con: as the failing query.
You can anonymize the queries as long as it is still deducable which module
submitted the query.
Also send list of modules using the database please.
Modules what i am using
loadmodule "db_mysql.so"
loadmodule "mi_fifo.so"
loadmodule "kex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "maxfwd.so"
loadmodule "usrloc.so"
loadmodule "registrar.so"
loadmodule "textops.so"
loadmodule "siputils.so"
loadmodule "xlog.so"
loadmodule "sanity.so"
loadmodule "ctl.so"
loadmodule "mi_rpc.so"
loadmodule "acc.so"
loadmodule "auth.so"
loadmodule "auth_db.so"
loadmodule "alias_db.so"
loadmodule "presence.so"
loadmodule "presence_xml.so"
loadmodule "tls.so"
loadmodule "htable.so"
loadmodule "pike.so"
loadmodule "siptrace.so"
loadmodule "lcr.so"
loadmodule "enum.so"
loadmodule "cfg_rpc.so"
modparam("usrloc", "db_mode", 3)
Only one assumption:
Could it related to this change:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commitdiff;h=
dfc2834223b7c6b2e799da5a0876b8096cfdae5e
That one can be safely reverted if you
don't use the PV $sqlrows. But please
do above test without reverting this.
1:45 p.m.
On Sunday 28 August 2011, MÉSZÁROS Mihály wrote:
I attached the log file.
If you need detailed log/higher log level, then please let me know.
usrloc seems to be using the same connection from multiple processes:
pid: 18389 and 18391, connection: 0xb7387d5c
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='mutf-hd' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='ppke-vjk' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:177]:
store_result: con: 0xb7387d5c table: location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: update location set
expires='2011-08-28 12:45:10',q=-1.00
,cseq=2,flags=0,cflags=0,user_agent='Polycom HDX 8000 HD (Release -
3.0.2.1-17007)',received=NULL,path=NULL,socket='tcp:195.111.192.7:5060',methods=24575,last_modified='2011-08-28
12:40:10' where
username='mutf-hd' AND
contact='sip:mutf-hd@193.225.216.28:5060;transport=tcp' AND
callid='3533311123-1752'
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:177]:
store_result: con: 0xb7387d5c table: location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: insert into location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='de-tek-hpc' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: ERROR: db_mysql [km_dbase.c:131]: driver
error on query: Commands out of sync; you can't run this command now
It probably needs a fix like below because mod_init has also created a db
connection which is inherited by at least one child and ul_dbh is not 0 anymore.
That process needs to be excluded from opening a database connection, all
other childs need to open their own DB connection. I just don't know what
rank mod_init is run as and thus don't know which process to exclude. Maybe
some other dev can jump in.
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index b3a9499..ca50b01 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -378,7 +378,7 @@ static int child_init(int _rank)
break;
}
- if (!ul_dbh)
+ if (rank != PROC_MAIN)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database connection */
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n", _rank);
29 Aug
29 Aug
11:51 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi,
Your patch didn't work for me. The kamailio didn't start if i use "if (
_rank != PROC_MAIN)"
So i commented out, both if statement, and now "out of sync problem
disappeared"
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -355,8 +355,11 @@ static int child_init(int _rank)
break;
}
- if (!ul_dbh)
+LM_INFO("before misi ul_mod con: %p rank: %d",ul_dbh,_rank);
+// if (!ul_dbh)
+// if ( _rank != PROC_MAIN)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+LM_INFO("after misi ul_mod con: %p rank: %d",ul_dbh,_rank);
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n",
_rank);
return -1;
BUT
I am experiencing that in usrloc module, still more then one worker
process share the same sql connection:
Aug 29 11:16:04 hal /usr/sbin/kamailio[21521]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21523]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 3
Aug 29 11:16:04 hal /usr/sbin/kamailio[21525]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 5
Aug 29 11:16:04 hal /usr/sbin/kamailio[21521]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21524]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 4
Aug 29 11:16:04 hal /usr/sbin/kamailio[21527]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 7
Aug 29 11:16:04 hal /usr/sbin/kamailio[21522]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 2
Aug 29 11:16:04 hal /usr/sbin/kamailio[21526]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 6
Aug 29 11:16:04 hal /usr/sbin/kamailio[21530]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: -1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21508]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 0
Aug 29 11:16:04 hal /usr/sbin/kamailio[21528]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: 8
Aug 29 11:16:04 hal /usr/sbin/kamailio[21523]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 3
Aug 29 11:16:04 hal /usr/sbin/kamailio[21524]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 4
Aug 29 11:16:04 hal /usr/sbin/kamailio[21525]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 5
Aug 29 11:16:04 hal /usr/sbin/kamailio[21528]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 8
Aug 29 11:16:04 hal /usr/sbin/kamailio[21522]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 2
Aug 29 11:16:04 hal /usr/sbin/kamailio[21526]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 6
Aug 29 11:16:04 hal /usr/sbin/kamailio[21529]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: (nil) rank: -1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21527]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 7
Aug 29 11:16:04 hal /usr/sbin/kamailio[21508]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: 0
Aug 29 11:16:04 hal /usr/sbin/kamailio[21530]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: -1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21529]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb7286d5c rank: -1
Aug 29 11:16:04 hal /usr/sbin/kamailio[21536]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: 0xb7286d5c rank: 12
Aug 29 11:16:04 hal /usr/sbin/kamailio[21534]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: 0xb7286d5c rank: 10
Aug 29 11:16:04 hal /usr/sbin/kamailio[21533]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: 0xb7286d5c rank: 9
Aug 29 11:16:04 hal /usr/sbin/kamailio[21533]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb72ab174 rank: 9
Aug 29 11:16:04 hal /usr/sbin/kamailio[21535]: INFO: usrloc
[ul_mod.c:358]: before misi ul_mod con: 0xb7286d5c rank: 11
Aug 29 11:16:04 hal /usr/sbin/kamailio[21534]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb72ab174 rank: 10
Aug 29 11:16:04 hal /usr/sbin/kamailio[21536]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb72ab174 rank: 12
Aug 29 11:16:04 hal /usr/sbin/kamailio[21535]: INFO: usrloc
[ul_mod.c:363]: after misi ul_mod con: 0xb72ab174 rank: 11
Misi
2011-08-28 13:45 keltezéssel, Alex Hermann írta:
On Sunday 28 August 2011, MÉSZÁROS Mihály wrote:
I attached the log file.
If you need detailed log/higher log level, then please let me know.
usrloc seems
to be using the same connection from multiple processes:
pid: 18389 and 18391, connection: 0xb7387d5c
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='mutf-hd' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='ppke-vjk' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:177]:
store_result: con: 0xb7387d5c table: location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: update location set
expires='2011-08-28 12:45:10',q=-1.00
,cseq=2,flags=0,cflags=0,user_agent='Polycom HDX 8000 HD (Release -
3.0.2.1-17007)',received=NULL,path=NULL,socket='tcp:195.111.192.7:5060',methods=24575,last_modified='2011-08-28
12:40:10' where
username='mutf-hd' AND
contact='sip:mutf-hd@193.225.216.28:5060;transport=tcp' AND
callid='3533311123-1752'
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:177]:
store_result: con: 0xb7387d5c table: location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18391]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: insert into location
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: INFO: db_mysql [km_dbase.c:83]:
submit_query: con: 0xb7387d5c table: location query: select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='de-tek-hpc' order by q
Aug 28 12:40:10 hal /usr/sbin/kamailio[18389]: ERROR: db_mysql [km_dbase.c:131]: driver
error on query: Commands out of sync; you can't run this command now
It probably needs a fix like below because mod_init has also created a db
connection which is inherited by at least one child and ul_dbh is not 0 anymore.
That process needs to be excluded from opening a database connection, all
other childs need to open their own DB connection. I just don't know what
rank mod_init is run as and thus don't know which process to exclude. Maybe
some other dev can jump in.
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index b3a9499..ca50b01 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -378,7 +378,7 @@ static int child_init(int _rank)
break;
}
- if (!ul_dbh)
+ if (rank != PROC_MAIN)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database connection */
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n", _rank);
1:09 p.m.
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
Your patch didn't work for me. The kamailio
didn't start if i use "if (
_rank != PROC_MAIN)"
So i commented out, both if statement, and now "out of sync problem
disappeared"
That should do the trick, but it might be possible to create a
zombie
connection this way. I don't know how the initialization of modules works
exactly, so I can't really help you with this.
BUT
I am experiencing that in usrloc module, still more then one worker
process share the same sql connection:
That is weird. AFAIK, connections can't be shared between processes, there
seems to be no locking/semaphores/whatever to protect against simultaneous
access.
Maybe you got lucky in your tests and just didn't have enough traffic to hit
the simultaneous access problem (yet).
I'm out of ideas here, sorry.
--
Greetings,
Alex Hermann
1:44 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi,
Thank You Alex for your help!
Others? Daniel? Can You please help me?
Thanks,
Misi
2011-08-29 13:09 keltezéssel, Alex Hermann írta:
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
Your patch didn't work for me. The kamailio
didn't start if i use "if (
_rank != PROC_MAIN)"
So i commented out, both if statement, and now "out of sync problem
disappeared"
That should do the trick, but it might be possible to create a
zombie
connection this way. I don't know how the initialization of modules works
exactly, so I can't really help you with this.
BUT
I am experiencing that in usrloc module, still more then one worker
process share the same sql connection:
That is weird. AFAIK, connections can't
be shared between processes, there
seems to be no locking/semaphores/whatever to protect against simultaneous
access.
Maybe you got lucky in your tests and just didn't have enough traffic to hit
the simultaneous access problem (yet).
I'm out of ideas here, sorry.
2 p.m.
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
I am experiencing that in usrloc module, still more
then one worker
process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of the
childs, they have the same memory layout and a very high chance of allocating
the same address (in their own address space) for the connection struct.
Attached patch should give a thread_id truly unique per connection. If you're
able to find multiple processes using the same thread_id, you've found the
cause.
--
Greetings,
Alex Hermann
5:12 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi,
I find the following:
grep "con: 17212"
Aug 29 17:05:27 hal /usr/sbin/kamailio[24001]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
insert into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
) values
('de-tek-hpc','sip:de-tek-hpc@193.6.138.201:5060;transport=tcp','2011-08-29
17:10:27',-1.00 ,'966616894-1736',2,0,0,'Polycom HDX 8000 HD
(Release -
3.0.2.1-17007)',NULL,NULL,'tcp:195.111.192.7:5060',24575,'2011-08-29
17:05:27')
Aug 29 17:05:27 hal /usr/sbin/kamailio[24001]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
delete from location where username='de-tek-hpc'
Aug 29 17:05:30 hal /usr/sbin/kamailio[24002]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='me-iit' order by q
Aug 29 17:05:30 hal /usr/sbin/kamailio[24002]: INFO: db_mysql
[km_dbase.c:175]: store_result: con: 17212 table: location
Aug 29 17:05:30 hal /usr/sbin/kamailio[24002]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
update location set expires='2011-08-29 17:10:30',q=-1.00
,cseq=3,flags=0,cflags=0,user_agent='Polycom HDX 8000 HD (Release -
3.0.2.1-17007)',received=NULL,path=NULL,socket='tcp:195.111.192.7:5060',methods=NULL,last_modified='2011-08-29
17:05:30' where username='me-iit' AND
contact='sip:me-iit@193.6.5.220:5060;transport=tcp' AND
callid='385875516-1729'
Aug 29 17:05:37 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='de-tek-hpc' order by q
Aug 29 17:05:37 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
insert into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
) values
('de-tek-hpc','sip:de-tek-hpc@193.6.138.201:5060;transport=tcp','2011-08-29
17:10:37',-1.00 ,'976693266-1736',2,0,0,'Polycom HDX 8000 HD
(Release -
3.0.2.1-17007)',NULL,NULL,'tcp:195.111.192.7:5060',24575,'2011-08-29
17:05:37')
Aug 29 17:05:37 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
delete from location where username='de-tek-hpc'
Aug 29 17:05:47 hal /usr/sbin/kamailio[24004]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
select
contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='de-tek-hpc' order by q
Aug 29 17:05:47 hal /usr/sbin/kamailio[24004]: INFO: db_mysql
[km_dbase.c:175]: store_result: con: 17212 table: location
Aug 29 17:05:47 hal /usr/sbin/kamailio[24004]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
update location set expires='2011-08-29 17:10:47',q=-1.00
,cseq=2,flags=0,cflags=0,user_agent='Polycom HDX 8000 HD (Release -
3.0.2.1-17007)',received=NULL,path=NULL,socket='tcp:195.111.192.7:5060',methods=24575,last_modified='2011-08-29
17:05:47' where username='de-tek-hpc' AND
contact='sip:de-tek-hpc@193.6.138.201:5060;transport=tcp' AND
callid='385871516-1736'
a full log piece:
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
select c
ontact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
from location where username='ppke-vjk' ord
er by q
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: db_mysql
[km_dbase.c:129]: driver error on query: Commands out of sync; you can't run
this command now
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: <core>
[db_query.c:103]: error while submitting query
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: usrloc
[udomain.c:570]: db_query failed
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
insert i
nto location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified
) values ('ppke-vjk
','sip:ppke-vjk@193.225.195.133:5061;transport=tls','2011-08-29
17:15:16',-1.00 ,'1254092986-1737',2,0,0,'Polycom HDX 8000 HD
(Release
- 3.0.2.1-17007)',NULL,NULL,'tls:195.111.192.7:5061',24575,'2011-08-29
17:10:16')
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: db_mysql
[km_dbase.c:129]: driver error on query: Commands out of sync; you can't run
this command now
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: <core>
[db_query.c:186]: error while submitting query
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: usrloc
[ucontact.c:513]: inserting contact in db failed
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: usrloc
[urecord.c:474]: failed to insert in database
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: registrar
[save.c:430]: failed to insert contact
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: INFO: db_mysql
[km_dbase.c:83]: submit_query: con: 17212 table: location query:
delete f
rom location where username='ppke-vjk'
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: db_mysql
[km_dbase.c:129]: driver error on query: Commands out of sync; you can't run
this command now
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: <core>
[db_query.c:242]: error while submitting query
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: usrloc
[urecord.c:426]: failed to delete from database
Aug 29 17:10:16 hal /usr/sbin/kamailio[24003]: ERROR: usrloc
[udomain.c:896]: DB delete failed
Thanks,
Misi
(I don't know may be matter, and i didn't mentioned yet, that i am
running multiple kamaillio instance on different ip address but on the
same machine.)
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
I am experiencing that in usrloc module, still
more then one worker
process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of the
childs, they have the same memory layout and a very high chance of allocating
the same address (in their own address space) for the connection struct.
Attached patch should give a thread_id truly unique per connection. If you're
able to find multiple processes using the same thread_id, you've found the
cause.
10:44 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi,
With this debug i can see that all tcp connections are using the same db
connection(18549).
Any suggestion highly appreciated!
Please read collected information on the bottom of my email.
Misi
--- a/modules_k/usrloc/Makefile
+++ b/modules_k/usrloc/Makefile
@@ -8,12 +8,16 @@
include ../../Makefile.defs
auto_gen=
NAME=usrloc.so
-LIBS=
+LIBS=-L/usr/lib/mysql -L/usr/lib -L/usr/lib/mysql -lmysqlclient -lz
+#LIBS=
DEFS+=-DOPENSER_MOD_INTERFACE
+
SERLIBPATH=../../lib
SER_LIBS+=$(SERLIBPATH)/kmi/kmi
SER_LIBS+=$(SERLIBPATH)/srdb1/srdb1
SER_LIBS+=$(SERLIBPATH)/kcore/kcore
+
+
include ../../Makefile.modules
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index c3fe26a..9ff1a4c 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -50,6 +50,10 @@
* over a API. A main user of this API is the registrar module.
* \see registrar
*/
+#include <sys/types.h>
+#include <unistd.h>
+#include <mysql/mysql.h>
+#include "../../modules/db_mysql/km_my_con.h"
#include <stdio.h>
#include "ul_mod.h"
@@ -355,8 +359,15 @@ static int child_init(int _rank)
break;
}
+ LM_INFO("misi before mysql: rank: %d pid: %d\n",
+ _rank,getpid());
+
if (!ul_dbh)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+
+ LM_INFO("misi after mysql: con: %ld rank: %d pid: %d\n",
+ mysql_thread_id(((struct
my_con*)(ul_dbh->tail))->con),_rank,getpid());
+
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n",
_rank);
return -1;
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18543 rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18544 rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18545 rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18548 rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18547 rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18546 rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18550 rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18554 rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 12 pid: 8306
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 12 pid: 8306
hal:/home/misi# kamctl-vvc ps
database engine 'MYSQL' loaded
Control engine 'FIFO' loaded
entering fifo_cmd ps
Process:: ID=0 PID=8256 Type=attendant
Process:: ID=1 PID=8275 Type=udp receiver child=0 sock=195.111.192.7:5060
Process:: ID=2 PID=8285 Type=udp receiver child=1 sock=195.111.192.7:5060
Process:: ID=3 PID=8288 Type=udp receiver child=2 sock=195.111.192.7:5060
Process:: ID=4 PID=8291 Type=udp receiver child=3 sock=195.111.192.7:5060
Process:: ID=5 PID=8294 Type=udp receiver child=0
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=6 PID=8296 Type=udp receiver child=1
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=7 PID=8297 Type=udp receiver child=2
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=8 PID=8298 Type=udp receiver child=3
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=9 PID=8299 Type=slow timer
Process:: ID=10 PID=8300 Type=timer
Process:: ID=11 PID=8301 Type=MI FIFO
Process:: ID=12 PID=8302 Type=ctl handler
Process:: ID=13 PID=8303 Type=tcp receiver child=0
Process:: ID=14 PID=8304 Type=tcp receiver child=1
Process:: ID=15 PID=8305 Type=tcp receiver child=2
Process:: ID=16 PID=8306 Type=tcp receiver child=3
Process:: ID=17 PID=8307 Type=tcp main process
FIFO command was:
:ps:openser_receiver_9501
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
I am experiencing that in usrloc module, still
more then one worker
process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of the
childs, they have the same memory layout and a very high chance of allocating
the same address (in their own address space) for the connection struct.
Attached patch should give a thread_id truly unique per connection. If you're
able to find multiple processes using the same thread_id, you've found the
cause.
30 Aug
30 Aug
9:58 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
So the problem is that rank: 0 PROC_MAIN process initialitzed and have
db connection with mod_child_init,
and after rank 0 PROC_MAIN process is forking for tcp workers it
contains the initialized ul_dbh and no unique connection created for the
tcp workers.
Any suggestion, solution?
Thanks,
Misi
2011-08-29 22:44 keltezéssel, MÉSZÁROS Mihály írta:
Hi,
With this debug i can see that all tcp connections are using the same
db connection(18549).
Any suggestion highly appreciated!
Please read collected information on the bottom of my email.
Misi
--- a/modules_k/usrloc/Makefile
+++ b/modules_k/usrloc/Makefile
@@ -8,12 +8,16 @@
include ../../Makefile.defs
auto_gen=
NAME=usrloc.so
-LIBS=
+LIBS=-L/usr/lib/mysql -L/usr/lib -L/usr/lib/mysql -lmysqlclient -lz
+#LIBS=
DEFS+=-DOPENSER_MOD_INTERFACE
+
SERLIBPATH=../../lib
SER_LIBS+=$(SERLIBPATH)/kmi/kmi
SER_LIBS+=$(SERLIBPATH)/srdb1/srdb1
SER_LIBS+=$(SERLIBPATH)/kcore/kcore
+
+
include ../../Makefile.modules
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index c3fe26a..9ff1a4c 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -50,6 +50,10 @@
* over a API. A main user of this API is the registrar module.
* \see registrar
*/
+#include <sys/types.h>
+#include <unistd.h>
+#include <mysql/mysql.h>
+#include "../../modules/db_mysql/km_my_con.h"
#include <stdio.h>
#include "ul_mod.h"
@@ -355,8 +359,15 @@ static int child_init(int _rank)
break;
}
+ LM_INFO("misi before mysql: rank: %d pid: %d\n",
+ _rank,getpid());
+
if (!ul_dbh)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+
+ LM_INFO("misi after mysql: con: %ld rank: %d pid: %d\n",
+ mysql_thread_id(((struct
my_con*)(ul_dbh->tail))->con),_rank,getpid());
+
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n",
_rank);
return -1;
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18543 rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18544 rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18545 rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18548 rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18547 rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18546 rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18550 rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18554 rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 12 pid: 8306
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 12 pid: 8306
hal:/home/misi# kamctl-vvc ps
database engine 'MYSQL' loaded
Control engine 'FIFO' loaded
entering fifo_cmd ps
Process:: ID=0 PID=8256 Type=attendant
Process:: ID=1 PID=8275 Type=udp receiver child=0
sock=195.111.192.7:5060
Process:: ID=2 PID=8285 Type=udp receiver child=1
sock=195.111.192.7:5060
Process:: ID=3 PID=8288 Type=udp receiver child=2
sock=195.111.192.7:5060
Process:: ID=4 PID=8291 Type=udp receiver child=3
sock=195.111.192.7:5060
Process:: ID=5 PID=8294 Type=udp receiver child=0
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=6 PID=8296 Type=udp receiver child=1
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=7 PID=8297 Type=udp receiver child=2
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=8 PID=8298 Type=udp receiver child=3
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=9 PID=8299 Type=slow timer
Process:: ID=10 PID=8300 Type=timer
Process:: ID=11 PID=8301 Type=MI FIFO
Process:: ID=12 PID=8302 Type=ctl handler
Process:: ID=13 PID=8303 Type=tcp receiver child=0
Process:: ID=14 PID=8304 Type=tcp receiver child=1
Process:: ID=15 PID=8305 Type=tcp receiver child=2
Process:: ID=16 PID=8306 Type=tcp receiver child=3
Process:: ID=17 PID=8307 Type=tcp main process
FIFO command was:
:ps:openser_receiver_9501
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
I am experiencing that in usrloc module, still
more then one worker
process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of the
childs, they have the same memory layout and a very high chance of
allocating
the same address (in their own address space) for the connection struct.
Attached patch should give a thread_id truly unique per connection.
If you're
able to find multiple processes using the same thread_id, you've
found the
cause.
31 Aug
31 Aug
9:43 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello,
thanks for investigating further. I just committed a patch, pull the
latest GIT and try again. Let me know if works ok.
Thanks,
Daniel
On 8/30/11 9:58 AM, MÉSZÁROS Mihály wrote:
So the problem is that rank: 0 PROC_MAIN process
initialitzed and have
db connection with mod_child_init,
and after rank 0 PROC_MAIN process is forking for tcp workers it
contains the initialized ul_dbh and no unique connection created for
the tcp workers.
Any suggestion, solution?
Thanks,
Misi
2011-08-29 22:44 keltezéssel, MÉSZÁROS Mihály írta:
--
Daniel-Constantin Mierla -- http://www.asipto.com
Kamailio Advanced Training, Oct 10-13, Berlin: http://asipto.com/u/kat
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi,
With this debug i can see that all tcp connections are using the same
db connection(18549).
Any suggestion highly appreciated!
Please read collected information on the bottom of my email.
Misi
--- a/modules_k/usrloc/Makefile
+++ b/modules_k/usrloc/Makefile
@@ -8,12 +8,16 @@
include ../../Makefile.defs
auto_gen=
NAME=usrloc.so
-LIBS=
+LIBS=-L/usr/lib/mysql -L/usr/lib -L/usr/lib/mysql -lmysqlclient -lz
+#LIBS=
DEFS+=-DOPENSER_MOD_INTERFACE
+
SERLIBPATH=../../lib
SER_LIBS+=$(SERLIBPATH)/kmi/kmi
SER_LIBS+=$(SERLIBPATH)/srdb1/srdb1
SER_LIBS+=$(SERLIBPATH)/kcore/kcore
+
+
include ../../Makefile.modules
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index c3fe26a..9ff1a4c 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -50,6 +50,10 @@
* over a API. A main user of this API is the registrar module.
* \see registrar
*/
+#include <sys/types.h>
+#include <unistd.h>
+#include <mysql/mysql.h>
+#include "../../modules/db_mysql/km_my_con.h"
#include <stdio.h>
#include "ul_mod.h"
@@ -355,8 +359,15 @@ static int child_init(int _rank)
break;
}
+ LM_INFO("misi before mysql: rank: %d pid: %d\n",
+ _rank,getpid());
+
if (!ul_dbh)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+
+ LM_INFO("misi after mysql: con: %ld rank: %d pid: %d\n",
+ mysql_thread_id(((struct
my_con*)(ul_dbh->tail))->con),_rank,getpid());
+
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n",
_rank);
return -1;
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18543 rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18544 rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18545 rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18548 rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18547 rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18546 rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18550 rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18554 rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 12 pid: 8306
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 12 pid: 8306
hal:/home/misi# kamctl-vvc ps
database engine 'MYSQL' loaded
Control engine 'FIFO' loaded
entering fifo_cmd ps
Process:: ID=0 PID=8256 Type=attendant
Process:: ID=1 PID=8275 Type=udp receiver child=0
sock=195.111.192.7:5060
Process:: ID=2 PID=8285 Type=udp receiver child=1
sock=195.111.192.7:5060
Process:: ID=3 PID=8288 Type=udp receiver child=2
sock=195.111.192.7:5060
Process:: ID=4 PID=8291 Type=udp receiver child=3
sock=195.111.192.7:5060
Process:: ID=5 PID=8294 Type=udp receiver child=0
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=6 PID=8296 Type=udp receiver child=1
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=7 PID=8297 Type=udp receiver child=2
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=8 PID=8298 Type=udp receiver child=3
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=9 PID=8299 Type=slow timer
Process:: ID=10 PID=8300 Type=timer
Process:: ID=11 PID=8301 Type=MI FIFO
Process:: ID=12 PID=8302 Type=ctl handler
Process:: ID=13 PID=8303 Type=tcp receiver child=0
Process:: ID=14 PID=8304 Type=tcp receiver child=1
Process:: ID=15 PID=8305 Type=tcp receiver child=2
Process:: ID=16 PID=8306 Type=tcp receiver child=3
Process:: ID=17 PID=8307 Type=tcp main process
FIFO command was:
:ps:openser_receiver_9501
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
_______________________________________________
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 On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
I am experiencing that in usrloc module, still
more then one worker
process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of the
childs, they have the same memory layout and a very high chance of
allocating
the same address (in their own address space) for the connection
struct.
Attached patch should give a thread_id truly unique per connection.
If you're
able to find multiple processes using the same thread_id, you've
found the
cause.
10:49 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hi Daniel,
Thank You for your reply!
- if (!ul_dbh)
- ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+ ul_dbh = ul_dbf.init(&db_url); /* Get a database connection per
child */
Are you sure that it will not cause any problem that rank -1 process in
usrloc database will be initialized twice, and ul_dbh will be overloaded
with new connection?
I guess this will cause problem.
You can see before:
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Thanks,
Misi
2011-08-31 09:43 keltezéssel, Daniel-Constantin Mierla írta:
Hello,
thanks for investigating further. I just committed a patch, pull the
latest GIT and try again. Let me know if works ok.
Thanks,
Daniel
On 8/30/11 9:58 AM, MÉSZÁROS Mihály wrote:
So the problem is that rank: 0 PROC_MAIN process
initialitzed and
have db connection with mod_child_init,
and after rank 0 PROC_MAIN process is forking for tcp workers it
contains the initialized ul_dbh and no unique connection created for
the tcp workers.
Any suggestion, solution?
Thanks,
Misi
2011-08-29 22:44 keltezéssel, MÉSZÁROS Mihály írta:
Hi,
With this debug i can see that all tcp connections are using the
same db connection(18549).
Any suggestion highly appreciated!
Please read collected information on the bottom of my email.
Misi
--- a/modules_k/usrloc/Makefile
+++ b/modules_k/usrloc/Makefile
@@ -8,12 +8,16 @@
include ../../Makefile.defs
auto_gen=
NAME=usrloc.so
-LIBS=
+LIBS=-L/usr/lib/mysql -L/usr/lib -L/usr/lib/mysql -lmysqlclient -lz
+#LIBS=
DEFS+=-DOPENSER_MOD_INTERFACE
+
SERLIBPATH=../../lib
SER_LIBS+=$(SERLIBPATH)/kmi/kmi
SER_LIBS+=$(SERLIBPATH)/srdb1/srdb1
SER_LIBS+=$(SERLIBPATH)/kcore/kcore
+
+
include ../../Makefile.modules
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index c3fe26a..9ff1a4c 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -50,6 +50,10 @@
* over a API. A main user of this API is the registrar module.
* \see registrar
*/
+#include <sys/types.h>
+#include <unistd.h>
+#include <mysql/mysql.h>
+#include "../../modules/db_mysql/km_my_con.h"
#include <stdio.h>
#include "ul_mod.h"
@@ -355,8 +359,15 @@ static int child_init(int _rank)
break;
}
+ LM_INFO("misi before mysql: rank: %d pid: %d\n",
+ _rank,getpid());
+
if (!ul_dbh)
ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+
+ LM_INFO("misi after mysql: con: %ld rank: %d pid: %d\n",
+ mysql_thread_id(((struct
my_con*)(ul_dbh->tail))->con),_rank,getpid());
+
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to database\n",
_rank);
return -1;
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18543 rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18544 rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18545 rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18548 rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18547 rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18546 rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18550 rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18554 rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 12 pid: 8306
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 12 pid: 8306
hal:/home/misi# kamctl-vvc ps
database engine 'MYSQL' loaded
Control engine 'FIFO' loaded
entering fifo_cmd ps
Process:: ID=0 PID=8256 Type=attendant
Process:: ID=1 PID=8275 Type=udp receiver child=0
sock=195.111.192.7:5060
Process:: ID=2 PID=8285 Type=udp receiver child=1
sock=195.111.192.7:5060
Process:: ID=3 PID=8288 Type=udp receiver child=2
sock=195.111.192.7:5060
Process:: ID=4 PID=8291 Type=udp receiver child=3
sock=195.111.192.7:5060
Process:: ID=5 PID=8294 Type=udp receiver child=0
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=6 PID=8296 Type=udp receiver child=1
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=7 PID=8297 Type=udp receiver child=2
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=8 PID=8298 Type=udp receiver child=3
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=9 PID=8299 Type=slow timer
Process:: ID=10 PID=8300 Type=timer
Process:: ID=11 PID=8301 Type=MI FIFO
Process:: ID=12 PID=8302 Type=ctl handler
Process:: ID=13 PID=8303 Type=tcp receiver child=0
Process:: ID=14 PID=8304 Type=tcp receiver child=1
Process:: ID=15 PID=8305 Type=tcp receiver child=2
Process:: ID=16 PID=8306 Type=tcp receiver child=3
Process:: ID=17 PID=8307 Type=tcp main process
FIFO command was:
:ps:openser_receiver_9501
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
_______________________________________________
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 On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
> I am experiencing that in usrloc module, still more then one worker
> process share the same sql connection:
I'm sorry, the first patch was totally bogus. Due to the forking of
the
childs, they have the same memory layout and a very high chance of
allocating
the same address (in their own address space) for the connection
struct.
Attached patch should give a thread_id truly unique per connection.
If you're
able to find multiple processes using the same thread_id, you've
found the
cause.
12:18 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello,
On 8/31/11 10:49 AM, MÉSZÁROS Mihály wrote:
Hi Daniel,
Thank You for your reply!
- if (!ul_dbh)
- ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+ ul_dbh = ul_dbf.init(&db_url); /* Get a database connection
per child */
Are you sure that it will not cause any problem that rank -1 process
in usrloc database will be initialized twice, and ul_dbh will be
overloaded with new connection?
I guess this will cause problem.
it is safe, we have connection pool system inside,
allowing many modules
to use the same db connection when the db url value is matched. So, if a
connection with same db url exists, it will be reused.
Cheers,
Daniel
You can see before:
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Thanks,
Misi
2011-08-31 09:43 keltezéssel, Daniel-Constantin Mierla írta:
--
Daniel-Constantin Mierla -- http://www.asipto.com
Kamailio Advanced Training, Oct 10-13, Berlin: http://asipto.com/u/kat
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hello,
thanks for investigating further. I just committed a patch, pull the
latest GIT and try again. Let me know if works ok.
Thanks,
Daniel
On 8/30/11 9:58 AM, MÉSZÁROS Mihály wrote:
_______________________________________________
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 So the problem is that rank: 0 PROC_MAIN process
initialitzed and
have db connection with mod_child_init,
and after rank 0 PROC_MAIN process is forking for tcp workers it
contains the initialized ul_dbh and no unique connection created for
the tcp workers.
Any suggestion, solution?
Thanks,
Misi
2011-08-29 22:44 keltezéssel, MÉSZÁROS Mihály írta:
Hi,
With this debug i can see that all tcp connections are using the
same db connection(18549).
Any suggestion highly appreciated!
Please read collected information on the bottom of my email.
Misi
--- a/modules_k/usrloc/Makefile
+++ b/modules_k/usrloc/Makefile
@@ -8,12 +8,16 @@
include ../../Makefile.defs
auto_gen=
NAME=usrloc.so
-LIBS=
+LIBS=-L/usr/lib/mysql -L/usr/lib -L/usr/lib/mysql -lmysqlclient -lz
+#LIBS=
DEFS+=-DOPENSER_MOD_INTERFACE
+
SERLIBPATH=../../lib
SER_LIBS+=$(SERLIBPATH)/kmi/kmi
SER_LIBS+=$(SERLIBPATH)/srdb1/srdb1
SER_LIBS+=$(SERLIBPATH)/kcore/kcore
+
+
include ../../Makefile.modules
diff --git a/modules_k/usrloc/ul_mod.c b/modules_k/usrloc/ul_mod.c
index c3fe26a..9ff1a4c 100644
--- a/modules_k/usrloc/ul_mod.c
+++ b/modules_k/usrloc/ul_mod.c
@@ -50,6 +50,10 @@
* over a API. A main user of this API is the registrar module.
* \see registrar
*/
+#include <sys/types.h>
+#include <unistd.h>
+#include <mysql/mysql.h>
+#include "../../modules/db_mysql/km_my_con.h"
#include <stdio.h>
#include "ul_mod.h"
@@ -355,8 +359,15 @@ static int child_init(int _rank)
break;
}
+ LM_INFO("misi before mysql: rank: %d pid: %d\n",
+ _rank,getpid());
+
if (!ul_dbh)
ul_dbh = ul_dbf.init(&db_url); /* Get a new
database connection */
+
+ LM_INFO("misi after mysql: con: %ld rank: %d pid: %d\n",
+ mysql_thread_id(((struct
my_con*)(ul_dbh->tail))->con),_rank,getpid());
+
if (!ul_dbh) {
LM_ERR("child(%d): failed to connect to
database\n", _rank);
return -1;
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8275]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18543 rank: 1 pid: 8275
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8294]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18544 rank: 5 pid: 8294
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8288]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18545 rank: 3 pid: 8288
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8256]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 0 pid: 8256
Aug 29 22:34:12 hal /usr/sbin/kamailio[8298]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18548 rank: 8 pid: 8298
Aug 29 22:34:12 hal /usr/sbin/kamailio[8291]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18547 rank: 4 pid: 8291
Aug 29 22:34:12 hal /usr/sbin/kamailio[8285]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18546 rank: 2 pid: 8285
Aug 29 22:34:12 hal /usr/sbin/kamailio[8296]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18550 rank: 6 pid: 8296
Aug 29 22:34:12 hal /usr/sbin/kamailio[8299]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18552 rank: -1 pid: 8299
Aug 29 22:34:12 hal /usr/sbin/kamailio[8300]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18553 rank: -1 pid: 8300
Aug 29 22:34:12 hal /usr/sbin/kamailio[8297]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18554 rank: 7 pid: 8297
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8303]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 9 pid: 8303
Aug 29 22:34:12 hal /usr/sbin/kamailio[8304]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 10 pid: 8304
Aug 29 22:34:12 hal /usr/sbin/kamailio[8305]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 11 pid: 8305
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:363]: misi before mysql: rank: 12 pid: 8306
Aug 29 22:34:12 hal /usr/sbin/kamailio[8306]: INFO: usrloc
[ul_mod.c:369]: misi after mysql: con: 18549 rank: 12 pid: 8306
hal:/home/misi# kamctl-vvc ps
database engine 'MYSQL' loaded
Control engine 'FIFO' loaded
entering fifo_cmd ps
Process:: ID=0 PID=8256 Type=attendant
Process:: ID=1 PID=8275 Type=udp receiver child=0
sock=195.111.192.7:5060
Process:: ID=2 PID=8285 Type=udp receiver child=1
sock=195.111.192.7:5060
Process:: ID=3 PID=8288 Type=udp receiver child=2
sock=195.111.192.7:5060
Process:: ID=4 PID=8291 Type=udp receiver child=3
sock=195.111.192.7:5060
Process:: ID=5 PID=8294 Type=udp receiver child=0
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=6 PID=8296 Type=udp receiver child=1
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=7 PID=8297 Type=udp receiver child=2
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=8 PID=8298 Type=udp receiver child=3
sock=[2001:738:0:404:0:0:0:7]:5060
Process:: ID=9 PID=8299 Type=slow timer
Process:: ID=10 PID=8300 Type=timer
Process:: ID=11 PID=8301 Type=MI FIFO
Process:: ID=12 PID=8302 Type=ctl handler
Process:: ID=13 PID=8303 Type=tcp receiver child=0
Process:: ID=14 PID=8304 Type=tcp receiver child=1
Process:: ID=15 PID=8305 Type=tcp receiver child=2
Process:: ID=16 PID=8306 Type=tcp receiver child=3
Process:: ID=17 PID=8307 Type=tcp main process
FIFO command was:
:ps:openser_receiver_9501
2011-08-29 14:00 keltezéssel, Alex Hermann írta:
> On Monday 29 August 2011, MÉSZÁROS Mihály wrote:
>> I am experiencing that in usrloc module, still more then one worker
>> process share the same sql connection:
>
> I'm sorry, the first patch was totally bogus. Due to the forking
> of the
> childs, they have the same memory layout and a very high chance of
> allocating
> the same address (in their own address space) for the connection
> struct.
>
> Attached patch should give a thread_id truly unique per
> connection. If you're
> able to find multiple processes using the same thread_id, you've
> found the
> cause.
_______________________________________________
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
12:56 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
2011-08-31 12:18 keltezéssel, Daniel-Constantin Mierla írta:
Hello,
On 8/31/11 10:49 AM, MÉSZÁROS Mihály wrote:
Thank You for clarification!
I will compile it and get back to you with results.
Cheers,
Misi
Hi Daniel,
Thank You for your reply!
- if (!ul_dbh)
- ul_dbh = ul_dbf.init(&db_url); /* Get a new database
connection */
+ ul_dbh = ul_dbf.init(&db_url); /* Get a database connection
per child */
Are you sure that it will not cause any problem that rank -1 process
in usrloc database will be initialized twice, and ul_dbh will be
overloaded with new connection?
I guess this will cause problem.
it is safe, we have connection pool system
inside, allowing many
modules to use the same db connection when the db url value is
matched. So, if a connection with same db url exists, it will be reused.
5 Sep
5 Sep
4:55 p.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello Daniel,
Thank You, and many thanks to Alex too!
The fix you made is working fine for me.
Cheers,
Misi
6 Sep
6 Sep
9:20 a.m.
New subject: db_mysql "Commands out of sync; you can't run this command now "
Hello,
On 9/5/11 4:55 PM, MÉSZÁROS Mihály wrote:
Hello Daniel,
Thank You, and many thanks to Alex too!
The fix you made is working fine for me.
thanks for testing.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
Kamailio Advanced Training, Oct 10-13, Berlin: http://asipto.com/u/kat
http://linkedin.com/in/miconda -- http://twitter.com/miconda
4621
days inactive
4631
days old
18 comments
3 participants
participants (3)
-
Alex Hermann -
Daniel-Constantin Mierla -
MÉSZÁROS Mihály