[BUG] reactor.core.Exceptions$ReactiveException: java.lang.InterruptedException occurs at computeManager.virtualMachines().getByResourceGroup(resGroup, name)

[zlishaojiez]

Describe the bug
computeManager.virtualMachines().getByResourceGroup(resGroup, name) got reactor.core.Exceptions$ReactiveException: java.lang.InterruptedException

Exception or Stack Trace
reactor.core.Exceptions$ReactiveException: java.lang.InterruptedException
at reactor.core.Exceptions.propagate(Exceptions.java:396)
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:91)
at reactor.core.publisher.Mono.block(Mono.java:1742)
at com.azure.resourcemanager.resources.fluentcore.arm.collection.implementation.GroupableResourcesImpl.getByResourceGroup(GroupableResourcesImpl.java:106)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.getCloudAzureVM(VirtualMachineAzureV2.java:537)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.lambda$beginCreateSnapshotAsync$14(VirtualMachineAzureV2.java:255)
at com.vmware.horizon.sg.clouddriver.impl.azure.internal.RxDelayedRetry$RxSingleHelper.call(RxDelayedRetry.java:175)
at com.vmware.horizon.sg.clouddriver.impl.azure.internal.RxDelayedRetry.retryWithDelaySingleRxV3(RxDelayedRetry.java:53)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.getWithRetry(VirtualMachineAzureV2.java:427)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.beginCreateSnapshotAsync(VirtualMachineAzureV2.java:255)
at com.vmware.horizon.sg.clouddriver.impl.azure.internal.RxDelayedRetry$RxSingleHelper.call(RxDelayedRetry.java:175)
at com.vmware.horizon.sg.clouddriver.impl.azure.internal.RxDelayedRetry.retryWithDelaySingleRxV3(RxDelayedRetry.java:53)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.getWithRetry(VirtualMachineAzureV2.java:427)
at com.vmware.horizon.sg.clouddriver.impl.azure.v2.VirtualMachineAzureV2.beginCreateOsDiskSnapshot(VirtualMachineAzureV2.java:192)
at com.vmware.horizon.sg.clouddriver.task.impl.TaskSubmitterTakeSnapshot.submitOne(TaskSubmitterTakeSnapshot.java:14)
at com.vmware.horizon.sg.clouddriver.task.impl.TaskSubmitterTakeSnapshot.submitOne(TaskSubmitterTakeSnapshot.java:8)
at com.vmware.horizon.sg.clouddriver.task.base.BaseSubmitterTask.processOne(BaseSubmitterTask.java:150)
at com.vmware.horizon.sg.clouddriver.task.base.composite.QueueExecutor$Worker.run(QueueExecutor.java:185)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.InterruptedException: null
at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(Unknown Source)
at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown Source)
at java.base/java.util.concurrent.CountDownLatch.await(Unknown Source)
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87)
... 17 common frames omitted

To Reproduce
I could reproduce it, it just happens some times on stress test.

Code Snippet

Expected behavior
The VirtualMachine object returned by the API

Screenshots
API issue, no screenshots

Setup (please complete the following information):

• OS: [e.g. iOS]
• IDE: IntelliJ
• Library/Libraries: 2.23.0
• Java version: [e.g. 8]
• App Server/Environment: [e.g. Tomcat, WildFly, Azure Function, Apache Spark, Databricks, IDE plugin or anything special]
• Frameworks: [e.g. Spring Boot, Micronaut, Quarkus, etc]

If you suspect a dependency version mismatch (e.g. you see NoClassDefFoundError, NoSuchMethodError or similar), please check out Troubleshoot dependency version conflict article first. If it doesn't provide solution for the problem, please provide:

• verbose dependency tree (mvn dependency:tree -Dverbose)
• exception message, full stack trace, and any available logs

Additional context
We use the AzureClient with okhttpClient and the API was called in thread.

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

• Bug Description Added
• Repro Steps Added
• Setup information Added

[XiaofeiCao]

Hi @zlishaojiez , thanks for your report. Seems Mono.block() got interrupted. I'll take a deeper look.

[zlishaojiez]

Hi, Xiaofei
There were such az.sdk.message
{"az.sdk.message":"Refreshing token.","scopes":"amqp://stress1-westus2-cp102-titan.servicebus.windows.net/system-activity"}

Feb 27, 2023 @ 19:49:10.608 2023-02-27T19:49:10.607Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":"amqp:link:detach-forced","errorDescription":"Idle link tracker, link system-activity has been idle for 1800000ms TrackingId:7cf1e1dc-770c-40ae-838e-49bc26165f9c_G4, SystemTracker:stress1-westus2-cp102-titan:EventHub:system-activity, Timestamp:2023-02-27T19:49:10","linkName":"system-activity","entityPath":"system-activity"}

Feb 27, 2023 @ 19:49:10.608 2023-02-27T19:49:10.607Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_68107f_1677520455488","linkName":"system-activity","entityPath":"system-activity","state":"ACTIVE"}

Feb 27, 2023 @ 19:54:10.513 2023-02-27T19:54:10.513Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"system-activity"}

Feb 27, 2023 @ 19:54:10.513 2023-02-27T19:54:10.513Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"system-activity"}

Feb 27, 2023 @ 19:54:10.513 2023-02-27T19:54:10.513Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:89280c208e504ebb882f8ebc65e171e1_G4, SystemTracker:gateway5, Timestamp:2023-02-27T19:54:10","linkName":"cbs:sender","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:10.513 2023-02-27T19:54:10.513Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_68107f_1677520455488","linkName":"cbs:sender","entityPath":"$cbs","state":"ACTIVE"}

Feb 27, 2023 @ 19:54:10.513 2023-02-27T19:54:10.513Z [trace_id=26f625cc30e55a98db943d0953391be0]
[transaction_id=b2478bb2c2b9a9ee] WARN [reactor-executor-11 ] c.a.c.a.i.RequestResponseChannel.performLogging:362 - {"az.sdk.message":"Error in SendLinkHandler. Disposing unconfirmed sends.","exception":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:89280c208e504ebb882f8ebc65e171e1_G4, SystemTracker:gateway5, Timestamp:2023-02-27T19:54:10, errorContext[NAMESPACE: stress1-westus2-cp102-titan.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 93]","connectionId":"MF_68107f_1677520455488","linkName":"cbs"}

Feb 27, 2023 @ 19:54:10.514 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Transient error occurred. Retrying.","exception":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:89280c208e504ebb882f8ebc65e171e1_G4, SystemTracker:gateway5, Timestamp:2023-02-27T19:54:10, errorContext[NAMESPACE: stress1-westus2-cp102-titan.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 93]","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs","tryCount":0,"interval_ms":4511}

Feb 27, 2023 @ 19:54:10.514 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0]
[transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}

Feb 27, 2023 @ 19:54:10.514 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ReceiveLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:89280c208e504ebb882f8ebc65e171e1_G4, SystemTracker:gateway5, Timestamp:2023-02-27T19:54:10","linkName":"cbs:receiver","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:10.514 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ReceiveLinkHandler.performLogging:359 - {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_68107f_1677520455488","linkName":"cbs:receiver","entityPath":"$cbs","state":"ACTIVE"}

Feb 27, 2023 @ 19:54:10.515 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ConnectionHandler.performLogging:359 - {"az.sdk.message":"onConnectionRemoteClose","connectionId":"MF_68107f_1677520455488","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:89280c208e504ebb882f8ebc65e171e1_G4, SystemTracker:gateway5, Timestamp:2023-02-27T19:54:10","hostName":"stress1-westus2-cp102-titan.servicebus.windows.net"}

Feb 27, 2023 @ 19:54:10.515 2023-02-27T19:54:10.515Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ConnectionHandler.performLogging:359 - {"az.sdk.message":"onConnectionLocalClose","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"hostName":"stress1-westus2-cp102-titan.servicebus.windows.net"}

Feb 27, 2023 @ 19:54:10.515 2023-02-27T19:54:10.514Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}

Feb 27, 2023 @ 19:54:10.515 2023-02-27T19:54:10.515Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ConnectionHandler.performLogging:359 - {"az.sdk.message":"onConnectionUnbound","connectionId":"MF_68107f_1677520455488","hostName":"stress1-westus2-cp102-titan.servicebus.windows.net","state":"CLOSED","remoteState":"CLOSED"}

Feb 27, 2023 @ 19:54:10.515 2023-02-27T19:54:10.515Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=8eb595b1d81a5c6d] INFO [reactor-executor-11 ] c.a.c.a.implementation.ReactorConnection.performLogging:359 - {"az.sdk.message":"Disposing of ReactorConnection.","connectionId":"MF_68107f_1677520455488","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"Connection handler closed."}

Feb 27, 2023 @ 19:54:10.516 2023-02-27T19:54:10.515Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=8eb595b1d81a5c6d] INFO [reactor-executor-11 ] c.a.m.e.i.EventHubConnectionProcessor.performLogging:359 - {"az.sdk.message":"Channel is closed. Requesting upstream.","entityPath":"system-activity"}

Feb 27, 2023 @ 19:54:10.516 2023-02-27T19:54:10.516Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=8eb595b1d81a5c6d] INFO [reactor-executor-11 ] c.a.m.e.i.EventHubConnectionProcessor.performLogging:359 - {"az.sdk.message":"Setting next AMQP channel.","entityPath":"system-activity"}

Feb 27, 2023 @ 19:54:10.516 2023-02-27T19:54:10.516Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkFinal","connectionId":"MF_68107f_1677520455488","linkName":"system-activity","entityPath":"system-activity"}

Feb 27, 2023 @ 19:54:10.516 2023-02-27T19:54:10.516Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=8eb595b1d81a5c6d] INFO [reactor-executor-11 ] c.a.m.eventhubs.EventHubClientBuilder.performLogging:359 - {"az.sdk.message":"Emitting a single connection.","connectionId":"MF_a8cade_1677527650516"}

Feb 27, 2023 @ 19:54:10.516 2023-02-27T19:54:10.516Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=8eb595b1d81a5c6d] INFO [reactor-executor-11 ] c.a.m.e.i.EventHubConnectionProcessor.performLogging:359 - {"az.sdk.message":"Connection not requested, yet. Requesting one.","entityPath":"system-activity"}

Feb 27, 2023 @ 19:54:10.517 2023-02-27T19:54:10.516Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionFinal.","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"system-activity"}

Feb 27, 2023 @ 19:54:10.517 2023-02-27T19:54:10.517Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkFinal","connectionId":"MF_68107f_1677520455488","linkName":"cbs:sender","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:10.517 2023-02-27T19:54:10.517Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ReceiveLinkHandler.performLogging:359 - {"az.sdk.message":"onLinkFinal","connectionId":"MF_68107f_1677520455488","linkName":"cbs:receiver","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:10.517 2023-02-27T19:54:10.517Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ConnectionHandler.performLogging:359 - {"az.sdk.message":"onConnectionFinal","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"hostName":"stress1-westus2-cp102-titan.servicebus.windows.net"}

Feb 27, 2023 @ 19:54:10.517 2023-02-27T19:54:10.517Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SessionHandler.performLogging:359 - {"az.sdk.message":"onSessionFinal.","connectionId":"MF_68107f_1677520455488","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}

Feb 27, 2023 @ 19:54:15.026 2023-02-27T19:54:15.026Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Connection not requested, yet. Requesting one.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:15.026 2023-02-27T19:54:15.026Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Requesting from upstream.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs","tryCount":0}

Feb 27, 2023 @ 19:54:15.027 2023-02-27T19:54:15.027Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.implementation.ReactorConnection.performLogging:359 - {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs","linkName":"cbs"}

Feb 27, 2023 @ 19:54:15.028 2023-02-27T19:54:15.027Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:15.028 2023-02-27T19:54:15.027Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.SendLinkHandler.performLogging:359 - {"az.sdk.message":"Sender link was never active. Closing endpoint states.","connectionId":"MF_68107f_1677520455488","linkName":"cbs","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:15.029 2023-02-27T19:54:15.028Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Next AMQP channel received.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs","subscriberId":"un_6d9be2_1677527650515"}

Feb 27, 2023 @ 19:54:15.029 2023-02-27T19:54:15.029Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [parallel-3 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Upstream connection publisher was completed. Terminating processor.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:15.029 2023-02-27T19:54:15.029Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.handler.ReceiveLinkHandler.performLogging:359 - {"az.sdk.message":"Receiver link was never active. Closing endpoint states","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs","linkName":"cbs"}

Feb 27, 2023 @ 19:54:15.030 2023-02-27T19:54:15.029Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.i.AmqpChannelProcessor.performLogging:359 - {"az.sdk.message":"Channel is disposed.","connectionId":"MF_68107f_1677520455488","entityPath":"$cbs"}

Feb 27, 2023 @ 19:54:15.030 2023-02-27T19:54:15.030Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.implementation.ReactorConnection.performLogging:359 - {"az.sdk.message":"Closing executor.","connectionId":"MF_68107f_1677520455488"}

Feb 27, 2023 @ 19:54:19.045 2023-02-27T19:54:19.045Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.implementation.ReactorConnection.performLogging:359 - {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_68107f_1677520455488","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"connectionId[MF_68107f_1677520455488] Reactor selectable is disposed.","namespace":"stress1-westus2-cp102-titan.servicebus.windows.net"}

Feb 27, 2023 @ 19:54:19.045 2023-02-27T19:54:19.045Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.implementation.ReactorExecutor.performLogging:359 - {"az.sdk.message":"Processing all pending tasks and closing old reactor.","connectionId":"MF_68107f_1677520455488"}

Feb 27, 2023 @ 19:54:19.045 2023-02-27T19:54:19.045Z [trace_id=26f625cc30e55a98db943d0953391be0] [transaction_id=b2478bb2c2b9a9ee] INFO [reactor-executor-11 ] c.a.c.a.implementation.ReactorDispatcher.performLogging:359 - {"az.sdk.message":"Reactor selectable is being disposed.","connectionId":"MF_68107f_1677520455488"}

I don't makesure whether these logs about the API calls or is about another system "system-activity".
Maybe "Reactor selectable is being disposed." can cause this issue if the logs are related to the API call.

[XiaofeiCao]

Hi @zlishaojiez, thanks for the log!

Maybe "Reactor selectable is being disposed." can cause this issue if the logs are related to the API call.

It could be.

The above logs are from eventhubs. If you are doing long running API calls on eventhubs threads(like creating VMs), the eventhub connection may exceed max idle timeout and got disposed. Then the thread on which API calls are executed would get interrupted.

Could you show me how you combine the API calls with eventhubs?

[zlishaojiez]

Hi, Xiaofei
These logs form thread "reactor-executor-11", my API calls on another thread "worker-w20". They are not in the same thread.
I just do the computeManager.virtualMachines().getByResourceGroup(resGroup, name) call in the thread "worker-w20"
Sometimes it is interrupted and sometimes the call blocks and does not respond in 20 minutes

The okhttpclient configuration is
https://github.com/Azure/autorest-clientruntime-for-java/blob/master/client-runtime/src/main/java/com/microsoft/rest/RestClient.java#L264-L265

[XiaofeiCao]

Got it.

reactor-executor-11 is from eventhub client. I wonder which thread pool you use for your worker threads? How do you schedule the getByResourceGroup call on the thread?

(The OkHttpClient configuration you mentioned is from track1, and the SDK you are actually using is track2(2.23.0). So I guess you are using the default settings for OkHttpClient?)

[zlishaojiez]

Hi, Xiaofei
The worker thread is just a new Thread.
This happens on our scale test, there will be lots of getByResourceGroup in concurrency.
Will the Azure subscription delay the request when there are lots of requests at the same time?

[XiaofeiCao]

Hi @zlishaojiez

Will the Azure subscription delay the request when there are lots of requests at the same time?

I'm not aware of that and I don't find it in docs either(except for a 30 seconds call timeout):
https://learn.microsoft.com/en-us/azure/azure-resource-manager/management/azure-subscription-service-limits#api-management-limits

Our OkHttpClient has default total timeout of 10 (connect) + 60 (write) + 60 (read) = 130 seconds:

azure-sdk-for-java/sdk/core/azure-core-http-okhttp/src/main/java/com/azure/core/http/okhttp/OkHttpAsyncHttpClientBuilder.java

Lines 41 to 50 in a29b606

	static {
	ClientLogger logger = new ClientLogger(OkHttpAsyncHttpClientBuilder.class);
	Configuration configuration = Configuration.getGlobalConfiguration();
	DEFAULT_CONNECT_TIMEOUT = getDefaultTimeoutFromEnvironment(configuration,
	PROPERTY_AZURE_REQUEST_CONNECT_TIMEOUT, Duration.ofSeconds(10), logger);
	DEFAULT_WRITE_TIMEOUT = getDefaultTimeoutFromEnvironment(configuration, PROPERTY_AZURE_REQUEST_WRITE_TIMEOUT,
	Duration.ofSeconds(60), logger);
	DEFAULT_READ_TIMEOUT = getDefaultTimeoutFromEnvironment(configuration, PROPERTY_AZURE_REQUEST_READ_TIMEOUT,
	Duration.ofSeconds(60), logger);
	}

And we have a default retry policy of max 3 retries and max delay of 8 seconds between each retry. It could take a total of 4 network calls in a single method call, but 20 minutes is still weirdly long time.

Any chance you manually trigger an interruption? Some framework's implementation may enforce implicit method call timeout by interrupting the calling thread.

Manual interruption in this demo will produce similar result:

Click to see the log

reactor.core.Exceptions$ReactiveException: java.lang.InterruptedException
    at reactor.core.Exceptions.propagate(Exceptions.java:396)
    at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:91)
    at reactor.core.publisher.Mono.block(Mono.java:1742)
    at com.azure.resourcemanager.resources.fluentcore.arm.collection.implementation.GroupableResourcesImpl.getByResourceGroup(GroupableResourcesImpl.java:106)
    at com.azure.resourcemanager.resources.fluentcore.arm.collection.implementation.GroupableResourcesImpl.getByResourceGroup(GroupableResourcesImpl.java:28)
    at com.azure.resourcemanager.repro.ioexception.test.interrupted.GetResourceGroupInterruptedTests.lambda$test$0(GetResourceGroupInterruptedTests.java:87)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.InterruptedException
    at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1048)
    at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
    at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87)
    ... 5 more

Thank you for your feedback. This has been routed to the support team for assistance.