[QUERY] Downgrade log level for MsalClientException

[felix-ebert]

Query/Question

We encountered the following log statement:

ERROR [Timer-0] c.a.i.i.IdentityClient - com.microsoft.aad.msal4j.MsalClientException: Token not found in the cache.

However, despite this error being logged, the application operates as expected.

Can this exception be caught properly and the log level downgraded?

Why is this not a Bug or a feature Request?

A similar bug #27585 had been closed stating the error can be ignored.

Stack Trace

ERROR [Timer-0] c.a.i.i.IdentityClient - com.microsoft.aad.msal4j.MsalClientException: Token not found in the cache
com.azure.core.exception.ClientAuthenticationException: com.microsoft.aad.msal4j.MsalClientException: Token not found in the cache
	at com.azure.identity.implementation.IdentitySyncClient.authenticateWithConfidentialClientCache(IdentitySyncClient.java:192)
	at com.azure.identity.ClientSecretCredential.getTokenSync(ClientSecretCredential.java:128)
	at com.azure.identity.EnvironmentCredential.getTokenSync(EnvironmentCredential.java:185)
	at com.azure.identity.ChainedTokenCredential.getTokenSync(ChainedTokenCredential.java:120)
	at com.azure.core.implementation.AccessTokenCache.lambda$new$2(AccessTokenCache.java:62)
	at com.azure.core.implementation.AccessTokenCache.lambda$retrieveTokenSync$11(AccessTokenCache.java:223)
	at com.azure.core.implementation.AccessTokenCache.getTokenSync(AccessTokenCache.java:88)
	at com.azure.core.http.policy.BearerTokenAuthenticationPolicy.setAuthorizationHeaderHelperSync(BearerTokenAuthenticationPolicy.java:183)
	at com.azure.core.http.policy.BearerTokenAuthenticationPolicy.setAuthorizationHeaderSync(BearerTokenAuthenticationPolicy.java:169)
	at com.azure.security.keyvault.secrets.implementation.KeyVaultCredentialPolicy.authorizeRequestSync(KeyVaultCredentialPolicy.java:227)
	at com.azure.core.http.policy.BearerTokenAuthenticationPolicy.processSync(BearerTokenAuthenticationPolicy.java:131)
	at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:41)
	at com.azure.core.http.policy.RetryPolicy.attemptSync(RetryPolicy.java:164)
	at com.azure.core.http.policy.RetryPolicy.processSync(RetryPolicy.java:114)
	at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:41)
	at com.azure.core.http.policy.AddHeadersPolicy.processSync(AddHeadersPolicy.java:39)
	at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:41)
	at com.azure.core.http.policy.HttpPipelineSyncPolicy.processSync(HttpPipelineSyncPolicy.java:42)
	at com.azure.core.http.policy.UserAgentPolicy.processSync(UserAgentPolicy.java:153)
	at com.azure.core.http.HttpPipelineNextSyncPolicy.processSync(HttpPipelineNextSyncPolicy.java:41)
	at com.azure.core.http.HttpPipeline.sendSync(HttpPipeline.java:131)
	at com.azure.core.implementation.http.rest.SyncRestProxy.send(SyncRestProxy.java:55)
	at com.azure.core.implementation.http.rest.SyncRestProxy.invoke(SyncRestProxy.java:76)
	at com.azure.core.implementation.http.rest.RestProxyBase.invoke(RestProxyBase.java:110)
	at com.azure.core.http.rest.RestProxy.invoke(RestProxy.java:91)
	at jdk.proxy2/jdk.proxy2.$Proxy13.getSecretsSync(Unknown Source)
	at com.azure.security.keyvault.secrets.implementation.SecretClientImpl.getSecretsSinglePage(SecretClientImpl.java:1313)
	at com.azure.security.keyvault.secrets.SecretClient.lambda$listPropertiesOfSecrets$16(SecretClient.java:870)
	at com.azure.core.http.rest.PagedIterable.lambda$new$5(PagedIterable.java:185)
	at com.azure.core.util.paging.ContinuablePagedByIteratorBase.requestPage(ContinuablePagedByIteratorBase.java:104)
	at com.azure.core.util.paging.ContinuablePagedByPageIterable$ContinuablePagedByPageIterator.<init>(ContinuablePagedByPageIterable.java:82)
	at com.azure.core.util.paging.ContinuablePagedByPageIterable.iterator(ContinuablePagedByPageIterable.java:58)
	at java.base/java.lang.Iterable.spliterator(Unknown Source)
	at com.azure.spring.cloud.autoconfigure.implementation.keyvault.environment.KeyVaultOperation.lambda$refreshProperties$2(KeyVaultOperation.java:140)
	at java.base/java.util.Optional.map(Unknown Source)
	at com.azure.spring.cloud.autoconfigure.implementation.keyvault.environment.KeyVaultOperation.refreshProperties(KeyVaultOperation.java:140)
	at com.azure.spring.cloud.autoconfigure.implementation.keyvault.environment.KeyVaultOperation$1.run(KeyVaultOperation.java:94)
	at java.base/java.util.TimerThread.mainLoop(Unknown Source)
	at java.base/java.util.TimerThread.run(Unknown Source)
Caused by: java.util.concurrent.ExecutionException: com.microsoft.aad.msal4j.MsalClientException: Token not found in the cache
	at java.base/java.util.concurrent.CompletableFuture.reportGet(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)
	at com.azure.identity.implementation.IdentitySyncClient.authenticateWithConfidentialClientCache(IdentitySyncClient.java:182)
	... 38 common frames omitted
Caused by: com.microsoft.aad.msal4j.MsalClientException: Token not found in the cache
	at com.microsoft.aad.msal4j.AcquireTokenSilentSupplier.execute(AcquireTokenSilentSupplier.java:75)
	at com.microsoft.aad.msal4j.AuthenticationResultSupplier.get(AuthenticationResultSupplier.java:69)
	at com.microsoft.aad.msal4j.AuthenticationResultSupplier.get(AuthenticationResultSupplier.java:18)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

Setup

• OS: AKS Ubuntu 22.04
• Library/Libraries:
  • spring-boot v3.2.1
  • spring-cloud-azure-starter-keyvault-secrets v5.8.0

Current workaround

Disable the log statement via Logback:

<logger name="com.azure.identity.implementation.IdentityClient" level="off" />

Possible solution

Catch the exception properly in IdentitySyncClient.java#L189 and downgrade the log level.

Additional context

There is also closed bug #669 inside the used microsoft-authentication-library-for-java dependency, which is maybe related. Nevertheless, the used version 5.8.0 should already include the fix.

[joshfree]

@billwert could you follow up since you investigated the linked issue?

[petarchou]

I started experiencing the same issue after upgrading "azure-security-keyvault-secrets" from "4.6.1" to "4.7.3". No other changes were made.
The library version of msal4j wasn't changed - 1.13.7.

Application also operates as expected (so far).

[billwert]

Thanks for the reports folks. We're looking into how we can improve this logging experience.

[petarchou]

Update:
The logging error for me starts to appear in keyvault-secrets 4.6.4 or 4.6.5 (I didn't have time to test which one exactly).
Based on the changelog there are only dependency updates for these versions and specifically azure-core from 1.4.0 -> 1.4.2

[billwert]

@petarchou Can you upgrade to Azure Identity 1.11.2 and let us know if this improves your experience? We've moved this log from ERROR to DEBUG.

[github-actions]

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

[github-actions]

Hi @felix-ebert, since you haven’t asked that we /unresolve the issue, we’ll close this out. If you believe further discussion is needed, please add a comment /unresolve to reopen the issue.