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

[joshfree]

Ported issue filed by @krysiuda at Azure/azure-sdk-for-java#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):

• OS: linux
• IDE: IntelliJ
• Library/Libraries: msal4j-1.15.0-sources.jar
• Java version: openjdk-21
• App Server/Environment: N/A
• Frameworks: N/A

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]

Hello @joshfree : I believe the most recent change to that logging level was in #756 as part of v1.14.1, b105389 is the relevant commit, and those changes were to resolve #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

[papaya2k]

Hello. I've also been affected by this. The logging is definitely overly verbose. I've suggested a code correction for this to change the logging level of a CACHE_MISS to debug level. Thank you.

[Avery-Dunn]

Thanks to @papaya2k, the logging level was reduced in #844, and was released in MSAL Java 1.16.2