azure-sdk-for-java
azure-sdk-for-java copied to clipboard
Published
20 hours ago •
Azure
Azure
[BUG] KeyVaultPropertySource/KeyVaultOperation blocks forever
Describe the bug We use the Spring-Boot-Gradle-Plugin to build our apps. We configured a KeyVaultPropertySource using the new Azure Spring Cloud 4.0.0 bom for dependency management. On our build server (hosted Azure DevOps Build Agent) the application hangs forever on startup using the bootRun task. It also hangs on startup using a Spring Boot JUnit test which tries to load the Spring Context. The same gradle tasks work fine on local development using the same Java and Gradle Version. After building the Apps without executing the tests, they also run deployed in an AKS. It has to be some kind of race condition, which should not happen. Please see the thread dump below.
Exception or Stack Trace Full thread dump of the blocked app. This stays forever.
2022-05-11T16:01:00.2881819Z
2022-05-11T16:01:00.2882207Z Threads class SMR info:
2022-05-11T16:01:00.2882780Z _java_thread_list=0x00007fea74202c80, length=18, elements={
2022-05-11T16:01:00.2883507Z 0x00007feab402a9a0, 0x00007feab40f7760, 0x00007feab40f8b40, 0x00007feab4100790,
2022-05-11T16:01:00.2884272Z 0x00007feab4101b40, 0x00007feab4102f50, 0x00007feab4104480, 0x00007feab4105900,
2022-05-11T16:01:00.2885024Z 0x00007feab410e830, 0x00007feab4111940, 0x00007feab4844380, 0x00007feab4f9f250,
2022-05-11T16:01:00.2885809Z 0x00007feab4f9fcb0, 0x00007feab4fa0de0, 0x00007feab4fa1bd0, 0x00007fea8c060c40,
2022-05-11T16:01:00.2886514Z 0x00007fea980026e0, 0x00007fea742021d0
2022-05-11T16:01:00.2887003Z }
2022-05-11T16:01:00.2887210Z
2022-05-11T16:01:00.2887831Z "main" #1 prio=5 os_prio=0 cpu=1597.67ms elapsed=120.46s tid=0x00007feab402a9a0 nid=0x829 waiting on condition [0x00007feab9125000]
2022-05-11T16:01:00.2888634Z java.lang.Thread.State: WAITING (parking)
2022-05-11T16:01:00.2889273Z at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
2022-05-11T16:01:00.2890274Z - parking to wait for <0x0000000094300000> (a java.util.concurrent.CountDownLatch$Sync)
2022-05-11T16:01:00.2891081Z at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
2022-05-11T16:01:00.2891964Z at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:715)
2022-05-11T16:01:00.2892968Z at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:1047)
2022-05-11T16:01:00.2894264Z at java.util.concurrent.CountDownLatch.await([email protected]/CountDownLatch.java:230)
2022-05-11T16:01:00.2895161Z at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87)
2022-05-11T16:01:00.2895978Z at reactor.core.publisher.Flux.blockLast(Flux.java:2645)
2022-05-11T16:01:00.2896839Z at com.azure.core.util.paging.ContinuablePagedByIteratorBase.requestPage(ContinuablePagedByIteratorBase.java:94)
2022-05-11T16:01:00.2898132Z - locked <0x00000000943001c0> (a com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator)
2022-05-11T16:01:00.2899236Z at com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator.<init>(ContinuablePagedByPageIterable.java:57)
2022-05-11T16:01:00.2900320Z at com.azure.core.util.paging.ContinuablePagedByPageIterable.iterator(ContinuablePagedByPageIterable.java:41)
2022-05-11T16:01:00.2901347Z at java.lang.Iterable.spliterator([email protected]/Iterable.java:101)
2022-05-11T16:01:00.2902307Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.lambda$refreshProperties$2(KeyVaultOperation.java:140)
2022-05-11T16:01:00.2903372Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation$$Lambda$313/0x0000000800e6ef50.apply(Unknown Source)
2022-05-11T16:01:00.2904209Z at java.util.Optional.map([email protected]/Optional.java:260)
2022-05-11T16:01:00.2905159Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.refreshProperties(KeyVaultOperation.java:140)
2022-05-11T16:01:00.2906198Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.<init>(KeyVaultOperation.java:77)
2022-05-11T16:01:00.2944312Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySource(KeyVaultEnvironmentPostProcessor.java:127)
2022-05-11T16:01:00.2945627Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySourceList(KeyVaultEnvironmentPostProcessor.java:115)
2022-05-11T16:01:00.2946851Z at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.postProcessEnvironment(KeyVaultEnvironmentPostProcessor.java:86)
2022-05-11T16:01:00.2948025Z at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:102)
2022-05-11T16:01:00.2949167Z at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:87)
2022-05-11T16:01:00.2950220Z at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
2022-05-11T16:01:00.2951228Z at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
2022-05-11T16:01:00.2952262Z at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
2022-05-11T16:01:00.2957251Z at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
2022-05-11T16:01:00.2958433Z at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
2022-05-11T16:01:00.2959409Z at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
2022-05-11T16:01:00.2960289Z at org.springframework.boot.SpringApplicationRunListeners$$Lambda$77/0x0000000800cb4838.accept(Unknown Source)
2022-05-11T16:01:00.2960992Z at java.util.ArrayList.forEach([email protected]/ArrayList.java:1511)
2022-05-11T16:01:00.2961761Z at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
2022-05-11T16:01:00.2962693Z at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
2022-05-11T16:01:00.2963846Z at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
2022-05-11T16:01:00.2964706Z at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:339)
2022-05-11T16:01:00.2965468Z at org.springframework.boot.SpringApplication.run(SpringApplication.java:297)
2022-05-11T16:01:00.2966145Z at com.bosch.bt.services.map.MapApp.main(MapApp.java:43)
2022-05-11T16:01:00.2966420Z
2022-05-11T16:01:00.2967044Z "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.88ms elapsed=120.44s tid=0x00007feab40f7760 nid=0x832 waiting on condition [0x00007feaa5968000]
2022-05-11T16:01:00.2967735Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2968296Z at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
2022-05-11T16:01:00.2969123Z at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:253)
2022-05-11T16:01:00.2969829Z at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:215)
2022-05-11T16:01:00.2970165Z
2022-05-11T16:01:00.2970752Z "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.24ms elapsed=120.44s tid=0x00007feab40f8b40 nid=0x833 in Object.wait() [0x00007feaa4ffe000]
2022-05-11T16:01:00.2971517Z java.lang.Thread.State: WAITING (on object monitor)
2022-05-11T16:01:00.2972615Z at java.lang.Object.wait([email protected]/Native Method)
2022-05-11T16:01:00.2973791Z - waiting on <0x0000000093a10610> (a java.lang.ref.ReferenceQueue$Lock)
2022-05-11T16:01:00.2974452Z at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
2022-05-11T16:01:00.2975305Z - locked <0x0000000093a10610> (a java.lang.ref.ReferenceQueue$Lock)
2022-05-11T16:01:00.2975950Z at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
2022-05-11T16:01:00.2976640Z at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:172)
2022-05-11T16:01:00.2976983Z
2022-05-11T16:01:00.2977591Z "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.11ms elapsed=120.43s tid=0x00007feab4100790 nid=0x834 waiting on condition [0x0000000000000000]
2022-05-11T16:01:00.2978273Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2978465Z
2022-05-11T16:01:00.2979054Z "Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.26ms elapsed=120.43s tid=0x00007feab4101b40 nid=0x835 runnable [0x0000000000000000]
2022-05-11T16:01:00.2979713Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2979924Z
2022-05-11T16:01:00.2980525Z "Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=2.98ms elapsed=120.43s tid=0x00007feab4102f50 nid=0x836 runnable [0x0000000000000000]
2022-05-11T16:01:00.2981204Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2981394Z
2022-05-11T16:01:00.2982018Z "C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=692.32ms elapsed=120.43s tid=0x00007feab4104480 nid=0x837 waiting on condition [0x0000000000000000]
2022-05-11T16:01:00.2982712Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2983110Z No compile task
2022-05-11T16:01:00.2983278Z
2022-05-11T16:01:00.2983851Z "Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=0.09ms elapsed=120.43s tid=0x00007feab4105900 nid=0x838 runnable [0x0000000000000000]
2022-05-11T16:01:00.2984501Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2984692Z
2022-05-11T16:01:00.2985281Z "Notification Thread" #10 daemon prio=9 os_prio=0 cpu=0.11ms elapsed=120.42s tid=0x00007feab410e830 nid=0x839 runnable [0x0000000000000000]
2022-05-11T16:01:00.2985937Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.2986147Z
2022-05-11T16:01:00.2987061Z "Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=1.18ms elapsed=120.41s tid=0x00007feab4111940 nid=0x83b in Object.wait() [0x00007feaa439c000]
2022-05-11T16:01:00.2987801Z java.lang.Thread.State: TIMED_WAITING (on object monitor)
2022-05-11T16:01:00.2988350Z at java.lang.Object.wait([email protected]/Native Method)
2022-05-11T16:01:00.2989282Z - waiting on <0x0000000093a10830> (a java.lang.ref.ReferenceQueue$Lock)
2022-05-11T16:01:00.2989932Z at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
2022-05-11T16:01:00.2990764Z - locked <0x0000000093a10830> (a java.lang.ref.ReferenceQueue$Lock)
2022-05-11T16:01:00.2991390Z at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:140)
2022-05-11T16:01:00.2991993Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3000123Z at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:162)
2022-05-11T16:01:00.3000522Z
2022-05-11T16:01:00.3001654Z "pool-1-thread-1" #12 prio=5 os_prio=0 cpu=14.17ms elapsed=120.24s tid=0x00007feab4844380 nid=0x83d waiting on condition [0x00007feaa4199000]
2022-05-11T16:01:00.3002365Z java.lang.Thread.State: WAITING (parking)
2022-05-11T16:01:00.3013576Z at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
2022-05-11T16:01:00.3015254Z - parking to wait for <0x0000000094349ac0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2022-05-11T16:01:00.3016162Z at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:341)
2022-05-11T16:01:00.3017112Z at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block([email protected]/AbstractQueuedSynchronizer.java:506)
2022-05-11T16:01:00.3018039Z at java.util.concurrent.ForkJoinPool.unmanagedBlock([email protected]/ForkJoinPool.java:3463)
2022-05-11T16:01:00.3018861Z at java.util.concurrent.ForkJoinPool.managedBlock([email protected]/ForkJoinPool.java:3434)
2022-05-11T16:01:00.3019789Z at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await([email protected]/AbstractQueuedSynchronizer.java:1623)
2022-05-11T16:01:00.3020810Z at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:1170)
2022-05-11T16:01:00.3021829Z at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:899)
2022-05-11T16:01:00.3022767Z at java.util.concurrent.ThreadPoolExecutor.getTask([email protected]/ThreadPoolExecutor.java:1062)
2022-05-11T16:01:00.3023660Z at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1122)
2022-05-11T16:01:00.3024769Z at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635)
2022-05-11T16:01:00.3025917Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3026644Z
2022-05-11T16:01:00.3035093Z "reactor-http-epoll-1" #14 daemon prio=5 os_prio=0 cpu=290.21ms elapsed=118.84s tid=0x00007feab4f9f250 nid=0x83f runnable [0x00007fea94dec000]
2022-05-11T16:01:00.3036848Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3038121Z at io.netty.channel.epoll.Native.epollWait(Native Method)
2022-05-11T16:01:00.3070156Z at io.netty.channel.epoll.Native.epollWait(Native.java:209)
2022-05-11T16:01:00.3070983Z at io.netty.channel.epoll.Native.epollWait(Native.java:202)
2022-05-11T16:01:00.3071829Z at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:294)
2022-05-11T16:01:00.3072747Z at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:351)
2022-05-11T16:01:00.3073607Z at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
2022-05-11T16:01:00.3074533Z at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2022-05-11T16:01:00.3076617Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2022-05-11T16:01:00.3077415Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3078025Z
2022-05-11T16:01:00.3079224Z "reactor-http-epoll-2" #15 daemon prio=5 os_prio=0 cpu=0.24ms elapsed=118.84s tid=0x00007feab4f9fcb0 nid=0x840 runnable [0x00007fea94ceb000]
2022-05-11T16:01:00.3080037Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3080924Z at io.netty.channel.epoll.Native.epollWait(Native Method)
2022-05-11T16:01:00.3081609Z at io.netty.channel.epoll.Native.epollWait(Native.java:209)
2022-05-11T16:01:00.3082972Z at io.netty.channel.epoll.Native.epollWait(Native.java:202)
2022-05-11T16:01:00.3083881Z at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:294)
2022-05-11T16:01:00.3084726Z at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:351)
2022-05-11T16:01:00.3085610Z at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
2022-05-11T16:01:00.3086479Z at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2022-05-11T16:01:00.3087326Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2022-05-11T16:01:00.3088111Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3088641Z
2022-05-11T16:01:00.3089730Z "reactor-http-epoll-3" #16 daemon prio=5 os_prio=0 cpu=0.21ms elapsed=118.84s tid=0x00007feab4fa0de0 nid=0x841 runnable [0x00007fea94bea000]
2022-05-11T16:01:00.3090560Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3091161Z at io.netty.channel.epoll.Native.epollWait(Native Method)
2022-05-11T16:01:00.3091845Z at io.netty.channel.epoll.Native.epollWait(Native.java:209)
2022-05-11T16:01:00.3092567Z at io.netty.channel.epoll.Native.epollWait(Native.java:202)
2022-05-11T16:01:00.3093370Z at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:294)
2022-05-11T16:01:00.3094197Z at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:351)
2022-05-11T16:01:00.3095050Z at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
2022-05-11T16:01:00.3095910Z at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2022-05-11T16:01:00.3097063Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2022-05-11T16:01:00.3097880Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3934181Z
2022-05-11T16:01:00.3937281Z "reactor-http-epoll-4" #17 daemon prio=5 os_prio=0 cpu=0.88ms elapsed=118.84s tid=0x00007feab4fa1bd0 nid=0x842 runnable [0x00007fea94ae9000]
2022-05-11T16:01:00.3938157Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3938765Z at io.netty.channel.epoll.Native.epollWait(Native Method)
2022-05-11T16:01:00.3941841Z at io.netty.channel.epoll.Native.epollWait(Native.java:209)
2022-05-11T16:01:00.3943118Z at io.netty.channel.epoll.Native.epollWait(Native.java:202)
2022-05-11T16:01:00.3943982Z at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:294)
2022-05-11T16:01:00.3944863Z at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:351)
2022-05-11T16:01:00.3945761Z at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
2022-05-11T16:01:00.3946682Z at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2022-05-11T16:01:00.3947550Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2022-05-11T16:01:00.3948333Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3948684Z
2022-05-11T16:01:00.3949312Z "process reaper" #20 daemon prio=10 os_prio=0 cpu=1.19ms elapsed=118.27s tid=0x00007fea8c060c40 nid=0x846 runnable [0x00007feaa4065000]
2022-05-11T16:01:00.3950120Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3950786Z at java.lang.ProcessHandleImpl.waitForProcessExit0([email protected]/Native Method)
2022-05-11T16:01:00.3951566Z at java.lang.ProcessHandleImpl$1.run([email protected]/ProcessHandleImpl.java:147)
2022-05-11T16:01:00.3952399Z at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1136)
2022-05-11T16:01:00.3953269Z at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635)
2022-05-11T16:01:00.3954044Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3954814Z
2022-05-11T16:01:00.3956025Z "Thread-7" #23 daemon prio=5 os_prio=0 cpu=1.83ms elapsed=111.56s tid=0x00007fea980026e0 nid=0x86d runnable [0x00007fea662d5000]
2022-05-11T16:01:00.3956682Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3957207Z at java.io.FileInputStream.readBytes([email protected]/Native Method)
2022-05-11T16:01:00.3958052Z at java.io.FileInputStream.read([email protected]/FileInputStream.java:276)
2022-05-11T16:01:00.3959076Z at java.io.BufferedInputStream.read1([email protected]/BufferedInputStream.java:282)
2022-05-11T16:01:00.3959885Z at java.io.BufferedInputStream.read([email protected]/BufferedInputStream.java:343)
2022-05-11T16:01:00.3960927Z - locked <0x0000000099a02810> (a java.lang.ProcessImpl$ProcessPipeInputStream)
2022-05-11T16:01:00.3961710Z at sun.nio.cs.StreamDecoder.readBytes([email protected]/StreamDecoder.java:270)
2022-05-11T16:01:00.3962697Z at sun.nio.cs.StreamDecoder.implRead([email protected]/StreamDecoder.java:313)
2022-05-11T16:01:00.3963467Z at sun.nio.cs.StreamDecoder.read([email protected]/StreamDecoder.java:188)
2022-05-11T16:01:00.3964401Z - locked <0x0000000099a0ae70> (a java.io.InputStreamReader)
2022-05-11T16:01:00.3965157Z at java.io.InputStreamReader.read([email protected]/InputStreamReader.java:177)
2022-05-11T16:01:00.3968061Z at java.io.BufferedReader.fill([email protected]/BufferedReader.java:162)
2022-05-11T16:01:00.3968860Z at java.io.BufferedReader.readLine([email protected]/BufferedReader.java:329)
2022-05-11T16:01:00.3969920Z - locked <0x0000000099a0ae70> (a java.io.InputStreamReader)
2022-05-11T16:01:00.3970661Z at java.io.BufferedReader.readLine([email protected]/BufferedReader.java:396)
2022-05-11T16:01:00.3971555Z at com.azure.identity.implementation.PowershellManager.lambda$readData$4(PowershellManager.java:103)
2022-05-11T16:01:00.3972480Z at com.azure.identity.implementation.PowershellManager$$Lambda$528/0x0000000801030490.get(Unknown Source)
2022-05-11T16:01:00.3973326Z at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:44)
2022-05-11T16:01:00.3974186Z at reactor.core.publisher.FluxRepeatWhen$RepeatWhenMainSubscriber.resubscribe(FluxRepeatWhen.java:184)
2022-05-11T16:01:00.3975135Z at reactor.core.publisher.FluxRepeatWhen$RepeatWhenOtherSubscriber.onNext(FluxRepeatWhen.java:239)
2022-05-11T16:01:00.3976051Z at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:282)
2022-05-11T16:01:00.3977003Z at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:863)
2022-05-11T16:01:00.3977923Z at reactor.core.publisher.FluxConcatMap$WeakScalarSubscription.request(FluxConcatMap.java:479)
2022-05-11T16:01:00.3978826Z at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.request(Operators.java:2158)
2022-05-11T16:01:00.3979724Z at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.request(FluxConcatMap.java:331)
2022-05-11T16:01:00.3980617Z at reactor.core.publisher.Operators$DeferredSubscription.request(Operators.java:1680)
2022-05-11T16:01:00.3981520Z at reactor.core.publisher.FluxRepeatWhen$RepeatWhenMainSubscriber.onComplete(FluxRepeatWhen.java:164)
2022-05-11T16:01:00.3982370Z at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:148)
2022-05-11T16:01:00.3983198Z at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
2022-05-11T16:01:00.3984072Z at reactor.core.publisher.MonoCompletionStage.lambda$subscribe$0(MonoCompletionStage.java:83)
2022-05-11T16:01:00.3984974Z at reactor.core.publisher.MonoCompletionStage$$Lambda$496/0x0000000801020238.accept(Unknown Source)
2022-05-11T16:01:00.3985844Z at java.util.concurrent.CompletableFuture.uniWhenComplete([email protected]/CompletableFuture.java:863)
2022-05-11T16:01:00.3986744Z at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire([email protected]/CompletableFuture.java:841)
2022-05-11T16:01:00.3987649Z at java.util.concurrent.CompletableFuture.postComplete([email protected]/CompletableFuture.java:510)
2022-05-11T16:01:00.3988752Z at java.util.concurrent.CompletableFuture$AsyncSupply.run([email protected]/CompletableFuture.java:1773)
2022-05-11T16:01:00.3989532Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3989903Z
2022-05-11T16:01:00.3990527Z "process reaper" #24 daemon prio=10 os_prio=0 cpu=0.14ms elapsed=0.23s tid=0x00007fea742021d0 nid=0x8bb runnable [0x00007fea94022000]
2022-05-11T16:01:00.3991288Z java.lang.Thread.State: RUNNABLE
2022-05-11T16:01:00.3991944Z at java.lang.ProcessHandleImpl.waitForProcessExit0([email protected]/Native Method)
2022-05-11T16:01:00.3992722Z at java.lang.ProcessHandleImpl$1.run([email protected]/ProcessHandleImpl.java:147)
2022-05-11T16:01:00.3993550Z at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1136)
2022-05-11T16:01:00.3994453Z at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635)
2022-05-11T16:01:00.3995337Z at java.lang.Thread.run([email protected]/Thread.java:833)
2022-05-11T16:01:00.3995689Z
2022-05-11T16:01:00.3996222Z "VM Thread" os_prio=0 cpu=18.21ms elapsed=120.44s tid=0x00007feab40f3830 nid=0x831 runnable
2022-05-11T16:01:00.3996660Z
2022-05-11T16:01:00.3997195Z "GC Thread#0" os_prio=0 cpu=43.18ms elapsed=120.45s tid=0x00007feab40647b0 nid=0x82b runnable
2022-05-11T16:01:00.3997517Z
2022-05-11T16:01:00.3998263Z "GC Thread#1" os_prio=0 cpu=36.77ms elapsed=120.36s tid=0x00007fea8c0046a0 nid=0x83c runnable
2022-05-11T16:01:00.3998702Z
2022-05-11T16:01:00.3999234Z "G1 Main Marker" os_prio=0 cpu=0.46ms elapsed=120.45s tid=0x00007feab40736c0 nid=0x82c runnable
2022-05-11T16:01:00.3999560Z
2022-05-11T16:01:00.4000162Z "G1 Conc#0" os_prio=0 cpu=29.20ms elapsed=120.45s tid=0x00007feab4074620 nid=0x82e runnable
2022-05-11T16:01:00.4000595Z
2022-05-11T16:01:00.4001588Z "G1 Refine#0" os_prio=0 cpu=1.20ms elapsed=120.45s tid=0x00007feab40c6f00 nid=0x82f runnable
2022-05-11T16:01:00.4002023Z
2022-05-11T16:01:00.4002600Z "G1 Service" os_prio=0 cpu=22.81ms elapsed=120.45s tid=0x00007feab40c7df0 nid=0x830 runnable
2022-05-11T16:01:00.4002951Z
2022-05-11T16:01:00.4003722Z "VM Periodic Task Thread" os_prio=0 cpu=74.90ms elapsed=120.42s tid=0x00007feab410ffb0 nid=0x83a waiting on condition
2022-05-11T16:01:00.4004126Z
2022-05-11T16:01:00.4004509Z JNI global refs: 25, weak refs: 45
2022-05-11T16:01:00.4004722Z
2022-05-11T16:01:00.4005017Z Heap
2022-05-11T16:01:00.4006104Z garbage-first heap total 65536K, used 28558K [0x0000000093600000, 0x0000000100000000)
2022-05-11T16:01:00.4006754Z region size 1024K, 8 young (8192K), 3 survivors (3072K)
2022-05-11T16:01:00.4007307Z Metaspace used 30166K, committed 30528K, reserved 1081344K
2022-05-11T16:01:00.4007871Z class space used 4051K, committed 4224K, reserved 1048576K
2022-05-11T16:01:00.4008120Z
To Reproduce Steps to reproduce the behavior: It's not easy to reproduce. It works for us locally using the gradle test task. It also works deployed to AKS. But it does fail always and for all of our apps on Azure DevOps Build Agents. The problem started to show after the update to Azure Spring Cloud 4.0.0.
Code Snippet We use this configuration:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources[0]:
endpoint: https://xxx.vault.azure.net/
tenant-id: xxx.onmicrosoft.com
client-id: xxx
client-secret: xxx
Expected behavior It should never block forever, at least an exception after some timeout should be there.
Setup (please complete the following information):
- OS: Ubuntu 20 (Azure DevOps hosted build agent)
- Library/Libraries: com.azure.spring:spring-cloud-azure-dependencies:4.0.0
- Java version: 17.02 (openjdk)
- App Server/Environment: Tomcat
- Frameworks: Spring Boot 2.6.7
Additional context Related resolved dependencies:
+--- com.azure.spring:spring-cloud-azure-starter-keyvault-secrets -> 4.0.0
| +--- com.azure.spring:spring-cloud-azure-starter:4.0.0
| | +--- org.springframework.boot:spring-boot-starter:2.6.3 -> 2.6.7 (*)
| | \--- com.azure.spring:spring-cloud-azure-autoconfigure:4.0.0
| | +--- com.azure.spring:spring-cloud-azure-service:4.0.0
| | | \--- com.azure.spring:spring-cloud-azure-core:4.0.0
| | | +--- org.springframework:spring-context:5.3.15 -> 5.3.19 (*)
| | | +--- com.azure:azure-core:1.26.0
| | | | +--- com.fasterxml.jackson.core:jackson-annotations:2.13.1 -> 2.13.2 (*)
| | | | +--- com.fasterxml.jackson.core:jackson-core:2.13.1 -> 2.13.2 (*)
| | | | +--- com.fasterxml.jackson.core:jackson-databind:2.13.1 -> 2.13.2.1 (*)
| | | | +--- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:2.13.1 -> 2.13.2 (*)
| | | | +--- com.fasterxml.jackson.dataformat:jackson-dataformat-xml:2.13.1 -> 2.13.2
| | | | | +--- com.fasterxml.jackson.core:jackson-core:2.13.2 (*)
| | | | | +--- com.fasterxml.jackson.core:jackson-annotations:2.13.2 (*)
| | | | | +--- com.fasterxml.jackson.core:jackson-databind:2.13.2 -> 2.13.2.1 (*)
| | | | | +--- org.codehaus.woodstox:stax2-api:4.2.1
| | | | | +--- com.fasterxml.woodstox:woodstox-core:6.2.7
| | | | | | \--- org.codehaus.woodstox:stax2-api:4.2.1
| | | | | \--- com.fasterxml.jackson:jackson-bom:2.13.2 -> 2.13.2.1 (*)
| | | | +--- org.slf4j:slf4j-api:1.7.33 -> 1.7.35
| | | | +--- io.projectreactor:reactor-core:3.4.14 -> 3.4.17
| | | | | \--- org.reactivestreams:reactive-streams:1.0.3
| | | | \--- io.netty:netty-tcnative-boringssl-static:2.0.47.Final -> 2.0.51.Final
| | | | \--- io.netty:netty-tcnative-classes:2.0.51.Final
| | | +--- com.azure:azure-identity:1.4.6
| | | | +--- com.azure:azure-core:1.26.0 (*)
| | | | +--- com.azure:azure-core-http-netty:1.11.8
| | | | | +--- com.azure:azure-core:1.26.0 (*)
| | | | | +--- io.netty:netty-handler:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-resolver:4.1.76.Final
| | | | | | | \--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final
| | | | | | | \--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-transport:4.1.76.Final
| | | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | | \--- io.netty:netty-resolver:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-codec:4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | +--- io.netty:netty-handler-proxy:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec-socks:4.1.76.Final
| | | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | | \--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-codec-http:4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-handler:4.1.76.Final (*)
| | | | | +--- io.netty:netty-buffer:4.1.73.Final -> 4.1.76.Final (*)
| | | | | +--- io.netty:netty-codec-http:4.1.73.Final -> 4.1.76.Final (*)
| | | | | +--- io.netty:netty-codec-http2:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-handler:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-codec-http:4.1.76.Final (*)
| | | | | +--- io.netty:netty-transport-native-unix-common:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | +--- io.netty:netty-transport-native-epoll:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport-native-unix-common:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport-classes-epoll:4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport-native-unix-common:4.1.76.Final (*)
| | | | | +--- io.netty:netty-transport-native-kqueue:4.1.73.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport-native-unix-common:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport-classes-kqueue:4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport-native-unix-common:4.1.76.Final (*)
| | | | | \--- io.projectreactor.netty:reactor-netty-http:1.0.15 -> 1.0.18
| | | | | +--- io.netty:netty-codec-http:4.1.75.Final -> 4.1.76.Final (*)
| | | | | +--- io.netty:netty-codec-http2:4.1.75.Final -> 4.1.76.Final (*)
| | | | | +--- io.netty:netty-resolver-dns:4.1.75.Final -> 4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-resolver:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | +--- io.netty:netty-codec-dns:4.1.76.Final
| | | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | | +--- io.netty:netty-buffer:4.1.76.Final (*)
| | | | | | | +--- io.netty:netty-transport:4.1.76.Final (*)
| | | | | | | \--- io.netty:netty-codec:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-handler:4.1.76.Final (*)
| | | | | +--- io.netty:netty-resolver-dns-native-macos:4.1.75.Final -> 4.1.76.Final
| | | | | | \--- io.netty:netty-resolver-dns-classes-macos:4.1.76.Final
| | | | | | +--- io.netty:netty-common:4.1.76.Final
| | | | | | +--- io.netty:netty-resolver-dns:4.1.76.Final (*)
| | | | | | \--- io.netty:netty-transport-native-unix-common:4.1.76.Final (*)
| | | | | +--- io.netty:netty-transport-native-epoll:4.1.75.Final -> 4.1.76.Final (*)
| | | | | +--- io.projectreactor.netty:reactor-netty-core:1.0.18
| | | | | | +--- io.netty:netty-handler:4.1.75.Final -> 4.1.76.Final (*)
| | | | | | +--- io.netty:netty-handler-proxy:4.1.75.Final -> 4.1.76.Final (*)
| | | | | | +--- io.netty:netty-resolver-dns:4.1.75.Final -> 4.1.76.Final (*)
| | | | | | +--- io.netty:netty-resolver-dns-native-macos:4.1.75.Final -> 4.1.76.Final (*)
| | | | | | +--- io.netty:netty-transport-native-epoll:4.1.75.Final -> 4.1.76.Final (*)
| | | | | | \--- io.projectreactor:reactor-core:3.4.17 (*)
| | | | | \--- io.projectreactor:reactor-core:3.4.17 (*)
| | | | +--- com.microsoft.azure:msal4j:1.11.0
| | | | | +--- com.nimbusds:oauth2-oidc-sdk:9.7
| | | | | | +--- com.github.stephenc.jcip:jcip-annotations:1.0-1
| | | | | | +--- com.nimbusds:content-type:2.1
| | | | | | +--- net.minidev:json-smart:[1.3.3,2.4.7] -> 2.4.8
| | | | | | | \--- net.minidev:accessors-smart:2.4.8
| | | | | | | \--- org.ow2.asm:asm:9.1
| | | | | | +--- com.nimbusds:lang-tag:1.5
| | | | | | \--- com.nimbusds:nimbus-jose-jwt:9.9.3 -> 9.16.1
| | | | | | \--- com.github.stephenc.jcip:jcip-annotations:1.0-1
| | | | | +--- org.slf4j:slf4j-api:1.7.28 -> 1.7.35
| | | | | \--- com.fasterxml.jackson.core:jackson-databind:2.12.1 -> 2.13.2.1 (*)
| | | | +--- com.microsoft.azure:msal4j-persistence-extension:1.1.0
| | | | | +--- com.microsoft.azure:msal4j:1.4.0 -> 1.11.0 (*)
| | | | | +--- net.java.dev.jna:jna:5.5.0 -> 5.6.0
| | | | | +--- net.java.dev.jna:jna-platform:5.5.0 -> 5.6.0
| | | | | | \--- net.java.dev.jna:jna:5.6.0
| | | | | \--- org.slf4j:slf4j-api:1.7.7 -> 1.7.35
| | | | +--- net.java.dev.jna:jna-platform:5.6.0 (*)
| | | | \--- net.minidev:json-smart:2.4.7 -> 2.4.8 (*)
| | | +--- com.azure:azure-core-amqp:2.4.1
| | | | +--- com.azure:azure-core:1.26.0 (*)
| | | | +--- com.microsoft.azure:qpid-proton-j-extensions:1.2.4
| | | | | +--- org.apache.qpid:proton-j:0.33.8
| | | | | \--- org.slf4j:slf4j-api:1.7.28 -> 1.7.35
| | | | \--- org.apache.qpid:proton-j:0.33.8
| | | \--- com.azure:azure-core-management:1.5.3
| | | \--- com.azure:azure-core:1.26.0 (*)
| | +--- org.springframework.boot:spring-boot-autoconfigure:2.6.3 -> 2.6.7 (*)
| | \--- jakarta.validation:jakarta.validation-api:2.0.2
| \--- com.azure:azure-security-keyvault-secrets:4.3.8
| +--- com.azure:azure-core:1.26.0 (*)
| \--- com.azure:azure-core-http-netty:1.11.8 (*)
Information Checklist Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report
- [x] Bug Description Added
- [x] Repro Steps Added
- [x] Setup information Added
If you have a hint how to circumvent the problem, I would be happy to test it out.
I gave version 4.0.1 a try, but the problem remains the same.
Hi, @frbosch
Thank you for your detailed description about this problem.
My guess
I guess some exception happened but there is no log outputted in KeyVaultEnvironmentPostProcessor, you can check this question for more information.
My request
Please help to move related code out of KeyVaultEnvironmentPostProcessor, run in your build server (hosted Azure DevOps Build Agent), check where there is any useful log.
Here is an example:
https://github.com/chenrujun/azure-sdk-for-java_issue_28790/blob/b79d676a463ae2d4984b557dbfb696530d45bc9d/src/main/java/com/azure/spring/keyvault/secrets/sample/single/property/source/PropertySourceApplication.java
@SpringBootApplication
public class PropertySourceApplication implements CommandLineRunner {
@Value("${client-id}")
private String clientId;
@Value("${client-secret}")
private String clientSecret;
@Value("${tenant-id}")
private String tenantId;
@Value("${vault-uri}")
private String vaultUri;
public static void main(String[] args) {
SpringApplication.run(PropertySourceApplication.class, args);
}
public void run(String[] args) {
ClientSecretCredential clientSecretCredential = new ClientSecretCredentialBuilder()
.clientId(clientId)
.clientSecret(clientSecret)
.tenantId(tenantId)
.build();
final SecretClient secretClient = new SecretClientBuilder()
.vaultUrl(vaultUri)
.credential(clientSecretCredential)
.buildClient();
Map<String, String> properties = Optional.of(secretClient)
.map(SecretClient::listPropertiesOfSecrets)
.map(ContinuablePagedIterable::iterableByPage)
.map(i -> StreamSupport.stream(i.spliterator(), false))
.orElseGet(Stream::empty)
.map(PagedResponse::getElements)
.flatMap(i -> StreamSupport.stream(i.spliterator(), false))
.filter(SecretProperties::isEnabled)
.map(p -> secretClient.getSecret(p.getName(), p.getVersion()))
.filter(Objects::nonNull)
.collect(Collectors.toMap(
KeyVaultSecret::getName,
KeyVaultSecret::getValue
));
properties.forEach((key, value) -> System.out.println(key + ": " + value));
}
}
Thank you @chenrujun,
i found the problem: The properties we configured had the wrong format. What was happening is:
- On local development: It was falling back to use azure cli token.
- On build server: It had no correct config, which caused it to stuck.
- In AKS: It was using the pod identity (managed identity).
So i guess the problem occurs whenever the credentials are not available?
What we had is:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources[0]:
endpoint: https://xxx.vault.azure.net/
tenant-id: xxx.onmicrosoft.com
client-id: xxx
client-secret: xxx
Correct is:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources[0]:
endpoint: https://xxx.vault.azure.net/
profile:
tenant-id: xxx.onmicrosoft.com
credential:
client-id: xxx
client-secret: xxx
Hi, @frbosch
Thank you for you information. I have 2 points to share:
- You should change
property-sources[0]toproperty-sourcesin yourapplication.yml. - When credentials are not available, it may cost few minutes to retry then throw an exception. So it's not blocks forever, please wait a few minutes. In my machine, it will throw exception after 3 minutes like this:
14:20:50.265 [main] ERROR org.springframework.boot.SpringApplication - Application run failed
java.lang.IllegalStateException: Failed to configure KeyVault property source
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySource(KeyVaultEnvironmentPostProcessor.java:130)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySourceList(KeyVaultEnvironmentPostProcessor.java:115)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.postProcessEnvironment(KeyVaultEnvironmentPostProcessor.java:86)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:102)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:87)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:339)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:297)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301)
at com.azure.spring.keyvault.secrets.sample.single.property.source.PropertySourceApplication.main(PropertySourceApplication.java:45)
Caused by: com.azure.identity.CredentialUnavailableException: 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
ManagedIdentityCredential authentication unavailable. Connection to IMDS endpoint cannot be established, Network is unreachable: connect.
SharedTokenCacheCredential authentication unavailable. No accounts were found in the cache.
IntelliJ Authentication not available. Please log in with Azure Tools for IntelliJ plugin in the IDE.
Failed to read Vs Code credentials from Windows Credential API.
AzureCliCredential authentication unavailable. Please run 'az login' to set up account. To further mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/java/identity/azclicredential/troubleshoot
Azure PowerShell authentication failed using defaultpowershell(pwsh) with following error: Az.Account module with version >= 2.2.0 is not installed. It needs to be installed to use Azure PowerShell Credential.
Azure PowerShell authentication failed using powershell-core(powershell) with following error: Az.Account module with version >= 2.2.0 is not installed. It needs to be installed to use Azure PowerShell Credential.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azure-identity-java-default-azure-credential-troubleshoot
Hi @chenrujun, thanks for your response. property-sources: does not work for me. At least with property-sources[0] it definitely blocks forever for us. All our builds ran into the 1h DevOps Pipeline timeout.
Here is sample project, which blocks forever if deployed with the provided Azure DevOps pipeline: Sample Project
It prints a thread dump every 2 minutes and the spring context does not finish loading.
Hi, @frbosch
- About
property-sourcesandproperty-sources[0], I found both the following 2 formats are right:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources[0]:
endpoint:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources:
- endpoint:
- I run your sample in my local machine after logout azure cli. I can see the exception but the app does not exit:
az logout
Caused by: com.azure.identity.CredentialUnavailableException: 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/java/identity/environmentcredential/troubleshoot
- Continue to previous step, after I deleted
ThreadLogger.javarelated logic, the app can exit after about 3 minutes:
Seems block for ever is caused by ThreadLogger.java.
Hi @chenrujun, no ThreadLogger does not block. You can remove it, it's just there to log the running Threads if deployed to DevOps. It's not blocking on my local machine as well, deploy it to Azure DevOps and it will block.
@frbosch Thank you for your quick response.
On local development: It was falling back to use azure cli token.
On build server: It had no correct config, which caused it to stuck.
I'm wondering what's the difference between localhost and Azure DevOps. In localhost, it will wait for about 3minutes, but for Azure DevOps, it will block.
IMU, if we execute az logout in localhost, localhost should have same behavior with Azure DevOps.
@frbosch
FYI:
When I use ./gradlew bootRun to run your sample application in my localhost, it can exit after about 3 minutes, here is the log:
./gradlew bootRun
Welcome to Gradle 7.4!
Here are the highlights of this release:
- Aggregated test and JaCoCo reports
- Marking additional test source directories as tests in IntelliJ
- Support for Adoptium JDKs in Java toolchains
For more details see https://docs.gradle.org/7.4/release-notes.html
Starting a Gradle Daemon (subsequent builds will be faster)
<-----------<==========---> 80% EXECUTING [23s]
<==========-<==========---> 80% EXECUTING [1m 12s]
<==========-<==========---> 80% EXECUTING [1m 57s]]6s]
<==========-<==========---> 80% EXECUTING [2m 35s]25s] C
> Task :bootRun1m==========---> 80% EXECUTING [2m 22s] =
15:23:09.349 [main] ERROR org.springframework.boot.SpringApplication - Application run failed
java.lang.IllegalStateException: Failed to configure KeyVault property source
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySource(KeyVaultEnvironmentPostProcessor.java:127)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySourceList(KeyVaultEnvironmentPostProcessor.java:112)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.postProcessEnvironment(KeyVaultEnvironmentPostProcessor.java:85)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:102)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:87)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:339)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:297)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301)
at com.test.bug28790.TestApp.main(TestApp.java:19)
Caused by: com.azure.identity.CredentialUnavailableException: 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/java/identity/environmentcredential/troubleshoot
ManagedIdentityCredential authentication unavailable. Connection to IMDS endpoint cannot be established, Network is unreachable: connect.
SharedTokenCacheCredential authentication unavailable. No accounts were found in the cache.
IntelliJ Authentication not available. Please log in with Azure Tools for IntelliJ plugin in the IDE.
Failed to read Vs Code credentials from Windows Credential API.
AzureCliCredential authentication unavailable. Please run 'az login' to set up account. To further mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azsdk/java/identity/azclicredential/troubleshoot
Azure PowerShell authentication failed using defaultpowershell(pwsh) with following error: Az.Account module with version >= 2.2.0 is not installed. It needs to be installed to use Azure PowerShell Credential.
Azure PowerShell authentication failed using powershell-core(powershell) with following error: Az.Account module with version >= 2.2.0 is not installed. It needs to be installed to
use Azure PowerShell Credential.To mitigate this issue, please refer to the troubleshooting guidelines here at https://aka.ms/azure-identity-java-default-azure-credential-troubleshoot
at com.azure.identity.ChainedTokenCredential.lambda$getToken$3(ChainedTokenCredential.java:95)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:44)
at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:82)
at reactor.core.publisher.MonoNext$NextSubscriber.onComplete(MonoNext.java:102)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:846)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:608)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:894)
at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:997)
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2058)
at reactor.core.publisher.Operators.complete(Operators.java:137)
at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:46)
at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onError(FluxPeekFuseable.java:234)
at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onError(MonoPeekTerminal.java:258)
at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onError(FluxPeekFuseable.java:903)
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onError(Operators.java:2063)
at reactor.core.publisher.Operators.error(Operators.java:198)
at reactor.core.publisher.MonoError.subscribe(MonoError.java:53)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:82)
at reactor.core.publisher.MonoNext$NextSubscriber.onComplete(MonoNext.java:102)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:846)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:608)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:894)
at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:997)
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2058)
at reactor.core.publisher.Operators.complete(Operators.java:137)
at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:46)
at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onError(FluxDoFinally.java:136)
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:142)
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$FlatMapMain.onNext(MonoFlatMap.java:151)
at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82)
at reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:99)
at reactor.core.publisher.FluxRepeatWhen$RepeatWhenMainSubscriber.onNext(FluxRepeatWhen.java:142)
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:151)
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
at reactor.core.publisher.MonoCompletionStage.lambda$subscribe$0(MonoCompletionStage.java:83)
at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1705)
at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
Suppressed: java.lang.Exception: #block terminated with an error
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:99)
at reactor.core.publisher.Flux.blockLast(Flux.java:2645)
at com.azure.core.util.paging.ContinuablePagedByIteratorBase.requestPage(ContinuablePagedByIteratorBase.java:94)
at com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator.<init>(ContinuablePagedByPageIterable.java:57)
at com.azure.core.util.paging.ContinuablePagedByPageIterable.iterator(ContinuablePagedByPageIterable.java:41)
at java.base/java.lang.Iterable.spliterator(Iterable.java:101)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.lambda$refreshProperties$2(KeyVaultOperation.java:140)
at java.base/java.util.Optional.map(Optional.java:265)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.refreshProperties(KeyVaultOperation.java:140)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.<init>(KeyVaultOperation.java:77)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySource(KeyVaultEnvironmentPostProcessor.java:124)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.buildKeyVaultPropertySourceList(KeyVaultEnvironmentPostProcessor.java:112)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultEnvironmentPostProcessor.postProcessEnvironment(KeyVaultEnvironmentPostProcessor.java:85)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:102)
at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:87)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:85)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:66)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:120)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:114)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:65)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:339)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:297)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1312)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301)
at com.test.bug28790.TestApp.main(TestApp.java:19)
> Task :bootRun FAILED
FAILURE: Build failed with an exception.
@chenrujun
Thank you for looking into it. It's the same for me, but on DevOps it runs for an hour:
@frbosch
FYI:
I can't access https://dev.azure.com/ now.
But I reproduced this problem in GitHub Action: https://github.com/chenrujun/frbosch-spring-cloud-azure-starter-keyvault-secrets-bug-28790/runs/6466733765?check_suite_focus=true#step:3:49
The root cause is still under investigation.
@frbosch
Until now, I didn't found the root cause.
Is this problem urgent? Could you please avoid this problem by setting spring.cloud.azure.keyvault.secret.property-source-enabled=false in your Azure DevOps?
@chenrujun
It's not urgent, the problem does not exist if the properties are set the right way. Just took me a day to figure this out, because there is no exception or something ...
@frbosch Thank you for your quick response. I'll put this issue to Backlog milestone.
I found the reason causes this hang forever.
take a look of @chenrujun log https://github.com/chenrujun/frbosch-spring-cloud-azure-starter-keyvault-secrets-bug-28790/runs/6466733765?check_suite_focus=true#step:3:49
the main thread is WAITING
"main" #1 prio=5 os_prio=0 cpu=1253.20ms elapsed=120.43s tid=0x00007ff84002b000 nid=0x787 waiting on condition [0x00007ff8477f1000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
- parking to wait for <0x0000000098a9a008> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:194)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt([email protected]/AbstractQueuedSynchronizer.java:885)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:10[39](https://github.com/chenrujun/frbosch-spring-cloud-azure-starter-keyvault-secrets-bug-28790/runs/6466733765?check_suite_focus=true#step:3:40))
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:1345)
at java.util.concurrent.CountDownLatch.await([email protected]/CountDownLatch.java:232)
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87)
at reactor.core.publisher.Flux.blockLast(Flux.java:26[45](https://github.com/chenrujun/frbosch-spring-cloud-azure-starter-keyvault-secrets-bug-28790/runs/6466733765?check_suite_focus=true#step:3:46))
at com.azure.core.util.paging.ContinuablePagedByIteratorBase.requestPage(ContinuablePagedByIteratorBase.java:94)
the actual interesting part is the other thread
"Thread-7" #21 daemon prio=5 os_prio=0 cpu=2.08ms elapsed=105.57s tid=0x00007ff818003000 nid=0x7c6 runnable [0x00007ff81042a000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.readBytes([email protected]/Native Method)
at java.io.FileInputStream.read([email protected]/FileInputStream.java:279)
at java.io.BufferedInputStream.read1([email protected]/BufferedInputStream.java:290)
at java.io.BufferedInputStream.read([email protected]/BufferedInputStream.java:351)
- locked <0x000000009cd02a80> (a java.lang.ProcessImpl$ProcessPipeInputStream)
at sun.nio.cs.StreamDecoder.readBytes([email protected]/StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead([email protected]/StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read([email protected]/StreamDecoder.java:178)
- locked <0x000000009cd0b260> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read([email protected]/InputStreamReader.java:181)
at java.io.BufferedReader.fill([email protected]/BufferedReader.java:161)
at java.io.BufferedReader.readLine([email protected]/BufferedReader.java:326)
- locked <0x000000009cd0b260> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine([email protected]/BufferedReader.java:392)
at com.azure.identity.implementation.PowershellManager.lambda$readData$4(PowershellManager.java:103)
you can see this thread is reading from a input stream, I believe this is what causing the application blocked.
and it explains why you can't reproduce this locally but only on Github Actions or ADO -- because you don't have PowerShell installed locally, but it is part of the image used in the Github Actions
if you have Powershell installed, it is easily to reproduce this issue on your local machine.
since we use DefaultAzureCredential to build the token credential and Powershell credential is part of the chain, which causing this issue.
The underlying reason of why it is blocking is still under clear, but I think this is more a Azure Identity issue, @schaabs and @g2vinay I'm assigning this to you and please take a look
https://github.com/stliu/frbosch-spring-cloud-azure-starter-keyvault-secrets-bug-28790/runs/7758044109?check_suite_focus=true
from this run, you can see if we delete the pwsh, it went well and no blocking any more
@frbosch can you try the latest version of the azure spring cloud bom to check if the issue still persists ?
Hi. I'm using spring-cloud-azure-dependencies:4.10.0, specifically spring-cloud-azure-starter-keyvault-secrets. (I'm on Spring Boot 2.7 for now).
I've scratched my head for about three days finding why the app won't start after enabling property-sources.
The problem, in my case, was: Missing the secret-keys value to be read from the Key Vault Secret:
spring:
cloud:
azure:
keyvault:
secret:
property-source-enabled: true
property-sources:
- endpoint: https://my-endpoint.vault.azure.net/
secret-keys:
- my-secret-key-from-azure
The behavior was the same as stated in previous comments: the app hanged forever, with no log available.
And it was stuck in here:
"main" #1 prio=5 os_prio=0 cpu=1617,17ms elapsed=34,60s tid=0x00007fe3e00302b0 nid=0x78ec waiting on condition [0x00007fe3e7f13000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
- parking to wait for <0x000000070a200000> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:715)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:1047)
at java.util.concurrent.CountDownLatch.await([email protected]/CountDownLatch.java:230)
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:87)
at reactor.core.publisher.Flux.blockLast(Flux.java:2761)
at com.azure.core.util.paging.ContinuablePagedByIteratorBase.requestPage(ContinuablePagedByIteratorBase.java:102)
- locked <0x000000070a200190> (a com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator)
at com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator.<init>(ContinuablePagedByPageIterable.java:74)
at com.azure.core.util.paging.ContinuablePagedByPageIterable.iterator(ContinuablePagedByPageIterable.java:55)
at java.lang.Iterable.spliterator([email protected]/Iterable.java:101)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation.lambda$refreshProperties$2(KeyVaultOperation.java:140)
at com.azure.spring.cloud.autoconfigure.keyvault.environment.KeyVaultOperation$$Lambda$434/0x00000008012fcd50.apply(Unknown Source)
This is the call in the code that make me realize what was my problem: com.azure.security.keyvault.secrets.SecretClient#listPropertiesOfSecrets(com.azure.core.util.Context)
Hi @vvalencia-cl, what credential is used in your case? And which Spring Boot version you are using?
Hi @vvalencia-cl, what credential is used in your case? And which Spring Boot version you are using?
Hi @saragluna, Client credentials configured in bootstrap.yml:
spring:
cloud:
azure:
keyvault:
secret:
property-sources:
- endpoint: https://my-vault.vault.azure.net/
secret-keys:
- my-secret-from-azure
credential:
client-id: <>
client-secret: <>
profile:
tenant-id: <>
But I've also tested it with az login and with the login inside IntelliJ IDEA
Hi @vvalencia-cl, but it should not block even if there's no secret key provided. How many secrets do you have in your KV?
Hi @vvalencia-cl, but it should not block even if there's no secret key provided. How many secrets do you have in your KV?
Hi @saragluna ! Just one secret in the KV.
I've tried with bad credentials and the app failed with a well described error. But when everything was fine (except when no setting any value in secret-keys), the app won't start, and no log line was showed.
Thanks @vvalencia-cl, could you help provide a minimal reproducible project for us to investigate the issue?
Hey @frbosch, @vvalencia-cl.
It looks like this issue went under our radar for a good bit after Strong's comments (here and here) on the matter pointed at an interaction in AzurePowerShellCredential when people authenticate using the DefaultAzureCredential. We have changed owners for the Azure Identity libraries since the issue and comments were posted, so I will assign it to the current owner. @billwert, would you mind taking a look at this issue when you get a chance? Thanks!
/cc @stliu, @saragluna, @chenrujun
