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