[BUG] Error c.m.a.m.CrossProcessCacheFileLock when using tokenCachePErsistenceOptions

[xchopin]

Describe the bug
Impossible to use tokenCachePersistenceOptions() in my ClientSecretCredentialBuilder in order to cache the token (for making several requests with ONE token).

Exception or Stack Trace

2022-04-11 14:04:56.150 ERROR 18948 --- [onPool-worker-1] c.m.a.m.CrossProcessCacheFileLock        : null
2022-04-11 14:04:56.151  INFO 18948 --- [onPool-worker-1] c.azure.identity.ClientSecretCredential  : Azure Identity => getToken() result for scopes [https://graph.microsoft.com/.default]: SUCCESS

2022-04-11 14:04:56.274 ERROR 18948 --- [onPool-worker-1] c.m.a.m.CrossProcessCacheFileLock        : null
2022-04-11 14:04:56.274  INFO 18948 --- [onPool-worker-1] c.azure.identity.ClientSecretCredential  : Azure Identity => getToken() result for scopes [https://graph.microsoft.com/.default]: SUCCESS

To Reproduce
Create a ClientSecretCredentialBuilder and try adding the method .tokenCachePersistenceOptions()

Code Snippet

 ClientSecretCredential clientSecretCredential = new ClientSecretCredentialBuilder()
   .clientId(clientId)
   .clientSecret(clientSecret)
   .tenantId(tenantId)
   .tokenCachePersistenceOptions(new TokenCachePersistenceOptions())
   .build();

Expected behavior
It should cache the token and not calling getToken over and over

Setup (please complete the following information):

• OS: Windows 10 (last build)
• IDE: IntelliJ
• Library/Libraries: com.azure 1.4.6 / com.microsoft.graph 5.19.0
• Java version: 8
• App Server/Environment: Spring Batch / local environment
• Frameworks: Spring Batch

Additional context
Add any other context about the problem here.

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
• Setup information Added

[joshfree]

@billwert could you follow up with @xchopin

[Kelukin]

I have the same issue.
Refer to the code in PersistenceTokenCacheAccessAspect.java:133, the CrossProcessCacheFileLock.unlock() will delete the lock file without setting the CrossProcessCacheFileLock.lock to null. Hence, in the PersistenceTokenCacheAccessAspect.java:150, the CrossProcessCacheFileLock will try to unlock again and release the underlying resource. However, the lockfile has been deleted by the last unlock call. Hence, there will be an exception.

[Kelukin]

@xchopin, I guess that you infer the cache mechanism is failed from the log Azure Identity => getToken(). I experimented and found that no matter where the token comes from (cache or send a request), the log will always print such a line.
A default token cache mechanism is stored in the memory, which could automatically refresh the expired cache with thread safety. Hence, even if you do not enable the tokenCachePersistenceOptions, the ClientSecretCredential will still reuse the token cached in the memory.

[xchopin]

Hi @Kelukin thank you for your investigation on the issue.

From what I understand, the cache system works and it's only a log issue from the SDK.

Looking forward for a fix on that.

Thank you!

[billwert]

The logging here is indicating that getToken() was called on a credential, so it's doing the right thing. I don't think we're going to change that - it's important to see that apps are trying to get a token when they do. If there is something else you would like to see here, let us know.

[mcantrell]

Maybe more useful logging would be better than just logging the exception message. In this case, the message is null and that's not helpful at all.

[mcantrell]

For example, the exception thrown is ClosedChannelException. That gives you a good hint that the following check is not enough:

    private void releaseResources() {
        try {
            if (lock != null) {
                lock.release();
            }
            if (fileChannel != null) {
                fileChannel.close();
            }
        }
        catch (IOException ex){
            LOG.error(ex.getMessage());
        }
    }

The null guards should be enhanced to check validity as well:

lock != null && lock.isValid()

fileChannel != null && fileChannel.isOpen()

edit:

To address the source of the issue, you can turn on debug logging and see the unlock is being called twice:

16:07:43.205 [ForkJoinPool.commonPool-worker-1] DEBUG CrossProcessCacheFileLock - pid:5539 thread:20 acquiring file lock
16:07:43.208 [ForkJoinPool.commonPool-worker-1] DEBUG CrossProcessCacheFileLock - pid:5539 thread:20 acquired OK file lock
16:07:43.364 [ForkJoinPool.commonPool-worker-1] DEBUG CrossProcessCacheFileLock - pid:5539 thread:20 releasing lock
16:07:43.368 [ForkJoinPool.commonPool-worker-1] DEBUG CrossProcessCacheFileLock - pid:5539 thread:20 releasing lock
16:07:43.368 [ForkJoinPool.commonPool-worker-1] ERROR CrossProcessCacheFileLock - null

The second release fails because it's already been released.