I've a Java application that performs some aggregations on MongoDB, but sometimes it just hangs and throw a SocketTimeout exception. After the Exception the app will run just fine (for a bit, then it will probably raise again the exception).
I've just found this explanation that seems a possible cause but I'm not sure.
I initalize the MongoClient and keep the connection to the DB open. I'm not sure if this could be a problem and I should just get everytime the database and then let the database to be garbage collected (and close the connection).
Another approach could be ping periodically Mongo to keep the connection pool "fresh".
The client used is something like this:
public class DbClient {
private static MongoClient mongoClient;
private static MongoDatabase db;
private DbClient() {}
public static void init() throws Exception {
mongoClient = new MongoClient();
}
public static MongoDatabase getDB() {
if(mongoClient == null)
throw new IllegalStateException("Client not initialized!");
if(db == null) {
db = mongoClient.getDatabase("my_db");
}
return db;
}
}
Is this the possible cause of the SocketTimeout?
This is the exception thrown:
09:20:45.742 [qtp605535417-46] INFO org.mongodb.driver.connection - Closed connection [connectionId{localValue:16, serverValue:6562}] to myapp.com:27017 because there was a socket exception raised by this connection.
09:20:45.743 [qtp605535417-46] ERROR myapp.service.Api - Error processing request
com.mongodb.MongoSocketReadTimeoutException: Timeout while receiving message
at com.mongodb.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:474) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:225) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.CommandProtocol.execute(CommandProtocol.java:112) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:173) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:215) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:206) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:112) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.FindOperation$1.call(FindOperation.java:487) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.OperationIterable.iterator(OperationIterable.java:47) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.FindIterableImpl.iterator(FindIterableImpl.java:143) ~[mongo-java-driver-3.2.2.jar!/:na]
at myapp.common.db.service.dao.AnalysisMongoImpl.getAnalysis(AnalysisMongoImpl.java:66) ~[common-0.2.0-SNAPSHOT.jar!/:na]
at myapp.common.db.service.AnalysisServiceImpl.getAnalysis(AnalysisServiceImpl.java:31) ~[common-0.2.0-SNAPSHOT.jar!/:na]
at myapp.aggregator.service.Api$1.handle(Api.java:88) ~[aggregator-0.2.0-SNAPSHOT.jar!/:na]
at spark.webserver.MatcherFilter.doFilter(MatcherFilter.java:139) [spark-core-1.1.1.jar!/:na]
at spark.webserver.JettyHandler.doHandle(JettyHandler.java:54) [spark-core-1.1.1.jar!/:na]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:179) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.server.Server.handle(Server.java:451) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:252) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:266) [jetty-server-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:240) [jetty-io-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:596) [jetty-util-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:527) [jetty-util-9.0.2.v20130417.jar!/:9.0.2.v20130417]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_95]
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.7.0_95]
at java.net.SocketInputStream.read(SocketInputStream.java:152) ~[na:1.7.0_95]
at java.net.SocketInputStream.read(SocketInputStream.java:122) ~[na:1.7.0_95]
at com.mongodb.connection.SocketStream.read(SocketStream.java:85) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491) ~[mongo-java-driver-3.2.2.jar!/:na]
at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar!/:na]
... 34 common frames omitted
After few tries I've found out that it was a problem with the Azure's Load Balancer.
After 60s of inactivity it will disconnect any pending TCP connection.
After further digging I've found this post of the MongoDB diagnostics FAQ, and I've set the tcp keepalive to 120s:
sudo sysctl -w net.ipv4.tcp_keepalive_time=<value>
and I've also set the socketKeepAlive of the MongoClient to true:
MongoClientOptions.Builder options = MongoClientOptions.builder();
options.socketKeepAlive(true);
mongoClient = new MongoClient(mongoAddress, options.build());
After these fixes the issue seems gone!