[sr-dev] [SR-Users] db_mysql "Commands out of sync; you can't run this command now "

Daniel-Constantin Mierla miconda at gmail.com
Wed Aug 31 12:18:26 CEST 2011


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:
>> 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:
>>>>> 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 at lists.sip-router.org
>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at 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




More information about the sr-dev mailing list