GenericJDBCException: Cannot open connection in catalina.out

[kjakkanen]

Hi,

After the update to Scalix 11.2 we keep getting these lines into the catalina.out logfile, they re-appear every 30 seconds or so and clutter up the file (currently 22 MB) - the system seems to be running though and a "service scalix-tomcat restart" didn't help any.

Would anyone have an idea of what it's complaining about and more importantly, how to fix it (if anything is even broken)?

TIA;
Kimmo

--- clip clip clip ---
org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:420)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.BorrowedConnectionProxy.invoke(BorrowedConnectionProxy.java:40)
at $Proxy0.createStatement(Unknown Source)
at com.scalix.api.db.DbUtils.getSession(DbUtils.java:62)
at com.scalix.api.mailbox.Mailbox.checkForTables(Mailbox.java:1523)
at com.scalix.api.mailbox.Mailbox.init(Mailbox.java:166)
at com.scalix.api.service.Context.getServiceByName(Context.java:194)
at com.scalix.api.service.Context.getMailboxService(Context.java:166)
at com.scalix.api.rest.MailboxServlet.doGet(MailboxServlet.java:63)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.springframework.web.servlet.mvc.ServletWrappingController.handleRequestInternal(ServletWrappingController.java:174)
at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:839)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:774)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:460)
at com.scalix.api.PlatformDispatcherServlet.service(PlatformDispatcherServlet.java:73)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.springframework.web.filter.AbstractRequestLoggingFilter.doFilterInternal(AbstractRequestLoggingFilter.java:133)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:75)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
at java.lang.Thread.run(Unknown Source)
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:104)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:236)
at com.mchange.v2.c3p0.PoolBackedDataSource.getConnection(PoolBackedDataSource.java:94)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
... 38 more
Caused by: com.mchange.v2.resourcepool.CannotAcquireResourceException: A ResourcePool could not acquire a resource from its primary factory or source.
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAcquire(BasicResourcePool.java:970)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:208)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:232)
... 41 more
--- clip clip clip ---

[kjakkanen]

Gets even stranger, it seems that each catalina.out entry has a corresponding entry in the scalix-api.log as well (could this be some kind of trouble in the postgres db?):

--- clip clip clip ---
2007-10-22 14:18:05,778 ERROR [Mailbox.checkForTables:1544] MAILBOX - clientId: 578A0F869312A5F94361190C91E8E404, user: AUTHID - Error (M00021) checking fo
r tables.
org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:420)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.BorrowedConnectionProxy.invoke(BorrowedConnectionProxy.java:40)
at $Proxy0.createStatement(Unknown Source)
at com.scalix.api.db.DbUtils.getSession(DbUtils.java:62)
at com.scalix.api.mailbox.Mailbox.checkForTables(Mailbox.java:1523)
at com.scalix.api.mailbox.Mailbox.init(Mailbox.java:166)
at com.scalix.api.service.Context.getServiceByName(Context.java:194)
at com.scalix.api.service.Context.getServiceByName(Context.java:179)
at com.scalix.api.service.Context.getMailboxService(Context.java:162)
at com.scalix.api.notification.EventServiceConnection.handleNotification(EventServiceConnection.java:381)
at com.scalix.api.notification.EventServiceConnection.drainChannel(EventServiceConnection.java:323)
at com.scalix.api.notification.EventServiceConnection.run(EventServiceConnection.java:184)
at java.lang.Thread.run(Unknown Source)
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:104)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:236)
at com.mchange.v2.c3p0.PoolBackedDataSource.getConnection(PoolBackedDataSource.java:94)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
... 13 more
Caused by: com.mchange.v2.resourcepool.CannotAcquireResourceException: A ResourcePool could not acquire a resource from its primary factory or source.
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAcquire(BasicResourcePool.java:970)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:208)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:232)
... 16 more
2007-10-22 14:18:05,778 ERROR [Context.getServiceByName:198] Error in delayed service initialization!
M00021 could not connect to database
at com.scalix.api.mailbox.Mailbox.checkForTables(Mailbox.java:1545)
at com.scalix.api.mailbox.Mailbox.init(Mailbox.java:166)
at com.scalix.api.service.Context.getServiceByName(Context.java:194)
at com.scalix.api.service.Context.getServiceByName(Context.java:179)
at com.scalix.api.service.Context.getMailboxService(Context.java:162)
at com.scalix.api.notification.EventServiceConnection.handleNotification(EventServiceConnection.java:381)
at com.scalix.api.notification.EventServiceConnection.drainChannel(EventServiceConnection.java:323)
at com.scalix.api.notification.EventServiceConnection.run(EventServiceConnection.java:184)
at java.lang.Thread.run(Unknown Source)
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:420)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.BorrowedConnectionProxy.invoke(BorrowedConnectionProxy.java:40)
at $Proxy0.createStatement(Unknown Source)
at com.scalix.api.db.DbUtils.getSession(DbUtils.java:62)
at com.scalix.api.mailbox.Mailbox.checkForTables(Mailbox.java:1523)
... 8 more
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:104)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:236)
at com.mchange.v2.c3p0.PoolBackedDataSource.getConnection(PoolBackedDataSource.java:94)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
--- clip clip clip ---

-Kimmo

[kjakkanen]

Continuing discussions with myself, I found out that this is a problem of scalix-postgresql not starting properly, there were thousands of errors in pgstartup.log about failed authentication for user "scalix".

Tried all the tricks I found from the Forums (except the whole recreation of the data-directory, a.k.a. scalix db) - but no luck. In the end I ended up loosening the access from pg_hba.conf for my host IP - but I see this only as a temporary solution and would like to find out the real source of the problem.

Here's what I've done so far:
---
1. Check the postgresql password from /var/opt/scalix/nn/caa/scalix.res/config/psdata
2. Change that same password to platform/platform.properties
3. Change the Scalix DB password using sxpsql-setpwd
4. Restart tomcat & postgresql
---

No help. Only thing that got it working was that loosening of the pg_hba.conf file. It still gives some random schema errors about "ERROR: schema "sx_c6b681a5bf2cf5526462cf1943908b6f" does not exist" but don't know if it's even related....

Any help appreciated.

Thanks,
Kimmo

[kjakkanen]

Closing this one, the issue was solved by our distributor who found out that the Scalix 11.2 installer had not initialised the PostgreSQL DB properly (he realised this because during the update the installer had not run ompatchom to solve library version differences and it failed originally).

Also we had used a password with "!" character in it and this was a pain in the a** to use with Postgres. Changed that to normal characters one, also changed the password in the /var/opt/scalix/nn/caa/scalix.res/config/psdata file and restarted tomcat.

All is good, SWA search is working now (knock knock...

KR;
Kimmo