Masstransit: Does not reconnect after timeout error with ExceptionRequiresRecycle=true

[cmeeren]

I have two seemingly separate cases of MT stuff being shut down and not recovering after a message timeout error in a request/response cycle. My immediate thoughts are that 1) the message should not time out at all in this case, 2) it seems weird that timeouts require recycle, and 3) it should automatically come back up again.

Note that the behavior is the same if I remove all the AutoStart lines in the snippets below.

Here is the bus init code for both services:

```f#
let mutable private bus : IBusControl = null

let init loggerFactory connStr queueName =
async {
LogContext.ConfigureCurrentLogContext loggerFactory
bus <-
Bus.Factory.CreateUsingAzureServiceBus(fun config ->
config.AutoStart <- true
config.Host(connStr)
// The below is only for the service that responds
config.ReceiveEndpoint(
queueName,
fun (epCfg: IServiceBusReceiveEndpointConfigurator) ->
epCfg.AutoStart <- true
epCfg.Consumer(fun () -> ..)
)
)

let! ct = Async.CancellationToken
do! bus.StartAsync ct |> Async.AwaitTask |> Async.Ignore

}

Here is the request code in the requesting service:

```f#
let getUserIdForSession (msg: GetSessionUserIdRequest) =
  async {
    let client = bus.CreateRequestClient<GetSessionUserIdRequest>()
    let! ct = Async.CancellationToken
    let! resp =
      client.GetResponse<GetSessionUserIdResponse>(msg, ct, !TimeSpan.FromSeconds 3.)
      |> Async.AwaitTask
    return ..
  }

Note the 3-second timeout. There is also a Polly retry policy in place above this function (not shown, but you see it in the logs below).

Case 1

Here are logs from the requesting service, with some comments:

[09:03:09.433 INF] Request starting HTTP/1.1 GET http://localhost:46812/stringGroups?fields[stringGroup]=name
[09:03:09.472 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-0cba-08d8b3abd69f Vbit.Api.Authentication.Messages.GetSessionUserIdRequest

# Error starts here. I don't understand why the message expired. As you can see, the error comes <1s after the request starts, but the message timeout is 2s.

[09:03:10.249 ERR] Exception on Receiver sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 during UserCallback ActiveDispatchCount(0) ErrorRequiresRecycle(True)
MassTransit.Azure.ServiceBus.Core.MessageTimeToLiveExpiredException: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 => The message expired: 3bb50000ace500ff8ab708d8b3abd703
   at Task MassTransit.Azure.ServiceBus.Core.Transport.MessageLockContextReceiveLock.ValidateLockStatus()
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Azure.ServiceBus.Core.Transport.BrokeredMessageReceiver.MassTransit.Azure.ServiceBus.Core.Transport.IBrokeredMessageReceiver.Handle(Message message, CancellationToken cancellationToken, Action<ReceiveContext> contextCallback)
   at void MassTransit.Azure.ServiceBus.Core.Contexts.QueueClientContext+<>c__DisplayClass15_0+<<OnMessageAsync>b__0>d.MoveNext()
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.MessageDispatchTask(Message message)

# The shutdown starts here

[09:03:10.306 DBG] Receiver shutdown completed: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300
[09:03:10.312 DBG] Endpoint Completed: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300
[09:03:10.315 DBG] Consumer completed sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300: 2 received, 1 concurrent

# Note that the log entry below is 1ms after the next entry further below

[09:03:10.350 WRN] Exception on Receiver sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 during Abandon ActiveDispatchCount(0) ErrorRequiresRecycle(False)
Microsoft.Azure.ServiceBus.MessageLockLostException: The lock supplied is invalid. Either the lock expired, or the message has already been removed from the queue, or was received by a different receiver instance.
   at async Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.DisposeMessagesAsync(IEnumerable<Guid> lockTokens, Outcome outcome)
   at async Task Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func<Task> operation, TimeSpan operationTimeout)
   at async Task Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func<Task> operation, TimeSpan operationTimeout)
   at async Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.AbandonAsync(string lockToken, IDictionary<string, object> propertiesToModify)
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.AbandonMessageIfNeededAsync(Message message)

[09:03:10.349 ERR] Connection Failed: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300
MassTransit.Azure.ServiceBus.Core.ServiceBusConnectionException: ReceiveTransport faulted: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300
 ---> System.AggregateException: One or more errors occurred. (One or more errors occurred. (sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 => The message expired: 3bb50000ace500ff8ab708d8b3abd703))
 ---> System.AggregateException: One or more errors occurred. (sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 => The message expired: 3bb50000ace500ff8ab708d8b3abd703)
 ---> MassTransit.Azure.ServiceBus.Core.MessageTimeToLiveExpiredException: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300 => The message expired: 3bb50000ace500ff8ab708d8b3abd703
   at Task MassTransit.Azure.ServiceBus.Core.Transport.MessageLockContextReceiveLock.ValidateLockStatus()
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Azure.ServiceBus.Core.Transport.BrokeredMessageReceiver.MassTransit.Azure.ServiceBus.Core.Transport.IBrokeredMessageReceiver.Handle(Message message, CancellationToken cancellationToken, Action<ReceiveContext> contextCallback)
   at void MassTransit.Azure.ServiceBus.Core.Contexts.QueueClientContext+<>c__DisplayClass15_0+<<OnMessageAsync>b__0>d.MoveNext()
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.MessageDispatchTask(Message message)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.MessageReceiverFilter.GreenPipes.IFilter<MassTransit.Azure.ServiceBus.Core.ClientContext>.Send(?)
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.MessageReceiverFilter.GreenPipes.IFilter<MassTransit.Azure.ServiceBus.Core.ClientContext>.Send(?)
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.ConfigureTopologyFilter<TSettings>.Send(ClientContext context, IPipe<ClientContext> next)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task MassTransit.Transports.ReceiveTransport<TContext>+ReceiveTransportAgent.Run()+(?) => { }
   --- End of inner exception stack trace ---

[09:03:10.379 DBG] Endpoint Faulted: sb://sb-vbit-dev-001.servicebus.windows.net/MIPHA_Api_bus_8q4oyyfchwyx9a46bdcm8k61yr?autodelete=300

# Retries start here, but all fail, perhaps because receiver didn't recover?

[09:03:12.463 INF] MassTransit retry policy: Exception thrown, performing retry 1, operation MassTransit.getUserIdForSession
MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-dfe8-08d8b3abd69e
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
[09:03:12.499 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-e55d-08d8b3abd86c Vbit.Api.Authentication.Messages.GetSessionUserIdRequest
[09:03:15.486 INF] MassTransit retry policy: Exception thrown, performing retry 2, operation MassTransit.getUserIdForSession
MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-dc56-08d8b3abd86c
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
[09:03:15.522 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-5d78-08d8b3abda3a Vbit.Api.Authentication.Messages.GetSessionUserIdRequest
[09:03:18.511 INF] MassTransit retry policy: Exception thrown, performing retry 3, operation MassTransit.getUserIdForSession
MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-4e9a-08d8b3abda3a
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()
[09:03:18.547 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-cf83-08d8b3abdc07 Vbit.Api.Authentication.Messages.GetSessionUserIdRequest
[09:03:21.526 INF] MassTransit retry policy: Exception thrown, performing retry 4, operation MassTransit.getUserIdForSession
MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-c420-08d8b3abdc07
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
[09:03:21.557 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-a4cf-08d8b3abddd3 Vbit.Api.Authentication.Messages.GetSessionUserIdRequest

# Last retry failed, so now request fails

[09:03:31.943 ERR] Unhandled exception while executing request
System.AggregateException: One or more errors occurred. (Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-9b8f-08d8b3abddd3)
 ---> MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-9b8f-08d8b3abddd3
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
   at void Polly.Utilities.ExceptionExtensions.RethrowWithOriginalStackTraceIfDiffersFrom(Exception exceptionPossiblyToThrow, Exception exceptionToCompare)
   at async Task<TResult> Polly.Retry.AsyncRetryEngine.ImplementationAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates<TResult> shouldRetryResultPredicates, Func<DelegateResult<TResult>, TimeSpan, int, Context, Task> onRetryAsync, int permittedRetryCount, IEnumerable<TimeSpan> sleepDurationsEnumerable, Func<int, DelegateResult<TResult>, Context, TimeSpan> sleepDurationProvider, bool continueOnCapturedContext)
   at async Task<TResult> Polly.AsyncPolicy.ExecuteAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   at async Task<TResult> Polly.Wrap.AsyncPolicyWrapEngine.ImplementationAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> func, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext, IAsyncPolicy outerPolicy, IAsyncPolicy<TResult> innerPolicy)
   at async Task<TResult> Polly.AsyncPolicy<TResult>.ExecuteAsync(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   --- End of inner exception stack trace ---
   at a Utils+ExceptionExtensions.Exception.Reraise<a>(Exception) in D:/Source/Repos/Vbit.Api.Language/src/Core/Utils.fs:line 116
   at FSharpAsync<c> [email protected](Exception _arg2) in D:/Source/Repos/Vbit.Api.Language/src/Core/CompositionHelpers.fs:line 120
   at FSharpOption<FSharpAsync<c>> [email protected](Exception exn) in D:/Source/Repos/Vbit.Api.Language/src/Core/CompositionHelpers.fs:line 112
   at FSharpOption<FSharpAsync<c>> [email protected](Exception edi) in D:/Source/Repos/Vbit.Api.Language/src/Core/CompositionHelpers.fs:line 112
   at AsyncReturn Microsoft.FSharp.Control.AsyncPrimitives.CallFilterThenInvoke<T>(AsyncActivation<T> ctxt, FSharpFunc<Exception, FSharpOption<FSharpAsync<T>>> catchFilter, ExceptionDispatchInfo edi) in F:/workspace/_work/1/s/src/fsharp/FSharp.Core/async.fs:line 424
   at AsyncReturn Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc<Unit, AsyncReturn> firstAction) in F:/workspace/_work/1/s/src/fsharp/FSharp.Core/async.fs:line 105
   at Step<b> [e-mail](Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> [e-mail](Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> [e-mail](Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> [e-mail](Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<Unit> [email protected](Unit unitVar0)
   at Step<a> FSharp.Control.Tasks.TaskBuilder.tryWith<a>(FSharpFunc<Unit, Step<a>> step, FSharpFunc<Exception, Step<a>> catch)
[09:03:32.020 INF] Request finished in 22586.4398ms 500 application/vnd.api+json

After this, all requests made by the requesting service fails:

[09:24:10.626 INF] Request starting HTTP/1.1 GET http://localhost:46812/stringGroups?fields[stringGroup]=name
[09:24:10.694 DBG] SEND sb://sb-vbit-dev-001.servicebus.windows.net/Vbit.Api.Authentication.Messages/GetSessionUserIdRequest 3bb50000-ace5-00ff-89ae-08d8b3aec659 Vbit.Api.Authentication.Messages.GetSessionUserIdRequest
[09:24:13.652 INF] MassTransit retry policy: Exception thrown, performing retry 1, operation MassTransit.getUserIdForSession
MassTransit.RequestTimeoutException: Timeout waiting for response, RequestId: 3bb50000-ace5-00ff-71ac-08d8b3aec659
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<TResponse>> MassTransit.Clients.ResponseHandlerConnectHandle<TResponse>.GetTask()
   at async Task<Response<T>> MassTransit.Clients.RequestClient<TRequest>.GetResponseInternal<T>(SendRequestCallback request, CancellationToken cancellationToken, RequestTimeout timeout)
   at async Task MassTransit.Clients.ClientRequestHandle<TRequest>.HandleFault()

# etc.

Only a restart of the requesting service brings things up again.

Note that the requests are received by the responding service, and it seems responses are successfully sent, but the requesting service times out since (I assume) its reply subscription is down.

Case 2

If I just change the timeout from 3 seconds to 2 seconds and make no other changes, it is consistently the responding service that fails and does not recover. Here are logs from the responding service:

# This error is the very first thing that is logged in the responding service when the requesting service sends a request

[09:27:32.433 ERR] Exception on Receiver sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication during UserCallback ActiveDispatchCount(0) ErrorRequiresRecycle(True)
MassTransit.Azure.ServiceBus.Core.MessageTimeToLiveExpiredException: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication => The message expired: 3bb50000ace500ff3ad008d8b3af3e91
   at Task MassTransit.Azure.ServiceBus.Core.Transport.MessageLockContextReceiveLock.ValidateLockStatus()
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Azure.ServiceBus.Core.Transport.BrokeredMessageReceiver.MassTransit.Azure.ServiceBus.Core.Transport.IBrokeredMessageReceiver.Handle(Message message, CancellationToken cancellationToken, Action<ReceiveContext> contextCallback)
   at void MassTransit.Azure.ServiceBus.Core.Contexts.QueueClientContext+<>c__DisplayClass15_0+<<OnMessageAsync>b__0>d.MoveNext()
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.MessageDispatchTask(Message message)

# Shutdown starts here

[09:27:32.497 DBG] Receiver shutdown completed: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication
[09:27:32.503 DBG] Endpoint Completed: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication
[09:27:32.506 DBG] Consumer completed sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication: 1 received, 1 concurrent
[09:27:32.546 ERR] Connection Failed: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication
MassTransit.Azure.ServiceBus.Core.ServiceBusConnectionException: ReceiveTransport faulted: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication
 ---> System.AggregateException: One or more errors occurred. (One or more errors occurred. (sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication => The message expired: 3bb50000ace500ff3ad008d8b3af3e91))
 ---> System.AggregateException: One or more errors occurred. (sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication => The message expired: 3bb50000ace500ff3ad008d8b3af3e91)
 ---> MassTransit.Azure.ServiceBus.Core.MessageTimeToLiveExpiredException: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication => The message expired: 3bb50000ace500ff3ad008d8b3af3e91
   at Task MassTransit.Azure.ServiceBus.Core.Transport.MessageLockContextReceiveLock.ValidateLockStatus()
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Transports.ReceivePipeDispatcher.Dispatch(ReceiveContext context, ReceiveLockContext receiveLock)
   at async Task MassTransit.Azure.ServiceBus.Core.Transport.BrokeredMessageReceiver.MassTransit.Azure.ServiceBus.Core.Transport.IBrokeredMessageReceiver.Handle(Message message, CancellationToken cancellationToken, Action<ReceiveContext> contextCallback)
   at void MassTransit.Azure.ServiceBus.Core.Contexts.QueueClientContext+<>c__DisplayClass15_0+<<OnMessageAsync>b__0>d.MoveNext()
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.MessageDispatchTask(Message message)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.MessageReceiverFilter.GreenPipes.IFilter<MassTransit.Azure.ServiceBus.Core.ClientContext>.Send(?)
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.MessageReceiverFilter.GreenPipes.IFilter<MassTransit.Azure.ServiceBus.Core.ClientContext>.Send(?)
   at async Task MassTransit.Azure.ServiceBus.Core.Pipeline.ConfigureTopologyFilter<TSettings>.Send(ClientContext context, IPipe<ClientContext> next)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task GreenPipes.Agents.PipeContextSupervisor<TContext>.GreenPipes.IPipeContextSource<TContext>.Send(?)
   at async Task MassTransit.Transports.ReceiveTransport<TContext>+ReceiveTransportAgent.Run()+(?) => { }
   --- End of inner exception stack trace ---
[09:27:32.568 DBG] Endpoint Faulted: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication
[09:27:36.019 ERR] Exception on Receiver sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication during Abandon ActiveDispatchCount(0) ErrorRequiresRecycle(True)
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'ConcurrentExpiringSet has already been closed. Please create a new set instead.'.
   at void Microsoft.Azure.ServiceBus.Primitives.ConcurrentExpiringSet<TKey>.ThrowIfClosed()
   at bool Microsoft.Azure.ServiceBus.Primitives.ConcurrentExpiringSet<TKey>.Contains(TKey key)
   at Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.OnAbandonAsync(string lockToken, IDictionary<string, object> propertiesToModify)+(Guid lt) => { }
   at bool System.Linq.Enumerable.Any<TSource>(IEnumerable<TSource> source, Func<TSource, bool> predicate)
   at Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.OnAbandonAsync(string lockToken, IDictionary<string, object> propertiesToModify)
   at Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.AbandonAsync(string lockToken, IDictionary<string, object> propertiesToModify)+() => { }
   at async Task Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func<Task> operation, TimeSpan operationTimeout)
   at async Task Microsoft.Azure.ServiceBus.RetryPolicy.RunOperation(Func<Task> operation, TimeSpan operationTimeout)
   at async Task Microsoft.Azure.ServiceBus.Core.MessageReceiver.AbandonAsync(string lockToken, IDictionary<string, object> propertiesToModify)
   at async Task Microsoft.Azure.ServiceBus.MessageReceivePump.AbandonMessageIfNeededAsync(Message message)
[09:27:36.028 DBG] Receiver shutdown completed: sb://sb-vbit-dev-001.servicebus.windows.net/api-authentication

# No further requests are received

Again, let me draw attention to the fact that given the logged timestamps, the message should not time out at all in the first place. But I think the most important message here is that it doesn't come back up, on either end.

Also note that if I remove the message timeout and instead enforce a timeout at a higher level using a Polly policy, things seem to work correctly.

Please let me know if I'm doing anything wrong.

[cmeeren]

Actually, I suspect this issue is the root cause for #2223. I am using 2s timeouts, which as detailed here seems to cause the receiver to fail and not recover. The symptoms and logs match fairly well.

[phatboyg]

Your clock has likely drifted off and your timeout is just too short. You should not be using time to live that short with a remote cloud based message broker.

[cmeeren]

Thanks, that explains why it's timing out. Still, why do timeouts like these require recycle? And shouldn't it be brought back up again?

[phatboyg]

It shouldn't, not sure why until I get time to look at it. I haven't at all yet beyond reading the issue detail you've provided (which is great btw)

[phatboyg]

Also, I hate polly, but whatever - are you cancelling the token passed to the request client when polly aborts your attempt? Or is the request client doing the 3-second timeout?

Which again, I say is way too short.

[cmeeren]

are you cancelling the token passed to the request client when polly aborts your attempt? Or is the request client doing the 3-second timeout?

Which again, I say is way too short.

I have now removed the message expiration and I'm instead aborting the request (using a Polly timeout policy). So far, it seems to work correctly (but again, the issue about requiring a recycle and bringing it back up again still stands).

To answer your specific question: In the original code I posted, Polly doesn't abort the attempt. There is no Polly timeout policy; only a retry policy. The only timeout/abortion is whatever is performed by MassTransit internally from setting the message expiration.

In my new method (Polly timeout policy), I think the token should be canceled, but that's not relevant for this issue.

[phatboyg]

As stated in the other thread, if you increase the message expiration to say 1 minute and then keep your request client timeout, you should be fine. That way, messages don't disappear before they're consumed by the client.

[phatboyg]

So is there anything to be done here? I'm thinking not.

[cmeeren]

As I understand it, there are two potential bugs here:

1. Don't recycle on the message expiration error, unless it's actually necessary for some reason
2. When recycling, bring the connection back up again. This is not happening in this case; whether the recycle happens on the requesting service (case 1) or the responding service (case 2), the consumer etc. are permanently down after the error happens and I have to restart the services to bring things back up again.

[phatboyg]

So the error of not reconnecting may be related to the error I fixed yesterday. The latest develop has it. #2072

[phatboyg]

Any chance to test this, or are you waiting for the official 7.1.3 packages to verify?

[cmeeren]

I'll try to test it tomorrow.

[cmeeren]

Unfortunately I was unable to repro the original issue, even when checking out the old commit. If you think this is fixed, feel free to close.

[phatboyg]

Thanks. If you see it again let me know.