Uploaded image for project: 'Java Driver'
  1. Java Driver
  2. JAVA-3159

Intermittent MongoSocketWriteException and MongoSocketReadException on a Mongo Vertx application

    XMLWordPrintableJSON

Details

    • Icon: Task Task
    • Resolution: Cannot Reproduce
    • Icon: Major - P3 Major - P3
    • None
    • 3.4.3
    • API
    • None
    • 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);
          }
        }
      

       

       

      Attachments

        Activity

          People

            Unassigned Unassigned
            satish.anupindi@aexp.com Satish Anupindi
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: