diff --git a/docs/LOGGING.md b/docs/LOGGING.md index 92b86cf..1c06b4a 100644 --- a/docs/LOGGING.md +++ b/docs/LOGGING.md @@ -9,6 +9,7 @@ This reference defines safe event fields, request flow, and runtime differences. | Compare runtime output | [Runtime formats](#runtime-formats) | | Follow one request | [Event sequence](#event-sequence) | | Interpret IDs and fields | [Safe fields and identifiers](#safe-fields-and-identifiers) | +| Distinguish credential failures | [Credential diagnostics](#credential-diagnostics) | | Configure collection | [Levels and collection](#levels-and-collection) | **Exclude request bodies, decrypted fields, credentials, nonces, raw exceptions, and provider @@ -56,7 +57,8 @@ Failures emit `request_failed` with stage, reason, and HTTP status (`FailureStag `missing_provider_message_id`, or `invalid_provider_json`. `provider_response_processed` includes that classification, upstream HTTP status, and normalized status, never descriptions/bodies. Credential acquisition failures use `request_failed` with stage `provider_credentials`, reason -`credential_unavailable`, and HTTP `502`. There are no background credential-refresh events. +`credential_unavailable`, and HTTP `502`. A preceding `provider_credential_resolution_failed` +event supplies the [internal diagnostic](#credential-diagnostics). There are no background credential-refresh events. Unexpected failures use `unexpected_error`. No event adds credential reads, acquisition, or send retries. `response_prepared` runs before successful and failed returns. It does not prove caller receipt. @@ -67,6 +69,21 @@ An upstream `200` can precede a body-read timeout: `provider_response_received` Unknown status text and malformed JSON are never logged. Malformed JSON emits only `provider_response_invalid_json` before provider outcome rules run. +## Credential diagnostics + +The request-correlated `provider_credential_resolution_failed` event logs only `aadstsCode` +(`AadstsCode` in .NET), extracted from the SDK error message. It is one of the codes below or +null; raw error text, responses and credentials are never logged. Python/.NET use event ID +**1103** at Error level. Public HTTP responses and credential acquisition behavior are unchanged. + +| Code | Meaning and next check | +|---|---| +| [`AADSTS70025`](https://login.microsoftonline.com/error?code=70025) | No federated identity credentials configured for the client application. | +| [`AADSTS70021`](https://login.microsoftonline.com/error?code=70021) | No matching federation; check issuer, subject and audience. | +| [`AADSTS700016`](https://login.microsoftonline.com/error?code=700016) | Application not found in the requested directory; check app and tenant IDs. This alone does not prove missing provider consent. | + +The event does not identify which acquisition step failed or infer a root cause. + ## Safe fields and identifiers Build metadata from validated allowlisted fields. Exclude unknown, tenant, locale, risk, and diff --git a/docs/MONITORING.md b/docs/MONITORING.md index 74adc1a..4dc0e0e 100644 --- a/docs/MONITORING.md +++ b/docs/MONITORING.md @@ -173,6 +173,10 @@ Credential acquisition failures have `failureStage=provider_credentials` and or idle credential-health signal. A successful evaluation does not prove provider credentials work; validate that path separately through an approved live test. +The preceding `provider_credential_resolution_failed` event includes a safe `aadstsCode` +(`AadstsCode` in .NET). See [credential diagnostics](LOGGING.md#credential-diagnostics). +Do not count it and `request_failed` as two failed requests or enable raw SDK/body logging. + ## Runtime log formats diff --git a/dotnet/Functions/SendOtp.cs b/dotnet/Functions/SendOtp.cs index 767831b..13e098d 100644 --- a/dotnet/Functions/SendOtp.cs +++ b/dotnet/Functions/SendOtp.cs @@ -242,8 +242,9 @@ int Failure(int status, string stage, string reason) : "key_vault"); credential = await _credentials.GetCredentialsAsync(provider, config); } - catch + catch (Exception error) { + OtpLog.CredentialResolutionFailed(_log, CredentialTokenService.AadstsCode(error)); return Failure(502, "provider_credentials", "credential_unavailable"); } @@ -254,7 +255,10 @@ int Failure(int status, string stage, string reason) _ => true, }; if (credentialUnavailable) + { + OtpLog.CredentialResolutionFailed(_log, null); return Failure(502, "provider_credentials", "credential_unavailable"); + } OtpLog.CredentialResolved( _log, provider.Name, diff --git a/dotnet/Src/CredentialTokenService.cs b/dotnet/Src/CredentialTokenService.cs index 7c8352a..4b91015 100644 --- a/dotnet/Src/CredentialTokenService.cs +++ b/dotnet/Src/CredentialTokenService.cs @@ -1,3 +1,5 @@ +using System.Text.RegularExpressions; + namespace Epp.Otp; public sealed class CredentialTokenService @@ -24,13 +26,19 @@ public async Task GetCredentialsAsync( { throw; } - catch + catch (Exception error) { - // SendOtp logs the request failure without exposing SDK error details. - throw Unavailable(); + // Retain only an allowlisted code, never the SDK exception or response. + throw Unavailable(error); } } - internal static InvalidOperationException Unavailable() => - new("provider credential unavailable"); + internal static string? AadstsCode(Exception? error) + { + var match = Regex.Match(error?.Message ?? "", @"\bAADSTS(?:70025|70021|700016)\b"); + return match.Success ? match.Value : null; + } + + internal static InvalidOperationException Unavailable(Exception? error = null) => + new(AadstsCode(error) ?? "provider credential unavailable"); } diff --git a/dotnet/Src/OtpLog.cs b/dotnet/Src/OtpLog.cs index e937cd5..11ff614 100644 --- a/dotnet/Src/OtpLog.cs +++ b/dotnet/Src/OtpLog.cs @@ -48,6 +48,11 @@ internal static partial void CredentialResolutionStarted( internal static partial void CredentialResolved( ILogger logger, string providerName, long elapsedMs); + [LoggerMessage(EventId = 1103, EventName = "provider_credential_resolution_failed", Level = LogLevel.Error, + Message = "Provider credential resolution failed; AADSTS code: {AadstsCode}")] + internal static partial void CredentialResolutionFailed( + ILogger logger, string? aadstsCode); + [LoggerMessage(EventId = 1200, EventName = "provider_request_build_started", Level = LogLevel.Information, Message = "Building provider request")] internal static partial void ProviderRequestBuildStarted(ILogger logger); diff --git a/dotnet/tests/SendOtpTests.cs b/dotnet/tests/SendOtpTests.cs index 2780d5b..77bad85 100644 --- a/dotnet/tests/SendOtpTests.cs +++ b/dotnet/tests/SendOtpTests.cs @@ -837,6 +837,33 @@ public async Task FailuresEmitSeparateServiceEventsAndCompleteSummaries(string s Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); } + [Theory] + [InlineData("70025", "AADSTS70025")] + [InlineData("70021", "AADSTS70021")] + [InlineData("700016", "AADSTS700016")] + [InlineData("999999", null)] + [InlineData("700211", null)] + public async Task CredentialDiagnosticsPreservePublicResponseAndCorrelation(string code, string? expected) + { + using var rig = new HandlerRig(); + rig.OAuthError = new InvalidOperationException($"AADSTS{code}: PRIVATE-ASSERTION PRIVATE-TOKEN PRIVATE-RESPONSE"); + var response = await rig.Invoke(headers: new() { ["x-ms-client-request-id"] = "ms-request-id" }); + Assert.Equal(502, response.StatusCode); + var body = Assert.IsType(response.Value); + Assert.Equal("provider_delivery_failed", body.Error); + Assert.Equal(Correlation, body.CorrelationId); + var entry = rig.Log.Entry("provider_credential_resolution_failed"); + Assert.Equal(1103, entry.EventId.Id); + Assert.Equal(expected, entry.State["AadstsCode"]); + Assert.Equal(body.RequestId, entry.Scope["FunctionRequestId"]); + Assert.Equal(Correlation, entry.Scope["MsCorrelationId"]); + Assert.Equal("ms-request-id", entry.Scope["MsClientRequestId"]); + Assert.Equal("credential_unavailable", rig.Log.Entry("request_failed").State["FailureReason"]); + Assert.Equal(0, rig.Http.Calls); + Assert.DoesNotContain(rig.Log.Entries, value => value.EventId.Name == "provider_request_started"); + Assert.DoesNotContain("PRIVATE", JsonSerializer.Serialize(rig.Log.Entries) + JsonSerializer.Serialize(body)); + } + [Fact] public async Task SuccessfulLifecycleLogsAllowedBodyMetadataRawOAuthIdsAndEndpointWithoutQuery() { diff --git a/javascript/src/functions/SendOtp.js b/javascript/src/functions/SendOtp.js index 533efc5..9e9ba52 100644 --- a/javascript/src/functions/SendOtp.js +++ b/javascript/src/functions/SendOtp.js @@ -12,7 +12,7 @@ const { parseEntraPayload } = require('./entraPayload'); const { OtpDelivery } = require('./delivery'); const { decryptDeliveryContext } = require('./jwe'); const { selectProvider } = require('./providers'); -const { credentialTokenService } = require('./credentials'); +const { credentialTokenService, aadstsCode } = require('./credentials'); const { ProviderTransportError, isValidProviderUrl, @@ -169,7 +169,8 @@ app.http('SendOtp', { provider.credentialSpec, config, ); - } catch { + } catch (error) { + emit(logContext, 'provider_credential_resolution_failed', { aadstsCode: aadstsCode(error) }, 'error'); fail('provider_credentials', 'credential_unavailable', 502); return respond(502, { error: 'provider_delivery_failed', correlationId, requestId }); } @@ -179,6 +180,8 @@ app.http('SendOtp', { && (!credential.secret || (needsIdentity && !credential.identity))) || (credential.mode === 'oauth' && !credential.accessToken); if (credentialUnavailable) { + emit(logContext, 'provider_credential_resolution_failed', + { aadstsCode: null }, 'error'); fail('provider_credentials', 'credential_unavailable', 502); return respond(502, { error: 'provider_delivery_failed', correlationId, requestId }); } diff --git a/javascript/src/functions/credentials.js b/javascript/src/functions/credentials.js index 9e124ff..e5193a3 100644 --- a/javascript/src/functions/credentials.js +++ b/javascript/src/functions/credentials.js @@ -13,12 +13,17 @@ const OAUTH_MODE = 'oauth'; const TOKEN_EXCHANGE_SCOPE = 'api://AzureADTokenExchange/.default'; const ACQUISITION_TIMEOUT_MS = 2500; const TOKEN_SKEW_MS = 30000; -const unavailable = () => new Error('provider credential unavailable'); +const unavailable = (error) => new Error(aadstsCode(error) || 'provider credential unavailable'); /** @type {AsyncLocalStorage} */ const acquisition = new AsyncLocalStorage(); /** @type {typeof AzureLogger.log | undefined} */ let filteredLogger; +function aadstsCode(error) { + return typeof error?.message === 'string' + ? error.message.match(/\bAADSTS(?:70025|70021|700016)\b/)?.[0] ?? null : null; +} + // The installed identity SDK does not propagate every getToken abort signal to HTTP. /** @returns {import('@azure/core-rest-pipeline').HttpClient} */ function credentialHttpClient() { @@ -138,10 +143,10 @@ class CredentialTokenService { throw unavailable(); }), interrupted, - ])).catch(() => { + ])).catch((error) => { controller.abort(); - // The handler logs a request-correlated failure without SDK error details. - throw unavailable(); + // Retain only an allowlisted code, never the SDK exception or response. + throw unavailable(error); }).finally(() => { clearTimeout(timeout); this.controllers.delete(controller); @@ -160,4 +165,5 @@ const credentialTokenService = new CredentialTokenService(); module.exports = { CredentialTokenService, credentialTokenService, + aadstsCode, }; diff --git a/javascript/test/sendotp.test.js b/javascript/test/sendotp.test.js index 07485ef..bae3c67 100644 --- a/javascript/test/sendotp.test.js +++ b/javascript/test/sendotp.test.js @@ -357,6 +357,35 @@ test('a credential failure is request-correlated and the next live request can r assert.equal(fetchMock.mock.callCount(), 1); }); +for (const [code, expected] of [ + ['70025', 'AADSTS70025'], ['70021', 'AADSTS70021'], ['700016', 'AADSTS700016'], + ['999999', null], ['700211', null], +]) { + test(`AADSTS${code} changes only internal correlated logs, not the public credential-failure response`, async () => { + getToken.mock.mockImplementation(async function () { + await this.getAssertion(); + throw new Error(`AADSTS${code}: PRIVATE-ASSERTION PRIVATE-TOKEN PRIVATE-RESPONSE`); + }); + const response = await invoke(await envelope(), { 'x-ms-client-request-id': 'ms-request-id' }); + const diagnostic = event('provider_credential_resolution_failed'); + assert.deepEqual(response.jsonBody, { + error: 'provider_delivery_failed', correlationId: 'correlation-id', + requestId: diagnostic.functionRequestId, + }); + assert.equal(response.status, 502); + assert.equal(diagnostic.aadstsCode, expected); + assert.doesNotMatch(JSON.stringify(records) + JSON.stringify(response.jsonBody), /PRIVATE/); + assert.equal(diagnostic['x-ms-client-request-id'], 'ms-request-id'); + assert.equal(diagnostic['x-ms-correlation-id'], 'correlation-id'); + assert.equal(records.filter((entry) => entry.eventName === 'provider_credential_resolution_failed').length, 1); + assert.equal(event('request_failed').failureReason, 'credential_unavailable'); + assert.equal(fetchMock.mock.callCount(), 0); + assert.equal(event('provider_request_started'), undefined); + assert.equal((await invoke(await envelope({ mode: 2 }))).status, 200); + assert.equal(event('provider_credential_resolution_failed'), undefined); + }); +} + test('startup does not warm credentials and shutdown closes pending acquisition', async () => { assert.equal(startHook, undefined); assert.equal(getToken.mock.callCount(), 0); diff --git a/python/function_app.py b/python/function_app.py index a17caea..57d0031 100644 --- a/python/function_app.py +++ b/python/function_app.py @@ -9,7 +9,7 @@ from src import otp_log from src.config import read_config -from src.credentials import CredentialTokenService +from src.credentials import CredentialTokenService, aadsts_code from src.jwe import JweDecryptor from src.models import EntraSendOtpPayload, OtpDelivery from src.provider import ( @@ -82,7 +82,8 @@ def _send_to_provider(delivery, log): try: otp_log.credential_resolution_started(log, provider.name, credential_source) credential = _credentials.get_credentials(provider, config) - except Exception: + except Exception as error: + otp_log.credential_resolution_failed(log, aadsts_code(error)) return _failure(log, 502, "provider_credentials", "credential_unavailable"), log otp_log.credential_resolved( log, provider.name, int((time.monotonic() - credential_started) * 1000)) diff --git a/python/src/credentials.py b/python/src/credentials.py index a6ce659..de06497 100644 --- a/python/src/credentials.py +++ b/python/src/credentials.py @@ -2,6 +2,7 @@ import logging import math +import re import threading import time from collections.abc import Callable, Mapping @@ -24,6 +25,11 @@ T = TypeVar("T") +def aadsts_code(error: Exception) -> str | None: + match = re.search(r"\bAADSTS(?:70025|70021|700016)\b", str(error)) + return match[0] if match else None + + class Token(Protocol): @property def token(self) -> str: ... @@ -91,26 +97,26 @@ def resolve(self, spec: Mapping[str, str], config: AppConfig) -> ApiKeyCredentia threading.Thread(target=self._run, args=(spec, config, pending), daemon=True).start() try: return pending.result(timeout=self._wait_timeout) - except Exception: + except Exception as error: with self._lock: pending.cancel() - # The handler logs the failure without exposing SDK error details. - raise ValueError(CREDENTIAL_ERROR) from None + raise ValueError(aadsts_code(error) or CREDENTIAL_ERROR) from None def _run(self, spec: Mapping[str, str], config: AppConfig, pending: Future[ApiKeyCredential | OAuthCredential]) -> None: value = None + failure = CREDENTIAL_ERROR try: value = _private_acquisition( lambda: self._fetch_api_key(spec) if spec["mode"] == API_KEY_MODE else self._fetch_token(config)) - except Exception: - # Publish only the sanitized error to the waiting request. - value = None + except Exception as error: + # Retain only an allowlisted code, never the SDK exception or response. + failure = aadsts_code(error) or CREDENTIAL_ERROR with self._lock: self._requests.discard(pending) if not pending.done(): if value is None: - pending.set_exception(ValueError(CREDENTIAL_ERROR)) + pending.set_exception(ValueError(failure)) else: pending.set_result(value) close_clients = self._closed and not self._requests @@ -126,8 +132,8 @@ def read() -> None: if self._closed: raise ValueError(CREDENTIAL_ERROR) result.set_result(_private_acquisition(lambda: self._secrets.resolve(name))) - except Exception: - result.set_exception(ValueError(CREDENTIAL_ERROR)) + except Exception as error: + result.set_exception(ValueError(aadsts_code(error) or CREDENTIAL_ERROR)) # Executor threads are joined at exit; unfinished SDK reads must not block shutdown. threading.Thread(target=read, daemon=True).start() diff --git a/python/src/otp_log.py b/python/src/otp_log.py index dd6ba14..3422772 100644 --- a/python/src/otp_log.py +++ b/python/src/otp_log.py @@ -63,6 +63,11 @@ def credential_resolved(log, provider_name, elapsed_ms): providerName=provider_name, elapsedMs=elapsed_ms) +def credential_resolution_failed(log, aadsts_code): + _emit(log, 1103, "provider_credential_resolution_failed", "Provider credential resolution failed", + level=logging.ERROR, aadstsCode=aadsts_code) + + def provider_request_build_started(log): _emit(log, 1200, "provider_request_build_started", "Building provider request") diff --git a/python/tests/test_credentials.py b/python/tests/test_credentials.py index 2fb2a5a..f99a554 100644 --- a/python/tests/test_credentials.py +++ b/python/tests/test_credentials.py @@ -38,12 +38,15 @@ def token(value): return SimpleNamespace(token=value, expires_on=NOW + 3600) -def test_api_keys_are_read_per_request_without_warmup_stale_fallback_or_failure_cooldown(monkeypatch): +@pytest.mark.parametrize("message,expected", [ + ("PRIVATE-FAILURE", "provider credential unavailable"), ("AADSTS70025: PRIVATE-FAILURE", "AADSTS70025"), +]) +def test_api_keys_are_read_per_request_without_warmup_stale_fallback_or_failure_cooldown(monkeypatch, message, expected): version, fail = 1, False def read(name): if fail and name == "id": - raise ValueError("PRIVATE-FAILURE") + raise ValueError(message) return f"{name}-{version}" monkeypatch.setattr(credentials_module, "ClientAssertionCredential", @@ -56,7 +59,7 @@ def read(name): version = 2 assert manager.resolve(AUTH, CONFIG) == {"mode": "apiKey", "secret": "key-2", "identity": "id-2"} fail = True - with pytest.raises(ValueError, match="^provider credential unavailable$"): + with pytest.raises(ValueError, match=f"^{expected}$"): manager.resolve(AUTH, CONFIG) fail, version = False, 3 assert manager.resolve(AUTH, CONFIG)["identity"] == "id-3" @@ -165,17 +168,24 @@ def get_token_info(scope): identity.close.assert_called_once() -def test_oauth_failure_can_retry_immediately_using_the_same_sdk_client(monkeypatch): +@pytest.mark.parametrize("message,expected", [ + ("PRIVATE-SDK-FAILURE", "provider credential unavailable"), + ("AADSTS70025: PRIVATE-SDK-FAILURE", "AADSTS70025"), + ("AADSTS70021: PRIVATE-SDK-FAILURE", "AADSTS70021"), + ("AADSTS700016: PRIVATE-SDK-FAILURE", "AADSTS700016"), + ("AADSTS999999: PRIVATE-SDK-FAILURE", "provider credential unavailable"), +]) +def test_oauth_failure_can_retry_immediately_using_the_same_sdk_client(monkeypatch, message, expected): identity = Mock(spec=["get_token", "close"]) credential = Mock(spec=["get_token", "close"], get_token=Mock(side_effect=[ - ValueError("PRIVATE-SDK-FAILURE"), token("PRIVATE-TOKEN"), + ValueError(message), token("PRIVATE-TOKEN"), ])) monkeypatch.setattr(credentials_module, "ManagedIdentityCredential", Mock(return_value=identity)) create = Mock(return_value=credential) monkeypatch.setattr(credentials_module, "ClientAssertionCredential", create) manager = CredentialTokenService(Mock(), clock=lambda: NOW) try: - with pytest.raises(ValueError, match="^provider credential unavailable$"): + with pytest.raises(ValueError, match=f"^{expected}$"): manager.resolve({"mode": "oauth"}, OAUTH) assert manager.resolve({"mode": "oauth"}, OAUTH)["access_token"] == "PRIVATE-TOKEN" create.assert_called_once() diff --git a/python/tests/test_function_app.py b/python/tests/test_function_app.py index e3c7ccd..9e6a13a 100644 --- a/python/tests/test_function_app.py +++ b/python/tests/test_function_app.py @@ -575,6 +575,35 @@ def test_selection_and_credential_failures_are_safe( assert "PRIVATE" not in caplog.text +@pytest.mark.parametrize("code,expected", [ + ("70025", "AADSTS70025"), ("70021", "AADSTS70021"), ("700016", "AADSTS700016"), + ("999999", None), ("700211", None), +]) +def test_credential_diagnostic_preserves_public_response_and_correlation(caplog, code, expected): + caplog.set_level(logging.INFO) + function_app._credentials.get_credentials.side_effect = ValueError( + f"AADSTS{code}: PRIVATE-ASSERTION PRIVATE-TOKEN PRIVATE-RESPONSE") + response = _HANDLER(_request(_envelope(), {"x-ms-client-request-id": "ms-request-id"})) + diagnostic, = (record for record in _events(caplog) if record.event_name == "provider_credential_resolution_failed") + assert response.status_code == 502 + assert json.loads(response.get_body()) == { + "error": "provider_delivery_failed", "correlationId": _CORRELATION, + "requestId": diagnostic.functionRequestId, + } + assert diagnostic.event_id == 1103 + assert diagnostic.aadstsCode == expected + assert diagnostic.__dict__["x-ms-client-request-id"] == "ms-request-id" + assert diagnostic.__dict__["x-ms-correlation-id"] == _CORRELATION + failure, = (record for record in _events(caplog) if record.event_name == "request_failed") + assert failure.failureReason == "credential_unavailable" + assert not any(record.event_name == "provider_request_started" for record in _events(caplog)) + provider_module.requests.request.assert_not_called() + assert "PRIVATE" not in str([record.__dict__ for record in caplog.records]) + caplog.clear() + assert _HANDLER(_request(_envelope(mode=2))).status_code == 200 + assert not any(record.event_name == "provider_credential_resolution_failed" for record in _events(caplog)) + + def test_request_context_is_isolated_between_concurrent_invocations(monkeypatch, caplog): caplog.set_level(logging.INFO) monkeypatch.setattr(provider_module.requests, "request", Mock(