[Kamailio-Users] Failure at startup

[Francisco Javier Lizarán Vilches]

Hi all:

 

Running Openser v1.2.3-notls. It has been suffering failures at startup since some weeks ago and it seems to be related with database operation. Nothing has changed in config. The only remarkable change in the system is a slight increase in database registers at subscribers, location and lcr tables. Log excerpt from openser startup:

 

Jun 19 15:23:32 openser[2196]: INFO: statistics manager successfully initialized

Jun 19 15:23:32 openser[2196]: StateLess module - initializing

Jun 19 15:23:32 openser[2196]: TM - initializing...

Jun 19 15:23:32 openser[2196]: Maxfwd module- initializing

Jun 19 15:23:32 openser[2196]: INFO:ul_init_locks: locks array size 512

Jun 19 15:23:32 openser[2196]: AUTH module - initializing

Jun 19 15:23:32 openser[2196]: AUTH_DB module - initializing

Jun 19 15:23:32 openser[2196]: TextOPS - initializing

Jun 19 15:23:32 openser[2196]: AVPops - initializing

Jun 19 15:23:32 openser[2196]: permissions - initializing

Jun 19 15:23:32 openser[2196]: WARNING: File not found: /etc/openser/permissions.allow

Jun 19 15:23:32 openser[2196]: Default allow file (/etc/openser/permissions.allow) not found => empty rule set

Jun 19 15:23:32 openser[2196]: WARNING: File not found: /etc/openser/permissions.deny

Jun 19 15:23:32 openser[2196]: Default deny file (/etc/openser/permissions.deny) not found => empty rule set

Jun 19 15:23:32 openser[2196]: ACC - initializing

Jun 19 15:23:32 openser[2196]: Dialog module - initializing

Jun 19 15:23:32 openser[2196]: INFO: SNMPStats: Starting up the SNMPStats Module

Jun 19 15:23:32 openser[2196]: UAC - initializing

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type (32) instead of <Refer-To>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type (7) instead of <Contact>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Referred-By>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Replaces>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Forwarder>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Referred-by>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <RG>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Origin>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Referred-By>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Replaces>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type name <Forwarder>

Jun 19 15:23:32 openser[2196]: xl_fill_extra_spec: found extra item [DLG_status]

Jun 19 15:23:32 openser[2196]: xl_fill_extra_spec: found extra item [T_reply_code]

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type (4) instead of <From>

Jun 19 15:23:32 openser[2196]: INFO:textops:hname_fixup: using hdr type (3) instead of <To>

Jun 19 15:23:32 openser[2196]: xl_fill_extra_spec: found extra item [T_reply_code]

Jun 19 15:23:32 openser[2196]: xl_fill_extra_spec: found extra item [T_reply_code]

Jun 19 15:23:32 openser[2196]: xl_fill_extra_spec: found extra item [T_branch_idx]

Jun 19 15:23:32 openser[2196]: INFO: udp_init: SO_RCVBUF is initially 109568

Jun 19 15:23:32 openser[2196]: INFO: udp_init: SO_RCVBUF is finally 262142

 

...Some registers, invites, etc logs...

 

Jun 19 15:23:34 openser[2204]: new_connection: Can't connect to MySQL server on 'bbdd.bariksip.es' (4)

Jun 19 15:23:34 openser[2201]: new_connection: Can't connect to MySQL server on 'bbdd.bariksip.es' (4)

Jun 19 15:23:34 openser[2201]: ERROR:ul:child_init(5): Error while connecting database

Jun 19 15:23:34 openser[2204]: ERROR:ul:child_init(-1): Error while connecting database

Jun 19 15:23:34 openser[2201]: ERROR:init_mod_child: Error while initializing module usrloc, rank 5

Jun 19 15:23:34 openser[2204]: ERROR:init_mod_child: Error while initializing module usrloc, rank -1

Jun 19 15:23:34 openser[2201]: init_child failed

Jun 19 15:23:34 openser[2204]: timer: init_child failed

Jun 19 15:23:34 openser[2203]: INFO: signal 15 received

Jun 19 15:23:34 openser[2201]: INFO: SNMPStats: The SNMPStats module got the kill signal

Jun 19 15:23:34 openser[2201]:                  Shutting down the AgentX Sub-Agent!

Jun 19 15:23:34 openser[2201]: INFO:mi_fifo:mi_destroy: process hasn't been created -> nothing to kill

Jun 19 15:23:34 openser[2202]: INFO: signal 15 received

Jun 19 15:23:34 openser[2200]: INFO: signal 15 received

Jun 19 15:23:34 openser[2199]: INFO: signal 15 received

Jun 19 15:23:34 openser[2198]: INFO: signal 15 received

Jun 19 15:23:34 openser[2197]: INFO: signal 15 received

Jun 19 15:23:34 openser[2204]: INFO: SNMPStats: The SNMPStats module got the kill signal

Jun 19 15:23:34 openser[2204]:                  Shutting down the AgentX Sub-Agent!

Jun 19 15:23:34 openser[2204]: INFO:mi_fifo:mi_destroy: process hasn't been created -> nothing to kill

Jun 19 15:23:34 openser[2196]: new_connection: Can't connect to MySQL server on 'bbdd.bariksip.es' (4)

Jun 19 15:23:34 openser[2196]: ERROR:ul:child_init(0): Error while connecting database

Jun 19 15:23:34 openser[2196]: ERROR:init_mod_child: Error while initializing module usrloc, rank 0

Jun 19 15:23:34 openser[2196]: main: error in init_child

Jun 19 15:23:34 openser[2196]: INFO: SNMPStats: The SNMPStats module got the kill signal

Jun 19 15:23:34 openser[2196]:                  Shutting down the AgentX Sub-Agent!

Jun 19 15:23:34 openser[2196]: INFO:mi_fifo:mi_destroy: process hasn't been created -> nothing to kill

 

After multiple attempts the result is the same. This is the list of modules that use db:

acc|auth_db|permissions|uri_db|usrloc|avpops|lcr|avpops|domain|speeddial|alias_db

Looking at the traces, when openser places the request packet carrying this query "select prefix,from_uri,grp_id,priority from lcr", mysql server begins to perform retransmissions of the requested data; although openser eventually sends back the ack. Later request's responses from mysql server needs also retransmit until openser fails.  

If I change, for example, usrloc's dbmode to 0 (disables db use), the module that fails this time is auth_db.

 

The mySql server is located in the same LAN that Openser(0.112s rtt). I have realized that Openser can be started without any problem when:

            -Log level is raised to 4(!).

            or

            -Another mysql server in a remote location is used (10s rtt).

            

Has anybody experienced an issue like this?

 

Thanks:

 

Francisco Javier Lizarán Vilches

----------------------------------------------

BARIK (Grupo Ormazabal)

Departamento Técnico

Tel.: +34 917 479 900

www.barik.es <http://www.barik.es/> 

----------------------------------------------

 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/users/attachments/20090624/d4c9e808/attachment.htm>