[QUERY] Correct configuration for azure service bus using spring-cloud-azure-stream-binder-servicebus
See original GitHub issueQuery/Question
We have a simple spring app that uses spring-cloud-stream to publish/consume events. We want to use manage-identity for authentication and auto-creation of service bus topics/subscriptions. To do the same, we added spring-cloud-azure-stream-binder-servicebus binder and implemented user-assigned managed identity on azure.
Based on sample here, I added following configuration:
spring.cloud.azure.credential.managed-identity-enabled=true
spring.cloud.azure.credential.client-id=${AZURE_CLIENT_ID}
spring.cloud.azure.servicebus.namespace=<namespace>
spring.cloud.azure.servicebus.entity-type=topic
However starting the app, we get the following exception and the app is kind of blocked with no more logs:
2022-05-24 02:18:55.442 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.RequestResponseChannel : {"az.sdk.message":"Settling message.","connectionId":"MF_10393e_1653358733489","linkName":"cbs","messageId":"1"}
2022-05-24 02:18:55.445 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.ActiveClientTokenManager : {"az.sdk.message":"Scheduling refresh token task.","scopes":"https://servicebus.azure.net/.default"}
2022-05-24 02:18:55.463 ERROR [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.ActiveClientTokenManager : {"az.sdk.message":"Error occurred while refreshing token that is not retriable. Not scheduling refresh task. Use ActiveClientTokenManager.authorize() to schedule task again.","exception":"period >= 0 required but it was -1488019624000000000","scopes":"https://servicebus.azure.net/.default","audience":"amqp://sb-befound-asb-297.servicebus.windows.net/createPerson/subscriptions/example-events-service.createPerson"}
java.lang.IllegalArgumentException: period >= 0 required but it was -1488019624000000000
at reactor.core.publisher.FluxInterval.<init>(FluxInterval.java:52)
at reactor.core.publisher.Flux.interval(Flux.java:1318)
at reactor.core.publisher.Flux.interval(Flux.java:1298)
at reactor.core.publisher.Flux.interval(Flux.java:1258)
at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:106)
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
at reactor.core.publisher.EmitterProcessor.subscribe(EmitterProcessor.java:209)
at reactor.core.publisher.Flux.subscribe(Flux.java:8469)
at reactor.core.publisher.Flux.subscribeWith(Flux.java:8642)
at reactor.core.publisher.Flux.subscribe(Flux.java:8439)
at reactor.core.publisher.Flux.subscribe(Flux.java:8363)
at reactor.core.publisher.Flux.subscribe(Flux.java:8333)
at com.azure.core.amqp.implementation.ActiveClientTokenManager.scheduleRefreshTokenTask(ActiveClientTokenManager.java:158)
at com.azure.core.amqp.implementation.ActiveClientTokenManager.lambda$authorize$2(ActiveClientTokenManager.java:93)
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:113)
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:119)
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.complete(MonoIgnoreThen.java:292)
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onNext(MonoIgnoreThen.java:187)
at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:165)
at com.azure.core.amqp.implementation.RequestResponseChannel.settleMessage(RequestResponseChannel.java:398)
at com.azure.core.amqp.implementation.RequestResponseChannel.lambda$new$0(RequestResponseChannel.java:180)
at reactor.core.publisher.LambdaSubscriber.onNext(LambdaSubscriber.java:160)
at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:200)
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:100)
at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
at com.azure.core.amqp.implementation.handler.ReceiveLinkHandler.onDelivery(ReceiveLinkHandler.java:164)
at org.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:185)
at org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108)
at org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324)
at org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:291)
at com.azure.core.amqp.implementation.ReactorExecutor.run(ReactorExecutor.java:91)
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2022-05-24 02:18:55.466 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ReceiveLinkHandler : {"az.sdk.message":"onDelivery.","connectionId":"MF_10393e_1653358733489","errorCondition":null,"errorDescription":null,"entityPath":"$cbs","linkName":"cbs","updatedLinkCredit":0,"remoteCredit":0,"delivery.isPartial":false,"delivery.isSettled":false}
2022-05-24 02:18:55.468 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorSession : {"az.sdk.message":"Creating a new receiver link.","connectionId":"MF_10393e_1653358733489","sessionName":"createPerson/subscriptions/example-events-service.createPerson","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583"}
2022-05-24 02:18:55.471 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorReceiver : {"az.sdk.message":"State UNINITIALIZED","connectionId":"MF_10393e_1653358733489","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 02:18:55.472 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorReceiver : {"az.sdk.message":"Token refreshed.","connectionId":"MF_10393e_1653358733489","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","response":"ACCEPTED"}
2022-05-24 02:18:55.480 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.m.s.ServiceBusReceiverAsyncClient : {"az.sdk.message":"Created consumer for Service Bus resource.","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","entityPath":"createPerson/subscriptions/example-events-service.createPerson","mode":"PEEK_LOCK","isSessionEnabled":true,"entityType":"SUBSCRIPTION"}
2022-05-24 02:18:55.480 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.m.s.i.ServiceBusReceiveLinkProcessor : {"az.sdk.message":"Setting next AMQP receive link.","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 02:18:55.489 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.m.s.i.ServiceBusReceiveLinkProcessor : {"az.sdk.message":"Adding credits.","prefetch":0,"requested":1,"linkCredits":0,"expectedTotalCredit":1,"queuedMessages":0,"creditsToAdd":1,"messageQueueSize":0}
2022-05-24 02:18:55.492 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] .a.m.s.i.ServiceBusReactorAmqpConnection : {"az.sdk.message":"Get or create consumer.","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 02:18:55.492 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorSession : {"az.sdk.message":"Returning existing receive link.","connectionId":"MF_10393e_1653358733489","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 02:18:55.494 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ReceiveLinkHandler : {"az.sdk.message":"onLinkLocalOpen","connectionId":"MF_10393e_1653358733489","entityPath":"createPerson/subscriptions/example-events-service.createPerson","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","localSource":"Source{address='createPerson/subscriptions/example-events-service.createPerson', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
2022-05-24 02:18:55.500 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorReceiver : {"az.sdk.message":"State ACTIVE","connectionId":"MF_10393e_1653358733489","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 02:18:55.501 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ReceiveLinkHandler : {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_10393e_1653358733489","entityPath":"createPerson/subscriptions/example-events-service.createPerson","linkName":"createPerson/subscriptions/example-events-service.createPerson_53212c_1653358733583","remoteSource":"Source{address='createPerson/subscriptions/example-events-service.createPerson', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
Adding subscription id and resourcegroup
spring.cloud.azure.credential.managed-identity-enabled: true
spring.cloud.azure.credential.client-id: ${AZURE_CLIENT_ID}
spring.cloud.azure.servicebus.namespace: <namespace>
spring.cloud.azure.servicebus.entity-type: topic
spring.cloud.azure.profile.subscription-id: <subscription-id>
spring.cloud.azure.servicebus.resource.resource-group: <resource-group>
This manages to get the token, but it tries to refresh the token on each operation and the startup of application is very slow. The topics and subscription do get created but again its tried to fetch token again. Also, for topic to be created we have to hit a request that actually tried to push something to service bus. Follwing are the logs:
2022-05-24 01:49:49.296 DEBUG [example-events-service,,[] 1 --- [ main[] c.azure.identity.EnvironmentCredential : Azure Identity => Found the following environment variables: AZURE_CLIENT_ID, AZURE_TENANT_ID
2022-05-24 01:49:49.298 DEBUG [example-events-service,,[] 1 --- [ main[] c.azure.identity.EnvironmentCredential : Azure Identity => ERROR in EnvironmentCredential: Failed to create a ClientSecretCredential or ClientCertificateCredential. Missing required environment variable either AZURE_CLIENT_SECRET or AZURE_CLIENT_CERTIFICATE_PATH
2022-05-24 01:49:49.299 DEBUG [example-events-service,,[] 1 --- [ main[] c.azure.identity.EnvironmentCredential : Azure Identity => ERROR in EnvironmentCredential: Failed to determine an authentication scheme based on the available environment variables. Please specify AZURE_TENANT_ID and AZURE_CLIENT_SECRET to authenticate through a ClientSecretCredential; AZURE_TENANT_ID and AZURE_CLIENT_CERTIFICATE_PATH to authenticate through a ClientCertificateCredential; or AZURE_USERNAME and AZURE_PASSWORD to authenticate through a UserPasswordCredential.
2022-05-24 01:49:49.323 INFO [example-events-service,,[] 1 --- [ main[] c.a.c.i.jackson.JacksonVersion : Package versions: jackson-annotations=2.13.2, jackson-core=2.13.2, jackson-databind=2.13.2.2, jackson-dataformat-xml=2.13.2, jackson-datatype-jsr310=2.13.2, azure-core=1.26.0, Troubleshooting version conflicts: https://aka.ms/azsdk/java/dependency/troubleshoot
2022-05-24 01:49:49.424 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => Found the following environment variables: AZURE_CLIENT_ID, AZURE_TENANT_ID
2022-05-24 01:49:49.426 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.identity.SharedTokenCacheCredential : Azure Identity => Found the following environment variables: AZURE_CLIENT_ID, AZURE_TENANT_ID
2022-05-24 01:49:49.500 DEBUG [example-events-service,,[] 1 --- [ main[] s.c.c.i.c.AzureHttpProxyOptionsConverter : Proxy hostname or port is not set.
2022-05-24 01:49:49.501 DEBUG [example-events-service,,[] 1 --- [ main[] .f.AbstractAzureHttpClientBuilderFactory : No HTTP proxy properties available.
2022-05-24 01:49:49.502 DEBUG [example-events-service,,[] 1 --- [ main[] AbstractAzureServiceClientBuilderFactory : No authentication credential configured for class ManagedIdentityCredentialBuilder.
2022-05-24 01:49:49.502 INFO [example-events-service,,[] 1 --- [ main[] AbstractAzureServiceClientBuilderFactory : Will configure the default credential of type DefaultAzureCredential for class com.azure.identity.ManagedIdentityCredentialBuilder.
2022-05-24 01:49:49.510 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.c.i.http.HttpClientProviders : Using com.azure.core.http.netty.NettyAsyncHttpClientProvider as the default HttpClientProvider.
2022-05-24 01:49:49.653 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => Found the following environment variables: AZURE_CLIENT_ID, AZURE_TENANT_ID
2022-05-24 01:49:52.780 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:49:54.249 INFO [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:49:54.250 INFO [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:49:54.250 INFO [example-events-service,,[] 1 --- [ main[] c.a.c.implementation.AccessTokenCache : Acquired a new access token.
2022-05-24 01:49:55.119 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 2 seconds
2022-05-24 01:50:24.476 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:50:24.478 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:50:24.478 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353396 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:49:52.780 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:49:54.249 INFO [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:49:54.250 INFO [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:49:54.250 INFO [example-events-service,,[] 1 --- [ main[] c.a.c.implementation.AccessTokenCache : Acquired a new access token.
2022-05-24 01:49:55.119 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 2 seconds
2022-05-24 01:50:24.476 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:50:24.478 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:50:24.478 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353396 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:50:54.603 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:50:54.603 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:50:54.603 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353426 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:50:55.405 INFO [example-events-service,,[] 1 --- [ main[] zureServiceBusMessagingAutoConfiguration : Service Bus connection string is set from com.azure.spring.cloud.resourcemanager.implementation.connectionstring.ServiceBusArmConnectionStringProvider now.
2022-05-24 01:50:58.383 WARN [example-events-service,,[] 1 --- [ main[] .s.s.UserDetailsServiceAutoConfiguration :
+[
+[ Using generated security password: 4164cff7-b4be-44c1-a3a9-884ecb4e45ff
+[
+[ This generated password is for development use only. Your security configuration must be updated before running your application in production.
+[
2022-05-24 01:50:59.285 DEBUG [example-events-service,,[] 1 --- [ main[] s.c.c.i.c.AzureAmqpRetryOptionsConverter : The max-retries is not set, skip the convert.
2022-05-24 01:50:59.286 DEBUG [example-events-service,,[] 1 --- [ main[] .f.AbstractAzureAmqpClientBuilderFactory : No AMQP retry properties available.
2022-05-24 01:50:59.287 DEBUG [example-events-service,,[] 1 --- [ main[] s.c.c.i.c.AzureAmqpProxyOptionsConverter : Proxy hostname or port is not set.
2022-05-24 01:50:59.287 DEBUG [example-events-service,,[] 1 --- [ main[] .f.AbstractAzureAmqpClientBuilderFactory : No AMQP proxy properties available.
2022-05-24 01:50:59.292 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.identity.ManagedIdentityCredential : Azure Identity => Found the following environment variables: AZURE_CLIENT_ID, AZURE_TENANT_ID
2022-05-24 01:50:59.294 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:51:25.615 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:51:25.616 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:51:25.616 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353460 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:51:25.900 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 26 seconds
2022-05-24 01:51:55.749 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:51:55.750 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:51:55.750 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353486 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:52:25.958 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:52:25.959 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:52:25.959 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353517 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:52:27.067 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:52:56.139 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:52:56.139 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:52:56.139 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353548 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:52:57.280 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 30 seconds
2022-05-24 01:53:26.295 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:53:26.295 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:53:26.296 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353578 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:53:56.472 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:53:56.472 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:53:56.472 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353607 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:53:57.978 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.ServiceBusClientBuilder : {"az.sdk.message":"Setting entity from connection string.","entityPath":null}
2022-05-24 01:53:57.978 DEBUG [example-events-service,,[] 1 --- [ main[] AbstractAzureServiceClientBuilderFactory : Connection string configured for class ServiceBusClientBuilder.
2022-05-24 01:53:59.211 WARN [example-events-service,,[] 1 --- [ main[] iguration$LoadBalancerCaffeineWarnLogger : Spring Cloud LoadBalancer is currently working with the default cache. You can switch to using Caffeine cache, by adding it and org.springframework.cache.caffeine.CaffeineCacheManager to the classpath.
2022-05-24 01:53:59.637 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusSubscription with name 'example-events-service.createPerson' ...
2022-05-24 01:53:59.638 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching Topic with name 'createPerson' ...
2022-05-24 01:53:59.638 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:54:26.587 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:54:26.587 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:54:26.588 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353640 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:54:26.730 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 27 seconds
2022-05-24 01:54:56.735 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:54:56.736 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:54:56.736 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353667 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:54:57.489 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching Topic with name 'createPerson' finished in 57 seconds
2022-05-24 01:55:26.873 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:55:26.874 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:55:26.874 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353698 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:55:28.704 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusSubscription with name 'example-events-service.createPerson' finished in 89 seconds
2022-05-24 01:55:28.705 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Creating ServiceBusSubscription with name 'example-events-service.createPerson' ...
2022-05-24 01:55:28.705 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching Topic with name 'createPerson' ...
2022-05-24 01:55:28.705 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' ...
2022-05-24 01:55:56.980 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:55:56.980 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:55:56.980 INFO [example-events-service,,[] 1 --- [ parallel-2[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353729 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:55:57.132 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching ServiceBusNamespace with name 'sb-befound-asb-297' finished in 28 seconds
2022-05-24 01:56:27.104 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:56:27.104 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:56:27.104 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353758 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:56:27.875 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Fetching Topic with name 'createPerson' finished in 59 seconds
2022-05-24 01:56:57.224 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => Managed Identity environment: AZURE AKS TOKEN EXCHANGE
2022-05-24 01:56:57.225 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.identity.ManagedIdentityCredential : Azure Identity => getToken() result for scopes [https://management.core.windows.net//.default]: SUCCESS
2022-05-24 01:56:57.225 INFO [example-events-service,,[] 1 --- [ parallel-1[] c.a.c.implementation.AccessTokenCache : Acquired a new access token at 1653353788 seconds after expiry. Retry may be attempted after 30 seconds.
2022-05-24 01:56:58.105 INFO [example-events-service,,[] 1 --- [ main[] c.a.s.c.r.i.crud.AbstractResourceCrud : Creating ServiceBusSubscription with name 'example-events-service.createPerson' finished in 89 seconds
2022-05-24 01:56:58.142 DEBUG [example-events-service,,[] 1 --- [ main[] a.s.m.l.AbstractMessageListenerContainer : Starting container with name null
2022-05-24 01:56:58.159 DEBUG [example-events-service,,[] 1 --- [ main[] s.c.c.i.c.AzureAmqpRetryOptionsConverter : The max-retries is not set, skip the convert.
2022-05-24 01:56:58.159 DEBUG [example-events-service,,[] 1 --- [ main[] .f.AbstractAzureAmqpClientBuilderFactory : No AMQP retry properties available.
2022-05-24 01:56:58.159 DEBUG [example-events-service,,[] 1 --- [ main[] s.c.c.i.c.AzureAmqpProxyOptionsConverter : Proxy hostname or port is not set.
2022-05-24 01:56:58.159 DEBUG [example-events-service,,[] 1 --- [ main[] .f.AbstractAzureAmqpClientBuilderFactory : No AMQP proxy properties available.
2022-05-24 01:56:58.160 DEBUG [example-events-service,,[] 1 --- [ main[] AbstractAzureServiceClientBuilderFactory : No authentication credential configured for class ServiceBusProcessorClientBuilder.
2022-05-24 01:56:58.161 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.ServiceBusClientBuilder : {"az.sdk.message":"Setting entity from connection string.","entityPath":null}
2022-05-24 01:56:58.161 DEBUG [example-events-service,,[] 1 --- [ main[] AbstractAzureServiceClientBuilderFactory : Connection string configured for class ServiceBusProcessorClientBuilder.
2022-05-24 01:56:58.210 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.c.a.i.ReactorConnection : {"az.sdk.message":"State UNINITIALIZED","connectionId":"MF_883a51_1653357418178"}
2022-05-24 01:56:58.211 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.i.ServiceBusConnectionProcessor : {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}
2022-05-24 01:56:58.211 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.i.ServiceBusConnectionProcessor : {"az.sdk.message":"Next AMQP channel received, updating 0 current subscribers","entityPath":"N/A"}
2022-05-24 01:56:58.213 DEBUG [example-events-service,,[] 1 --- [ main[] c.a.c.a.i.ReactorConnection : {"az.sdk.message":"State UNINITIALIZED","connectionId":"MF_34f0cd_1653357418213"}
2022-05-24 01:56:58.213 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.ServiceBusClientBuilder : # of open clients with shared connection: 1
2022-05-24 01:56:58.225 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.ServiceBusReceiverAsyncClient : {"az.sdk.message":"Creating consumer.","linkName":"createPerson/subscriptions/example-events-service.createPerson_860b64_1653357418225","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 01:56:58.232 INFO [example-events-service,,[] 1 --- [ main[] c.a.m.s.i.ServiceBusReceiveLinkProcessor : Requesting a new AmqpReceiveLink from upstream.
2022-05-24 01:56:58.236 INFO [example-events-service,,[] 1 --- [ main[] c.a.c.a.i.ReactorConnection : {"az.sdk.message":"Creating and starting connection.","connectionId":"MF_883a51_1653357418178","hostName":"sb-befound-asb-297.servicebus.windows.net","port":5671}
2022-05-24 01:56:58.261 INFO [example-events-service,,[] 1 --- [ main[] c.a.c.a.implementation.ReactorExecutor : {"az.sdk.message":"Starting reactor.","connectionId":"MF_883a51_1653357418178"}
2022-05-24 01:56:58.268 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ConnectionHandler : {"az.sdk.message":"onConnectionInit","connectionId":"MF_883a51_1653357418178","hostName":"sb-befound-asb-297.servicebus.windows.net","namespace":"sb-befound-asb-297.servicebus.windows.net"}
2022-05-24 01:56:58.269 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ReactorHandler : {"az.sdk.message":"reactor.onReactorInit","connectionId":"MF_883a51_1653357418178"}
2022-05-24 01:56:58.269 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ConnectionHandler : {"az.sdk.message":"onConnectionLocalOpen","connectionId":"MF_883a51_1653357418178","errorCondition":null,"errorDescription":null,"hostName":"sb-befound-asb-297.servicebus.windows.net"}
2022-05-24 01:56:58.303 INFO [example-events-service,,[] 1 --- [ main[] .s.i.s.i.ServiceBusInboundChannelAdapter : started com.azure.spring.integration.servicebus.inbound.ServiceBusInboundChannelAdapter@7c9a5397
2022-05-24 01:56:58.705 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ConnectionHandler : {"az.sdk.message":"onConnectionBound","connectionId":"MF_883a51_1653357418178","hostName":"sb-befound-asb-297.servicebus.windows.net","peerDetails":"sb-befound-asb-297.servicebus.windows.net:5671"}
2022-05-24 01:56:59.018 INFO [example-events-service,,[] 1 --- [ main[] com.backbase.example.Application : Started Application in 436.628 seconds (JVM running for 437.627)
2022-05-24 01:56:59.203 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.StrictTlsContextSpi : SSLv2Hello was an enabled protocol. Filtering out.
2022-05-24 01:56:59.277 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.ConnectionHandler : {"az.sdk.message":"onConnectionRemoteOpen","connectionId":"MF_883a51_1653357418178","hostName":"sb-befound-asb-297.servicebus.windows.net","remoteContainer":"0550df7b353e4267af45866809a52cf1_G9"}
2022-05-24 01:56:59.279 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.ReactorConnection : {"az.sdk.message":"State ACTIVE","connectionId":"MF_883a51_1653357418178"}
2022-05-24 01:56:59.281 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.m.s.i.ServiceBusConnectionProcessor : {"az.sdk.message":"Channel is now active.","entityPath":"N/A"}
2022-05-24 01:56:59.299 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorSession : {"az.sdk.message":"Got endpoint state.","connectionId":"MF_883a51_1653357418178","sessionName":"createPerson/subscriptions/example-events-service.createPerson","state":"UNINITIALIZED"}
2022-05-24 01:56:59.303 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.SessionHandler : {"az.sdk.message":"onSessionLocalOpen","connectionId":"MF_883a51_1653357418178","errorCondition":null,"errorDescription":null,"sessionName":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 01:56:59.311 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.handler.SessionHandler : {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_883a51_1653357418178","sessionName":"createPerson/subscriptions/example-events-service.createPerson","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2022-05-24 01:56:59.311 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorSession : {"az.sdk.message":"Got endpoint state.","connectionId":"MF_883a51_1653357418178","sessionName":"createPerson/subscriptions/example-events-service.createPerson","state":"ACTIVE"}
2022-05-24 01:56:59.312 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] .a.m.s.i.ServiceBusReactorAmqpConnection : {"az.sdk.message":"Get or create consumer.","entityPath":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 01:56:59.314 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.AzureTokenManagerProvider : {"az.sdk.message":"Creating new token manager.","audience":"amqp://sb-befound-asb-297.servicebus.windows.net/createPerson/subscriptions/example-events-service.createPerson","resource":"createPerson/subscriptions/example-events-service.createPerson"}
2022-05-24 01:56:59.365 INFO [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.i.ReactorConnection : {"az.sdk.message":"Setting CBS channel.","connectionId":"MF_883a51_1653357418178"}
2022-05-24 01:56:59.370 DEBUG [example-events-service,,[] 1 --- [ctor-executor-1[] c.a.c.a.implementation.ReactorSession : {"az.sdk.message":"Got endpoint state.","connectionId":"MF_883a51_1653357418178","sessionName":"cbs-session","state":"UNINITIALIZED"}
2022-05-24 01:56:59.372 DEBUG [example-eve
The token expiry is set to 1 day in the cluster.
#Library/Libraries:
- Spring boot - :2.6.6
- Spring Cloud - 2021.0.0
- spring-cloud-azure-stream-binder-servicebus - 4.0.0
Can someone help with the correct configuration for spring apps with managed identity and suggestion on how to auto-create topics at application startup without having to run a test request?
Issue Analytics
- State:
- Created a year ago
- Comments:16 (8 by maintainers)
Top Results From Across the Web
How to use Spring Cloud Azure Stream Binder for Azure ...
In this article. Prerequisites; Use the Spring Cloud Stream Binder starter; Configure the app for your service bus; Implement basic Service Bus ......
Read more >Spring Cloud Azure - Reference Documentation
Authenticate with Azure Active Directory. For applications want to connect to resources that support Azure Active Directory (Azure AD) authentication, below ...
Read more >AZURE SERVICE BUS TOPICS & SUBSCRIPTIONS - YouTube
Hey Azure Service Bus is a fully managed enterprise message broker with message queues and publish-subscribe topics. Service Bus is used ...
Read more >Refreshing configuration at Runtime with Spring Cloud Bus ...
Unsurprisingly, Azure provides an excellent integration of Service Bus with Spring Cloud Stream by spring-cloud-azure-stream-binder-servicebus dependency that ...
Read more >Determining how many messages are on the Azure Service ...
var nsmgr = Microsoft.ServiceBus.NamespaceManager.CreateFromConnectionString(connectionString); long count = nsmgr.GetQueue(queueName).MessageCount;.
Read more >
Top Related Medium Post
No results found
Top Related StackOverflow Question
No results found
Troubleshoot Live Code
Lightrun enables developers to add logs, metrics and snapshots to live code - no restarts or redeploys required.
Start Free
Top Related Reddit Thread
No results found
Top Related Hackernoon Post
No results found
Top Related Tweet
No results found
Top Related Dev.to Post
No results found
Top Related Hashnode Post
No results found
Quick update. Workload identity currently only supports federated credentials with SPNs which doesn’t seem to work with the binder,
Judging by: https://azure.github.io/azure-workload-identity/docs/#limitations MSI support is coming soon so hopefully no changes will be required your side 👍
Please ignore my comments and leave this issue in closed state (https://github.com/Azure/azure-workload-identity/issues/325)
@hui1110 Thanks for your response! I believe this issue may need to remain open (or be resolved with something other than duplicate) as it’s a separate discussion. https://github.com/Azure/azure-sdk-for-java/issues/30324 is related to auto-creation of topics an issue our developers were seeing. They will update further there 👍
This issue is related to authentication with Azure Workload Identity (see: https://github.com/Azure/azure-sdk-for-java/issues/29032#issuecomment-1147337663) not working with the spring-cloud-azure-stream-binder-servicebus binder, We see long delays in provisioning topics (up to 4 mins) when using this method of authentication,
If the answer is that currently Workload identity is not supported that’s no problem, this may instead be a feature request