[JAVA-3159] Intermittent MongoSocketWriteException and MongoSocketReadException on a Mongo Vertx application Created: 30/Jan/19  Updated: 17/Jan/20  Resolved: 04/Mar/19

Status: Closed
Project: Java Driver
Component/s: API
Affects Version/s: 3.4.3
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Satish Anupindi Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

MongoDB running on Red Hat Enterprise Linux Server release 7.6 (Maipo) VMs.



 Description   

An application running in our environment is experiencing intermittent timeouts during read and write operations against MongoDB 3.6.7. The trace error is below : 

com.mongodb.MongoSocketWriteException: Exception sending messagecom.mongodb.MongoSocketWriteException: Exception sending message at com.mongodb.connection.InternalStreamConnection.translateWriteException(InternalStreamConnection.java:518) at com.mongodb.connection.InternalStreamConnection.access$1200(InternalStreamConnection.java:74) at com.mongodb.connection.InternalStreamConnection$3.failed(InternalStreamConnection.java:447) at com.mongodb.connection.AsynchronousSocketChannelStream$1.failed(AsynchronousSocketChannelStream.java:121) at com.mongodb.connection.AsynchronousSocketChannelStream$2.failed(AsynchronousSocketChannelStream.java:186) at com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter$WriteCompletionHandler.failed(AsynchronousSocketChannelStream.java:212) at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) at sun.nio.ch.Invoker$2.run(Invoker.java:218) at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:748)Caused by: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcherImpl.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) at sun.nio.ch.IOUtil.write(IOUtil.java:65) at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:691) at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382) at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399) at java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:577) at com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter.write(AsynchronousSocketChannelStream.java:194) at com.mongodb.connection.AsynchronousSocketChannelStream.pipeOneBuffer(AsynchronousSocketChannelStream.java:174) at com.mongodb.connection.AsynchronousSocketChannelStream.writeAsync(AsynchronousSocketChannelStream.java:109) at com.mongodb.connection.InternalStreamConnection.writeAsync(InternalStreamConnection.java:438) at com.mongodb.connection.InternalStreamConnection.sendMessageAsync(InternalStreamConnection.java:434) at com.mongodb.connection.InternalStreamConnection.sendCommandMessageAsync(InternalStreamConnection.java:348) at com.mongodb.connection.InternalStreamConnection.sendAndReceiveAsync(InternalStreamConnection.java:327) at com.mongodb.connection.UsageTrackingInternalConnection.sendAndReceiveAsync(UsageTrackingInternalConnection.java:113) at com.mongodb.connection.DefaultConnectionPool$PooledConnection.sendAndReceiveAsync(DefaultConnectionPool.java:452) at com.mongodb.connection.CommandProtocolImpl.executeAsync(CommandProtocolImpl.java:91) at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.executeAsync(DefaultServer.java:200) at com.mongodb.connection.DefaultServerConnection.executeProtocolAsync(DefaultServerConnection.java:279) at com.mongodb.connection.DefaultServerConnection.commandAsync(DefaultServerConnection.java:151) at com.mongodb.operation.MixedBulkWriteOperation.executeCommandAsync(MixedBulkWriteOperation.java:382) at com.mongodb.operation.MixedBulkWriteOperation.executeBatchesAsync(MixedBulkWriteOperation.java:314) at com.mongodb.operation.MixedBulkWriteOperation.access$900(MixedBulkWriteOperation.java:66) at com.mongodb.operation.MixedBulkWriteOperation$2$1.call(MixedBulkWriteOperation.java:233) at com.mongodb.operation.OperationHelper.validateWriteRequests(OperationHelper.java:175) at com.mongodb.operation.MixedBulkWriteOperation$2.call(MixedBulkWriteOperation.java:216) at com.mongodb.operation.OperationHelper$7.onResult(OperationHelper.java:525) at com.mongodb.operation.OperationHelper$7.onResult(OperationHelper.java:522) at com.mongodb.connection.DefaultServer$1.onResult(DefaultServer.java:99) at com.mongodb.connection.DefaultServer$1.onResult(DefaultServer.java:90) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:49) at com.mongodb.connection.DefaultConnectionPool.openAsync(DefaultConnectionPool.java:189) at com.mongodb.connection.DefaultConnectionPool.getAsync(DefaultConnectionPool.java:146) at com.mongodb.connection.DefaultServer.getConnectionAsync(DefaultServer.java:90) at com.mongodb.binding.AsyncClusterBinding$AsyncClusterBindingConnectionSource.getConnection(AsyncClusterBinding.java:114) at com.mongodb.async.client.ClientSessionBinding$SessionBindingAsyncConnectionSource.getConnection(ClientSessionBinding.java:124) at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:522) at com.mongodb.operation.OperationHelper.access$100(OperationHelper.java:61) at com.mongodb.operation.OperationHelper$AsyncCallableWithConnectionAndSourceCallback.onResult(OperationHelper.java:542) at com.mongodb.operation.OperationHelper$AsyncCallableWithConnectionAndSourceCallback.onResult(OperationHelper.java:530) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:49) at com.mongodb.async.client.ClientSessionBinding$1.onResult(ClientSessionBinding.java:57) at com.mongodb.async.client.ClientSessionBinding$1.onResult(ClientSessionBinding.java:51) at com.mongodb.binding.AsyncClusterBinding$1.onResult(AsyncClusterBinding.java:88) at com.mongodb.binding.AsyncClusterBinding$1.onResult(AsyncClusterBinding.java:82) at com.mongodb.connection.BaseCluster$ServerSelectionRequest.onResult(BaseCluster.java:421) at com.mongodb.connection.BaseCluster.handleServerSelectionRequest(BaseCluster.java:285) at com.mongodb.connection.BaseCluster.selectServerAsync(BaseCluster.java:145) at com.mongodb.binding.AsyncClusterBinding.getAsyncClusterBindingConnectionSource(AsyncClusterBinding.java:82) at com.mongodb.binding.AsyncClusterBinding.getWriteConnectionSource(AsyncClusterBinding.java:77) at com.mongodb.async.client.ClientSessionBinding.getWriteConnectionSource(ClientSessionBinding.java:51) at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:481) at com.mongodb.operation.MixedBulkWriteOperation.executeAsync(MixedBulkWriteOperation.java:210) at com.mongodb.async.client.AsyncOperationExecutorImpl$2.onResult(AsyncOperationExecutorImpl.java:100) at com.mongodb.async.client.AsyncOperationExecutorImpl$2.onResult(AsyncOperationExecutorImpl.java:92) at com.mongodb.async.client.ClientSessionHelper.createClientSession(ClientSessionHelper.java:60) at com.mongodb.async.client.ClientSessionHelper.withClientSession(ClientSessionHelper.java:48) at com.mongodb.async.client.AsyncOperationExecutorImpl.execute(AsyncOperationExecutorImpl.java:92) at com.mongodb.async.client.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:1114) at com.mongodb.async.client.MongoCollectionImpl.executeReplaceOne(MongoCollectionImpl.java:670) at com.mongodb.async.client.MongoCollectionImpl.replaceOne(MongoCollectionImpl.java:652) at io.vertx.ext.mongo.impl.MongoClientImpl.replaceDocumentsWithOptions(MongoClientImpl.java:261) at io.vertx.ext.mongo.impl.MongoClientImpl.replaceDocuments(MongoClientImpl.java:242) at com.axp.microdose.contexthub.verticles.ContextHubVerticle.lambda$handle$2(ContextHubVerticle.java:100) at io.vertx.ext.mongo.impl.MongoClientImpl.lambda$null$11(MongoClientImpl.java:758) at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:339) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:463) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ... 1 more

and 

2019-01-04T19:43:25.120750231Z app_name=one-data container_name=k8s_one-data_one-data-deployment-24-9s3bf_one-data_e2858ac9-fe12-11e8-bf65-fa163e95d45a_0 environment=e3_ipc2 ns=one-data pod_container=one-data pod_ip=192.168.82.126 pod_name=one-data-deployment-24-9s3bf message={"name":"com.axp.microdose.contexthub.util.ResponseDecorator","timestamp":"2019-01-04T19:43:25.116Z","level":"error","schemaVersion":"0.1","application":{"name":"com.axp.microdose.contexthub.verticles.ContextHubVerticle","version":"1"},"request":{"address":{"uri":"UpdateContextHub.v1"},"metadata":{"one-data-correlation-id":"ee2943cd-770f-4763-9a0b-7295108fa203"}},"message":"DB Query failed :: ","error":{"name":"com.mongodb.MongoSocketReadException","message":"Prematurely reached end of stream","throwLocation":{"file":"ResponseDecorator.java","method":"handleDBReadFailure","lineNumber":23},"stackTrace":"com.mongodb.MongoSocketReadException: Prematurely reached end of stream\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:231)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$BasicCompletionHandler.completed(AsynchronousSocketChannelStream.java:217)\n\tat sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)\n\tat sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)\n\tat sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)\n\tat sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276)\n\tat sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream.readAsync(AsynchronousSocketChannelStream.java:129)\n\tat com.mongodb.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:484)\n\tat com.mongodb.connection.InternalStreamConnection.access$1100(InternalStreamConnection.java:74)\n\tat com.mongodb.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:359)\n\tat com.mongodb.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:348)\n\tat com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:49)\n\tat com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:441)\n\tat com.mongodb.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:438)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$1.completed(AsynchronousSocketChannelStream.java:115)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$1.completed(AsynchronousSocketChannelStream.java:109)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$2.completed(AsynchronousSocketChannelStream.java:180)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$2.completed(AsynchronousSocketChannelStream.java:174)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter$WriteCompletionHandler.completed(AsynchronousSocketChannelStream.java:206)\n\tat com.mongodb.connection.AsynchronousSocketChannelStream$AsyncWritableByteChannelAdapter$WriteCompletionHandler.completed(AsynchronousSocketChannelStream.java:197)\n\tat sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)\n\tat sun.nio.ch.Invoker$2.run(Invoker.java:218)\n\tat sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat java.lang.Thread.run(Thread.java:748)\n"}}

We do see some amount of "end connection" messages in the MongoDB logs. The application is not explicitly closing any connection. we were wondering what would cause the connection to close - given that the default connection for Mongo Vertx is set to never timeout. 

 

2018-12-21T03:15:34.352-0700 I NETWORK  [conn344922] end connection 10.36.141.29:35898 (562 connections now open)
2018-12-21T03:15:34.353-0700 I NETWORK  [conn343949] end connection 10.36.141.29:53450 (561 connections now open)
2018-12-21T03:15:34.356-0700 I NETWORK  [conn343971] end connection 10.36.141.3:33616 (560 connections now open)

This is their application connection string : 

 {
  "meta": {
    "connectionString": "mongodb://contexthubuser:####@lpdospdb00241.phx.aexp.com:27017,lpdospdb00327.phx.aexp.com:27017,lpdospdb00332.phx.aexp.com:27017/contexthubdb?authSource=admin&connectTimeoutMS=5000&maxPoolSize=50&w=0"
  }
}

  @Override
  public void start(Future<Void> startFuture) {
    try {
      mongoClient = MongoClient.createShared(vertx, mongoConfig(), "CHMongoClientPool");
      contextHubAddress = config()
              .getJsonObject(MicrodoseConstants.LAMBDA)
              .getJsonObject(MicrodoseConstants.DEPLOYMENT)
              .getString(MicrodoseConstants.ADDRESS);
      functionVersion = config().getJsonObject(MicrodoseConstants.LAMBDA)
              .getJsonObject(MicrodoseConstants.DEPLOY_COORDINATES).getString(MicrodoseConstants.VERSION);
      vertx.eventBus().consumer(contextHubAddress, this::handle);
      log.info(MARKER, "Started ContextHubVerticle {} at address :: {}", functionVersion, contextHubAddress);
      startFuture.complete();
    } catch (Exception e) {
      log.error(MARKER, "Exception initializing ContextHubVerticle {}", functionVersion, e);
      startFuture.fail(e);
    }
  }

 

 



 Comments   
Comment by Alejandro Condori [ 17/Jan/20 ]

Hi, I have the same problem,  

Every 30 minutes of inactivity, the connection is closed and the request fails immediately the next request starts working correctly

 

UncategorizedMongoDbException: Exception sending message; nested exception is com.mongodb.MongoSocketWriteException

I have tried adding the following parameters to the connection string:

 

ssl=true&replicaSet=globaldb&autoReconnect=true&keepAlive=1000&reconnectTries=2&reconnectInterval=1000

 

However the problem persists. I am working with mongodb 3.2 by azure cosmodb and my backend uses spring boot webflux reactive

 

Comment by Ian Whalen (Inactive) [ 04/Mar/19 ]

satish.anupindi@aexp.com please let us know if you see this again. Closing as cannot repro for now.

Comment by Jeffrey Yemin [ 05/Feb/19 ]

DRIVERS-383 is the tracking ticket for all of our drivers. It only closes once every driver has completed the work.

So if they are using a version of the vertx client that wraps a 3.5+ Java driver, then keep-alive was already enabled.

Comment by Satish Anupindi [ 05/Feb/19 ]

Jeff -they use the mongo-vertx-client 3.5.1 ... 2531 shows closed.
but... https://jira.mongodb.org/browse/DRIVERS-383 is that different and is that for all drivers? That's still 'in progress' . 

Comment by Jeffrey Yemin [ 05/Feb/19 ]

Yes, that's possible.   Also, note that JAVA-2531 enables keep alive by default.  This was released in 3.5.0.

 

 

Comment by Satish Anupindi [ 05/Feb/19 ]

Thank you Jeff. We set the keepalive to true on the connection string, and we don't see those connection exceptions anymore. Is it possible we were using stale/broken connections and this helped avoid that?

Comment by Jeffrey Yemin [ 30/Jan/19 ]

Can you check the version of the driver you're using. Looking here I don't see a match for the provided stack trace.

Also, it looks like there should be an IOException as the cause of the MongoSocketWriteException. Does that appear in the logs, and if so can you include the stack trace? I do see on the second stack trace a "Prematurely reached end of stream", which usually indicates that somewhere between the driver and the server the connection was closed. The driver itself should never close a socket while waiting for a read or write to complete.

This may require some Wireshark debugging on your part. There's usually not enough information in the stack traces to determine the root cause.

Generated at Thu Feb 08 08:58:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.