Service Bus: System.ObjectDisposedException when opening a receiver link #19731
Comments
ghost
added
needs-triage
jsquire
changed the title
jsquire
added
Client
ghost
removed
the
needs-triage
|
Hi @kanatgit. Thank you for reaching out and we regret that you're experiencing difficulties. May I ask if you're seeing these exceptions during periods of time when there is no activity on the Service Bus instance or on a recurring basis of around 20 minutes? |
|
@jsquire, Thanks for reply. This happens when there is activity on the service bus. Please see the graph for the exception distribution:
|
|
Hi @kanatgit, can you provide more information on how the ServiceBusClient is being managed? Is it possible that the client is being closed while the processor is still running? |
|
In our asp.net core web application Startup.cs file, ServiceBusClient is registered as QueueWorker is the only class depends on ServiceBusClient ( ServiceBusClient is instantiated by AutoFac container). |
|
Once these errors are hit, does the app ever process messages again or does it just keep spewing these errors until you shut it down? |
|
I think I have an idea of what could be happening. You are removing the event handlers while the processor is still running, which I believe will trigger an exception which would cause the processor to never get closed: Logger.LogInformation("Closing message pump");
messageProcessor.ProcessMessageAsync -= HandleMessageAsync;
messageProcessor.ProcessErrorAsync -= HandleReceivedExceptionAsync;
await messageProcessor.CloseAsync(cancellationToken: stoppingToken);This means when the app is shut down, the processor will still keep running. Instead you can close the processor before attempting to remove the handlers. Also, you are passing the stoppingToken into the CloseAsync call, so the CloseAsync would not work anyway. Finally, it may be better to override StopAsync to handle the processor shut down rather than putting it in ExecuteAsync. |
|
@JoshLove-msft , the removing handler code wasn't there when the exceptions were observed initially. I added them later just to see if it helps to solve the problem. |
Ah ok, well the stoppingToken would have prevented the processor from being closed. |
|
Also, I think we can try to fix this in the SDK so that the processor doesn't continually try to process if the client has been closed. Please let us know if it turns out that is what is happening here. |
while (!stoppingToken.IsCancellationRequested) public virtual async Task CloseAsync( |
|
StopProcessingAsync throws if the cancellationToken is cancelled. |
|
Ah, cancellatinoToken really means to cancel stopProcessing. I misunderstood it. I will remove the cancellationToken parameter to test our web app tomorrow and will keep you updated. Thanks for the help. |
JoshLove-msft
added
the
needs-author-feedback
|
Hi @kanatgit, just want to check to see if you were able to test this out. |
|
@JoshLove-msft , I implemented two of your suggestions,
Unfortunately, those two changes are not enough to solve the problem, the same exceptions still happened yesterday. As you can see, two messages "closing message pump" and "Message pump closed", one should be logged before CloseAync(), one after CloseAync(). From the AppInsight Logs, you can see that "Message pump closed" for ProcessId: "24436" is missing, which indicates that CloseAync() never returns. The exceptions also happens right after the timestamp of "closing message pump" message for ProcessId:"24436". I don't know why there were multiple processes, not sure if it is something related to azure environment. I am implementing your 3rd suggesting to the put the CloseAsync() method in an overriden BackgroudService.StopAsync() method. While testing this on my local machine, I found that ServicebusClient.CloseAsync() now takes 17 seconds to return, which was returned instantly when it was called from ExecuteAsyn(); I stopped the web app by pressing Ctrl+C after the app started, at that point, the servicebus queue should be empty. Do you have any explanation for this time consumption change? I will deploy this 3rd change to Azure see how it works and keep you updated. Thank you for your continuous help. |
ghost
added
needs-team-attention
Do you mean when calling processor.CloseAsync? It is expected that it would take some time while closing due to the processor waiting for any receive calls to complete. We are planning on improving this behavior in an upcoming release (see #17734). As for why the call would return immediately when in the Execute method, I'm not sure. Do you have logging enabled for the Service Bus SDK? |
|
Yes, the processor.CloseAsync() method takes 17 seconds to finish on my local machine. I implemented your 3rd suggestion calling processor.CloseAsnc() in overriden StopAsnc() function and deployed it to azure environment. Good news is that I haven't seen the ObjectDisposedExceptions happened, but it seems that a lot of times processor.CloseAsync() doesn't return because the "Message pump closed" log are missing most of the time when app got redeployed. |
|
Interesting.. are you able to enable SDK logs? |
|
@kanatgit just checking in on this. Were you able to enable SDK logging so we can debug further? |
|
@JoshLove-msft: Based on the stack trace, I'm reasonably sure this is related to #20255 with the root cause being unexpected behavior by the AMQP library. We've discussed with the team that maintains the AMQP library and they'll be addressing it in a future update. I'm working on a mitigation for both Event Hubs and Service Bus in the meantime. |
|
@kanatgit, the frequency that of this in your logs and the time clustering may be a concern. Assuming that I'm correct about the root cause, this log pattern would seem to indicate that your application is experiencing network instability which is causing connections/links to fail. With the forthcoming mitigation in the SDK, it will detect the scenario and try to recover by creating a new connection, but I wonder if you'll continue to experience connectivity difficulties. Can you help us understand the host environment and application a bit better? |
jsquire
added
needs-author-feedback
|
I have been investigating why this problem only happens at azure environment. The screen shots below shows our web app deployment pipelines. As you can see the task of stop app service returns in 1 second, which doesn't wait the servicebus processor.CloseAsync() to return, that's why "Message pump closed" log is missing. Web app is shutdown ungracefully and I don't see any option/configuration is available to change this behavior.
I have tried various suggestions I found online:
webHostBuilder
Unfortunately, none of them makes the Azure deployment to wait the _serviceBusProcessor.CloseAsync() to finish, and I don't see any configuration in Azure portal wait the web app to shutdown gracefully. @jsquire, this is not a network issue, all the ObjectDisposedExceptions happens during web app shutdown, during that time, serviceBusProcessor.CloseAsync() is hanging, then web app is brutally shut down. I think that serviceBusClient gets released, while servicebus receiver retrieving messages is still going on and caused the exceptions. |
ghost
added
needs-team-attention
|
@kanatgit. That makes sense and would trigger the behavior that I was talking about; tearing down the host environment is very likely to cause changes to the state of the network resources, upsetting the AMQP transport. What I'd expect to see in this case is one instance of the Does that match what you're seeing? |
jsquire
added
needs-author-feedback
|
I talked to @JoshLove-msft offline, and it looks like there are two issues at play. The gap that I wasn't seeing earlier is that the processor also isn't reacting to the client being closed, so the change in network state was likely first caused by the client closing rather than the AppService shutting down. Apologies for the confusion. |
|
I think there are a few things going on here. In the SDK itself, we have a bug where the receiver/sender/etc does not check if the client was closed before attempting operations. It checks only if the link is closed. A similar gap appears to exist in Event Hubs where closing the connection without closing the Consumer would result in the same behavior. This bug can be worked around by ensuring that processor.close is called, but there is some odd behavior occurring - it didn't seem to get called when it was in the Execute method. Moving the processor.close call into the stop method works locally, but it doesn't always return when deployed. The best way to debug further would be to enable SDK logs - I'm not seeing these in the latest screenshot. |
|
@JoshLove-msft, can you tell me specifically how do I enable SDK logs? Do you mean add |
ghost
added
needs-team-attention
|
Is this an App Service instance? This might help - https://docs.microsoft.com/en-us/azure/app-service/troubleshoot-diagnostic-logs |
|
@JoshLove-msft , Thanks for the app service logs document link. Unfortunately in order to use the app service logs, it requires to install .net core site extention, which is incompatible with our app, causing our app unable to start.
|
|
I found a temporary solution : Ignoring the ObjectDisposedException in the Error Handler HandleReceivedExceptionAsync() during shutdown. public class QueueWorker : BackgroundService where TMessage : class |
@pakrym do you know how we can enable SDK logging here? |
|
@JoshLove-msft , I managed to get the logging in azure environment with debug level enabled. Here is a bad logging, servicebusProcessor.CloseAsnc() never returns because the "Message pump closed" is missing. Please pay attention to the stop error at row 51. Even though the ObjectDisplosedException that I originally reported does not show up, somehow it's getting harder for me to reproduce it, but it is still good to show why the servicebusProcessor is not closed during web app shutdown.
Here is a good logging for your reference. (You can see both the "Closing message pump" and "Message pump closed" messages).
|
|
@jsquire ,Thanks for your continuous efforts bringing the fix. May I ask when this fix will be available in NuGet Repository? |
|
@kanatgit. You're very welcome. These changes will be part of our next release in early May. I can't speak to whether that planned as a beta or GA; I'll need to defer to @JoshLove-msft for insight. |
|
Since the fixes needed are now confirmed to have reached GA, I'm going to tag this as having been addressed and close it out. Please feel free to " |
jsquire
added
the
issue-addressed
|
Hi @kanatgit. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text “ |
ghost
removed
the
needs-team-attention
Hi,
I am getting thousands of ObjectDisplosedException a day throw out of Azure.Messaging.ServiceBus.Amqp.AmqpConnectionScope.OpenReceiverLinkAsync() at line 312.
By looking into the servicebus source code, the problem is the ActiveConnection was disposed. The version of Azure.Messaging.ServiceBus is 7.1.0.0. Is this an issue of servicebus code? Any suggestion? My sample code is provided at the end.
Thanks
Exception Detail:
{"HResult":-2146232798,"Message":"Cannot access a disposed object.\r\nObject name: 'FaultTolerantAmqpObject
1'.","Source":"Microsoft.Azure.Amqp","ObjectName":"FaultTolerantAmqpObject1","Type":"System.ObjectDisposedException"}Call Stack:
My sample code:
The text was updated successfully, but these errors were encountered: