[JAVA-3062] Connection Reset Created: 31/Oct/18  Updated: 11/Sep/19  Resolved: 14/Dec/18

Status: Closed
Project: Java Driver
Component/s: Connection Management
Affects Version/s: 3.8.2
Fix Version/s: None

Type: Task Priority: Minor - P4
Reporter: Matan Shukry Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

Every once in a while I'm getting a connection reset exception when querying mongodb. A second query succeed, and after some time it will fail again. Not really sure why it's even failing to begin with, and there seems to be no relevant logs in mongo either.

Attaching stacktrace:

java.net.SocketException: Connection reset 
at java.net.SocketInputStream.read(SocketInputStream.java:210) ~[na:1.8.0_191] 
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_191] 
at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:89) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:554) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136) ~[mongodb-driver-core-3.8.2.jar:na] 
at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:462) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:406) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:695) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.operation.FindOperation.execute(FindOperation.java:83) ~[mongodb-driver-core-3.8.2.jar:na] at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179) ~[mongodb-driver-3.8.2.jar:na] at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:132) ~[mongodb-driver-3.8.2.jar:na] at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:86) ~[mongodb-driver-3.8.2.jar:na] at org.springframework.data.mongodb.core.MongoTemplate.executeFindMultiInternal(MongoTemplate.java:2643) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.mongodb.core.MongoTemplate.doFind(MongoTemplate.java:2403) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.mongodb.core.ExecutableFindOperationSupport$ExecutableFindSupport.doFind(ExecutableFindOperationSupport.java:214) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.mongodb.core.ExecutableFindOperationSupport$ExecutableFindSupport.all(ExecutableFindOperationSupport.java:157) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.mongodb.repository.query.AbstractMongoQuery.lambda$getExecution$1(AbstractMongoQuery.java:115) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.mongodb.repository.query.AbstractMongoQuery.execute(AbstractMongoQuery.java:99) ~[spring-data-mongodb-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:605) ~[spring-data-commons-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.lambda$invoke$3(RepositoryFactorySupport.java:595) ~[spring-data-commons-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:595) ~[spring-data-commons-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:59) ~[spring-data-commons-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61) ~[spring-data-commons-2.1.2.RELEASE.jar:2.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at com.sun.proxy.$Proxy148.findAllByOwnerOrderByCreatedAt(Unknown Source) ~[na:na] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_191] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_191] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_191] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_191] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139) ~[spring-tx-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.1.2.RELEASE.jar:5.1.2.RELEASE] at com.sun.proxy.$Proxy148.findAllByOwnerOrderByCreatedAt(Unknown Source) ~[na:na]



 Comments   
Comment by Jeffrey Yemin [ 31/Oct/18 ]

Hi msh

It's just not possible to determine what the root cause is given this information. I suggest that you run Wireshark, or some equivalent network tracing tool, to figure out what's happening on the network.

Comment by Matan Shukry [ 31/Oct/18 ]

Hi Jeff,

I didn't mention it before because I didn't thought it was relevant, but you mentioned network so it might - I'm using mongodb inside a docker (using minikube). I'm also using it with Reddis and Elasticsearch though, and no problems in any of them. And most of the time, mongo is also working great.

 

Anyway, regarding the logs: I've tried to look in them, but it looks normal to me. I might be wrong though; this is what's in them (it pretty much repeats):

2018-10-31T08:12:31.015+0000 I NETWORK  [conn22] end connection 172.17.0.1:64261 (7 connections now open)
2018-10-31T08:12:31.032+0000 I NETWORK  [conn23] end connection 172.17.0.1:64262 (6 connections now open)
2018-10-31T08:13:51.410+0000 I NETWORK  [conn34] end connection 172.17.0.1:59451 (5 connections now open)
2018-10-31T08:13:51.411+0000 I NETWORK  [conn35] end connection 172.17.0.1:59452 (4 connections now open)
2018-10-31T08:14:06.316+0000 I NETWORK  [listener] connection accepted from 172.17.0.1:63235 #38 (5 connections now open)
2018-10-31T08:14:06.332+0000 I NETWORK  [conn38] received client metadata from 172.17.0.1:63235 conn38: { driver: { name: "mongo-java-driver", version: "3.8.2" }, os: { type: "Windows", name: "Windows 10", architecture: "amd64", version: "10.0" }, platform: "Java/OracleCorporation/1.8.0_191-b12" }
2018-10-31T08:14:06.912+0000 I NETWORK  [listener] connection accepted from 172.17.0.1:63236 #39 (6 connections now open)
2018-10-31T08:14:06.913+0000 I NETWORK  [conn39] received client metadata from 172.17.0.1:63236 conn39: { driver: { name: "mongo-java-driver", version: "3.8.2" }, os: { type: "Windows", name: "Windows 10", architecture: "amd64", version: "10.0" }, platform: "Java/OracleCorporation/1.8.0_191-b12" }
2018-10-31T08:19:25.228+0000 I NETWORK  [conn39] end connection 172.17.0.1:63236 (5 connections now open)
2018-10-31T08:23:24.556+0000 I NETWORK  [listener] connection accepted from 172.17.0.1:51524 #40 (6 connections now open)
2018-10-31T08:23:24.559+0000 I NETWORK  [conn40] received client metadata from 172.17.0.1:51524 conn40: { driver: { name: "mongo-java-driver", version: "3.8.2" }, os: { type: "Windows", name: "Windows 10", architecture: "amd64", version: "10.0" }, platform: "Java/OracleCorporation/1.8.0_191-b12" }

I am restarting my app many times (it is dev), so connection end/accepted make sense due to that, hence why the logs seems fine to me. 

Comment by Jeffrey Yemin [ 31/Oct/18 ]

Hi msh

The driver won't close a connection like this so something is happening either in the MongoDB server or in the network (e.g. a load balancer). Please start by checking for clues in the server logs to see if there are any connection drops logged there.

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