search

opencast / opencast-docker

Dockerfiles for Opencast
https://quay.io/organization/opencast/
Educational Community License v2.0
41 stars 36 forks source link

Default Opencast DB pool max.idle.time bigger than MariaDB wait_timeout (1h vs 10m) #109

Closed outofrange closed 5 years ago

outofrange commented 5 years ago

Hi!

Because of the Debian package used in MariaDB's docker image, the default value of wait_timeout isn't 28800 (8h), but 600 (10m) - which is below Opencast's default for org.opencastproject.db.jdbc.pool.max.idle.time, 3600 (1h)

This results in Opencast using closed connections without reopening them correctly (maybe another issue to solve) ``` 2019-04-16 08:58:46,735 | WARN | (Slf4jMLog$Slf4jMLogger$WarnLogger:220) - [c3p0] A PooledConnection that has already signalled a Connection error is still in use! 2019-04-16 08:58:46,736 | WARN | (Slf4jMLog$Slf4jMLogger$WarnLogger:223) - [c3p0] Another error has occurred [ com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners! com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)[:1.8.0_212] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)[:1.8.0_212] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)[:1.8.0_212] at java.lang.reflect.Constructor.newInstance(Constructor.java:423)[:1.8.0_212] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897)[69:opencast-db:6.4.0] at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1187)[69:opencast-db:6.4.0] at com.mysql.jdbc.Util.getInstance(Util.java:408)[69:opencast-db:6.4.0] at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)[69:opencast-db:6.4.0] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886)[69:opencast-db:6.4.0] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)[69:opencast-db:6.4.0] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:918)[69:opencast-db:6.4.0] at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1182)[69:opencast-db:6.4.0] at com.mysql.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:4068)[69:opencast-db:6.4.0] at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:567)[69:opencast-db:6.4.0] at com.mysql.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:4037)[69:opencast-db:6.4.0] at org.eclipse.persistence.internal.databaseaccess.DatabasePlatform.wasFailureCommunicationBased(DatabasePlatform.java:2917)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.processExceptionForCommError(DatabaseAccessor.java:1616)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:676)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.platform.server.ServerPlatformBase.wasFailureCommunicationBased(ServerPlatformBase.java:546)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:570)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2056)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:560)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:694)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2740)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:559)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:258)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:299)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2693)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1175)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1222)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:904)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:460)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1134)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2896)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.retryQuery(UnitOfWorkImpl.java:5536)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.retryQuery(AbstractSession.java:1928)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1857)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.retryQuery(UnitOfWorkImpl.java:5536)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1894)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.sessions.server.ClientSession.retryQuery(ClientSession.java:694)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.sessions.server.ClientSession.retryQuery(ClientSession.java:694)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.retryQuery(AbstractSession.java:1928)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1894)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:258)[324:org.eclipse.persistence.jpa:2.6.4.v20160829-44060b6] at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobDispatcher.run(ServiceRegistryJpaImpl.java:2934)[149:opencast-serviceregistry:6.4.0] at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl.getDispatchableJobsWithStatus(ServiceRegistryJpaImpl.java:1878)[149:opencast-serviceregistry:6.4.0] at org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:473)[324:org.eclipse.persistence.jpa:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1839)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1804)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_212] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_212] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_212] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_212] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_212] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_212] Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure at java.lang.Thread.run(Thread.java:748)[:1.8.0_212] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)[:1.8.0_212] The last packet successfully received from the server was 10,008 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)[:1.8.0_212] at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)[69:opencast-db:6.4.0] at java.lang.reflect.Constructor.newInstance(Constructor.java:423)[:1.8.0_212] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)[:1.8.0_212] at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)[69:opencast-db:6.4.0] at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)[69:opencast-db:6.4.0] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)[69:opencast-db:6.4.0] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)[69:opencast-db:6.4.0] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2494)[69:opencast-db:6.4.0] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)[69:opencast-db:6.4.0] at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)[69:opencast-db:6.4.0] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)[69:opencast-db:6.4.0] at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:353)[69:opencast-db:6.4.0] at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)[69:opencast-db:6.4.0] at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:1009)[323:org.eclipse.persistence.core:2.6.4.v20160829-44060b6] at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)[69:opencast-db:6.4.0] ... 39 more Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)[69:opencast-db:6.4.0] ... 49 more ```

Neither am I sure why Docker's default seems to be 600, nor which default timeout should be changed. I'll try to increase wait_timeout for my environment using 

command: [
  '--wait_timeout=28800'
]

in docker-compose.yml.

mtneug commented 5 years ago

Thanks @outofrange. This is also what we do in production. Would you create a pull request that updates our example docker-compose files to showcase a solution?

mtneug commented 5 years ago

This is fixed by #111 and #113.