search

AzureAD / microsoft-authentication-library-for-java

Microsoft Authentication Library (MSAL) for Java http://aka.ms/aadv2
MIT License
280 stars 137 forks source link

[BUG] AcquireTokenSilentSupplier failed: Token not found in the cache #833

Open joshfree opened 1 week ago

joshfree commented 1 week ago

Ported issue filed by @krysiuda at https://github.com/Azure/azure-sdk-for-java/issues/40654 to https://github.com/AzureAD/microsoft-authentication-library-for-java

Describe the bug Between msal4j versions 1.14.0 and 1.15.0 logging for AuthenticationErrorCode.CACHE_MISS has changed. I believe the change was accidental, resulting in additional (and potentially misleading) WARN messages being log.

Exception or Stack Trace Our production system is logging "Execution of class com.microsoft.aad.msal4j.AcquireTokenSilentSupplier failed: Token not found in the cache" on "com.microsoft.aad.msal4j.ConfidentialClientApplication" logger (severity: WARN) every hour.

Expected behavior Since cache miss simply triggers retrieval of a new token, I would expect this event (cache miss) to be logged with low severity. Preferably DEBUG level.

Setup (please complete the following information):

Additional context in msal4j-1.14.0 AuthenticationResultSupplier there was:

            if (exception.errorCode() != null && exception.errorCode().equalsIgnoreCase(AuthenticationErrorCode.CACHE_MISS)) {
                clientApplication.log.debug(logMessage, ex);
                return;
            }
            ...
            clientApplication.log.error(logMessage, ex);

logging CACHE_MISS on DEBUG level instead of ERROR.

in msal4j-1.15.0, there is only:

                clientApplication.log.warn(
                        LogHelper.createMessage(
                                String.format("Execution of %s failed: %s", this.getClass(), ex.getMessage()),
                                msalRequest.headers().getHeaderCorrelationIdValue()));

logging cache misses always on WARN level.

Avery-Dunn commented 1 week ago

Hello @joshfree : I believe the most recent change to that logging level was in https://github.com/AzureAD/microsoft-authentication-library-for-java/pull/756 as part of v1.14.1, https://github.com/AzureAD/microsoft-authentication-library-for-java/pull/756/commits/b105389c7164407de2d1f8f970826c61e6131d0a is the relevant commit, and those changes were to resolve https://github.com/AzureAD/microsoft-authentication-library-for-java/issues/662

If I remember right, the idea was to log at the 'warn' or 'debug' level rather than the 'error' level whenever an exception was thrown. However, as that code snippet you have points out there was a check specifically for putting cache misses at the debug level, and that was lost during the various logging changes done in v1.14.1

I agree that a cache miss exception should cause a debug log, since it doesn't necessarily mean that something wrong. It'll be a quick fix so will likely be in our next release, and I'll update this thread once we have some ETAs