 Zimbra 6.0.12: sometimes mysql does not start
Zimbra 6.0.12 on Ubuntu 10.04 LTS in a KVM virtual machine hosted by a Ubuntu 10.04 LTS server.
Sometimes (approx. 1 out of 10 boots), when starting Zimbra server (thus starting zimbra automatically at boot), mysql does not start preventing zimbra from working correctly.
If I shutdown and restart zimbra everything works fine.
The error from mailbox.log file is:
...
...
2011-05-23 02:23:48,702 INFO [main] [] system - Setting mysql connector property: maxActive=100
2011-05-23 02:23:48,714 INFO [main] [] system - Setting mysql connector property: maxActive=100
2011-05-23 02:23:48,725 INFO [main] [] dbconn - instantiating DB connection factory class com.zimbra.cs.db.ZimbraConnectionFactory
2011-05-23 02:23:52,898 WARN [main] [] misc - Could not establish a connection to the database. Retrying in 5 seconds.
com.zimbra.common.service.ServiceException: system failure: getting database connection
ExceptionId:main:1306110232894:54198d5de2583136
Code:service.FAILURE
at com.zimbra.common.service.ServiceException.FAILURE (ServiceException.java:248)
at com.zimbra.cs.db.DbPool.getConnection(DbPool.java: 313)
at com.zimbra.cs.db.DbPool.getConnection(DbPool.java: 277)
at com.zimbra.cs.db.DbPool.waitForDatabase(DbPool.jav a:199)
at com.zimbra.cs.db.DbPool.startup(DbPool.java:190)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:156)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:123)
at com.zimbra.soap.SoapServlet.init(SoapServlet.java: 125)
at javax.servlet.GenericServlet.init(GenericServlet.j ava:241)
at org.mortbay.jetty.servlet.ServletHolder.initServle t(ServletHolder.java:440)
at org.mortbay.jetty.servlet.ServletHolder.doStart(Se rvletHolder.java:263)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.servlet.ServletHandler.initializ e(ServletHandler.java:685)
at org.mortbay.jetty.servlet.Context.startContext(Con text.java:140)
at org.mortbay.jetty.webapp.WebAppContext.startContex t(WebAppContext.java:1254)
at org.mortbay.jetty.handler.ContextHandler.doStart(C ontextHandler.java:517)
at org.mortbay.jetty.webapp.WebAppContext.doStart(Web AppContext.java:471)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.jetty.handler.ContextHandlerCollection .doStart(ContextHandlerCollection.java:156)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.handler.DebugHandler.doStart(Deb ugHandler.java:127)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.Server.doStart(Server.java:224)
at org.mortbay.setuid.SetUIDServer.doStart(SetUIDServ er.java:158)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.xml.XmlConfiguration.main(XmlConfigura tion.java:985)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Nativ e Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Native MethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(De legatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.mortbay.start.Main.invokeMain(Main.java:194)
at org.mortbay.start.Main.start(Main.java:534)
at org.mortbay.start.Main.start(Main.java:441)
at org.mortbay.start.Main.main(Main.java:119)
Caused by: com.mysql.jdbc.exceptions.MySQLNonTransientConnect ionException: Server connection failure during transaction. Due to underlying exception: 'java.net.ConnectException: Connection refused'.
** BEGIN NESTED EXCEPTION **
java.net.ConnectException
MESSAGE: Connection refused
STACKTRACE:
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl .java:351)
at java.net.PlainSocketImpl.connectToAddress(PlainSoc ketImpl.java:213)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.j ava:200)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.j ava:366)
at java.net.Socket.connect(Socket.java:529)
at java.net.Socket.connect(Socket.java:478)
at java.net.Socket.<init>(Socket.java:375)
at java.net.Socket.<init>(Socket.java:218)
at com.mysql.jdbc.StandardSocketFactory.connect(Stand ardSocketFactory.java:256)
at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:271)
at com.mysql.jdbc.Connection.createNewIO(Connection.j ava:2921)
at com.mysql.jdbc.Connection.<init>(Connection.java:1 555)
at com.mysql.jdbc.NonRegisteringDriver.connect(NonReg isteringDriver.java:285)
at java.sql.DriverManager.getConnection(DriverManager .java:582)
at java.sql.DriverManager.getConnection(DriverManager .java:154)
at org.apache.commons.dbcp.DriverManagerConnectionFac tory.createConnection(DriverManagerConnectionFacto ry.java:68)
at com.zimbra.cs.db.ZimbraConnectionFactory.createCon nection(ZimbraConnectionFactory.java:50)
at org.apache.commons.dbcp.PoolableConnectionFactory. makeObject(PoolableConnectionFactory.java:294)
at org.apache.commons.pool.impl.GenericObjectPool.bor rowObject(GenericObjectPool.java:1148)
at org.apache.commons.dbcp.PoolingDataSource.getConne ction(PoolingDataSource.java:96)
at com.zimbra.cs.db.DbPool.getConnection(DbPool.java: 294)
at com.zimbra.cs.db.DbPool.getConnection(DbPool.java: 277)
at com.zimbra.cs.db.DbPool.waitForDatabase(DbPool.jav a:199)
at com.zimbra.cs.db.DbPool.startup(DbPool.java:190)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:156)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:123)
at com.zimbra.soap.SoapServlet.init(SoapServlet.java: 125)
at javax.servlet.GenericServlet.init(GenericServlet.j ava:241)
at org.mortbay.jetty.servlet.ServletHolder.initServle t(ServletHolder.java:440)
at org.mortbay.jetty.servlet.ServletHolder.doStart(Se rvletHolder.java:263)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.servlet.ServletHandler.initializ e(ServletHandler.java:685)
at org.mortbay.jetty.servlet.Context.startContext(Con text.java:140)
at org.mortbay.jetty.webapp.WebAppContext.startContex t(WebAppContext.java:1254)
at org.mortbay.jetty.handler.ContextHandler.doStart(C ontextHandler.java:517)
at org.mortbay.jetty.webapp.WebAppContext.doStart(Web AppContext.java:471)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.jetty.handler.ContextHandlerCollection .doStart(ContextHandlerCollection.java:156)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.handler.DebugHandler.doStart(Deb ugHandler.java:127)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.Server.doStart(Server.java:224)
at org.mortbay.setuid.SetUIDServer.doStart(SetUIDServ er.java:158)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.xml.XmlConfiguration.main(XmlConfigura tion.java:985)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Nativ e Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Native MethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(De legatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.mortbay.start.Main.invokeMain(Main.java:194)
at org.mortbay.start.Main.start(Main.java:534)
at org.mortbay.start.Main.start(Main.java:441)
at org.mortbay.start.Main.main(Main.java:119)
** END NESTED EXCEPTION **
Attempted reconnect 3 times. Giving up.
at com.mysql.jdbc.SQLError.createSQLException(SQLErro r.java:888)
at com.mysql.jdbc.Connection.createNewIO(Connection.j ava:2997)
at com.mysql.jdbc.Connection.<init>(Connection.java:1 555)
at com.mysql.jdbc.NonRegisteringDriver.connect(NonReg isteringDriver.java:285)
at java.sql.DriverManager.getConnection(DriverManager .java:582)
at java.sql.DriverManager.getConnection(DriverManager .java:154)
at org.apache.commons.dbcp.DriverManagerConnectionFac tory.createConnection(DriverManagerConnectionFacto ry.java:68)
at com.zimbra.cs.db.ZimbraConnectionFactory.createCon nection(ZimbraConnectionFactory.java:50)
at org.apache.commons.dbcp.PoolableConnectionFactory. makeObject(PoolableConnectionFactory.java:294)
at org.apache.commons.pool.impl.GenericObjectPool.bor rowObject(GenericObjectPool.java:1148)
at org.apache.commons.dbcp.PoolingDataSource.getConne ction(PoolingDataSource.java:96)
at com.zimbra.cs.db.DbPool.getConnection(DbPool.java: 294)
... 39 more
2011-05-23 02:24:01,915 WARN [main] [] misc - Could not establish a connection to the database. Retrying in 5 seconds.
...
...
Then continuing this way until restart...
No other error is listed in any log file. The system does an automatic shutdown at 2:01 and, after being backed up (it;s a virtual machine) it is restarted at 2:23.
In the mysql_error.log you may see at 2011-05-23 02:23 that there is no "mysql started" statement, there is another start later at 8:30, forced by hand after detecting that something was not working.
...
...
110522 18:48:04 mysqld started
110522 18:48:05 InnoDB: Started; log sequence number 0 327492748
110522 18:48:05 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.90-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution
110522 18:51:16 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown
110522 18:51:16 InnoDB: Starting shutdown...
110522 18:51:18 InnoDB: Shutdown completed; log sequence number 0 327552135
110522 18:51:18 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete
110522 18:51:18 mysqld ended
110522 18:52:37 mysqld started
110522 18:52:38 InnoDB: Started; log sequence number 0 327552135
110522 18:52:38 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.90-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution
110523 2:01:02 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown
110523 2:01:05 InnoDB: Starting shutdown...
110523 2:01:07 InnoDB: Shutdown completed; log sequence number 0 327727300
110523 2:01:07 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete
110523 02:01:07 mysqld ended
110523 08:30:30 mysqld started
110523 8:30:31 InnoDB: Started; log sequence number 0 327727300
110523 8:30:31 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.90-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution
110524 2:01:02 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown
110524 2:01:04 InnoDB: Starting shutdown...
110524 2:01:07 InnoDB: Shutdown completed; log sequence number 0 329872614
110524 2:01:07 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete
...
...
Thanks and regards
- Paolo  | 
Bugzilla
Wiki
Source
Linear Mode
