[Spacewalk-list] rhn-search broken since 2.1 upgrade?

Mon Jun 16 10:09:30 UTC 2014

This morning my spacewalk server almost ran out of diskspace.
The cause turned out to be the logs under /var/log/rhn/search

The logsize increased dramatically since the upgrade of 2.0 to 2.1 as it turns out
However the upgrade went fine, never saw any errors.

>From rhn_search.log I see loads of the following errors

[2014-06-16 12:01:56,581] ERROR - Job (updateIndex.errata threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: org.apache.ibatis.exceptions.PersistenceException:
### Error querying database.  Cause: java.sql.SQLException: Connections could not be acquired from the underlying database!
### The error may exist in com/redhat/satellite/search/db/errata.xml
### The error may involve errata.getLastErrataId
### The error occurred while executing a query
### Cause: java.sql.SQLException: Connections could not be acquired from the underlying database!]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:227)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
Caused by: org.apache.ibatis.exceptions.PersistenceException:
### Error querying database.  Cause: java.sql.SQLException: Connections could not be acquired from the underlying database!
### The error may exist in com/redhat/satellite/search/db/errata.xml
### The error may involve errata.getLastErrataId
### The error occurred while executing a query
### Cause: java.sql.SQLException: Connections could not be acquired from the underlying database!
        at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:23)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:107)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:98)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:62)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:57)
        at com.redhat.satellite.search.db.Query.load(Query.java:88)
        at com.redhat.satellite.search.scheduler.tasks.IndexErrataTask.getErrata(IndexErrataTask.java:160)
        at com.redhat.satellite.search.scheduler.tasks.IndexErrataTask.execute(IndexErrataTask.java:62)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
        ... 1 more
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:529)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
        at org.apache.ibatis.transaction.jdbc.JdbcTransaction.openConnection(JdbcTransaction.java:131)
        at org.apache.ibatis.transaction.jdbc.JdbcTransaction.getConnection(JdbcTransaction.java:58)
        at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:271)
        at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:69)
        at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:56)
        at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:259)
        at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:132)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:105)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:81)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:104)
        ... 8 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.awaitAvailable(BasicResourcePool.java:1319)
        at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
        ... 19 more

And from rhn_search_daemon.log

INFO   | jvm 1    | 2014/06/16 12:02:07 | Jun 16, 2014 12:02:07 PM com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask run
INFO   | jvm 1    | 2014/06/16 12:02:07 | WARNING: com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask at 1c9d510e -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception:
INFO   | jvm 1    | 2014/06/16 12:02:07 | org.postgresql.util.PSQLException: Connection refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:136)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:66)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:125)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:30)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.jdbc3g.AbstractJdbc3gConnection.<init>(AbstractJdbc3gConnection.java:22)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.jdbc4.AbstractJdbc4Connection.<init>(AbstractJdbc4Connection.java:31)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.jdbc4.Jdbc4Connection.<init>(Jdbc4Connection.java:24)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.Driver.makeConnection(Driver.java:393)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.Driver.connect(Driver.java:267)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:148)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at com.mchange.v2.async.ThreadPerTaskAsynchronousRunner$TaskThread.run(ThreadPerTaskAsynchronousRunner.java:255)
INFO   | jvm 1    | 2014/06/16 12:02:07 | Caused by: java.net.ConnectException: Connection refused
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.PlainSocketImpl.socketConnect(Native Method)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:327)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:193)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:180)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:385)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.Socket.connect(Socket.java:546)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.Socket.connect(Socket.java:495)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.Socket.<init>(Socket.java:392)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at java.net.Socket.<init>(Socket.java:206)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.core.PGStream.<init>(PGStream.java:62)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:76)
INFO   | jvm 1    | 2014/06/16 12:02:07 |       ... 15 more

My PostgreSQL logs appear pretty normal, only thing I see is a lot of

WARNING:  there is no transaction in progress

and

LOG:  unexpected EOF on client connection

errors. Other than that nothing to indicate it's an issue on the DB side.
max_connections is set to 500 , I have about 40 postgres processes active.

Spacewalk further appears to run just fine.
I have no updates available from yum if I check.

Any leads?
--
Jan-Albert

Jan-Albert van Ree
Linux System Administrator
MARIN Support Group
E mailto:J.A.v.Ree at marin.nl
T +31 317 49 35 48

MARIN
2, Haagsteeg, P.O. Box 28, 6700 AA Wageningen, The Netherlands
T +31 317 49 39 11, F +31 317 49 32 45, I www.marin.nl