Azure
OpenAIClient causes "channel not registered to an event loop" error when receiving a 429 response status
Describe the bug
When using the OpenAIClient, if I call an endpoint which returns a 429 response with a body, I get an exception with error message channel not registered to an event loop.
Exception or Stack Trace java.lang.IllegalStateException: channel not registered to an event loop
at io.netty.channel.AbstractChannel.eventLoop(AbstractChannel.java:163)
at com.azure.core.http.netty.implementation.NettyUtility.closeConnection(NettyUtility.java:79)
at com.azure.core.http.netty.implementation.NettyAsyncHttpResponse.close(NettyAsyncHttpResponse.java:116)
at com.azure.core.http.policy.RetryPolicy.attemptSync(RetryPolicy.java:249)
at com.azure.core.http.policy.RetryPolicy.processSync(RetryPolicy.java:161)
at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53)
at com.azure.core.http.policy.AddHeadersFromContextPolicy.processSync(AddHeadersFromContextPolicy.java:67)
at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53)
at com.azure.core.http.policy.RequestIdPolicy.processSync(RequestIdPolicy.java:77)
at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53)
at com.azure.core.http.policy.HttpPipelineSyncPolicy.processSync(HttpPipelineSyncPolicy.java:51)
at com.azure.core.http.policy.UserAgentPolicy.processSync(UserAgentPolicy.java:174)
at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53)
at com.azure.core.http.HttpPipeline.sendSync(HttpPipeline.java:138)
at com.azure.core.implementation.http.rest.SyncRestProxy.send(SyncRestProxy.java:62)
at com.azure.core.implementation.http.rest.SyncRestProxy.invoke(SyncRestProxy.java:83)
at com.azure.core.implementation.http.rest.RestProxyBase.invoke(RestProxyBase.java:124)
at com.azure.core.http.rest.RestProxy.invoke(RestProxy.java:95)
at jdk.proxy2/jdk.proxy2.$Proxy10.getChatCompletionsSync(Unknown Source)
at com.azure.ai.openai.implementation.OpenAIClientImpl.getChatCompletionsWithResponse(OpenAIClientImpl.java:1688)
at com.azure.ai.openai.OpenAIClient.getChatCompletionsWithResponse(OpenAIClient.java:329)
at com.azure.ai.openai.OpenAIClient.getChatCompletions(OpenAIClient.java:696)
To Reproduce Use the code below against an endpoint which returns 429
Code Snippet
OpenAIClientBuilder openAIClientBuilder = new OpenAIClientBuilder()
.endpoint(<ENDOINT>)
.credential(new KeyCredential(<KEY>))
.serviceVersion(OpenAIServiceVersion.V2024_06_01);
String tokens = IntStream.range(0, 10000)
.mapToObj(Integer::toString)
.collect(Collectors.joining(" "));
OpenAIClient openAIClient = openAIClientBuilder.buildClient();
ChatCompletionsOptions chatCompletionsOptions = new ChatCompletionsOptions(List.of(
new ChatRequestSystemMessage("Count the tokens")
, new ChatRequestUserMessage(tokens)));
openAIClient.getChatCompletions(<DEPLOYMENT>, chatCompletionsOptions);
Expected behavior The client to throw a suitable exception
I think the above is a bug in com.azure.core.http.policy.RetryPolicy which on line 249 calls httpResponse.close() which attempts to close the response without reading the response body. If I use the following retry policy everything works corrrectly:
ExponentialBackoffOptions exponentialBackoffOptions = new ExponentialBackoffOptions();
exponentialBackoffOptions.setMaxRetries(0);
RetryOptions retryOptions = new RetryOptions(exponentialBackoffOptions);
openAIClientBuilder.retryOptions(retryOptions);
@robmartin-scibite Thank you for reaching out. @mssfang Can you please look into this?
Hi, @robmartin-scibite I won't be able to reproduce the issue at my end. Do you have more detail log that I can have a look. However, FYI, I received a same error code 429 with retry-after header value equals 24h. it causes the library to hang there after the first failure.
Hi @mssfang, I have included more logging below:
09:25:31.350 [main] DEBUG com.azure.core.implementation.ReflectionUtils -- Attempting to use java.lang.invoke package to handle reflection.
09:25:31.353 [main] DEBUG com.azure.core.implementation.ReflectionUtils -- Successfully used java.lang.invoke package to handle reflection.
09:25:31.448 [main] DEBUG com.azure.core.implementation.util.Providers -- Using com.azure.core.http.netty.NettyAsyncHttpClientProvider as the default com.azure.core.http.HttpClientProvider.
09:25:31.459 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory -- Using SLF4J as the default logging framework
09:25:31.460 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- -Dio.netty.noUnsafe: false
09:25:31.460 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- Java version: 21
09:25:31.460 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- sun.misc.Unsafe.theUnsafe: available
09:25:31.461 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- sun.misc.Unsafe base methods: all available
09:25:31.461 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- sun.misc.Unsafe.storeFence: available
09:25:31.461 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- java.nio.Buffer.address: available
09:25:31.461 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- direct buffer constructor: unavailable
java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled
at io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)
at io.netty.util.internal.PlatformDependent0$5.run(PlatformDependent0.java:332)
at java.base/java.security.AccessController.doPrivileged(AccessController.java:319)
at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:325)
at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:334)
at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:90)
at io.netty.util.Version.identify(Version.java:66)
at io.netty.util.Version.identify(Version.java:56)
at com.azure.core.http.netty.implementation.NettyUtility.createNettyVersionLogInformation(NettyUtility.java:112)
at com.azure.core.http.netty.implementation.NettyUtility.validateNettyVersions(NettyUtility.java:100)
at com.azure.core.http.netty.NettyAsyncHttpClientBuilder.<clinit>(NettyAsyncHttpClientBuilder.java:118)
at com.azure.core.http.netty.NettyAsyncHttpClientProvider.createInstance(NettyAsyncHttpClientProvider.java:64)
at com.azure.core.http.netty.NettyAsyncHttpClientProvider.createInstance(NettyAsyncHttpClientProvider.java:70)
at com.azure.core.implementation.http.HttpClientProviders.lambda$createInstance$0(HttpClientProviders.java:58)
at com.azure.core.implementation.util.Providers.create(Providers.java:119)
at com.azure.core.implementation.http.HttpClientProviders.createInstance(HttpClientProviders.java:58)
at com.azure.core.http.HttpClient.createDefault(HttpClient.java:61)
at com.azure.core.http.HttpClient.createDefault(HttpClient.java:51)
at com.azure.core.http.HttpPipelineBuilder.build(HttpPipelineBuilder.java:88)
at com.azure.ai.openai.OpenAIClientBuilder.createHttpPipeline(OpenAIClientBuilder.java:328)
at com.azure.ai.openai.OpenAIClientBuilder.buildInnerClient(OpenAIClientBuilder.java:280)
at com.azure.ai.openai.OpenAIClientBuilder.buildClient(OpenAIClientBuilder.java:358)
at com.scibite.scibitesearch.api.config.AiConfigTest.openAi(AiConfigTest.java:49)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:156)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
09:25:31.462 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- java.nio.Bits.unaligned: available, true
09:25:31.462 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable
java.lang.IllegalAccessException: class io.netty.util.internal.PlatformDependent0$7 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @48a242ce
at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:394)
at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:714)
at java.base/java.lang.reflect.Method.invoke(Method.java:571)
at io.netty.util.internal.PlatformDependent0$7.run(PlatformDependent0.java:468)
at java.base/java.security.AccessController.doPrivileged(AccessController.java:319)
at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:459)
at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:334)
at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:90)
at io.netty.util.Version.identify(Version.java:66)
at io.netty.util.Version.identify(Version.java:56)
at com.azure.core.http.netty.implementation.NettyUtility.createNettyVersionLogInformation(NettyUtility.java:112)
at com.azure.core.http.netty.implementation.NettyUtility.validateNettyVersions(NettyUtility.java:100)
at com.azure.core.http.netty.NettyAsyncHttpClientBuilder.<clinit>(NettyAsyncHttpClientBuilder.java:118)
at com.azure.core.http.netty.NettyAsyncHttpClientProvider.createInstance(NettyAsyncHttpClientProvider.java:64)
at com.azure.core.http.netty.NettyAsyncHttpClientProvider.createInstance(NettyAsyncHttpClientProvider.java:70)
at com.azure.core.implementation.http.HttpClientProviders.lambda$createInstance$0(HttpClientProviders.java:58)
at com.azure.core.implementation.util.Providers.create(Providers.java:119)
at com.azure.core.implementation.http.HttpClientProviders.createInstance(HttpClientProviders.java:58)
at com.azure.core.http.HttpClient.createDefault(HttpClient.java:61)
at com.azure.core.http.HttpClient.createDefault(HttpClient.java:51)
at com.azure.core.http.HttpPipelineBuilder.build(HttpPipelineBuilder.java:88)
at com.azure.ai.openai.OpenAIClientBuilder.createHttpPipeline(OpenAIClientBuilder.java:328)
at com.azure.ai.openai.OpenAIClientBuilder.buildInnerClient(OpenAIClientBuilder.java:280)
at com.azure.ai.openai.OpenAIClientBuilder.buildClient(OpenAIClientBuilder.java:358)
at com.scibite.scibitesearch.api.config.AiConfigTest.openAi(AiConfigTest.java:49)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:156)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent0 -- java.nio.DirectByteBuffer.<init>(long, {int,long}): unavailable
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- sun.misc.Unsafe: available
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- -Dio.netty.tmpdir: /var/folders/p8/jd0cx1zn4rxclq0j8qyc6f280000gp/T (java.io.tmpdir)
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- -Dio.netty.bitMode: 64 (sun.arch.data.model)
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- Platform: MacOS
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- -Dio.netty.maxDirectMemory: -1 bytes
09:25:31.463 [main] DEBUG io.netty.util.internal.PlatformDependent -- -Dio.netty.uninitializedArrayAllocationThreshold: -1
09:25:31.464 [main] DEBUG io.netty.util.internal.CleanerJava9 -- java.nio.ByteBuffer.cleaner(): available
09:25:31.464 [main] DEBUG io.netty.util.internal.PlatformDependent -- -Dio.netty.noPreferDirect: false
09:25:31.486 [main] INFO com.azure.core.http.netty.implementation.NettyUtility -- {"az.sdk.message":"The following Netty versions were found on the classpath and have a mismatch with the versions used by azure-core-http-netty. If your application runs without issue this message can be ignored, otherwise please align the Netty versions used in your application. For more information, see https://aka.ms/azsdk/java/dependency/troubleshoot.","azure-netty-version":"4.1.110.Final","azure-netty-native-version":"2.0.65.Final","classpath-netty-version-io.netty:netty-common":"4.1.115.Final","classpath-netty-version-io.netty:netty-handler":"4.1.115.Final","classpath-netty-version-io.netty:netty-handler-proxy":"4.1.115.Final","classpath-netty-version-io.netty:netty-buffer":"4.1.115.Final","classpath-netty-version-io.netty:netty-codec":"4.1.115.Final","classpath-netty-version-io.netty:netty-codec-http":"4.1.115.Final","classpath-netty-version-io.netty:netty-codec-http2":"4.1.115.Final","classpath-netty-version-io.netty:netty-transport-native-unix-common":"4.1.115.Final","classpath-netty-version-io.netty:netty-transport-native-epoll":"4.1.115.Final","classpath-netty-version-io.netty:netty-transport-native-kqueue":"4.1.115.Final","classpath-native-netty-version-io.netty:netty-tcnative-boringssl-static":"2.0.69.Final"}
09:25:31.488 [main] DEBUG reactor.util.Loggers -- Using Slf4j logging framework
09:25:31.496 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap -- -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
09:25:31.496 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap -- -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
09:25:31.503 [main] DEBUG io.netty.util.ResourceLeakDetector -- -Dio.netty.leakDetection.level: simple
09:25:31.503 [main] DEBUG io.netty.util.ResourceLeakDetector -- -Dio.netty.leakDetection.targetRecords: 4
09:25:31.590 [main] DEBUG io.netty.util.NetUtil -- -Djava.net.preferIPv4Stack: false
09:25:31.590 [main] DEBUG io.netty.util.NetUtil -- -Djava.net.preferIPv6Addresses: false
09:25:31.593 [main] DEBUG io.netty.util.NetUtilInitializations -- Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
09:25:31.593 [main] DEBUG io.netty.util.NetUtil -- Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
09:25:31.601 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- -Dio.netty.native.workdir: /var/folders/p8/jd0cx1zn4rxclq0j8qyc6f280000gp/T (io.netty.tmpdir)
09:25:31.601 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- -Dio.netty.native.deleteLibAfterLoading: true
09:25:31.601 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- -Dio.netty.native.tryPatchShadedId: true
09:25:31.601 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- -Dio.netty.native.detectNativeLibraryDuplicates: true
09:25:31.784 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- Successfully loaded the library /var/folders/p8/jd0cx1zn4rxclq0j8qyc6f280000gp/T/libnetty_tcnative_osx_aarch_6416155586391274036616.dylib
09:25:31.785 [main] DEBUG io.netty.util.internal.NativeLibraryLoader -- Loaded library with name 'netty_tcnative_osx_aarch_64'
09:25:31.785 [main] DEBUG io.netty.handler.ssl.OpenSsl -- Initialize netty-tcnative using engine: 'default'
09:25:31.785 [main] DEBUG io.netty.handler.ssl.OpenSsl -- netty-tcnative using native library: BoringSSL
09:25:31.825 [main] DEBUG io.netty.buffer.AbstractByteBuf -- -Dio.netty.buffer.checkAccessible: true
09:25:31.825 [main] DEBUG io.netty.buffer.AbstractByteBuf -- -Dio.netty.buffer.checkBounds: true
09:25:31.825 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory -- Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@749f539e
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.numHeapArenas: 24
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.numDirectArenas: 24
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.pageSize: 8192
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.maxOrder: 9
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.chunkSize: 4194304
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.smallCacheSize: 256
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.normalCacheSize: 64
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.maxCachedBufferCapacity: 32768
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.cacheTrimInterval: 8192
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.cacheTrimIntervalMillis: 0
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.useCacheForAllThreads: false
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
09:25:31.829 [main] DEBUG io.netty.buffer.PooledByteBufAllocator -- -Dio.netty.allocator.disableCacheFinalizersForFastThreadLocalThreads: false
09:25:31.831 [main] DEBUG io.netty.buffer.ByteBufUtil -- -Dio.netty.allocator.type: pooled
09:25:31.832 [main] DEBUG io.netty.buffer.ByteBufUtil -- -Dio.netty.threadLocalDirectBufferSize: 0
09:25:31.832 [main] DEBUG io.netty.buffer.ByteBufUtil -- -Dio.netty.maxThreadLocalCharBufferSize: 16384
09:25:31.833 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory -- Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@7906578e
09:25:31.835 [main] DEBUG io.netty.util.Recycler -- -Dio.netty.recycler.maxCapacityPerThread: 4096
09:25:31.835 [main] DEBUG io.netty.util.Recycler -- -Dio.netty.recycler.ratio: 8
09:25:31.835 [main] DEBUG io.netty.util.Recycler -- -Dio.netty.recycler.chunkSize: 32
09:25:31.835 [main] DEBUG io.netty.util.Recycler -- -Dio.netty.recycler.blocking: false
09:25:31.835 [main] DEBUG io.netty.util.Recycler -- -Dio.netty.recycler.batchFastThreadLocalOnly: true
09:25:31.837 [main] DEBUG io.netty.util.internal.PlatformDependent -- org.jctools-core.MpscChunkedArrayQueue: available
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 => ECDHE-ECDSA-AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256 => ECDHE-RSA-AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 => ECDHE-ECDSA-AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384 => ECDHE-RSA-AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-ECDSA-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-RSA-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256 => ECDHE-PSK-CHACHA20-POLY1305
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA => ECDHE-ECDSA-AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA => ECDHE-RSA-AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_128_CBC_SHA => ECDHE-PSK-AES128-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA => ECDHE-ECDSA-AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA => ECDHE-RSA-AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_ECDHE_PSK_WITH_AES_256_CBC_SHA => ECDHE-PSK-AES256-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_RSA_WITH_AES_128_GCM_SHA256 => AES128-GCM-SHA256
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_RSA_WITH_AES_256_GCM_SHA384 => AES256-GCM-SHA384
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_RSA_WITH_AES_128_CBC_SHA => AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_RSA_WITH_AES_128_CBC_SHA => AES128-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_PSK_WITH_AES_128_CBC_SHA => PSK-AES128-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_RSA_WITH_AES_256_CBC_SHA => AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_RSA_WITH_AES_256_CBC_SHA => AES256-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: TLS_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.CipherSuiteConverter -- Cipher suite mapping: SSL_PSK_WITH_AES_256_CBC_SHA => PSK-AES256-CBC-SHA
09:25:31.841 [main] DEBUG io.netty.handler.ssl.OpenSsl -- Supported protocols (OpenSSL): [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2, TLSv1.3]
09:25:31.841 [main] DEBUG io.netty.handler.ssl.OpenSsl -- Default cipher suites (OpenSSL): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256]
09:25:31.861 [main] DEBUG reactor.netty.tcp.TcpResources -- [http] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-http, daemon=true, selectCount=12, workerCount=12}
09:25:31.861 [main] DEBUG reactor.netty.tcp.TcpResources -- [http] resources will use the default ConnectionProvider: reactor.netty.resources.DefaultPooledConnectionProvider@54562ea6
09:25:31.862 [main] DEBUG reactor.netty.resources.PooledConnectionProvider -- Creating a new [http] client pool [PoolFactory{evictionInterval=PT0S, leasingStrategy=fifo, maxConnections=500, maxIdleTime=-1, maxLifeTime=-1, metricsEnabled=false, pendingAcquireMaxCount=1000, pendingAcquireTimeout=45000}] for [<<URI>>/<unresolved>:443]
09:25:31.867 [main] DEBUG reactor.netty.resources.DefaultLoopIOUring -- Default io_uring support : false
09:25:31.872 [main] DEBUG reactor.netty.resources.DefaultLoopEpoll -- Default Epoll support : false
09:25:31.879 [main] DEBUG reactor.netty.resources.DefaultLoopKQueue -- Default KQueue support : false
09:25:31.880 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup -- -Dio.netty.eventLoopThreads: 24
09:25:31.883 [main] DEBUG io.netty.util.concurrent.GlobalEventExecutor -- -Dio.netty.globalEventExecutor.quietPeriodSeconds: 1
09:25:31.886 [main] DEBUG io.netty.channel.nio.NioEventLoop -- -Dio.netty.noKeySetOptimization: false
09:25:31.886 [main] DEBUG io.netty.channel.nio.NioEventLoop -- -Dio.netty.selectorAutoRebuildThreshold: 512
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@a52ca2e
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@4393593c
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@314c8b4a
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@26d820eb
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@507d20bb
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@9fec931
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5cbd159f
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@3b05a99b
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@2c43eb8
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@7d0cc890
09:25:31.887 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@49293b43
09:25:31.888 [main] TRACE io.netty.channel.nio.NioEventLoop -- instrumented a special java.util.Set into: sun.nio.ch.KQueueSelectorImpl@5ff60a8c
09:25:31.898 [main] DEBUG io.netty.channel.DefaultChannelId -- -Dio.netty.processId: 37544 (auto-detected)
09:25:31.898 [main] DEBUG io.netty.channel.DefaultChannelId -- -Dio.netty.machineId: 60:3e:5f:ff:fe:59:58:9f (auto-detected)
09:25:31.909 [reactor-http-nio-1] DEBUG reactor.netty.resources.PooledConnectionProvider -- [b28b587e] Created a new pooled channel, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
09:25:31.913 [reactor-http-nio-1] DEBUG io.netty.util.ResourceLeakDetectorFactory -- Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@580f36af
09:25:31.919 [reactor-http-nio-1] DEBUG reactor.netty.tcp.SslProvider -- [b28b587e] SSL enabled using engine io.netty.handler.ssl.OpenSslEngine@563cbc90 and SNI <<URI>>/<unresolved>:443
09:25:31.924 [reactor-http-nio-1] DEBUG reactor.netty.transport.TransportConfig -- [b28b587e] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
09:25:31.929 [reactor-http-nio-1] DEBUG reactor.netty.transport.TransportConnector -- [b28b587e] Connecting to [<<URI>>/100.64.1.16:443].
09:25:31.931 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Registering pool release on close event for channel
09:25:31.931 [reactor-http-nio-1] DEBUG reactor.netty.resources.PooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Channel connected, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
09:25:32.289 [reactor-http-nio-1] DEBUG io.netty.handler.ssl.SslHandler -- [id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] HANDSHAKEN: protocol:TLSv1.3 cipher suite:TLS_AES_256_GCM_SHA384
09:25:32.290 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}, [connected])
09:25:32.295 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(GET{uri=null, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [configured])
09:25:32.296 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientConnect -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Handler is being applied: {uri=<<URI>>/openai/deployments/sbs-gpt4o/chat/completions?api-version=2024-06-01, method=POST}
09:25:32.297 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [request_prepared])
09:25:32.299 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Added decoder [azureSdkHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureSdkHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
09:25:32.305 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [request_sent])
09:25:32.467 [reactor-http-nio-1] DEBUG io.netty.util.ResourceLeakDetectorFactory -- Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@4570bb8e
09:25:32.757 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientOperations -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 429 Too Many Requests
Date: <filtered>
Content-Type: <filtered>
Content-Length: <filtered>
Connection: <filtered>
Retry-After: <filtered>
x-ratelimit-reset-tokens: <filtered>
x-ms-client-request-id: <filtered>
apim-request-id: <filtered>
Strict-Transport-Security: <filtered>
x-content-type-options: <filtered>
policy-id: <filtered>
x-ms-region: <filtered>
x-ratelimit-remaining-requests: <filtered>
09:25:32.757 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [response_received])
09:25:32.763 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientOperations -- [b28b587e-1, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Received last HTTP packet
09:25:32.764 [reactor-http-nio-1] TRACE reactor.netty.channel.ChannelOperations -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Disposing ChannelOperation from a channel
java.lang.Exception: ChannelOperation terminal stack
at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:501)
at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:808)
at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:115)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at com.azure.core.http.netty.implementation.AzureSdkHandler.channelRead(AzureSdkHandler.java:224)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1503)
at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1377)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1417)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)
09:25:32.764 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [response_completed])
09:25:32.764 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Removed handler: azureSdkHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
09:25:32.764 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Non Removed handler: azureSdkHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
09:25:32.765 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [disconnecting])
09:25:32.765 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Releasing channel
09:25:32.766 [reactor-http-nio-1] DEBUG reactor.netty.resources.PooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Channel cleaned, now: 0 active connections, 1 inactive connections and 0 pending acquire requests.
09:25:32.766 [main] DEBUG com.azure.core.http.policy.RetryPolicy -- {"az.sdk.message":"Retrying.","tryCount":0,"durationMs":19000}
09:25:32.767 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientOperations -- [dbde41ea, L:/100.64.0.1:49411 ! R:<<URI>>/100.64.1.16:443] Http client inbound receiver cancelled, closing channel.
09:25:32.767 [reactor-http-nio-1] WARN io.netty.util.concurrent.AbstractEventExecutor -- A task raised an exception. Task: com.azure.core.http.netty.implementation.NettyUtility$$Lambda/0x00000070013702b8@26e241db
java.lang.IllegalStateException: channel not registered to an event loop
at io.netty.channel.AbstractChannel.eventLoop(AbstractChannel.java:163)
at io.netty.channel.AbstractChannelHandlerContext.executor(AbstractChannelHandlerContext.java:132)
at io.netty.channel.AbstractChannelHandlerContext.newPromise(AbstractChannelHandlerContext.java:1011)
at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:560)
at io.netty.channel.DefaultChannelPipeline.close(DefaultChannelPipeline.java:906)
at io.netty.channel.AbstractChannel.close(AbstractChannel.java:243)
at reactor.netty.http.client.HttpClientOperations.onInboundCancel(HttpClientOperations.java:302)
at reactor.netty.channel.FluxReceive.disposeAndUnsubscribeReceiver(FluxReceive.java:490)
at reactor.netty.channel.FluxReceive.lambda$new$0(FluxReceive.java:86)
at reactor.netty.channel.FluxReceive.cancelReceiver(FluxReceive.java:199)
at reactor.netty.channel.FluxReceive.doCancel(FluxReceive.java:205)
at reactor.netty.channel.FluxReceive.dispose(FluxReceive.java:118)
at reactor.netty.channel.ChannelOperations.discard(ChannelOperations.java:384)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)
09:25:51.775 [reactor-http-nio-1] DEBUG reactor.netty.resources.PooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Channel acquired, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
09:25:51.776 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientConnect -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Handler is being applied: {uri=<<URI>>/openai/deployments/sbs-gpt4o/chat/completions?api-version=2024-06-01, method=POST}
09:25:51.776 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [request_prepared])
09:25:51.777 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Added decoder [azureSdkHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureSdkHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
09:25:51.780 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [request_sent])
09:25:54.301 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientOperations -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Date: <filtered>
Content-Type: <filtered>
Content-Length: <filtered>
Connection: <filtered>
apim-request-id: <filtered>
Strict-Transport-Security: <filtered>
x-content-type-options: <filtered>
x-ratelimit-remaining-tokens: <filtered>
x-ms-rai-invoked: <filtered>
x-request-id: <filtered>
x-ms-region: <filtered>
azureml-model-session: <filtered>
x-ratelimit-remaining-requests: <filtered>
x-envoy-upstream-service-time: <filtered>
x-ms-client-request-id: <filtered>
09:25:54.301 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [response_received])
09:25:54.302 [reactor-http-nio-1] DEBUG reactor.netty.http.client.HttpClientOperations -- [b28b587e-2, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Received last HTTP packet
09:25:54.302 [reactor-http-nio-1] TRACE reactor.netty.channel.ChannelOperations -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Disposing ChannelOperation from a channel
java.lang.Exception: ChannelOperation terminal stack
at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:501)
at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:808)
at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:115)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at com.azure.core.http.netty.implementation.AzureSdkHandler.channelRead(AzureSdkHandler.java:224)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1503)
at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1377)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1417)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:1583)
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [response_completed])
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Removed handler: azureSdkHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.ReactorNetty -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Non Removed handler: azureSdkHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] onStateChange(POST{uri=/openai/deployments/sbs-gpt4o/chat/completions, connection=PooledConnection{channel=[id: 0xb28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443]}}, [disconnecting])
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.resources.DefaultPooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Releasing channel
09:25:54.303 [reactor-http-nio-1] DEBUG reactor.netty.resources.PooledConnectionProvider -- [b28b587e, L:/100.64.0.1:49411 - R:<<URI>>/100.64.1.16:443] Channel cleaned, now: 0 active connections, 1 inactive connections and 0 pending acquire requests.
09:25:54.315 [reactor-http-nio-1] DEBUG reactor.netty.channel.FluxReceive -- [bb5f636d, L:/100.64.0.1:49411 ! R:<<URI>>/100.64.1.16:443] [terminated=true, cancelled=false, pending=1, error=null]: subscribing inbound receiver
Process finished with exit code 0
I see the same issue occurred with me too when I am trying to use azure openai chat model from langchain4j:
java.lang.IllegalStateException: channel not registered to an event loop at io.netty.channel.AbstractChannel.eventLoop(AbstractChannel.java:163) ~[netty-transport-4.1.115.Final.jar:4.1.115.Final] at com.azure.core.http.netty.implementation.NettyUtility.closeConnection(NettyUtility.java:79) ~[azure-core-http-netty-1.15.7.jar:1.15.7] at com.azure.core.http.netty.implementation.NettyAsyncHttpResponse.close(NettyAsyncHttpResponse.java:116) ~[azure-core-http-netty-1.15.7.jar:1.15.7] at com.azure.core.http.policy.RetryPolicy.attemptSync(RetryPolicy.java:249) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.RetryPolicy.processSync(RetryPolicy.java:161) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.AddHeadersPolicy.processSync(AddHeadersPolicy.java:66) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.AddHeadersFromContextPolicy.processSync(AddHeadersFromContextPolicy.java:67) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.RequestIdPolicy.processSync(RequestIdPolicy.java:77) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.HttpPipelineSyncPolicy.processSync(HttpPipelineSyncPolicy.java:51) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.policy.UserAgentPolicy.processSync(UserAgentPolicy.java:174) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:53) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.HttpPipeline.sendSync(HttpPipeline.java:138) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.implementation.http.rest.SyncRestProxy.send(SyncRestProxy.java:62) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.implementation.http.rest.SyncRestProxy.invoke(SyncRestProxy.java:83) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.implementation.http.rest.RestProxyBase.invoke(RestProxyBase.java:124) ~[azure-core-1.54.1.jar:1.54.1] at com.azure.core.http.rest.RestProxy.invoke(RestProxy.java:95) ~[azure-core-1.54.1.jar:1.54.1] at jdk.proxy2/jdk.proxy2.$Proxy118.getChatCompletionsSync(Unknown Source) ~[na:na] at com.azure.ai.openai.implementation.OpenAIClientImpl.getChatCompletionsWithResponse(OpenAIClientImpl.java:1900) ~[azure-ai-openai-1.0.0-beta.13.jar:1.0.0-beta.13] at com.azure.ai.openai.OpenAIClient.getChatCompletionsWithResponse(OpenAIClient.java:350) ~[azure-ai-openai-1.0.0-beta.13.jar:1.0.0-beta.13] at com.azure.ai.openai.OpenAIClient.getChatCompletions(OpenAIClient.java:760) ~[azure-ai-openai-1.0.0-beta.13.jar:1.0.0-beta.13] at dev.langchain4j.model.azure.AzureOpenAiChatModel.generate(AzureOpenAiChatModel.java:378) ~[langchain4j-azure-open-ai-1.0.0-alpha1.jar:na] at dev.langchain4j.model.azure.AzureOpenAiChatModel.chat(AzureOpenAiChatModel.java:316) ~[langchain4j-azure-open-ai-1.0.0-alpha1.jar:na] at dev.langchain4j.service.DefaultAiServices$1.invoke(DefaultAiServices.java:282) ~[langchain4j-1.0.0-alpha1.jar:na] at jdk.proxy2/jdk.proxy2.$Proxy139.handleUserMessage(Unknown Source) ~[na:na] at com.automation.controllers.TabChatController.processChat(TabChatController.java:22) ~[main/:na] at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:255) ~[spring-web-6.2.0.jar:6.2.0] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:188) ~[spring-web-6.2.0.jar:6.2.0] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:986) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:891) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1088) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:978) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) ~[spring-webmvc-6.2.0.jar:6.2.0] at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914) ~[spring-webmvc-6.2.0.jar:6.2.0] at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590) ~[tomcat-embed-core-10.1.33.jar:6.0] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) ~[spring-webmvc-6.2.0.jar:6.2.0] at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.33.jar:6.0] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:195) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-6.2.0.jar:6.2.0] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.2.0.jar:6.2.0] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-6.2.0.jar:6.2.0] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.2.0.jar:6.2.0] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-6.2.0.jar:6.2.0] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.2.0.jar:6.2.0] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:397) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63) ~[tomcat-embed-core-10.1.33.jar:10.1.33] at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Same problem for us. The faulty behavior started after upgrading to spring boot ≥ 3.4.x. from 3.3.x
We also see this problem when using Azure OpenAI via SpringAI, however we're on Spring Boot version 3.3.7.
When receiving error code 429 TooManyRequest, the Azure OpenAI service will return a 24Hrs time window for the next request.
You can configure the RetryPolicy to handle this error. Here is an example of how to configure the RetryPolicy:
ExponentialBackoffOptions exponentialOptions = new ExponentialBackoffOptions()
.setMaxRetries(1) // The number of retries to attempt before giving up.
.setBaseDelay(Duration.ofSeconds(5)) // The base delay between retry attempts.
.setMaxDelay(Duration.ofSeconds(15)); // The maximum delay between retry attempts
// Alternatively, FixedDelay retry strategy can be used to configure the RetryPolicy.
// But here we are using ExponentialBackoff for demonstration.
ExponentialBackoff backoffPolicy = new ExponentialBackoff(exponentialOptions);
OpenAIClient client = new OpenAIClientBuilder()
.endpoint(endpoint)
.credential(new AzureKeyCredential(azureOpenaiKey))
.retryPolicy(new RetryPolicy(backoffPolicy, "{your-retry-header}", ChronoUnit.SECONDS))
.buildClient();
Hi, I have created a simple project that reproduces this issue https://github.com/joanna-kjm/azure-sdk-issue-43583
It's not related to the duration passed by azure in "Retry-After" header - it doesn't matter how how long client stops. As @robmartin-scibite said it's something inside retry mechanizm and I believe it only happens with netty client (default one). For me the solution is to use okhttp instead.
There are both netty and okhttp clients tests in my sample. I was only able to reproduce the issue when netty client is in use.
following some more investigation we have also switched to okHttp for the moment. thanks for the test setup @joanna-kjm !
When receiving error code 429
TooManyRequest, the Azure OpenAI service will return a 24Hrs time window for the next request. You can configure theRetryPolicyto handle this error. Here is an example of how to configure theRetryPolicy:
@mssfang The issue isn't about retry policy configuration, there's a flaw in retry logic implementation when dealing with Netty and @joanna-kjm gave you a pretty neat sample project to reproduce the issue, showing the different behaviour when using OkHttpClient. Is there any plan on resolving the issue?
Hi, I have created a simple project that reproduces this issue https://github.com/joanna-kjm/azure-sdk-issue-43583
It's not related to the duration passed by azure in "Retry-After" header - it doesn't matter how how long client stops. As @robmartin-scibite said it's something inside retry mechanizm and I believe it only happens with netty client (default one). For me the solution is to use okhttp instead.
There are both netty and okhttp clients tests in my sample. I was only able to reproduce the issue when netty client is in use.
@joanna-kjm Thank you for the investigation. May I know what is the version of Reactor Netty you are using?
@joanna-kjm Thank you for the investigation. May I know what is the version of Reactor Netty you are using?
@mssfang She gave you a full blown project to work on, check it out and look at the dependency hyerarchy. Anyway it's Reactor Netty 1.2.0. I already tryied overriding the transitive dependency to use the latest stable version (1.2.4) for another project with no luck.
Switching to OkHttp works, but there are a couple of things to note. The client's callTimeout we set doesn't work because the Azure SDK has a default setting that will interrupt the request (the O1 model requires more time for the call). Here's the fix:
var readTimeout = 120; // 120 sec
var writeTimeout = 120;
var httpClient = new OkHttpClient.Builder()
.readTimeout(readTimeout, TimeUnit.SECONDS) // set for O1 model which needs more time to respond
.callTimeout(writeTimeout, TimeUnit.SECONDS)
.build();
// you should also config this
var configuration = new ConfigurationBuilder()
.putProperty(Configuration.PROPERTY_AZURE_REQUEST_RESPONSE_TIMEOUT, String.valueOf(readTimeout * 1000))
.putProperty(Configuration.PROPERTY_AZURE_REQUEST_READ_TIMEOUT, String.valueOf(writeTimeout * 1000))
.build();
// client to use
var client = new OpenAIClientBuilder()
.httpClient(new OkHttpAsyncHttpClientBuilder(httpClient).build())
.configuration(configuration)
.buildClient()
@joanna-kjm Thank you for the investigation. May I know what is the version of Reactor Netty you are using?
@mssfang She gave you a full blown project to work on, check it out and look at the dependency hyerarchy. Anyway it's Reactor Netty 1.2.0. I already tryied overriding the transitive dependency to use the latest stable version (1.2.4) for another project with no luck.
It could be related to this: https://github.com/Azure/azure-sdk-for-java/pull/43367 @alzimmermsft do you know if we have a fix in the core netty httpclient? release in May?
Spring AI version: 1.0.0-M7 Spring Boot Version: 3.3.4 Open JDK: 21
`@Configuration public class AzureOpenAiConfig {
@Bean
public AzureOpenAIClientBuilderCustomizer azureOpenAiClientCustomizer() {
return openAiClientBuilder -> {
ExponentialBackoffOptions exponentialOptions = new ExponentialBackoffOptions()
.setMaxRetries(1)
.setBaseDelay(Duration.ofSeconds(5))
.setMaxDelay(Duration.ofSeconds(15));
RetryOptions retryOptions = new RetryOptions(exponentialOptions)
openAiClientBuilder.retryPolicy(new RetryPolicy(retryOptions));
};
}
}`
The above code could not fix the issue, what's the workaround?
Is there any plan on resolving the issue?
HI @thingersoft, the Azure OpenAI Inference SDK has been deprecated and won't receive updates in its current form. This package will be repurposed to provide Azure types to be used with the official OpenAI Java SDK in the future, but there is not much detail I can provide at this point in time, as things are still in flux. We have provided a basic migration guide for this in this folder.
Hi @robmartin-scibite. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
Hi @robmartin-scibite, we're sending this friendly reminder because we haven't heard back from you in 7 days. We need more information about this issue to help address it. Please be sure to give us your input. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!