Apologies for bit-misleading title.
I have a device-id
application, which basically saves any new deviceId
sent to system or return details of any deviceId
as per request.
This issue is not very frequent but it does pop up now-and-then and google is not helping solve it!
Datastore is on MariaDB-10.1.35. Service has a QPS activity of ~2.5k, couple of google links suggested to increase wait_timeout
but given the QPS, a wait_timeout of 600seconds is a safe bet.
prod config has:
validationQuery: "/* Health Check */ SELECT 1"
wait_timeout: 600
standard function ( built around hystrix wrapper is as below )
public Optional<DeviceId> get(final String token) throws DeviceIdException {
try {
return CommandFactory.<Optional<DeviceId>>create("DeviceId", "Get")
.executor(() -> DaoRegistry.getDeviceIdLookupDao().get(token))
.toObservable()
.toBlocking()
.single();
} catch (Exception e) {
log.error("Get error {}", e);
throw DeviceIdException.builder()
.code(Response.Status.INTERNAL_SERVER_ERROR.getStatusCode())
.errorCode("DI000")
.message("Oops! Something went wrong!")
.build();
}
}
Stack dump as below
Caused by: org.hibernate.TransactionException: JDBC begin transaction failed:
at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:73)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:263)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:214)
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:56)
at org.hibernate.internal.AbstractSharedSessionContract.beginTransaction(AbstractSharedSessionContract.java:409)
at io.dropwizard.sharding.utils.TransactionHandler.beginTransaction(TransactionHandler.java:96)
at io.dropwizard.sharding.utils.TransactionHandler.beforeStart(TransactionHandler.java:48)
at io.dropwizard.sharding.utils.Transactions.execute(Transactions.java:52)
at io.dropwizard.sharding.utils.Transactions.execute(Transactions.java:46)
at io.dropwizard.sharding.dao.LookupDao.get(LookupDao.java:192)
at io.dropwizard.sharding.dao.LookupDao.get(LookupDao.java:176)
at com.myOrganisation.MyCustomService.commands.DeviceIdCommands.lambda$get$1(DeviceIdCommands.java:73)
at io.appform.core.hystrix.GenericHystrixCommand$1.run(GenericHystrixCommand.java:43)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:302)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:298)
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:46)
... 26 common frames omitted
Caused by: java.sql.SQLNonTransientConnectionException: (conn=2997305) unexpected end of stream, read 0 bytes from 4 (socket was closed by server)
at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.get(ExceptionMapper.java:234)
at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getException(ExceptionMapper.java:165)
at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:238)
at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:356)
at org.mariadb.jdbc.MariaDbStatement.executeUpdate(MariaDbStatement.java:545)
at org.mariadb.jdbc.MariaDbConnection.setAutoCommit(MariaDbConnection.java:751)
at sun.reflect.GeneratedMethodAccessor39.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy53.setAutoCommit(Unknown Source)
at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:67)
... 41 common frames omitted
Caused by: java.sql.SQLException: unexpected end of stream, read 0 bytes from 4 (socket was closed by server)
Query is: set autocommit=0
java thread: hystrix-DeviceId.Get-4
at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:126)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:222)
at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:350)
... 53 common frames omitted
Caused by: java.io.EOFException: unexpected end of stream, read 0 bytes from 4 (socket was closed by server)
at org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacketArray(StandardPacketInputStream.java:238)
at org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacket(StandardPacketInputStream.java:207)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.readPacket(AbstractQueryProtocol.java:1427)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:1407)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:219)
... 54 common frames omitted
Can some one help with right direction here as to what might be broken / missing?
Looks like a wait_timeout
issue. If the value is set to be in hours; reduce it to a reasonable time; say 600 seconds. It would be overoptimistic to expect the connection to be kept alive for hours. Hope this helps.