Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG]MSI doesn't work for Eventhubs and Service Bus in Azure Spring Cloud. #26541

Closed
backwind1233 opened this issue Jan 17, 2022 · 8 comments
Closed

[BUG]MSI doesn't work for Eventhubs and Service Bus in Azure Spring Cloud. #26541

backwind1233 opened this issue Jan 17, 2022 · 8 comments
Assignees
@backwind1233
Labels
azure-spring All azure-spring related issues azure-spring-samples Client This issue points to a problem in the data-plane of the library. issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. Service This issue points to a problem in the service.
Milestone
Spring Cloud Azur...

Comments

@backwind1233
Copy link
Contributor

backwind1233 commented Jan 17, 2022 •
edited
Loading

@leonard520 please help review this issue.

Samples of Eventhubs and Service Bus in this repo doesn't work deployed in ASC with MSI.

Example:
error stack of multiple-namespaces while deploying with MSI in ASC.

2022-01-13 05:51:30.602 ERROR 1 --- [ctor-executor-1] c.a.c.a.implementation.ReactorReceiver   : Cannot add credits to closed link: queue1_604e38_1642053086338
2022-01-13 05:51:30.604 ERROR 1 --- [ctor-executor-1] reactor.core.publisher.Operators         : Operator called default onErrorDropped

reactor.core.Exceptions$ErrorCallbackNotImplemented: java.lang.IllegalStateException: Cannot add credits to closed link: queue1_604e38_1642053086338
Caused by: java.lang.IllegalStateException: Cannot add credits to closed link: queue1_604e38_1642053086338
        at com.azure.core.amqp.implementation.ReactorReceiver.addCredits(ReactorReceiver.java:176) ~[azure-core-amqp-2.3.4.jar!/:2.3.4]
        at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.checkAndAddCredits(ServiceBusReceiveLinkProcessor.java:537) [azure-messaging-servicebus-7.4.2.jar!/:7.4.2]
        at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.onNext(ServiceBusReceiveLinkProcessor.java:242) [azure-messaging-servicebus-7.4.2.jar!/:7.4.2]
        at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.onNext(ServiceBusReceiveLinkProcessor.java:43) [azure-messaging-servicebus-7.4.2.jar!/:7.4.2]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.lambda$onNext$1(TracingSubscriber.java:58) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.withActiveSpan(TracingSubscriber.java:79) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.onNext(TracingSubscriber.java:58) [na:na]
        at reactor.core.publisher.FluxRepeatPredicate$RepeatPredicateSubscriber.onNext(FluxRepeatPredicate.java:86) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.lambda$onNext$1(TracingSubscriber.java:58) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.withActiveSpan(TracingSubscriber.java:79) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.onNext(TracingSubscriber.java:58) [na:na]
        at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.lambda$onNext$1(TracingSubscriber.java:58) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.withActiveSpan(TracingSubscriber.java:79) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.onNext(TracingSubscriber.java:58) [na:na]
        at reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:99) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onNext(FluxRetryWhen.java:174) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.lambda$onNext$1(TracingSubscriber.java:58) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.withActiveSpan(TracingSubscriber.java:79) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.onNext(TracingSubscriber.java:58) [na:na]
        at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:210) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.lambda$onNext$1(TracingSubscriber.java:58) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.withActiveSpan(TracingSubscriber.java:79) [na:na]
        at io.opentelemetry.javaagent.shaded.instrumentation.reactor.TracingSubscriber.onNext(TracingSubscriber.java:58) [na:na]
        at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.Operators$MonoSubscriber.request(Operators.java:1906) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.request(FluxPeekFuseable.java:144) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.request(Operators.java:2158) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.SerializedSubscriber.request(SerializedSubscriber.java:151) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request(MonoPeekTerminal.java:139) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.request(Operators.java:2158) ~[reactor-core-3.4.9.jar!/:3.4.9]
        at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.requestUpstream(ServiceBusReceiveLinkProcessor.java:413) [azure-messaging-servicebus-7.4.2.jar!/:7.4.2]

logs of event hubs

2022-01-13 07:00:56.137  INFO 1 --- [ctor-executor-2] c.a.c.a.i.handler.SendLinkHandler        : onLinkRemoteOpen connectionId[MF_384c25_1642057236020], entityPath[eh1], linkName[eh1], remoteTarget[Target{address='eh1', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}]
2022-01-13 07:00:56.137  INFO 1 --- [ctor-executor-2] c.a.c.a.i.handler.SendLinkHandler        : onLinkRemoteClose connectionId[MF_384c25_1642057236020] linkName[eh1], errorCondition[null] errorDescription[null]
2022-01-13 07:01:00.511  INFO 1 --- [pool-7-thread-1] c.a.m.e.PartitionBasedLoadBalancer       : Load balancer already running
2022-01-13 07:01:01.702 ERROR 1 --- [     parallel-1] c.azure.identity.EnvironmentCredential   : EnvironmentCredential authentication unavailable. Environment variables are not fully configured.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/net/identity/environmentcredential/troubleshoot
2022-01-13 07:01:01.702  INFO 1 --- [     parallel-1] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential EnvironmentCredential is unavailable.
2022-01-13 07:01:01.730  INFO 1 --- [     parallel-1] c.a.identity.ManagedIdentityCredential   : Azure Identity => Managed Identity environment: AZURE VM IMDS ENDPOINT
2022-01-13 07:01:01.730  INFO 1 --- [     parallel-1] c.a.identity.ManagedIdentityCredential   : Azure Identity => getToken() result for scopes [https://storage.azure.com/.default]: SUCCESS
2022-01-13 07:01:01.730  INFO 1 --- [     parallel-1] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential ManagedIdentityCredential returns a token
2022-01-13 07:01:01.730  INFO 1 --- [     parallel-1] c.a.c.implementation.AccessTokenCache    : Acquired a new access token at 1641970832 seconds after expiry. Retry may be attempted after 30 seconds.
2022-01-13 07:01:01.806  INFO 1 --- [or-http-epoll-1] a.s.i.e.i.EventHubsInboundChannelAdapter : Started receiving on partition: 1
2022-01-13 07:01:01.808  INFO 1 --- [or-http-epoll-1] c.a.m.eventhubs.PartitionPumpManager     : Starting event processing from offset[@latest], sequenceNumber[null], enqueuedTime[null], isInclusive[false] for partition 1
2022-01-13 07:01:01.810  INFO 1 --- [or-http-epoll-1] c.a.m.eventhubs.EventHubClientBuilder    : connectionId[MF_f9cd79_1642057261810]: Emitting a single connection.
2022-01-13 07:01:01.810  INFO 1 --- [or-http-epoll-1] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Setting next AMQP channel.
2022-01-13 07:01:01.811  INFO 1 --- [or-http-epoll-1] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Next AMQP channel received, updating 0 current subscribers
2022-01-13 07:01:01.823  INFO 1 --- [or-http-epoll-1] c.a.m.e.i.AmqpReceiveLinkProcessor       : Setting new subscription for receive link processor
2022-01-13 07:01:01.823  INFO 1 --- [or-http-epoll-1] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:01.824  INFO 1 --- [or-http-epoll-1] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:01.824  INFO 1 --- [or-http-epoll-1] c.a.c.a.i.ReactorConnection              : connectionId[MF_f9cd79_1642057261810]: Creating and starting connection to ehn-eh-integration-tyaeb.servicebus.windows.net:5671
2022-01-13 07:01:01.825  INFO 1 --- [or-http-epoll-1] c.a.c.a.implementation.ReactorExecutor   : connectionId[MF_f9cd79_1642057261810] message[Starting reactor.]
2022-01-13 07:01:01.826  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler      : onConnectionInit connectionId[MF_f9cd79_1642057261810] hostname[ehn-eh-integration-tyaeb.servicebus.windows.net] amqpHostname[ehn-eh-integration-tyaeb.servicebus.windows.net]
2022-01-13 07:01:01.826  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReactorHandler         : connectionId[MF_f9cd79_1642057261810] reactor.onReactorInit
2022-01-13 07:01:01.826  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler      : onConnectionLocalOpen connectionId[MF_f9cd79_1642057261810] hostname[ehn-eh-integration-tyaeb.servicebus.windows.net] errorCondition[null] errorDescription[null]
2022-01-13 07:01:01.827  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler      : onConnectionBound connectionId[MF_f9cd79_1642057261810] hostname[ehn-eh-integration-tyaeb.servicebus.windows.net] peerDetails[ehn-eh-integration-tyaeb.servicebus.windows.net:5671]
2022-01-13 07:01:02.165  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler      : onConnectionRemoteOpen hostname[ehn-eh-integration-tyaeb.servicebus.windows.net], connectionId[MF_f9cd79_1642057261810], remoteContainer[83876f51a7d34132afd7156b3849dc9d_G9]
2022-01-13 07:01:02.167  INFO 1 --- [ctor-executor-3] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Channel is now active.
2022-01-13 07:01:02.233  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.SessionHandler         : onSessionRemoteOpen connectionId[MF_f9cd79_1642057261810], entityName[eh1/ConsumerGroups/$default/Partitions/1], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
2022-01-13 07:01:02.239  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection              : Setting CBS channel.
2022-01-13 07:01:02.305  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.SessionHandler         : onSessionRemoteOpen connectionId[MF_f9cd79_1642057261810], entityName[cbs-session], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
2022-01-13 07:01:02.306  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection              : connectionId[MF_f9cd79_1642057261810] entityPath[$cbs] linkName[cbs] Emitting new response channel.
2022-01-13 07:01:02.306  INFO 1 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs    : namespace[MF_f9cd79_1642057261810] entityPath[$cbs]: Setting next AMQP channel.
2022-01-13 07:01:02.306  INFO 1 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs    : namespace[MF_f9cd79_1642057261810] entityPath[$cbs]: Next AMQP channel received, updating 1 current subscribers
2022-01-13 07:01:02.306 ERROR 1 --- [ctor-executor-3] c.azure.identity.EnvironmentCredential   : EnvironmentCredential authentication unavailable. Environment variables are not fully configured.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/net/identity/environmentcredential/troubleshoot
2022-01-13 07:01:02.307  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential EnvironmentCredential is unavailable.
2022-01-13 07:01:02.330  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => Managed Identity environment: AZURE VM IMDS ENDPOINT
2022-01-13 07:01:02.330  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => getToken() result for scopes [https://eventhubs.azure.net/.default]: SUCCESS
2022-01-13 07:01:02.330  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential ManagedIdentityCredential returns a token
2022-01-13 07:01:02.397  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.SendLinkHandler        : onLinkRemoteOpen connectionId[MF_f9cd79_1642057261810], entityPath[$cbs], linkName[cbs:sender], remoteTarget[Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}]
2022-01-13 07:01:02.397  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteOpen connectionId[MF_f9cd79_1642057261810], entityPath[$cbs], linkName[cbs:receiver], remoteSource[Source{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}]
2022-01-13 07:01:02.398  INFO 1 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs    : namespace[MF_f9cd79_1642057261810] entityPath[$cbs]: Channel is now active.
2022-01-13 07:01:02.580  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Scheduling refresh token task. scopes[https://eventhubs.azure.net/.default]
2022-01-13 07:01:02.581 ERROR 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Error occurred while refreshing token that is not retriable. Not scheduling refresh task. Use ActiveClientTokenManager.authorize() to schedule task again. audience[amqp://ehn-eh-integration-tyaeb.servicebus.windows.net/eh1/ConsumerGroups/$default/Partitions/1] scopes[https://eventhubs.azure.net/.default]
period >= 0 required but it was -1477773778000000000
2022-01-13 07:01:02.588  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : connectionId[MF_f9cd79_1642057261810] sessionId[eh1/ConsumerGroups/$default/Partitions/1] linkName[1_b127ca_1642057261814] Creating a new receiver link.
2022-01-13 07:01:02.620  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.694  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.695  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Returning existing receive link.
2022-01-13 07:01:02.700  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receiver link was never active. Closing endpoint states.
2022-01-13 07:01:02.703  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]: Complete. Removing receive link.
2022-01-13 07:01:02.704  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.704  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.704  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.705  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.705  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.705  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.707 ERROR 1 --- [ctor-executor-3] c.azure.identity.EnvironmentCredential   : EnvironmentCredential authentication unavailable. Environment variables are not fully configured.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/net/identity/environmentcredential/troubleshoot
2022-01-13 07:01:02.707  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential EnvironmentCredential is unavailable.
2022-01-13 07:01:02.737  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => Managed Identity environment: AZURE VM IMDS ENDPOINT
2022-01-13 07:01:02.738  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => getToken() result for scopes [https://eventhubs.azure.net/.default]: SUCCESS
2022-01-13 07:01:02.738  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential ManagedIdentityCredential returns a token
2022-01-13 07:01:02.740  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:02.806  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteOpen connectionId[MF_f9cd79_1642057261810], entityPath[eh1/ConsumerGroups/$default/Partitions/1], linkName[1_b127ca_1642057261814], action[waitingForError]
2022-01-13 07:01:02.806  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteClose connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814], errorCondition[null] errorDescription[null]
2022-01-13 07:01:02.806  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:02.807  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Scheduling refresh token task. scopes[https://eventhubs.azure.net/.default]
2022-01-13 07:01:02.807 ERROR 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Error occurred while refreshing token that is not retriable. Not scheduling refresh task. Use ActiveClientTokenManager.authorize() to schedule task again. audience[amqp://ehn-eh-integration-tyaeb.servicebus.windows.net/eh1/ConsumerGroups/$default/Partitions/1] scopes[https://eventhubs.azure.net/.default]
period >= 0 required but it was -1477773778000000000
2022-01-13 07:01:02.808  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : connectionId[MF_f9cd79_1642057261810] sessionId[eh1/ConsumerGroups/$default/Partitions/1] linkName[1_b127ca_1642057261814] Creating a new receiver link.
2022-01-13 07:01:02.809  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.809  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.811  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Returning existing receive link.
2022-01-13 07:01:02.812  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receiver link was never active. Closing endpoint states.
2022-01-13 07:01:02.812  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]: Complete. Removing receive link.
2022-01-13 07:01:02.812  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.813  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.813  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.813  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.813  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.813  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.815 ERROR 1 --- [ctor-executor-3] c.azure.identity.EnvironmentCredential   : EnvironmentCredential authentication unavailable. Environment variables are not fully configured.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/net/identity/environmentcredential/troubleshoot
2022-01-13 07:01:02.815  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential EnvironmentCredential is unavailable.
2022-01-13 07:01:02.902  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => Managed Identity environment: AZURE VM IMDS ENDPOINT
2022-01-13 07:01:02.903  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => getToken() result for scopes [https://eventhubs.azure.net/.default]: SUCCESS
2022-01-13 07:01:02.903  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential ManagedIdentityCredential returns a token
2022-01-13 07:01:02.905  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:02.972  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteOpen connectionId[MF_f9cd79_1642057261810], entityPath[eh1/ConsumerGroups/$default/Partitions/1], linkName[1_b127ca_1642057261814], action[waitingForError]
2022-01-13 07:01:02.973  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteClose connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814], errorCondition[null] errorDescription[null]
2022-01-13 07:01:02.973  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:02.973  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Scheduling refresh token task. scopes[https://eventhubs.azure.net/.default]
2022-01-13 07:01:02.974 ERROR 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Error occurred while refreshing token that is not retriable. Not scheduling refresh task. Use ActiveClientTokenManager.authorize() to schedule task again. audience[amqp://ehn-eh-integration-tyaeb.servicebus.windows.net/eh1/ConsumerGroups/$default/Partitions/1] scopes[https://eventhubs.azure.net/.default]
period >= 0 required but it was -1477773778000000000
2022-01-13 07:01:02.974  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : connectionId[MF_f9cd79_1642057261810] sessionId[eh1/ConsumerGroups/$default/Partitions/1] linkName[1_b127ca_1642057261814] Creating a new receiver link.
2022-01-13 07:01:02.975  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.975  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.977  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Returning existing receive link.
2022-01-13 07:01:02.978  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receiver link was never active. Closing endpoint states.
2022-01-13 07:01:02.978  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorSession    : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]: Complete. Removing receive link.
2022-01-13 07:01:02.978  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.978  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.979  INFO 1 --- [ctor-executor-3] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2022-01-13 07:01:02.979  INFO 1 --- [ctor-executor-3] c.a.m.e.EventHubConsumerAsyncClient      : connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814] Creating receive consumer for partition '1'
2022-01-13 07:01:02.979  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : linkName[1_b127ca_1642057261814] entityPath[eh1/ConsumerGroups/$default/Partitions/1] Receive link endpoint states are closed. Requesting another.
2022-01-13 07:01:02.979  INFO 1 --- [oundedElastic-2] c.a.m.e.i.AmqpReceiveLinkProcessor       : Requesting a new AmqpReceiveLink from upstream.
2022-01-13 07:01:02.981 ERROR 1 --- [ctor-executor-3] c.azure.identity.EnvironmentCredential   : EnvironmentCredential authentication unavailable. Environment variables are not fully configured.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/net/identity/environmentcredential/troubleshoot
2022-01-13 07:01:02.981  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential EnvironmentCredential is unavailable.
2022-01-13 07:01:03.020  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => Managed Identity environment: AZURE VM IMDS ENDPOINT
2022-01-13 07:01:03.021  INFO 1 --- [ctor-executor-3] c.a.identity.ManagedIdentityCredential   : Azure Identity => getToken() result for scopes [https://eventhubs.azure.net/.default]: SUCCESS
2022-01-13 07:01:03.021  INFO 1 --- [ctor-executor-3] c.azure.identity.DefaultAzureCredential  : Azure Identity => Attempted credential ManagedIdentityCredential returns a token
2022-01-13 07:01:03.022  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:03.087  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteOpen connectionId[MF_f9cd79_1642057261810], entityPath[eh1/ConsumerGroups/$default/Partitions/1], linkName[1_b127ca_1642057261814], action[waitingForError]
2022-01-13 07:01:03.087  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkRemoteClose connectionId[MF_f9cd79_1642057261810] linkName[1_b127ca_1642057261814], errorCondition[null] errorDescription[null]
2022-01-13 07:01:03.088  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler     : onLinkFinal connectionId[MF_f9cd79_1642057261810], linkName[1_b127ca_1642057261814]
2022-01-13 07:01:03.088  INFO 1 --- [ctor-executor-3] c.a.c.a.i.handler.SessionHandler         : onSessionFinal connectionId[MF_f9cd79_1642057261810], entityName[eh1/ConsumerGroups/$default/Partitions/1], condition[null], description[null]
2022-01-13 07:01:03.101  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Scheduling refresh token task. scopes[https://eventhubs.azure.net/.default]
2022-01-13 07:01:03.102 ERROR 1 --- [ctor-executor-3] c.a.c.a.i.ActiveClientTokenManager       : Error occurred while refreshing token that is not retriable. Not scheduling refresh task. Use ActiveClientTokenManager.authorize() to schedule task again. audience[amqp://ehn-eh-integration-tyaeb.servicebus.windows.net/eh1/ConsumerGroups/$default/Partitions/1] scopes[https://eventhubs.azure.net/.default]
period >= 0 required but it was -1477773779000000000
2022-01-13 07:01:03.103  WARN 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorExecutor   : connectionId[MF_f9cd79_1642057261810] message[Unhandled exception while processing events in reactor, report this error.]
java.lang.IllegalStateException
2022-01-13 07:01:03.104  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection              : onConnectionError connectionId[MF_f9cd79_1642057261810], hostName[ehn-eh-integration-tyaeb.servicebus.windows.net], message[Starting new reactor], error[java.lang.IllegalStateException, TrackingId: 3b59ad23-d164-439e-81cf-77e3b2e08536, at: 2022-01-13T07:01:03.103Z[Etc/UTC], errorContext[NAMESPACE: ehn-eh-integration-tyaeb.servicebus.windows.net. ERROR CONTEXT: N/A]]
2022-01-13 07:01:03.104  INFO 1 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection              : connectionId[MF_f9cd79_1642057261810] signal[onReactorError: com.azure.core.amqp.exception.AmqpException: java.lang.IllegalStateException, TrackingId: 3b59ad23-d164-439e-81cf-77e3b2e08536, at: 2022-01-13T07:01:03.103Z[Etc/UTC], errorContext[NAMESPACE: ehn-eh-integration-tyaeb.servicebus.windows.net. ERROR CONTEXT: N/A], isTransient[false], initiatedByClient[false]]: Disposing of ReactorConnection.
2022-01-13 07:01:03.104  INFO 1 --- [ctor-executor-3] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Channel is closed. Requesting upstream. 
2022-01-13 07:01:03.104  INFO 1 --- [ctor-executor-3] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Connection not requested, yet. Requesting one.
2022-01-13 07:01:03.105  INFO 1 --- [ctor-executor-3] c.a.m.eventhubs.EventHubClientBuilder    : connectionId[MF_56678d_1642057263105]: Emitting a single connection.
2022-01-13 07:01:03.105  INFO 1 --- [ctor-executor-3] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Setting next AMQP channel.
2022-01-13 07:01:03.105  INFO 1 --- [ctor-executor-3] c.a.m.e.i.EventHubConnectionProcessor    : namespace[ehn-eh-integration-tyaeb.servicebus.windows.net] entityPath[eh1]: Next AMQP channel received, updating 0 current subscribers
2022-01-13 07:01:07.130  INFO 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorExecutor   : connectionId[MF_f9cd79_1642057261810] message[Processing all pending tasks and closing old reactor.]
2022-01-13 07:01:07.131  WARN 1 --- [ctor-executor-3] c.a.c.a.implementation.ReactorExecutor   : connectionId[MF_f9cd79_1642057261810] message[scheduleCompletePendingTasks - exception occurred while processing events.
java.lang.IllegalStateException
org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:112)
org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324)
org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:292)
com.azure.core.amqp.implementation.ReactorExecutor.lambda$scheduleCompletePendingTasks$0(ReactorExecutor.java:161)
reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)Cause: null
org.apache.qpid.proton.engine.impl.EndpointImpl.decref(EndpointImpl.java:54)
org.apache.qpid.proton.engine.impl.TransportSession.unsetLocalChannel(TransportSession.java:142)
org.apache.qpid.proton.engine.impl.TransportSession.freeLocalChannel(TransportSession.java:375)
org.apache.qpid.proton.engine.impl.TransportImpl.freeLocalChannel(TransportImpl.java:1025)
org.apache.qpid.proton.engine.impl.TransportImpl.processEnd(TransportImpl.java:1049)
org.apache.qpid.proton.engine.impl.TransportImpl.writeInto(TransportImpl.java:373)
org.apache.qpid.proton.engine.impl.TransportOutputAdaptor.pending(TransportOutputAdaptor.java:59)
org.apache.qpid.proton.engine.impl.SaslImpl$SwitchingSaslTransportWrapper.pending(SaslImpl.java:842)
org.apache.qpid.proton.engine.impl.HandshakeSniffingTransportWrapper.pending(HandshakeSniffingTransportWrapper.java:138)
org.apache.qpid.proton.engine.impl.ssl.SimpleSslTransportWrapper.wrapOutput(SimpleSslTransportWrapper.java:217)
org.apache.qpid.proton.engine.impl.ssl.SimpleSslTransportWrapper.pending(SimpleSslTransportWrapper.java:400)
org.apache.qpid.proton.engine.impl.ssl.SslImpl$UnsecureClientAwareTransportWrapper.pending(SslImpl.java:173)
org.apache.qpid.proton.engine.impl.TransportImpl.pending(TransportImpl.java:1591)
org.apache.qpid.proton.reactor.impl.IOHandler.pending(IOHandler.java:193)
org.apache.qpid.proton.reactor.impl.IOHandler.update(IOHandler.java:214)
org.apache.qpid.proton.reactor.impl.IOHandler.handleTransport(IOHandler.java:347)
org.apache.qpid.proton.reactor.impl.IOHandler.onUnhandled(IOHandler.java:384)
com.azure.core.amqp.implementation.handler.CustomIOHandler.onUnhandled(CustomIOHandler.java:41)
org.apache.qpid.proton.engine.BaseHandler.onTransport(BaseHandler.java:80)
org.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:188)
org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108)
org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324)
org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:292)
com.azure.core.amqp.implementation.ReactorExecutor.lambda$scheduleCompletePendingTasks$0(ReactorExecutor.java:161)
reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)]
@ghost ghost added the needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. label Jan 17, 2022
@backwind1233 backwind1233 added the azure-spring All azure-spring related issues label Jan 17, 2022
@ghost ghost removed the needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. label Jan 17, 2022
@backwind1233 backwind1233 added azure-spring-samples needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. labels Jan 17, 2022
@ghost ghost removed the needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. label Jan 17, 2022
@saragluna saragluna added Client This issue points to a problem in the data-plane of the library. Service This issue points to a problem in the service. labels Jan 17, 2022
@saragluna saragluna moved this to Todo in Spring Cloud Azure Jan 17, 2022
@saragluna saragluna mentioned this issue Jan 18, 2022
Closed
@saragluna
Copy link
Member

This error happens not only in Azure Spring Cloud Service, but also in AKS. @g2vinay could you take a look at this? (cc @conniey).

@saragluna
Copy link
Member

Not sure whether this issue is related #17810.

@g2vinay
Copy link
Member

g2vinay commented Jan 26, 2022 •
edited
Loading

@backwind1233
Can you manually add a more recent version of azure-identity dependency to your application and try again ?
Thanks

<dependency>
  <groupId>com.azure</groupId>
  <artifactId>azure-identity</artifactId>
  <version>1.4.2</version>
</dependency>

@saragluna saragluna moved this from Todo to In Progress in Spring Cloud Azure Jan 26, 2022
@saragluna
Copy link
Member

Hi @g2vinay, this is exactly the same version of azure-identity we are using.

@backwind1233
Copy link
Contributor Author

Thanks, @g2vinay, it works now with azure-identity:1.4.2.

@backwind1233 backwind1233 added the issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. label Jan 26, 2022
@ghost
Copy link

ghost commented Jan 26, 2022

Hi @backwind1233. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text “/unresolve” to remove the “issue-addressed” label and continue the conversation.

@saragluna
Copy link
Member

Verified with the customer when using azure-identity:1.4.2 the issue gets fixed.

Repository owner moved this from In Progress to Done in Spring Cloud Azure Jan 26, 2022
@saragluna
Copy link
Member

47724e4#diff-e17f63375a0aaeaaed50ee6c2d5284b6dd287b5b15ad8c11ae358233a3abbcd7

@github-actions github-actions bot locked and limited conversation to collaborators Apr 11, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@backwind1233 backwind1233

Labels
azure-spring All azure-spring related issues azure-spring-samples Client This issue points to a problem in the data-plane of the library. issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. Service This issue points to a problem in the service.
Projects
Spring Cloud Azure
Archived in project
Milestone
Spring Cloud Azure 4.0 Beta4
Development

No branches or pull requests
3 participants
@backwind1233 @g2vinay @saragluna