Retry loop stopped and connection state is invalid

[robertmircea]

I have a .net core 8 server which runs as a service permanently. I've noticed that starting at some point in time, the following message appeared in the log from NatsConnection and from that moment on, the server could not publish Nats messages anymore and never recovered without restart which is very bad for a server which supposes to run continuously. Even if the nats server was not accessible for a while (which I don't think is the case), wouldn't NatsConnection suppose to restore the connection to Nats servers when appropriate?

Nats nuget versions:

        <PackageReference Include="NATS.Extensions.Microsoft.DependencyInjection" Version="2.3.0" />
        <PackageReference Include="NATS.Net" Version="2.3.0" />

Nats servers are all three running in cluster mode hosted on-prem, version: 2.10.11

Stack trace of first exception observed in the app logs (nothing is missing) and from which issue started to occur:

[23:18:49.861 ERR] Retry loop stopped and connection state is invalid  } <s:NATS.Client.Core.NatsConnection>
System.TimeoutException: The operation has timed out.
   at NATS.Client.Core.Commands.CommandWriter.CancelReaderLoopAsync()
   at NATS.Client.Core.NatsConnection.ReconnectLoop()

The next lines of logs when attempting jetstream.PublishAsync were like these:

[23:18:58.461 ERR] NatsAuditEventProducer could not publish NATS Jetstream message  <s:AuditEvents.NatsAuditEventProducer>
NATS.Client.JetStream.NatsJSPublishNoResponseException: No response received from the server
   at NATS.Client.JetStream.NatsJSContext.PublishAsync[T](String subject, T data, INatsSerialize`1 serializer, NatsJSPubOpts opts, NatsHeaders headers, CancellationToken cancellationToken)
   at MyApp.AuditEvents.NatsAuditEventProducer.PublishAsync(AbstractAuditEvent auditEvent, CancellationToken cancellationToken)

[23:20:08.848 ERR] NatsAuditEventProducer could not publish NATS Jetstream message <s:MyApp.AuditEvents.NatsAuditEventProducer>
System.OperationCanceledException: The operation was canceled.
   at NATS.Client.Core.Commands.CommandWriter.PublishStateMachineAsync(Boolean lockHeld, String subject, String replyTo, NatsPooledBufferWriter`1 headersBuffer, NatsPooledBufferWriter`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at NATS.Client.Core.NatsConnection.RequestSubAsync[TRequest,TReply](String subject, TRequest data, NatsHeaders headers, INatsSerialize`1 requestSerializer, INatsDeserialize`1 replySerializer, NatsPubOpts requestOpts, NatsSubOpts replyOpts, CancellationToken cancellationToken)
   at NATS.Client.JetStream.NatsJSContext.PublishAsync[T](String subject, T data, INatsSerialize`1 serializer, NatsJSPubOpts opts, NatsHeaders headers, CancellationToken cancellationToken)
   at MyApp.AuditEvents.NatsAuditEventProducer.PublishAsync(AbstractAuditEvent auditEvent, CancellationToken cancellationToken)

Unfortunately I don't know how to reproduce this, but I was wondering if any recent nuget library code changes might have triggered this.

[mtmk]

thanks for reporting this @robertmircea

checking now. I don't think we made any changes around connection logic.

edit:
The exception from JetStream publish is expected since it won't be able to read any of the ACKs.

The only solution to me is to remove the timeout since there is no way to recover from it and timeout should not be necessary since worst case scenario socket exception should end the reader loop:

• issue: Retry loop stopped and connection state is invalid #553
• PR: Remove timeout from readerTask in CommandWriter #554

[mtmk]

Could you check the latest release that has the timeout fix please? I hope that fixes it, otherwise it's going to be a though one to replicate! https://github.com/nats-io/nats.net.v2/releases/tag/v2.3.2

[robertmircea]

I've updated the app with the latest nuget version and this morning I discovered again in the logs the following exception:

[00:48:38.978 ERR] Unexpected error in send buffer reader loop { EventId: { Id: 1007, Name: "Buffer" }} <s:NATS.Client.Core.Commands.CommandWriter>
System.Net.Sockets.SocketException (10058): A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call.
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
   at NATS.Client.Core.Commands.CommandWriter.ReaderLoopAsync(ILogger`1 logger, ISocketConnection connection, PipeReader pipeReader, Channel`1 channelSize, Memory`1 consolidateMem, PartialSendFailureCounter partialSendFailureCounter, CancellationToken cancellationToken)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

[mtmk]

log itself is expected if there was a connection issue but I assume it stopped retrying as well and didn't reconnect? are there any other log entries a round that?

[robertmircea]

Not after, but earlier these 3:

[00:22:54.005 WRN] Can't find subscription for _INBOX.n0RydAEHQum00RzP08A4yY/35 { EventId: { Id: 1002, Name: "Subscription" }} <s:NATS.Client.Core.Internal.SubscriptionManager>

[00:24:19.451 WRN] Unregistered message inbox received for _INBOX.wf4kMGOyx8m7mrjjqYTxcq.O2scoZFZ7gzQs2mc5YV9Ei { EventId: { Id: 1004, Name: "InboxSubscription" } } <s:NATS.Client.Core.Internal.InboxSubBuilder>

[00:24:19.654 WRN] Unregistered message inbox received for _INBOX.wf4kMGOyx8m7mrjjqYTxdq.za7x28MyQMD2W6fBWIoL9M { EventId: { Id: 1004, Name: "InboxSubscription" } } <s:NATS.Client.Core.Internal.InboxSubBuilder>

[mtmk]

they look too far apart to be related.