I have a Spring Boot service deployed on AWS ECS. The service offers a REST API for clients and stores its data on a MongoDB Atlas M2 cluster (Replica Set - 3 nodes).
Recently, I noticed some strange logs popping up:
MongoSocketReadException
2023-02-17 15:09:46.998 INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster : Exception in monitor thread while connecting to server <server-id>.mongodb.net:27017
com.mongodb.MongoSocketReadException: Prematurely reached end of stream
at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:112) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:135) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:713) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.receiveMessageWithAdditionalTimeout(InternalStreamConnection.java:571) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:410) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.receive(InternalStreamConnection.java:369) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.lookupServerDescription(DefaultServerMonitor.java:221) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:157) ~[mongodb-driver-core-4.6.1.jar:na]
at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]
MongoSocketWriteException
2023-02-17 15:09:47.015 INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster : Exception in monitor thread while connecting to server <server-id>.mongodb.net:27017
com.mongodb.MongoSocketWriteException: Exception sending message
at com.mongodb.internal.connection.InternalStreamConnection.translateWriteException(InternalStreamConnection.java:684) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.sendMessage(InternalStreamConnection.java:555) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.sendCommandMessage(InternalStreamConnection.java:381) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:329) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.CommandHelper.sendAndReceive(CommandHelper.java:101) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.CommandHelper.executeCommand(CommandHelper.java:45) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnectionInitializer.initializeConnectionDescription(InternalStreamConnectionInitializer.java:131) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnectionInitializer.startHandshake(InternalStreamConnectionInitializer.java:73) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:182) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.lookupServerDescription(DefaultServerMonitor.java:193) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:157) ~[mongodb-driver-core-4.6.1.jar:na]
at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]
Caused by: java.net.SocketException: Connection reset
at java.base/java.net.SocketInputStream.read(Unknown Source) ~[na:na]
at java.base/java.net.SocketInputStream.read(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketInputRecord.read(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketInputRecord.decode(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLTransport.decode(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl.decode(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl.ensureNegotiated(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(Unknown Source) ~[na:na]
at com.mongodb.internal.connection.SocketStream.write(SocketStream.java:99) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.sendMessage(InternalStreamConnection.java:552) ~[mongodb-driver-core-4.6.1.jar:na]
... 10 common frames omitted
MongoSocketOpenException
2023-02-17 15:09:57.018 INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster : Exception in monitor thread while connecting to server <server-id>.mongodb.net:27017
com.mongodb.MongoSocketOpenException: Exception opening socket
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:70) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:180) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.lookupServerDescription(DefaultServerMonitor.java:193) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:157) ~[mongodb-driver-core-4.6.1.jar:na]
at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]
Caused by: java.net.ConnectException: Connection refused (Connection refused)
at java.base/java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:na]
at java.base/java.net.AbstractPlainSocketImpl.doConnect(Unknown Source) ~[na:na]
at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source) ~[na:na]
at java.base/java.net.AbstractPlainSocketImpl.connect(Unknown Source) ~[na:na]
at java.base/java.net.SocksSocketImpl.connect(Unknown Source) ~[na:na]
at java.base/java.net.Socket.connect(Unknown Source) ~[na:na]
at java.base/sun.security.ssl.SSLSocketImpl.connect(Unknown Source) ~[na:na]
at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:107) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.SocketStream.initializeSocket(SocketStream.java:79) ~[mongodb-driver-core-4.6.1.jar:na]
at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:65) ~[mongodb-driver-core-4.6.1.jar:na]
... 4 common frames omitted
As this seems to consistently happen after idle periods, I figured this may be a timeout issue. Various sources on the internet suggest setting maxIdleTimeMS, but to no avail. Please note that my service is working nonetheless and I can retrieve data via its REST API w/o any issues. It seems to be able to recover from the above-mentioned connection exceptions...
My connection string looks as follows:
mongodb+srv://<user>:<password>@<server>.mongodb.net/<db>?retryWrites=true&w=majority&maxIdleTimeMS=60000
What am I missing?
I cross-posted this question to the MongoDB Developer Community Forum and got the following reply from a MongoDB employee:
The key line in the logs is “Exception in monitor thread while connecting to server …”.
It’s normal to see these sorts of messages during planned maintenance of MongoDB servers (e.g. restarts for upgrades). The automatic retry features of the driver should hide most of these from your application and avoid exceptions being thrown to application threads via the drivers’s CRUD API.
So my take from this is that those logs are expected (note the INFO log level) and the result of an Atlas node becoming (temporarily) unavailable, which is a perfectly normal scenario that won’t affect my service thanks to the MongoDB driver’s retry features.
If you want to dig deeper into "monitor threads" and MongoDB's Server Discovery and Monitoring, you can have a look at the general description here and the gory details here.