|
There's a distinct possibility that it's an issue in SERVER itself. (3.2.4 in our case)
I was able to make it happen about a dozen times yesterday, primarily in a VERY heavily threaded scenario. It was, however, entirely unpredictable in its occurrence... still happening once every million or so requests. I was monitoring every single bit of the server at the time it happened, and there were hundreds of other requests during that 5 second timeout window for one of the queries. The server was up and pushing 10-15mbps at the time, and very responsive. Ongoing connections around the same time are fine. We were not near any system limits, such as connection limits or system handles. If there are other possible stats that might be tracked around the time, we can get those.
Unfortunately the scenario in which we recreated this is not one that we can do during regular business hours, and is one that takes about an hour to complete, sometimes without issue 'til near the end, and sometimes without any issues whatsoever.
What's hard for us is that we're dumping the entire stack trace all the way down as far as we can find inner exceptions... and there isn't even a mention of anything in our code. It almost seems like an unused pool connection is timing out and improperly throwing to another thread. It almost always happens within a Parallel.ForEach, likely because that's the easiest way to create the massive threading we use.
|
|
This may be unrelated, but we're seeing something similar. It never happens in our web code, but occasionally happens in our back-end code, that we'll have a timeout. It's very rare, happening less than once every 100,000 queries, often less than 1 in a billion queries... but it happens. Logs from the mongo machine itself show plenty of successful connections around and during the same time as this failure.
Timed out connecting to Unspecified/hostname:27017. Timeout was 00:00:05.
|
at MongoDB.Driver.Core.Connections.TcpStreamFactory.<ConnectAsync>d__4.MoveNext()
|
--- End of stack trace from previous location where exception was thrown ---
|
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
|
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
|
at MongoDB.Driver.Core.Connections.TcpStreamFactory.<CreateStreamAsync>d__3.MoveNext()
|
--- End of stack trace from previous location where exception was thrown ---
|
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
|
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
|
at MongoDB.Driver.Core.Connections.BinaryConnection.<OpenAsyncHelperAsync>d__44.MoveNext()
|
|
|
I solved the issue, I think. I'm reposting here for your info or anyone else searching for the same issue.
The mongodb log files revealed that using my connection string, it was trying to connect to the admin database, but the user was not defined in the admin database, but in the operational database. Changing the connection string to include the database worked properly.
As for why it always worked the second time through, I'm not sure.
|
|
I'm also receiving this same error. There is a retry mechanism built-in. The process fails the first time, but immediately retries and is successful. Please tell me what else I can provide to help in solving the issue.
Driver version: 2.2.3.3
Connection string: mongodb://
{0}:{1}@localhost{0}
:
{1}
are filled in at runtime with values from the config file.
Here is the full call stack of what I'm seeing as the result:
System.TimeoutException: A timeout occured after 30000ms selecting a server using CompositeServerSelector{ Selectors = WritableServerSelector, LatencyLimitingServerSelector
{ AllowedLatencyRange = 00:00:00.0150000 }
}. Client view of cluster state is { ClusterId : "1", ConnectionMode : "Automatic", Type : "Unknown", State : "Disconnected", Servers : [{ ServerId: "
{ ClusterId : 1, EndPoint : "Unspecified/localhost:27017" }
", EndPoint: "Unspecified/localhost:27017", State: "Disconnected", Type: "Unknown", HeartbeatException: "MongoDB.Driver.MongoConnectionException: An exception occurred while opening a connection to the server. ---> MongoDB.Driver.MongoAuthenticationException: Unable to authenticate using sasl protocol mechanism SCRAM-SHA-1. ---> MongoDB.Driver.MongoCommandException: Command saslStart failed: Authentication failed..
at MongoDB.Driver.Core.WireProtocol.CommandWireProtocol`1.ProcessReply(ConnectionId connectionId, ReplyMessage`1 reply)
at MongoDB.Driver.Core.WireProtocol.CommandWireProtocol`1.<ExecuteAsync>d__11.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MongoDB.Driver.Core.Authentication.SaslAuthenticator.<AuthenticateAsync>d__7.MoveNext()
— End of inner exception stack trace —
at MongoDB.Driver.Core.Authentication.SaslAuthenticator.<AuthenticateAsync>d__7.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MongoDB.Driver.Core.Authentication.AuthenticationHelper.<AuthenticateAsync>d__1.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MongoDB.Driver.Core.Connections.ConnectionInitializer.<InitializeConnectionAsync>d__1.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
at MongoDB.Driver.Core.Connections.BinaryConnection.<OpenHelperAsync>d__47.MoveNext()
— End of inner exception stack trace —
at MongoDB.Driver.Core.Connections.BinaryConnection.<OpenHelperAsync>d__47.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MongoDB.Driver.Core.Servers.ClusterableServer.<HeartbeatAsync>d__42.MoveNext()" }] }.
at MongoDB.Driver.Core.Clusters.Cluster.WaitForDescriptionChangedHelper.HandleCompletedTask(Task completedTask)
at MongoDB.Driver.Core.Clusters.Cluster.WaitForDescriptionChanged(IServerSelector selector, ClusterDescription description, Task descriptionChangedTask, TimeSpan timeout, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Clusters.Cluster.SelectServer(IServerSelector selector, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Bindings.WritableServerBinding.GetWriteChannelSource(CancellationToken cancellationToken)
at MongoDB.Driver.Core.Operations.BulkMixedWriteOperation.Execute(IWriteBinding binding, CancellationToken cancellationToken)
at MongoDB.Driver.MongoCollectionImpl`1.ExecuteWriteOperation[TResult](IWriteOperation`1 operation, CancellationToken cancellationToken)
at MongoDB.Driver.MongoCollectionImpl`1.BulkWrite(IEnumerable`1 requests, BulkWriteOptions options, CancellationToken cancellationToken)
at MongoDB.Driver.MongoCollectionBase`1.UpdateOne(FilterDefinition`1 filter, UpdateDefinition`1 update, UpdateOptions options, CancellationToken cancellationToken)
at Samtec.Marketing.TickerAggregator.ManufacturingOrderChangedHandler.UpdateMongo(DateTime date, Int32 mfgOrderId, Int32 facilityId, Int32 partsCompleted) in d:\3\479\src\ManufacturingOrderChangedHandler.cs:line 74
at Samtec.Marketing.TickerAggregator.ManufacturingOrderChangedHandler.Handle(IManufacturingOrderChanged message) in d:\3\479\src\ManufacturingOrderChangedHandler.cs:line 61
at NServiceBus.Unicast.MessageHandlerRegistry.Invoke(Object handler, Object message, Dictionary`2 dictionary) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\MessageHandlerRegistry.cs:line 124
at NServiceBus.InvokeHandlersBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\InvokeHandlersBehavior.cs:line 23
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.SetCurrentMessageBeingHandledBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\SetCurrentMessageBeingHandledBehavior.cs:line 17
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.LoadHandlersBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\LoadHandlersBehavior.cs:line 45
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.ApplyIncomingMessageMutatorsBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\MessageMutator\ApplyIncomingMessageMutatorsBehavior.cs:line 23
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.ExecuteLogicalMessagesBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Messages\ExecuteLogicalMessagesBehavior.cs:line 24
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.CallbackInvocationBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\CallbackInvocationBehavior.cs:line 22
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.DeserializeLogicalMessagesBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Messages\DeserializeLogicalMessagesBehavior.cs:line 47
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.SubscriptionReceiverBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Subscriptions\MessageDrivenSubscriptions\SubscriptionReceiverBehavior.cs:line 32
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.UnitOfWorkBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\UnitOfWork\UnitOfWorkBehavior.cs:line 42
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.ChildContainerBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\ChildContainerBehavior.cs:line 17
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.ProcessingStatisticsBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Monitoring\ProcessingStatisticsBehavior.cs:line 23
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.<>c_DisplayClass4_0.<InvokeNext>b_0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
at NServiceBus.AuditBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Audit\AuditBehavior.cs:line 20
at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
at NServiceBus.BehaviorChain`1.Invoke() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 61
at NServiceBus.Pipeline.PipelineExecutor.Execute[T](BehaviorChain`1 pipelineAction, T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 129
at NServiceBus.Unicast.Transport.TransportReceiver.ProcessMessage(TransportMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 346
at NServiceBus.Unicast.Transport.TransportReceiver.TryProcess(TransportMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 230
at NServiceBus.Transports.Msmq.MsmqDequeueStrategy.Action() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Transports\Msmq\MsmqDequeueStrategy.cs:line 266
|
|
There is no reason that connect would only work some of the time unless there is some form of network issue involved. I'm not saying this isn't happening, just that I can't explain it.
This stack trace coupled with your answer indicates that when this exception occurs, your application can't talk to MongoDB at all because this code is only called at application startup, one time. More interesting is that this has nothing to do with load or queries. You simply can't connect to MongoDB. However, certain pieces of expected information are missing from the stack trace you provided, like the internal exception stemming from the server itself.
I have tried to reproduce this and simply cannot make it fail. Is there a small application you could provide that demonstrates this problem?
Craig
|