Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 18 additions & 1 deletion docs/LOGGING.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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.
Expand All @@ -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
Expand Down
4 changes: 4 additions & 0 deletions docs/MONITORING.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.

<a id="runtime-specific-log-discovery"></a>
## Runtime log formats

Expand Down
6 changes: 5 additions & 1 deletion dotnet/Functions/SendOtp.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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");
}

Expand All @@ -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,
Expand Down
18 changes: 13 additions & 5 deletions dotnet/Src/CredentialTokenService.cs
Original file line number Diff line number Diff line change
@@ -1,3 +1,5 @@
using System.Text.RegularExpressions;

namespace Epp.Otp;

public sealed class CredentialTokenService
Expand All @@ -24,13 +26,19 @@ public async Task<ProviderCredentials> 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");
}
5 changes: 5 additions & 0 deletions dotnet/Src/OtpLog.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
27 changes: 27 additions & 0 deletions dotnet/tests/SendOtpTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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<EndpointErrorResponse>(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()
{
Expand Down
7 changes: 5 additions & 2 deletions javascript/src/functions/SendOtp.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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 });
}
Expand All @@ -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 });
}
Expand Down
14 changes: 10 additions & 4 deletions javascript/src/functions/credentials.js
Original file line number Diff line number Diff line change
Expand Up @@ -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<AbortSignal>} */
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() {
Expand Down Expand Up @@ -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);
Expand All @@ -160,4 +165,5 @@ const credentialTokenService = new CredentialTokenService();
module.exports = {
CredentialTokenService,
credentialTokenService,
aadstsCode,
};
29 changes: 29 additions & 0 deletions javascript/test/sendotp.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
5 changes: 3 additions & 2 deletions python/function_app.py
Original file line number Diff line number Diff line change
Expand Up @@ -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 (
Expand Down Expand Up @@ -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))
Expand Down
24 changes: 15 additions & 9 deletions python/src/credentials.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

import logging
import math
import re
import threading
import time
from collections.abc import Callable, Mapping
Expand All @@ -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: ...
Expand Down Expand Up @@ -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
Expand All @@ -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()
Expand Down
5 changes: 5 additions & 0 deletions python/src/otp_log.py
Original file line number Diff line number Diff line change
Expand Up @@ -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")

Expand Down
Loading
Loading