No server chosen by WritableServerSelector

Hi, I have Spring backend app connected to Mongodb (configured with MongoDB Kubernetes Operator) on Kubernetes.

Sometimes (not for every write operation) there is problem with connection between database & backend app.

I attach the logs & config files. I hope you will guide me where I can read more to understand this problem.

Connection uri:

mongodb://username:password@kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local,kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local/kompas2?readPreference=primaryPreferred&ssl=false

Error from backend app

06:48:04.405 INFO org.mongodb.driver.connection       : Opened connection [connectionId{localValue:120, serverValue:49559}] to kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017
06:48:04.698 INFO org.mongodb.driver.cluster          : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=382123, setName='kompas2mongo', canonicalAddress=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, hosts=[kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017], passives=[], arbiters=[], primary='kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, topologyVersion=null, lastWriteDate=Mon Nov 07 06:47:54 GMT 2022, lastUpdateTimeNanos=4233730641707005}, ServerDescription{address=kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketReadException: Prematurely reached end of stream}}]}. Waiting for 30000 ms before timing out
06:48:04.699 INFO org.mongodb.driver.cluster          : Monitor thread successfully connected to server with description ServerDescription{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=374840, setName='kompas2mongo', canonicalAddress=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, hosts=[kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, topologyVersion=null, lastWriteDate=Mon Nov 07 06:48:04 GMT 2022, lastUpdateTimeNanos=4233734419530953}
06:48:04.700 INFO org.mongodb.driver.cluster          : Exception in monitor thread while connecting to server kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017
com.mongodb.MongoSocketOpenException: Exception opening socket
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:70)
at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:143)
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.lookupServerDescription(DefaultServerMonitor.java:188)
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:144)
at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: java.net.ConnectException: Connection refused
at java.base/sun.nio.ch.Net.pollConnect(Native Method)
at java.base/sun.nio.ch.Net.pollConnectNow(Net.java:589)
at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:542)
at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597)
at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:333)
at java.base/java.net.Socket.connect(Socket.java:648)
at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:107)
at com.mongodb.internal.connection.SocketStream.initializeSocket(SocketStream.java:79)
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:65)
... 4 common frames omitted
06:48:34.701 ERROR o.a.c.c.C.[.[.[.[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [/api] threw exception [Request processing failed; nested exception is org.springframework.dao.DataAccessResourceFailureException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=REPLICA_SET, servers=[{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, roundTripTime=0.4 ms, state=CONNECTED}, {address=kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]; nested exception is com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=REPLICA_SET, servers=[{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, roundTripTime=0.4 ms, state=CONNECTED}, {address=kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]] with root cause
com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=REPLICA_SET, servers=[{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, roundTripTime=0.4 ms, state=CONNECTED}, {address=kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]
at com.mongodb.internal.connection.BaseCluster.createTimeoutException(BaseCluster.java:413)
at com.mongodb.internal.connection.BaseCluster.selectServer(BaseCluster.java:118)
at com.mongodb.internal.connection.AbstractMultiServerCluster.selectServer(AbstractMultiServerCluster.java:50)
at com.mongodb.internal.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:105)
at com.mongodb.internal.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:100)
at com.mongodb.internal.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:92)
at com.mongodb.client.internal.ClientSessionBinding.getWriteConnectionSource(ClientSessionBinding.java:93)
at com.mongodb.internal.operation.OperationHelper.withReleasableConnection(OperationHelper.java:619)
at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:185)
at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:76)
at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:187)
at com.mongodb.client.internal.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:1009)
at com.mongodb.client.internal.MongoCollectionImpl.executeReplaceOne(MongoCollectionImpl.java:567)
at com.mongodb.client.internal.MongoCollectionImpl.replaceOne(MongoCollectionImpl.java:550)
at org.springframework.data.mongodb.core.MongoTemplate.lambda$saveDocument$18(MongoTemplate.java:1539)
at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:553)
at org.springframework.data.mongodb.core.MongoTemplate.saveDocument(MongoTemplate.java:1507)
at org.springframework.data.mongodb.core.MongoTemplate.doSave(MongoTemplate.java:1443)
at org.springframework.data.mongodb.core.MongoTemplate.save(MongoTemplate.java:1385)
at org.springframework.data.mongodb.repository.support.SimpleMongoRepository.save(SimpleMongoRepository.java:94)
at jdk.internal.reflect.GeneratedMethodAccessor313.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryFragmentMethodInvoker.lambda$new$0(RepositoryMethodInvoker.java:289)
at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:137)
at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:121)
at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:529)
at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:285)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:599)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:163)
at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:138)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:80)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.data.repository.core.support.MethodInvocationValidator.invoke(MethodInvocationValidator.java:98)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy163.save(Unknown Source)
at kompas2.recommendation.persistence.CustomCompanyRecommendationRepository.save(CompanyRecommendationRepository.kt)
at kompas2.recommendation.persistence.CustomCompanyRecommendationRepository.save(CompanyRecommendationRepository.kt:21)
at kompas2.recommendation.persistence.CustomCompanyRecommendationRepository$$FastClassBySpringCGLIB$$6cfc1920.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
at kompas2.recommendation.persistence.CustomCompanyRecommendationRepository$$EnhancerBySpringCGLIB$$e7db7271.save(<generated>)
at kompas2.recommendation.event.RecommendationCompanyUpdated.receive(RecommendationCompanyUpdated.kt:45)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:344)
at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:229)
at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:166)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:391)
at kompas2.company.events.CompanyUpdatedPublisher.publish(CompanyUpdated.kt:41)
at kompas2.company.application.CompanyBasicsWriter.update(CompanyBasicsWriter.kt:118)
at kompas2.company.application.CompanyBasicsWriter.updateMany(CompanyBasicsWriter.kt:110)
at kompas2.company.application.CompanyBasicsWriter.updateBasics(CompanyBasicsWriter.kt:103)
at kompas2.company.application.CompanyBasicsWriter.validateAndUpdateBasics(CompanyBasicsWriter.kt:41)
at kompas2.company.application.CompanyBasicsWriter$$FastClassBySpringCGLIB$$e20886b1.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
at kompas2.misc.metrics.SkipFirstMeanTiming$measureExecutionTime$2.invoke(SkipFirstMeanTiming.kt:25)
at kompas2.misc.metrics.SkipFirstMeanTimer.record$lambda-1(SkipFirstMeanTimer.kt:29)
at io.micrometer.core.instrument.AbstractTimer.recordCallable(AbstractTimer.java:138)
at kompas2.misc.metrics.SkipFirstMeanTimer.record(SkipFirstMeanTimer.kt:29)
at kompas2.misc.metrics.SkipFirstMeanTiming.measureExecutionTime(SkipFirstMeanTiming.kt:25)
at jdk.internal.reflect.GeneratedMethodAccessor213.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
at kompas2.company.application.CompanyBasicsWriter$$EnhancerBySpringCGLIB$$d206123c.validateAndUpdateBasics(<generated>)
at kompas2.company.web.CompanyBasicsController.updateBasics(CompanyBasicsController.kt:29)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doPut(FrameworkServlet.java:920)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:684)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:121)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:115)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at kompas2.security.JwtFilter.doFilterInternal(JwtFilter.kt:43)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
06:48:53.850 INFO org.mongodb.driver.cluster          : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=379787, setName='kompas2mongo', canonicalAddress=kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, hosts=[kompas2mongo-1.kompas2mongo-svc.test.svc.cluster.local:27017, kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, topologyVersion=null, lastWriteDate=Mon Nov 07 06:48:04 GMT 2022, lastUpdateTimeNanos=4233774899280824}, ServerDescription{address=kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused}}]}. Waiting for 30000 ms before timing out

MongoDB operator config:

apiVersion: mongodbcommunity.mongodb.com/v1
kind: MongoDBCommunity
metadata:
  name: kompas2mongo
spec:
  members: 2
  type: ReplicaSet
  version: "4.2.6"
  security:
    authentication:
      modes: ["SCRAM"]

Logs from mongo:

[2022-11-07T06:48:04.107+0000] [.info] [src/mongoctl/processctl.go:Update:3263] <kompas2mongo-0> [06:48:04.107] <DB_WRITE> Updated with query map[] and update [{$set [{agentFeatures [StateCache]} {lastVersion 2} {nextVersion 2}]}] and upsert=true on local.clustermanager
2022-11-07T06:48:04.376+0000 I  CONNPOOL [RS] Ending connection to host kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 due to bad connection status: HostUnreachable: Connection closed by peer; 1 connections to that host remain open
2022-11-07T06:48:04.377+0000 I  NETWORK  [conn9] end connection 10.244.1.183:47630 (9 connections now open)
2022-11-07T06:48:04.379+0000 I  REPL     [replication-20] Restarting oplog query due to error: HostUnreachable: error in fetcher batch callback :: caused by :: Connection closed by peer. Last fetched optime: { ts: Timestamp(1667803684, 102), t: 219 }. Restarts remaining: 1
2022-11-07T06:48:04.379+0000 I  CONNPOOL [replication-20] dropping unhealthy pooled connection to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017
2022-11-07T06:48:04.379+0000 I  CONNPOOL [RS] Connecting to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017
2022-11-07T06:48:04.379+0000 I  REPL     [replication-20] Scheduled new oplog query Fetcher source: kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp(1667803684, 102) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 219, readConcern: { afterClusterTime: Timestamp(0, 1) } } query metadata: { $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" } } active: 1 findNetworkTimeout: 7000ms getMoreNetworkTimeout: 10000ms shutting down?: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 304917 -- target:kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp(1667803684, 102) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 2000, batchSize: 13981010, term: 219, readConcern: { afterClusterTime: Timestamp(0, 1) } } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: {type: "NoRetryPolicy"}
2022-11-07T06:48:04.379+0000 I  NETWORK  [listener] connection accepted from 10.244.1.136:54320 #49559 (10 connections now open)
2022-11-07T06:48:04.380+0000 I  NETWORK  [conn49559] received client metadata from 10.244.1.136:54320 conn49559: { driver: { name: "mongo-java-driver|sync|spring-boot", version: "4.2.3" }, os: { type: "Linux", name: "Linux", architecture: "amd64", version: "4.19.0-17-amd64" }, platform: "Java/Azul Systems, Inc./14.0.2+12" }
2022-11-07T06:48:04.387+0000 I  REPL     [replication-18] Error returned from oplog query (no more query restarts left): HostUnreachable: error in fetcher batch callback :: caused by :: Error connecting to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 (10.244.1.183:27017) :: caused by :: Connection refused
...
2022-11-07T06:48:37.471+0000 I  REPL_HB  [replexec-4] Heartbeat to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 failed after 2 retries, response status: HostUnreachable: Error connecting to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 (10.244.1.183:27017) :: caused by :: Connection refused
2022-11-07T06:48:37.979+0000 I  ELECTION [replexec-3] Not starting an election, since we are not electable due to: Not standing for election because I cannot see a majority (mask 0x1)

Election after sec

2022-11-07T06:49:20.851+0000 I  ELECTION [replexec-4] Starting an election, since we've seen no PRIMARY in the past 10000ms
2022-11-07T06:49:20.851+0000 I  ELECTION [replexec-4] conducting a dry run election to see if we could be elected. current term: 219
2022-11-07T06:49:20.851+0000 I  REPL     [replexec-4] Scheduling remote command request for vote request: RemoteCommand 305346 -- target:kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 db:admin cmd:{ replSetRequestVotes: 1, setName: "kompas2mongo", dryRun: true, term: 219, candidateIndex: 1, configVersion: 2, lastCommittedOp: { ts: Timestamp(1667803684, 102), t: 219 } }
2022-11-07T06:49:20.851+0000 I  ELECTION [replexec-3] VoteRequester(term 219 dry run) received a yes vote from kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017; response message: { term: 219, voteGranted: true, reason: "", ok: 1.0, $clusterTime: { clusterTime: Timestamp(1667803684, 102), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, operationTime: Timestamp(1667803684, 102) }
2022-11-07T06:49:20.851+0000 I  ELECTION [replexec-3] dry election run succeeded, running for election in term 220
2022-11-07T06:49:20.851+0000 I  ELECTION [conn11] Received vote request: { replSetRequestVotes: 1, setName: "kompas2mongo", dryRun: true, term: 219, candidateIndex: 1, configVersion: 2, lastCommittedOp: { ts: Timestamp(1667803684, 102), t: 219 } }
2022-11-07T06:49:20.851+0000 I  ELECTION [conn11] Sending vote response: { term: 219, voteGranted: true, reason: "" }
2022-11-07T06:49:20.852+0000 I  REPL     [replexec-3] Scheduling remote command request for vote request: RemoteCommand 305347 -- target:kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 db:admin cmd:{ replSetRequestVotes: 1, setName: "kompas2mongo", dryRun: false, term: 220, candidateIndex: 1, configVersion: 2, lastCommittedOp: { ts: Timestamp(1667803684, 102), t: 219 } }
2022-11-07T06:49:20.852+0000 I  ELECTION [conn11] Received vote request: { replSetRequestVotes: 1, setName: "kompas2mongo", dryRun: false, term: 220, candidateIndex: 1, configVersion: 2, lastCommittedOp: { ts: Timestamp(1667803684, 102), t: 219 } }
2022-11-07T06:49:20.852+0000 I  ELECTION [conn11] Sending vote response: { term: 220, voteGranted: true, reason: "" }
2022-11-07T06:49:20.852+0000 I  ELECTION [replexec-4] VoteRequester(term 220) received a yes vote from kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017; response message: { term: 220, voteGranted: true, reason: "", ok: 1.0, $clusterTime: { clusterTime: Timestamp(1667803684, 102), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, operationTime: Timestamp(1667803684, 102) }
2022-11-07T06:49:20.852+0000 I  ELECTION [replexec-4] election succeeded, assuming primary role in term 220

And after that database connection is restored

Also on stackoverflow:

Hi @Lukasz_Milunas and welcome to the MongoDB community!!

From the logs shared above, it looks like, there are some issues in the kubernetes environment or deployment (i.e. “HostUnreachable” from a replica set node, and “Connection refused” from the application side)
It would be helpful if you could share a few more details to understand further:

  1. Is there a pattern that you are observing when the connection goes down and when the application connects to database?
  2. If the service IP mentioned in the logs Error connecting to kompas2mongo-0.kompas2mongo-svc.test.svc.cluster.local:27017 (10.244.1.183:27017) correct. You can check the following using

kubectl get pods -n namespace -owide

  1. Do you see the connection automatically recovering itself from after some amount of time. If yes, how long it take for the pod to make successful connection again?

  2. Can you share the output for rs.status() for a successful and unsuccessful connection.

  3. Also, please make sure you are following the right documentation to set up the replica set using the kubernetes deployment.
    You can verify the steps from the documentation on Deploy a Replica Set in Kubernetes Environment.

Since MongoDB version 4.2.6 is an old version, please upgrade to the latest in 4.2 series which is currently 4.2.23 to ensure you’re not seeing a fixed issue. I also would recommend you to have a minimum of 3 replica set deployment as per Replica Set Deployment Architectures

Thanks
Aasawari

Hi @Aasawari, thank you very much for response. :slight_smile:

  1. Unfortunately I can’t see any pattern. What would you recommend looking at besides the logs?

  2. Yes

  3. Yes, ~ 1,2 sec

14:24:47.543 INFO org.mongodb.driver.cluster          : Exception in monitor thread while connecting to server
14:26:00.244 INFO org.mongodb.driver.cluster          : Monitor thread successfully connected to server 
  1. It can be hard for unsuccessful. Usually I’m finding errors in logs and not while they occurs. I’ll add output for successful rs.status()

  2. Thanks! It definitely helps with electing new primary (and faster connection recovery). Unfortunately don’t solve problem with losing connections.

Since MongoDB version 4.2.6 is an old version, please upgrade to the latest in 4.2 series which is currently 4.2.23 to ensure you’re not seeing a fixed issue

Thanks, will do :slight_smile: