[CSHARP-4219] MongoDB.Driver.MongoConnectionException shouldn't be wrapped in a System.TimeoutException Created: 17/Jun/22  Updated: 27/Oct/23  Resolved: 14/Jul/22

Status: Closed
Project: C# Driver
Component/s: None
Affects Version/s: 2.16.0
Fix Version/s: None

Type: Improvement Priority: Unknown
Reporter: Jean Llorca Assignee: Dmitry Lukyanov (Inactive)
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

When the connection between client and server is impossible the exception is rethrown inside a System.Timeout exception.
I believe encapsulating the root cause of the problem hides the root cause of the problem, it also makes searching for hints over internet - S/O or here confusing as several exception are wrapped similarly.

 

System.TimeoutException: A timeout occurred after 30000ms selecting a server using CompositeServerSelector{ Selectors = MongoDB.Driver.MongoClient+AreSessionsSupportedServerSelector, LatencyLimitingServerSelector

{ AllowedLatencyRange = 00:00:00.0150000 }

, OperationsCountServerSelector }. Client view of cluster state is { ClusterId : "1", ConnectionMode : "ReplicaSet", Type : "ReplicaSet", State : "Disconnected", Servers : [{ ServerId: "

{ ClusterId : 1, EndPoint : "Unspecified/cluster0-shard-00-00.m6alu.mongodb.net:27017" }

", EndPoint: "Unspecified/cluster0-shard-00-00.m6alu.mongodb.net:27017", ReasonChanged: "Heartbeat", State: "Disconnected", ServerVersion: , TopologyVersion: , Type: "Unknown", HeartbeatException: "MongoDB.Driver.MongoConnectionException: An exception occurred while opening a connection to the server.
---> MongoDB.Driver.MongoConnectionException: An exception occurred while receiving a message from the server.
---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.
   at MongoDB.Driver.Core.Misc.StreamExtensionMethods.ReadBytes(Stream stream, Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
— End of stack trace from previous location —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveMessage(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.WireProtocol.CommandUsingQueryMessageWireProtocol`1.Execute(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.HelloHelper.GetResult(IConnection connection, CommandWireProtocol`1 helloProtocol, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.ConnectionInitializer.SendHello(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.Open(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.InitializeConnection(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.Heartbeat(CancellationToken cancellationToken)", LastHeartbeatTimestamp: "2022-06-16T06:54:19.2590694Z", LastUpdateTimestamp: "2022-06-16T06:54:19.2590697Z" }, { ServerId: "

{ ClusterId : 1, EndPoint : "Unspecified/cluster0-shard-00-01.m6alu.mongodb.net:27017" }

", EndPoint: "Unspecified/cluster0-shard-00-01.m6alu.mongodb.net:27017", ReasonChanged: "Heartbeat", State: "Disconnected", ServerVersion: , TopologyVersion: , Type: "Unknown", HeartbeatException: "MongoDB.Driver.MongoConnectionException: An exception occurred while opening a connection to the server.
---> MongoDB.Driver.MongoConnectionException: An exception occurred while receiving a message from the server.
---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.
   at MongoDB.Driver.Core.Misc.StreamExtensionMethods.ReadBytes(Stream stream, Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
— End of stack trace from previous location —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveMessage(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.WireProtocol.CommandUsingQueryMessageWireProtocol`1.Execute(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.HelloHelper.GetResult(IConnection connection, CommandWireProtocol`1 helloProtocol, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.ConnectionInitializer.SendHello(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.Open(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.InitializeConnection(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.Heartbeat(CancellationToken cancellationToken)", LastHeartbeatTimestamp: "2022-06-16T06:54:18.3550509Z", LastUpdateTimestamp: "2022-06-16T06:54:18.3550512Z" }, { ServerId: "

{ ClusterId : 1, EndPoint : "Unspecified/cluster0-shard-00-02.m6alu.mongodb.net:27017" }

", EndPoint: "Unspecified/cluster0-shard-00-02.m6alu.mongodb.net:27017", ReasonChanged: "Heartbeat", State: "Disconnected", ServerVersion: , TopologyVersion: , Type: "Unknown", HeartbeatException: "MongoDB.Driver.MongoConnectionException: An exception occurred while opening a connection to the server.
---> MongoDB.Driver.MongoConnectionException: An exception occurred while receiving a message from the server.
---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.
   at MongoDB.Driver.Core.Misc.StreamExtensionMethods.ReadBytes(Stream stream, Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
— End of stack trace from previous location —
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveBuffer(Int32 responseTo, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveMessage(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.WireProtocol.CommandUsingQueryMessageWireProtocol`1.Execute(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.HelloHelper.GetResult(IConnection connection, CommandWireProtocol`1 helloProtocol, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.ConnectionInitializer.SendHello(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   --- End of inner exception stack trace —
   at MongoDB.Driver.Core.Connections.BinaryConnection.OpenHelper(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Connections.BinaryConnection.Open(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.InitializeConnection(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.ServerMonitor.Heartbeat(CancellationToken cancellationToken)", LastHeartbeatTimestamp: "2022-06-16T06:54:19.9015049Z", LastUpdateTimestamp: "2022-06-16T06:54:19.9015051Z" }] }.
   at MongoDB.Driver.Core.Clusters.Cluster.ThrowTimeoutException(IServerSelector selector, ClusterDescription description)
   at MongoDB.Driver.Core.Clusters.Cluster.WaitForDescriptionChangedHelper.HandleCompletedTask(Task completedTask)
   at MongoDB.Driver.Core.Clusters.Cluster.WaitForDescriptionChangedAsync(IServerSelector selector, ClusterDescription description, Task descriptionChangedTask, TimeSpan timeout, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Clusters.Cluster.SelectServerAsync(IServerSelector selector, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoClient.AreSessionsSupportedAfterServerSelectionAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.MongoClient.AreSessionsSupportedAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.MongoClient.StartImplicitSessionAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.UsingImplicitSessionAsync[TResult](Func`2 funcAsync, CancellationToken cancellationToken)
   at MongoDB.Driver.IAsyncCursorSourceExtensions.ToListAsync[TDocument](IAsyncCursorSource`1 source, CancellationToken cancellationToken)



 Comments   
Comment by PM Bot [ 14/Jul/22 ]

There hasn't been any recent activity on this ticket, so we're resolving it. Thanks for reaching out! Please feel free to comment on this if you're able to provide more information.

Comment by Dmitry Lukyanov (Inactive) [ 29/Jun/22 ]

While we agree that having as more clear exception as possible is a good goal, it's not really possible for the current architecture because changing it, at the very least, would break many existing applications.
This timeout exception says not that some exception happened, but that there was no any successful server selecting attempt during some particular period and provided exception is just the last one. Other endpoints could also have exceptions and only looking at the whole picture we may understand the happened issue.

Comment by Jean Llorca [ 29/Jun/22 ]

Hi Dmitry,

Thank you for your answer. I understand the meaning of the exception relative to the architecture of the driver. I still believe there should be a better policy regarding the exception that get passed to the callers.

Well this is where I beg to differ.
The most common scenario when this particular exception gets thrown for instance is when the application starts, because security settings have been improperly set up for instance,

Yet one of the first thing I do is ensuring the various indexes are correct. I found there was a nice method allowing to set them up all at once. Having a TimeOutException lead me astray in trying one by one, in trying to set the deprecated IsBackground flag and so one before taking another look at the exception and finding out that all kind of error would be wrapped this way from the way the stack is built.

While having a nice guide to help troubleshoot is fine, actually caring for the developer experience while coding the client can actually help.

Each layer of the exception should have meaning, and the top most exception should have the most meaning, as it is the one that may end up in a specific catch, a retry condition and so on, or simply deciding on the severity of the log message.

Encapsulating every exception coming through this layer prevents to make such things but instead trigger the action based on some inner exception is cumbersome.

I hope I have made my point.

Best regards,
Jean Llorca

Comment by Dmitry Lukyanov (Inactive) [ 28/Jun/22 ]

Hey jean.llorca@inexto.com,

The behavior you're seeing is expected and related to how the driver works with servers.

I can provide some brief introduction. Each mongo client has ClusterDescription that represents current states of all tracked server endpoints. Additionally the driver creates internal background threads for each provided endpoint. Each of these background threads monitors state of a particular endpoint and updates ClusterDescription accordingly.
When you call any operation, the driver should select suitable healthy server based on the current state of ClusterDescription. So the TimeoutException you're observing just says that no healthy server has been found in last 30 seconds during server selecting. It may or may not be related to a particular exception. To investigate why it happens, the exception message prints the current ClusterDescription that provides all information about the servers states at the moment when the driver wasn't able to find a healthy server.

Please note that we're working on making such investigations easier for users. You can track this work here

Generated at Wed Feb 07 21:47:35 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.