[BUG] Service Bus SubscriptionClient: Unhandeled exception? TaskCompletionSource`1[TResult].SetException

[SHuygh]

Previous issue and what changed
Azure/azure-service-bus-dotnet#693
Azure/azure-service-bus-dotnet#682

About 10% of our users had this crash in the last month.

Describe the bug

1. Exception is thrown which causes the application to crash

Exception or Stack Trace
Android: 8.0.0
Android Build: R16NW
Manufacturer: samsung
Model: SM-A600FN
CrashReporter Key: 9246b0b2-7af1-4db1-99ed-980b0f207e8b
Date: undefined

Xamarin Exception Stack:
System.InvalidOperationException:
at System.Threading.Tasks.TaskCompletionSource`1[TResult].SetException (System.Exception exception) [0x00013] in :0
at Microsoft.Azure.Amqp.Transport.AmqpTransportInitiator+<>c__DisplayClass15_0.b__0 (Microsoft.Azure.Amqp.Transport.TransportAsyncCallbackArgs a) [0x00014] in :0
at Microsoft.Azure.Amqp.Transport.AmqpTransportInitiator.Complete (Microsoft.Azure.Amqp.Transport.TransportAsyncCallbackArgs args) [0x00076] in :0
at Microsoft.Azure.Amqp.Transport.AmqpTransportInitiator.OnConnectComplete (Microsoft.Azure.Amqp.Transport.TransportAsyncCallbackArgs args) [0x00008] in :0
at Microsoft.Azure.Amqp.Transport.TlsTransportInitiator.Complete () [0x00059] in :0
at Microsoft.Azure.Amqp.Transport.TlsTransportInitiator.HandleInnerTransportConnected (Microsoft.Azure.Amqp.Transport.TransportAsyncCallbackArgs innerArgs) [0x0002a] in :0
at Microsoft.Azure.Amqp.Transport.TlsTransportInitiator.OnInnerTransportConnected (Microsoft.Azure.Amqp.Transport.TransportAsyncCallbackArgs innerArgs) [0x00006] in :0
at Microsoft.Azure.Amqp.Transport.TcpTransportInitiator.Complete (System.Net.Sockets.SocketAsyncEventArgs e, System.Boolean completeSynchronously) [0x000b7] in :0
at Microsoft.Azure.Amqp.Transport.TcpTransportInitiator.OnConnectComplete (System.Object sender, System.Net.Sockets.SocketAsyncEventArgs e) [0x00026] in :0
at System.Net.Sockets.SocketAsyncEventArgs.OnCompleted (System.Net.Sockets.SocketAsyncEventArgs e) [0x0000e] in <4c0ea12a669844598cada415d99299fd>:0
at System.Net.Sockets.SocketAsyncEventArgs.Complete () [0x00000] in <4c0ea12a669844598cada415d99299fd>:0
at System.Net.Sockets.Socket+<>c.<.cctor>b__309_3 (System.IAsyncResult ares) [0x00057] in <4c0ea12a669844598cada415d99299fd>:0
at System.Net.Sockets.SocketAsyncResult+<>c.b__27_0 (System.Object state) [0x0000b] in <4c0ea12a669844598cada415d99299fd>:0
at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem () [0x00008] in :0
at System.Threading.ThreadPoolWorkQueue.Dispatch () [0x00074] in :0
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback () [0x00000] in :0

Thread 2:
0 md532e88b764fa2f2b57f502dd15796e5c4.GmsLocationTrackingService.n_onSensorChanged(GmsLocationTrackingService.java:-2)
1 md532e88b764fa2f2b57f502dd15796e5c4.GmsLocationTrackingService.onSensorChanged(GmsLocationTrackingService.java:48)
2 android.hardware.SystemSensorManager$SensorEventQueue.dispatchSensorEvent(SystemSensorManager.java:964)
3 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
4 android.os.MessageQueue.next(MessageQueue.java:325)
5 android.os.Looper.loop(Looper.java:142)
6 android.app.ActivityThread.main(ActivityThread.java:6944)
7 java.lang.reflect.Method.invoke(Method.java:-2)
8 com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
9 com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)

Thread 51698:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:178)
2 java.lang.Daemons$Daemon.run(Daemons.java:103)
3 java.lang.Thread.run(Thread.java:764)

Thread 51699:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Object.wait(Object.java:422)
2 java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:188)
3 java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:209)
4 java.lang.Daemons$FinalizerDaemon.runInternal(Daemons.java:232)
5 java.lang.Daemons$Daemon.run(Daemons.java:103)
6 java.lang.Thread.run(Thread.java:764)

Thread 51700:
0 java.lang.Thread.sleep(Thread.java:-2)
1 java.lang.Thread.sleep(Thread.java:373)
2 java.lang.Thread.sleep(Thread.java:314)
3 java.lang.Daemons$FinalizerWatchdogDaemon.sleepFor(Daemons.java:342)
4 java.lang.Daemons$FinalizerWatchdogDaemon.waitForFinalization(Daemons.java:364)
5 java.lang.Daemons$FinalizerWatchdogDaemon.runInternal(Daemons.java:281)
6 java.lang.Daemons$Daemon.run(Daemons.java:103)
7 java.lang.Thread.run(Thread.java:764)

Thread 51718:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 51719:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 51721:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 51722:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 51730:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 51737:
0 java.lang.Object.wait(Object.java:-2)
1 com.android.okhttp.okio.AsyncTimeout.awaitTimeout(AsyncTimeout.java:323)
2 com.android.okhttp.okio.AsyncTimeout.-wrap0
3 com.android.okhttp.okio.AsyncTimeout$Watchdog.run(AsyncTimeout.java:286)

Thread 51752:
0 android.os.MessageQueue.nativePollOnce(MessageQueue.java:-2)
1 android.os.MessageQueue.next(MessageQueue.java:325)
2 android.os.Looper.loop(Looper.java:142)
3 android.os.HandlerThread.run(HandlerThread.java:65)

Thread 52769:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Thread.parkFor$(Thread.java:2135)
2 sun.misc.Unsafe.park(Unsafe.java:358)
3 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)
4 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2101)
5 java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
6 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1086)
7 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1147)
8 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
9 java.lang.Thread.run(Thread.java:764)

Thread 52770:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Thread.parkFor$(Thread.java:2135)
2 sun.misc.Unsafe.park(Unsafe.java:358)
3 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)
4 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2101)
5 java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
6 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1086)
7 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1147)
8 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
9 java.lang.Thread.run(Thread.java:764)

Thread 52771:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Thread.parkFor$(Thread.java:2135)
2 sun.misc.Unsafe.park(Unsafe.java:358)
3 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)
4 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2101)
5 java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
6 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1086)
7 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1147)
8 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
9 java.lang.Thread.run(Thread.java:764)

Thread 52772:
0 java.lang.Object.wait(Object.java:-2)
1 com.android.okhttp.ConnectionPool$1.run(ConnectionPool.java:101)
2 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
3 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
4 java.lang.Thread.run(Thread.java:764)

Thread 52773:
0 java.lang.Object.wait(Object.java:-2)
1 java.lang.Thread.parkFor$(Thread.java:2135)
2 sun.misc.Unsafe.park(Unsafe.java:358)
3 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)
4 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2101)
5 java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
6 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1086)
7 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1147)
8 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
9 java.lang.Thread.run(Thread.java:764)

Thread 52851:
0 java.lang.Object.wait(Object.java:-2)
1 com.android.okhttp.ConnectionPool$1.run(ConnectionPool.java:101)
2 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
3 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
4 java.lang.Thread.run(Thread.java:764)

To Reproduce
It is not clear when this occurs

Code

_subscriptionClient = new SubscriptionClient(_settingsService.PrimaryOutboundEndpoint, PrimaryOutboundTopic, PrimaryOutboundSubscription, TokenProvider.CreateSharedAccessSignatureTokenProvider(PrimaryOutboundSasToken), receiveMode: ReceiveMode.PeekLock, retryPolicy: _retryPolicy);
`_subscriptionClient.RegisterMessageHandler(

           async (message, cancellationToken1) =>
            {
                if (_subscriptionClient != null && !_subscriptionClient.IsClosedOrClosing)
                {
                    await MessageHandler(message, cancellationToken1, _subscriptionClient);
                }
            },
            new MessageHandlerOptions(LogMessageHandlerException) { AutoComplete = false, MaxConcurrentCalls = MAX_CONCURRENT_CALLS });`

Expected behavior
Either

1. Exception can be caught and handled
2. Exception is not thrown

Setup (please complete the following information):

• OS platform and version: Android 8.0.0
• .NET Version: Xamarin
• NuGet package version or commit ID: 3.4.0

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

• [ x ] Bug Description Added
• [ x ] Repro Steps Added
• [ x ] Setup information Added

[kurtzeborn]

Thank you for opening this issue! We are routing it to the appropriate team for follow up.

CC: @AlexGhiondea

[SHuygh]

I was wondering if there are any updates. We currently also noticed that the exception also occurs when the user receives a phone call. However, it is not solely limited to this use case

[AlexGhiondea]

Adding @binzywu @makam -- could you take a look?

@SHuygh any more information about when this occurs?

[SHuygh]

@AlexGhiondea Thank you for responding.

It is still not clear when this occurs.
We have had users mention that the application crashes after receiving a phone call. I tried to reproduce this a few times but was not able to. However, this is not the only time this occurs.
Due to the bug #6252 we have to close and open the subscription client after not receiving messages for one minute. I have noticed that the amount of application crashes due to this issue has significantly increased.
For our latest release in a pilot group of 125 users, a total of 66 users have observed this crash with a total of 147 crashes in a period of 14 days.

[nemakam]

The fix has been released in the Azure.Amqp library version 2.4.3. Please use the latest library and see if it works out for you.

[SHuygh]

Thank you for the update. Wil try updating and come back to it when this is thoroughly tested.