An error occurred while attempting to establish a connection to server localhost:389

Hi,

I'm installing and evaluating Zimbra 8.0.1 NE on RHEL 6.2. After setting up the requirements, I ran install.sh then I saw an error from the zmsetup.log saying that I can't connect to LDAP.

Here's the entry from zmsetup.log:

Code:

Sat Dec 15 12:06:56 2012 *** Running as zimbra user: /opt/zimbra/bin/zmlicense -c [] FATAL: failed to initialize LDAP client com.zimbra.cs.ldap.LdapException: LDAP error: : An error occurred while attempting to connect to server localhost:389: java.io.IOException: An error occurred while attempting to establish a connection to server localhost:389: java.net.ConnectException: Connection refused ExceptionId:main:1355544418726:03e4754c9683ef69 Code:ldap.LDAP_ERROR at com.zimbra.cs.ldap.LdapException.LDAP_ERROR(LdapException.java:88) at com.zimbra.cs.ldap.unboundid.UBIDLdapException.mapToLdapException(UBIDLdapException.java:72) at com.zimbra.cs.ldap.unboundid.UBIDLdapException.mapToLdapException(UBIDLdapException.java:38) at com.zimbra.cs.ldap.unboundid.LdapConnectionPool.createConnPool(LdapConnectionPool.java:117) at com.zimbra.cs.ldap.unboundid.LdapConnectionPool.createConnectionPool(LdapConnectionPool.java:64) at com.zimbra.cs.ldap.unboundid.UBIDLdapContext.init(UBIDLdapContext.java:95) at com.zimbra.cs.ldap.unboundid.UBIDLdapClient.init(UBIDLdapClient.java:37) at com.zimbra.cs.ldap.LdapClient.getInstance(LdapClient.java:63) at com.zimbra.cs.ldap.LdapClient.initialize(LdapClient.java:86) at com.zimbra.cs.account.ldap.LdapProv.<init>(LdapProv.java:46) at com.zimbra.cs.account.ldap.LdapProvisioning.<init>(LdapProvisioning.java:256) at com.zimbra.cs.account.ldap.LdapProvisioning.<init>(LdapProvisioning.java:253) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:525) at java.lang.Class.newInstance0(Class.java:372) at java.lang.Class.newInstance(Class.java:325) at com.zimbra.cs.account.Provisioning.getInstance(Provisioning.java:278) at com.zimbra.cs.account.Provisioning.getInstance(Provisioning.java:238) at com.zimbra.cs.license.LdapLicenseCounter.<init>(LdapLicenseCounter.java:48) at com.zimbra.cs.license.LicenseManager.<init>(LicenseManager.java:76) at com.zimbra.cs.license.LicenseManager.<clinit>(LicenseManager.java:80) at com.zimbra.cs.license.LicenseCLI.exec(LicenseCLI.java:97) at com.zimbra.cs.license.LicenseCLI.main(LicenseCLI.java:161) Caused by: LDAPException(resultCode=91 (connect error), errorMessage='An error occurred while attempting to connect to server localhost:389: java.io.IOException: An error occurred while attempting to establish a connection to server localhost:389: java.net.ConnectException: Connection refused') at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:741) at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:675) at com.unboundid.ldap.sdk.LDAPConnection.<init>(LDAPConnection.java:507) at com.unboundid.ldap.sdk.SingleServerSet.getConnection(SingleServerSet.java:229) at com.unboundid.ldap.sdk.ServerSet.getConnection(ServerSet.java:98) at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:616) at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:562) at com.zimbra.cs.ldap.unboundid.LdapConnectionPool.createConnPool(LdapConnectionPool.java:113) ... 21 more Caused by: java.io.IOException: An error occurred while attempting to establish a connection to server localhost:389: java.net.ConnectException: Connection refused at com.unboundid.ldap.sdk.LDAPConnectionInternals.<init>(LDAPConnectionInternals.java:142) at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:732) ... 28 more

So I looked at the listening ports using netstat -plunt and got this:

Code:

[root@zcs8 ~]# netstat -plunt Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 192.168.0.50:53 0.0.0.0:* LISTEN 20352/named tcp 0 0 127.0.0.1:53 0.0.0.0:* LISTEN 20352/named tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 940/sshd tcp 0 0 127.0.0.1:953 0.0.0.0:* LISTEN 20352/named tcp 0 0 ::1:53 :::* LISTEN 20352/named tcp 0 0 :::22 :::* LISTEN 940/sshd tcp 0 0 ::1:953 :::* LISTEN 20352/named udp 0 0 192.168.0.50:53 0.0.0.0:* 20352/named udp 0 0 127.0.0.1:53 0.0.0.0:* 20352/named udp 0 0 ::1:53 :::* 20352/named

Nothing is listening on port 389. So probably that's why the connection was refused.

I'm not sure why is this happening. Hope you guys can shed a light on this.

Thanks in advance! :)

Check if all the services are up and running with:

Code:

zmcontrol status

When you've done that, restart ZCS and check in the log files to see what error(s) you've got.

Hi Bill,

Here is the result of zmcontrol status after the installation and after the ZCS restart:

Code:

[zimbra@zcs8 ~]$ zmcontrol status Host zcs8.ursi.ph antispam Running antivirus Running convertd Running ldap Running logger Running mailbox Stopped mysql.server is not running. mta Running snmp Running spell Running stats Stopped zmconfigd Running

Checked /opt/zimbra/log/mailbox.log and found these entries:

Code:

2012-12-16 17:36:27,714 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:1355650587713:7115b31b3f2f385d Code:service.FAILURE at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:258) at com.zimbra.cs.db.DbPool.getConnection(DbPool.java:358) at com.zimbra.cs.db.DbPool.getConnection(DbPool.java:320) at com.zimbra.cs.db.DbPool.waitForDatabase(DbPool.java:241) at com.zimbra.cs.db.DbPool.startup(DbPool.java:232) at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:164) at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:130) at com.zimbra.soap.SoapServlet.init(SoapServlet.java:119) at javax.servlet.GenericServlet.init(GenericServlet.java:241) at org.eclipse.jetty.servlet.ServletHolder.initServlet(ServletHolder.java:463) at org.eclipse.jetty.servlet.ServletHolder.doStart(ServletHolder.java:283) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:771) at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:249) at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1222) at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:676) at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:455) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.server.handler.HandlerCollection.doStart(HandlerCollection.java:224) at org.eclipse.jetty.server.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:167) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.server.handler.HandlerCollection.doStart(HandlerCollection.java:224) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:90) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:90) at org.eclipse.jetty.server.handler.DebugHandler.doStart(DebugHandler.java:126) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:90) at org.eclipse.jetty.server.Server.doStart(Server.java:261) at org.mortbay.setuid.SetUIDServer.doStart(SetUIDServer.java:171) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:59) at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1215) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1138) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at org.eclipse.jetty.start.Main.invokeMain(Main.java:457) at org.eclipse.jetty.start.Main.start(Main.java:602) at org.eclipse.jetty.start.Main.main(Main.java:82) Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:525) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.Util.getInstance(Util.java:386) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927) at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2237) at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2158) at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:792) at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:525) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:381) at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:305) at java.sql.DriverManager.getConnection(DriverManager.java:579) at java.sql.DriverManager.getConnection(DriverManager.java:190) at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:78) at com.zimbra.cs.db.ZimbraConnectionFactory.createConnection(ZimbraConnectionFactory.java:65) at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:582) at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1188) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) at com.zimbra.cs.db.DbPool.getConnection(DbPool.java:339) ... 40 more Caused by: java.sql.SQLException: Access denied for user 'zimbra'@'localhost' (using password: YES) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3609) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3541) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:943) at com.mysql.jdbc.MysqlIO.secureAuth411(MysqlIO.java:4113) at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1308) at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2336) at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2176) ... 58 more

It seems that zimbra@localhost can't log in to MySQL.

Quote:

Originally Posted by twilighthaevhen

It seems that zimbra@localhost can't log in to MySQL.

It can't login because the MySQL server isn't running, you need to look at the log files to see why it's not starting.

I looked at mysql_error.log under /opt/zimbra/log and found this:

Code:

121216 21:47:11 mysqld_safe Starting mysqld daemon with databases from /opt/zimbra/db/data 121216 21:47:11 InnoDB: The InnoDB memory heap is disabled 121216 21:47:11 InnoDB: Mutexes and rw_locks use GCC atomic builtins 121216 21:47:11 InnoDB: Compressed tables use zlib 1.2.3 121216 21:47:11 InnoDB: Initializing buffer pool, size = 2.0G 121216 21:47:11 InnoDB: Completed initialization of buffer pool 121216 21:47:11 InnoDB: highest supported file format is Barracuda. 121216 21:47:13 InnoDB: Waiting for the background threads to start 121216 21:47:14 InnoDB: 1.1.8 started; log sequence number 1595675 121216 21:47:14 [Note] Server hostname (bind-address): 'localhost'; port: 7306 121216 21:47:14 [Note] - 'localhost' resolves to '127.0.0.1'; 121216 21:47:14 [Note] Server socket created on IP: '127.0.0.1'. 121216 21:47:14 [Note] Event Scheduler: Loaded 0 events 121216 21:47:14 [Note] /opt/zimbra/mysql/bin/mysqld: ready for connections. Version: '5.5.24-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution

Based on this, it seems that MySQL is up and running. To be sure, I ran ps aux | grep mysql and saw this:

Code:

[root@zcs8 ~]# ps aux | grep mysql zimbra 18053 0.0 0.0 9484 1696 pts/2 S 21:47 0:00 /bin/sh /opt/zimbra/mysql/bin/mysqld_safe --defaults-file=/opt/zimbra/conf/my.cnf --external-locking --log-error=/opt/zimbra/log/mysql_error.log --malloc-lib=/opt/zimbra/tcmalloc/lib/libtcmalloc_minimal.so --ledir=/opt/zimbra/mysql/bin zimbra 18529 0.4 3.6 2488948 246664 pts/2 Sl 21:47 0:00 /opt/zimbra/mysql/bin/mysqld --defaults-file=/opt/zimbra/conf/my.cnf --basedir=/opt/zimbra/mysql --datadir=/opt/zimbra/db/data --plugin-dir=/opt/zimbra/mysql/lib/plugin --external-locking --log-error=/opt/zimbra/log/mysql_error.log --pid-file=/opt/zimbra/db/mysql.pid --socket=/opt/zimbra/db/mysql.sock --port=7306 root 20844 0.0 0.0 103208 828 pts/0 S+ 21:48 0:00 grep mysql

This just says MySQL is really running. Ran zmcontrol status and still saw the same output, mysql is not running.

There might be something wrong why zmcontrol can't detect that MySQL is running. Maybe the password being used doesn't match the password stored in MySQL. This might probably be related with the LDAP error I found on zmsetup.log that I posted above.

Good news! I managed to have my installation working.

I ran zmcontrol stop and check if there is another zimbra mysql server running (through ps aux | grep mysql) and found out that there is. Don't know why is it still running though since it should've stopped when I ran zmcontrol stop. So I forced kill it (kill -9 <mysql pid>) and ran /opt/zimbra/libexec/zmmyinit as zimbra user. Everything is working now.

Thanks! :)