feat: log Azure credential and ACR token acquisition - #2876
Conversation
The Azure credential path was completely silent: internal/cloudprovider/azure and internal/store/credentialprovider/azure had no logging at all, and CreateCredentialChain swallowed both credential construction errors, so there was no way to tell which identity was used or why registry auth failed. Log which credential sources are available (workload identity, managed identity) and why one is skipped, the AAD token acquisition and the ACR refresh token exchange with their durations, and the resolved credential TTL. Failures to build the chain or exchange the token are now logged at error level, and a TTL parse fallback at warn level. Signed-off-by: Charles Wu <yuewu2@microsoft.com>
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #2876 +/- ##
==========================================
+ Coverage 76.89% 77.03% +0.13%
==========================================
Files 90 90
Lines 4276 4302 +26
==========================================
+ Hits 3288 3314 +26
Misses 831 831
Partials 157 157 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
There was a problem hiding this comment.
Pull request overview
This PR closes an observability gap in Ratify v2’s Azure authentication flow by adding debug/error/warn logging around Azure credential chain construction and ACR token acquisition, aligning v2 operator experience closer to v1 for diagnosing AAD/ACR access issues.
Changes:
- Add request-scoped debug/error/warn logs in the ACR Azure credential provider for chain creation, token exchange durations, and resolved TTL.
- Add debug logs in Azure credential chain construction indicating which credential sources are available/unavailable and the resulting chain size.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| internal/store/credentialprovider/azure/register.go | Adds request-scoped authProvider logs for AAD token acquisition, ACR refresh token exchange, TTL parsing/fallback, and key error paths. |
| internal/cloudprovider/azure/tokencredential.go | Adds debug logs for workload identity / managed identity credential availability and the final chained credential source count. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| if err != nil { | ||
| // If JWT parsing fails, fall back to the default TTL | ||
| log.Warnf("failed to parse ACR refresh token TTL for %s, falling back to the default: %v", serverAddress, err) | ||
| ttl = DefaultACRTokenTTL | ||
| } |
There was a problem hiding this comment.
Good catch, fixed in 327e471.
parseJWTTokenTTL now returns a sentinel errTokenExpired instead of a formatted string, and a new tokenCacheTTL helper distinguishes the two failure modes:
- already expired -> TTL
0.CachedProvideronly writes to the cache whenTTL > 0, so an expired refresh token is now never stored and every request re-exchanges. Logged at warn level. - unparseable expiry ->
DefaultACRTokenTTLfallback, as before.
Unit tests cover both paths (TestTokenCacheTTL, TestTokenCacheTTL_ExpiredTokenIsNotCacheable).
parseJWTTokenTTL now returns a sentinel error for an expired token so the new tokenCacheTTL helper can tell it apart from an unparseable one. An expired token gets a zero TTL, which stops CachedProvider from storing it and serving 401s for hours; only a genuinely unparseable expiry falls back to the default TTL. Credential-chain logging moves into an appendCredential helper so both the available and unavailable paths are covered by tests. Signed-off-by: Charles Wu <yuewu2@microsoft.com>
…-logging Signed-off-by: Charles Wu <yuewu2@microsoft.com> # Conflicts: # internal/store/credentialprovider/azure/register.go
| if err != nil { | ||
| // If JWT parsing fails, fall back to the default TTL | ||
| ttl = DefaultACRTokenTTL | ||
| log.Warnf("could not determine the ACR refresh token TTL for %s, caching it for %s instead: %v", serverAddress, ttl, err) |
There was a problem hiding this comment.
ttl=DefaultACRTokenTTL logic is missing
BTW, it has no difference for expire error
There was a problem hiding this comment.
Both fair — fixed in 1f3925c.
You're right on the second point especially: the single warn message printed caching it for 0s instead for an expired token, which is simply wrong. It isn't cached for 0s, it isn't cached at all. And splitting ttl (helper) from the log (caller) is what hid DefaultACRTokenTTL from this hunk in the first place.
resolveTokenTTL now owns the TTL and the explanation, so all three outcomes are visible in one place:
func resolveTokenTTL(log dcontext.Logger, serverAddress, token string) time.Duration {
ttl, err := parseJWTTokenTTL(token)
switch {
case errors.Is(err, errTokenExpired):
log.Warnf("ACR returned an already-expired refresh token for %s; it will not be cached", serverAddress)
return 0
case err != nil:
log.Warnf("failed to parse the ACR refresh token TTL for %s, falling back to %s: %v", serverAddress, DefaultACRTokenTTL, err)
return DefaultACRTokenTTL
default:
log.Debugf("resolved ACR credential for %s, expires in %s", serverAddress, ttl)
return ttl
}
}GetWithTTL step 3 is now one line. Actual output:
level=warning msg="failed to parse the ACR refresh token TTL for testregistry.azurecr.io, falling back to 2h55m0s: failed to parse JWT token: ..."
level=warning msg="ACR returned an already-expired refresh token for testregistry.azurecr.io; it will not be cached"
TestResolveTokenTTL_ExpiredAndUnparseableDiffer asserts the two messages are not identical so this can't regress back. resolveTokenTTL is at 100% coverage.
The default-TTL fallback had moved out of GetWithTTL into a helper that only returned (ttl, err), so the caller logged one message for both failure modes: an expired token reported "caching it for 0s", which is not what happens - it is not cached at all. resolveTokenTTL now owns both the TTL and the explanation, naming DefaultACRTokenTTL where it is applied and logging the expired and unparseable cases distinctly. A test asserts the two messages differ. Signed-off-by: Charles Wu <yuewu2@microsoft.com>
Description
Follow-up to #2873 (request-path logging), covering the other half of the v2 logging gap: the Azure credential path is completely silent.
Compared to v1 there is no way to tell how ACR/AAD was accessed:
internal/cloudprovider/azure(token credential)successfully refreshed AAD token,successfully refreshed azure managed identity token)internal/store/credentialprovider/azure(ACR)Metrics Report: Duration=%dms, Host=%sCreateCredentialChainalso silently swallows both credential construction errors (if err == nil { append }with noelse), so when workload identity isn't configured the chain just quietly has fewer sources and a later registry 401 has no explanation.Change
internal/cloudprovider/azure/tokencredential.godebug: whether the workload identity / managed identity credential is available, and the reason when it is not (previously discarded), plus the resulting source count.appendCredentialhelper so both outcomes are unit-testable.debug: whether the identity binding credential (added by feat: add Dapr distributed cache provider #2870) is being used as the sole credential source, and the reason when it cannot be constructed. That branch previously returned without logging anything.internal/store/credentialprovider/azure/register.godebug: resolving an ACR credential for a server (with clientID/tenantID and whether identity binding is active), AAD token acquisition + duration, the ACR refresh token exchange + duration, and the resolved credential TTL.error: failure to build the credential chain, and failure to exchange the AAD token for an ACR refresh token.warn: when the refresh token's TTL cannot be determined.Logs use the request-scoped logger (
logger.GetLogger(ctx, logOpt), componentauthProvider) where a context is available, so they carry the trace ID. The credential-chain constructors have no context parameter, so they use the standard logger.No tokens or secrets are logged — only identity metadata (client/tenant ID, SNI name), durations, and TTL.
Bug fix: an expired ACR refresh token is no longer cached
Raised in review. Previously
parseJWTTokenTTLreturned a plain formatted error for both an unparseableexpand an already-expired token, and the caller appliedDefaultACRTokenTTL(~3h) in either case. For an expired token that meantCachedProviderstored a dead refresh token and served it for hours, producing persistent registry 401s until eviction.parseJWTTokenTTLnow returns a sentinelerrTokenExpired, and a newtokenCacheTTLhelper separates the two cases:expexpunparseableDefaultACRTokenTTL0CachedProvideronly caches whenTTL > 0)Testing
go build ./...,go vet, package tests andgolangci-lintpass.TestAppendCredential,TestTokenCacheTTL,TestTokenCacheTTL_ExpiredTokenIsNotCacheable.main;CreateCredentialChainis preserved as a thin wrapper overCreateCredentialChainWithIdentityBinding.Enable the new logs with
--set logger.level=debug(#2846).