Loading...

Type: Task
Resolution: Cannot Reproduce
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.4.3
Component/s: API
Labels:
None
Environment:
MongoDB running on Red Hat Enterprise Linux Server release 7.6 (Maipo) VMs.

Confidence Status:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name:
None
Goal Link:
None

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);
    }
  }

Details

Description

Attachments

Activity

People

Dates