From 9e7fba8857cded0ad4a88133c67889a1d7c86fb6 Mon Sep 17 00:00:00 2001 From: James Xian Date: Mon, 21 Sep 2026 12:00:27 -0700 Subject: [PATCH] Add structured request lifecycle logging across runtimes Emit separate service events and complete per-request summaries. Preserve raw Microsoft and provider support IDs, omit invalid identifier metadata, and remove credentials, query strings and fragments from endpoint logs. Add shared logging contract coverage and documentation. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- README.md | 6 +- docs/CONTRACT.md | 142 +++++++- docs/ONBOARDING.md | 12 + dotnet/Functions/SendOtp.cs | 45 ++- dotnet/Program.cs | 2 +- dotnet/README.md | 1 + dotnet/Src/DispatchEngine.cs | 98 ++++-- dotnet/Src/RequestLog.cs | 266 +++++++++++++++ dotnet/tests/EngineTests.cs | 449 ++++++++++++++++++++++++- javascript/README.md | 1 + javascript/src/functions/SendOtp.js | 39 ++- javascript/src/functions/dispatch.js | 57 +++- javascript/src/functions/requestLog.js | 234 +++++++++++++ javascript/test/sendotp.test.js | 337 ++++++++++++++++++- python/README.md | 1 + python/function_app.py | 40 ++- python/src/dispatch.py | 82 ++++- python/src/request_log.py | 210 ++++++++++++ python/tests/test_function_app.py | 349 ++++++++++++++++++- tests/fixtures/contract.json | 62 ++++ 20 files changed, 2287 insertions(+), 146 deletions(-) create mode 100644 dotnet/Src/RequestLog.cs create mode 100644 javascript/src/functions/requestLog.js create mode 100644 python/src/request_log.py diff --git a/README.md b/README.md index 32654a7..de359b1 100644 --- a/README.md +++ b/README.md @@ -224,7 +224,9 @@ omits that header on live sends and does not forward it from incoming requests. lookup entirely, rather than invoking Telesign shutter mode. Responses normalize `reference_id` and `status.code`/`status.description` internally; provider -metadata is not logged or exposed in the public nonce response. Existing numeric success codes +metadata is not exposed in the public nonce response. [Application logs](docs/CONTRACT.md#application-logs) +include only the provider HTTP status, mapped status/outcome and the bounded raw provider reference +ID as `providerMessageId` for support lookup, never the raw response or description. Existing numeric success codes are retained (SMS: 200, 203, 290-292; Voice: 100-103). EPP code `3001` ("Message in progress"), observed for both channels, is also accepted on successful HTTP responses. This acknowledges provider acceptance, not handset receipt or completed audio playback. The supplied EPP integration @@ -255,6 +257,8 @@ authentication; [separate deployed security checks](docs/ONBOARDING.md#4-package - **[docs/ONBOARDING.md](docs/ONBOARDING.md)**: customer setup, security, deployment, and validation. - **[docs/CONTRACT.md](docs/CONTRACT.md)**: the language-agnostic contract every implementation follows. +- **[Application logs](docs/CONTRACT.md#application-logs)**: separate service events, per-request summaries, + and the meaning of Microsoft, Function and provider identifier fields. ## Contributing a language or provider diff --git a/docs/CONTRACT.md b/docs/CONTRACT.md index e29a002..271b202 100644 --- a/docs/CONTRACT.md +++ b/docs/CONTRACT.md @@ -226,8 +226,11 @@ or string-key response dictionaries. Optional values default to null/None; a sta over a code during outcome mapping, as before. Custom Python adapters must return `ParsedResponse`, not the former dictionary. -This model is internal: do not serialize it into the endpoint response or log its fields. Public HTTP -responses still expose only the existing nonce/correlation/status or sanitized error contract. +This model is internal: do not serialize it into the endpoint response or logs. The +[request logger](#application-logs) selects only the provider HTTP status, a status found in the +adapter's mapping, the mapped outcome and a bounded raw provider message ID; descriptions and raw +metadata remain private. Public HTTP responses still expose only the existing +nonce/correlation/status or sanitized error contract. Provider requests are serialized only when building the outbound HTTP body; incoming provider JSON is parsed once and normalized inside its adapter. No serialization framework or provider-specific class hierarchy is required. @@ -326,13 +329,13 @@ subscription activation and changing tenant policy belong to provisioning, not t - **Managed identity**: Key Vault access via managed identity only (user-assigned if `AZURE_CLIENT_ID` set, else system-assigned). No static credentials. - **Privacy**: never log phone numbers, passcodes, nonce values, bearer tokens, API keys, JWE headers/payloads, - raw exceptions or provider responses. There is no plaintext diagnostic override. Each handler - writes one summary with a generated request ID, the first 16 lowercase hex characters of the - correlation ID's SHA256 hash, HTTP status, - elapsed milliseconds and evaluation flag. Original wire correlation IDs and the required nonce - echo remain unchanged. Hashes are pseudonymous, not anonymous; restrict log access and retention. - A configured encryption-key-ID mismatch adds a fixed warning, never either key ID or the JWE header. - Disable SDK, platform and proxy body tracing separately. + raw exceptions, provider descriptions/responses or endpoint query strings. There is no plaintext diagnostic + override. Each handler emits separate service events and one [request summary](#application-logs), + with generated Function IDs distinguished from raw Microsoft/provider support IDs. Original wire IDs + and the required nonce echo remain unchanged. Support IDs can correlate customer activity; restrict + log access and retention. Endpoint logs contain only scheme, host/port and API path, never userinfo, + query strings or fragments. A configured encryption-key-ID mismatch adds a correlated fixed warning, + never either key ID or the JWE header. Disable SDK, platform and proxy body tracing separately. - **Platform authentication only**: enable Easy Auth with `requireAuthentication=true`, `unauthenticatedClientAction=Return401` and `requireHttps=true`. Configure the trusted tenant issuer and `allowedAudiences` for the endpoint app, plus a **nonempty `allowedApplications`** list pinned to @@ -348,6 +351,123 @@ subscription activation and changing tenant policy belong to provisioning, not t therefore does not guarantee a 3.2-second end-to-end response, especially on cold starts. A timed-out POST may already have been accepted; avoid blind retries that duplicate messages. +### Application logs + +All three implementations emit JSON records with the same field names. .NET also supplies these +fields as structured `ILogger` state. Service events have `logType: "service"` and an individual +`eventName`: they are emitted as the work happens, **not buffered or combined into a multi-step log**. +Each handler invocation ends with exactly one `logType: "request"`, `eventName: "request_completed"` +summary, including validation failures, evaluation and provider failures. + +A successful live request emits these separate service events, followed by the request summary: + +| Service event | Safe information recorded | +|---|---| +| `request_received` | Function invocation and available raw Microsoft trace IDs under their `x-ms-*` names; no raw body or arbitrary headers. | +| `envelope_validated` | Allowlisted body metadata: validated `envelopeType`, normalized `channel`, `evaluation`, optional `ttlSeconds`, and `encryptedDeliveryContextPresent: true`. | +| `delivery_context_decrypted` | Decryption completed; no plaintext fields, JWE or key ID. | +| `provider_selected` | Registered provider and its authentication mode. | +| `provider_credential_resolution_started` | OAuth client-assertion or Key Vault credential source, with explicitly named raw OAuth application/identity/tenant IDs. | +| `provider_credential_resolved` | Credential resolution and usability checks completed, with elapsed time; no secret, token, assertion or claims. | +| `provider_request_build_started` | The adapter is preparing the outbound request. | +| `provider_request_built` | Allowlisted HTTP method, final endpoint scheme/host/port/API path, HTTPS and disabled redirects; no query string, authorization headers or body. | +| `provider_request_started` | The outbound send is beginning, with method, sanitized endpoint and timeout. | +| `provider_response_received` | Actual upstream HTTP status; emitted before response-body reading completes. | +| `provider_response_processed` | Mapped provider status/outcome, raw provider message/reference ID, duration and resulting Function HTTP status. | +| `response_prepared` | Response status and booleans indicating nonce/correlation inclusion, not their values or the response body. | + +Body metadata is built from validated fields, **not** from a body dump with a few sensitive +properties removed. Unknown request properties, `tenantId`, locale/risk data and all decrypted +fields remain excluded. An invalid envelope never contributes unvalidated type or TTL values. + +`providerCredentialSource` is `managed_identity_client_assertion` for the app-token path and +`key_vault` for API-key providers. Resolution may use cached credentials: these events do not claim +a Key Vault network fetch or a fresh identity/token exchange occurred. `providerCredentialElapsedMs` +covers resolution plus the existing credential checks, not a separately enforced deadline. SDK +diagnostics remain suppressed as before; logging adds no token acquisition, secret reads or retries. + +`provider_request_built` describes the adapter request, not creation of a new physical HTTP connection +or a new HTTP client in every runtime. `providerEndpoint` uses the **final** adapter URL, which can +differ from the configured base URL, but records only scheme + host/port + API path. For example, +`https://provider.example/epp/voice?key=secret` is logged as `https://provider.example/epp/voice`. +Userinfo, the entire query string and fragments are excluded. Use provider-approved paths that do +not embed secrets or personal data; path segments are not redacted. This does not alter the outbound +URL or its required query parameters. Standard HTTP verbs are logged in uppercase; custom or invalid +values are represented as `other` without changing the request sent. + +`response_prepared` is emitted on success **and failure** immediately before returning the handler +response. It does not claim the host has serialized/transmitted that response or Microsoft received +it; consult platform request telemetry for transport completion. Evaluation emits +`evaluation_completed` instead of provider events, then `response_prepared` and the summary, +without resolving provider configuration, credentials or HTTP. Failures emit their own stage event, +such as `decryption_failed`, `provider_credentials_failed` or `provider_transport_failed`. +A parsed provider rejection uses `provider_response_processed` with its non-success outcome and +fixed failure reason. + +Every service event carries the Function request/invocation IDs, the Microsoft trace IDs available +at that point, and the known channel, evaluation flag and selected provider. The initial event can +only know header trace IDs; a valid envelope can subsequently supply the selected correlation. +The generated Function request ID joins these events even when Microsoft IDs are absent or change +from header to envelope. The identifiers are intentionally not named simply `requestId` or +`correlationId` in logs: + +| Log field | Source and meaning | +|---|---| +| `functionName` | Runtime function name: `SendOtp` in JavaScript/.NET, `send_otp` in Python. The HTTP route remains `/api/SendOtp` in every runtime. | +| `functionRequestId` | Generated by this handler. Matches `requestId` in failure responses; it is not Microsoft's request ID. | +| `functionInvocationId` | Azure Functions host invocation ID. Null for direct handler calls without a host context. | +| `x-ms-client-request-id` | Raw Microsoft per-attempt ID from the header of the same name, not the generated fallback used by dispatch. | +| `x-ms-correlation-id` | Raw selected Microsoft correlation: envelope `correlationId` first, then the header of the same name. The existing precedence is unchanged, and this never contains a generated Function ID. | +| `msCorrelationIdSource` | `envelope`, `header` or `none`; disambiguates the selected value when the envelope and header differ. | +| `providerMessageId` | Raw adapter-normalized message/reference ID returned by the provider, including Telesign `reference_id`, for support lookup. Not filled from dispatch or Function IDs, although a provider may echo an ID it received. | +| `providerTenantId` | Raw configured `EPP_PROVIDER_TENANT_ID` for OAuth, not incoming envelope `tenantId`. | +| `functionOutboundClientId` | Raw application's `EPP_OUTBOUND_CLIENT_ID` used for provider access, not the endpoint application's inbound audience or a Microsoft request ID. | +| `functionOutboundManagedIdentityClientId` | Raw configured `EPP_OUTBOUND_MI_CLIENT_ID` used to obtain the app assertion, not the Key Vault identity or the identity's principal/Object ID. | +| `providerEndpoint` | Validated final outbound URL without userinfo, query string or fragment; scheme, host/port and API path remain visible. | + +The six external/configuration ID fields preserve their raw values and case for cross-system support +lookup; they are not hashed or truncated. To avoid dumping arbitrary text, only nonblank strings +of 1-128 ASCII characters are recorded: the first character must be a letter or digit, followed by +letters, digits, `.`, `_`, `:`, or `-`. This includes GUIDs, hex IDs and ordinary opaque references. +Missing/blank values are null; other invalid values are null and their field names appear in +`omittedIdFields`, never the rejected values. These guards affect logs only, not wire IDs or outcomes. +Application/client/tenant IDs are identifiers, not client secrets or bearer tokens. +These are tracing fields, not authentication assertions. In particular, an incoming `tenantId` +does not become a trusted tenant identity in logs. The existing wire correlation precedence, +provider request IDs and public responses are unchanged. + +The request summary contains: + +| Fields | Purpose | +|---|---| +| `httpStatus`, `result`, `elapsedMs` | Final Function response, `accepted` / `evaluated` / `failed`, and total handler time in milliseconds. Acceptance is not handset delivery. | +| `envelopeType`, `channel`, `evaluation`, `ttlSeconds` | Allowlisted request-body metadata; null until envelope validation succeeds. Omitted TTL remains null; logging does not introduce expiry enforcement. | +| `providerName`, `providerAuthMode`, `providerAttempted` | Registered adapter ID, its `apiKey` / `oauth` mode, and whether provider HTTP was attempted. Unknown configured names and credentials are never echoed. | +| `providerCredentialSource`, `providerCredentialElapsedMs` | Credential resolution path and duration, including failed resolution; null if it never started. | +| `providerTenantId`, `functionOutboundClientId`, `functionOutboundManagedIdentityClientId` | Raw configured OAuth identity IDs; null when OAuth resolution was not attempted. | +| `providerHttpMethod`, `providerEndpoint` | Final adapter request method and scheme/host/port/API path, set only after request construction and URL validation. No query string. | +| `providerHttpStatus`, `providerStatus`, `providerOutcome` | Actual upstream HTTP status and normalized response mapping. Status is logged only if it is an explicit adapter mapping key (not `default`); otherwise it is `unmapped`. | +| `providerMessageId` | Raw provider lookup/reference ID for support escalation. | +| `providerElapsedMs`, `providerTimeoutMs` | Outbound request duration including response-body reading, and the configured/clamped HTTP timeout. Neither is an end-to-end deadline. | +| `failureStage`, `failureReason` | Stage and fixed diagnostic reason, such as `provider_credentials` / `credential_unavailable`, `provider_transport` / `provider_timeout`, or `provider_response` / `provider_rejected`. No exception messages. | +| `encryptionKeyIdMismatch` | Whether the advisory warning was emitted; never the configured or received key ID. | +| `responseContainsNonce`, `responseContainsCorrelationId` | Whether those fields are in the prepared response, without recording their values. Null if no response was prepared. | +| `omittedIdFields` | Names of support ID fields whose current values failed the logging format/length guard; empty for ordinary valid IDs. | + +Provider fields remain null when their stage was not reached. `providerHttpStatus` is captured as +soon as headers arrive, so a response-body timeout can legitimately show upstream `200` alongside +Function `httpStatus: 504`, without a mapped provider status or success acknowledgement. Unknown +provider status text and malformed JSON are never logged; malformed JSON emits only +`provider_response_invalid_json` before the existing adapter outcome rules run. + +Normal events and request summaries use Information; invalid requests, non-success 4xx outcomes and +advisory warnings use Warning; 5xx failures and timeouts use Error. Keep application Information logs +enabled when investigating. This contract describes **emission**, not guaranteed collection: +host/telemetry filters and sampling can drop trace records. Application summaries are logs, not +the host's Request telemetry type, so excluding `Request` from sampling does not by itself retain +every summary. Configure collection and retention deliberately without enabling SDK/body tracing. +Easy Auth rejections occur before the handler and appear in platform telemetry, not these events. + --- ## 6. Lightweight tests @@ -358,7 +478,9 @@ Each language keeps lightweight offline tests covering representative applicatio - Fail-closed outcomes, missing credentials, HTTPS guards and timeouts. - Envelope validation and real JWE decryption/tamper rejection. - Evaluation without provider I/O. -- Awaited delivery, nonce acknowledgement and privacy-safe logging. +- Awaited delivery, nonce acknowledgement and privacy-safe logging, including the shared + service-event order and summary field set in [contract.json](../tests/fixtures/contract.json), + identifier provenance, error paths, provider-body timeouts and concurrent request isolation. The sample deliberately omits exhaustive input permutations and SDK internals. These tests use local keys and mocked external services; they do not send SMS and **do not test Easy Auth or platform diff --git a/docs/ONBOARDING.md b/docs/ONBOARDING.md index e8418d6..4cfe1b7 100644 --- a/docs/ONBOARDING.md +++ b/docs/ONBOARDING.md @@ -163,3 +163,15 @@ Use [CONTRACT.md](CONTRACT.md) for the full request contract and production limi or raw provider responses in reports. Keep platform/SDK body tracing off. Repeat the deployed checks after deployment, authentication changes, and slot swaps. Local evaluation and passing unit tests do not certify platform authentication or live delivery. + + For diagnostics, find the `logType: "request"` summary and join its separate service events by + `functionRequestId`. Inspect `failureStage`, `failureReason`, `httpStatus` and `providerHttpStatus` + rather than enabling payload tracing. Raw Microsoft `x-ms-client-request-id` / `x-ms-correlation-id`, + provider `providerMessageId`, and host `functionInvocationId` have different sources; see + [application logs](CONTRACT.md#application-logs) for their meanings and collection/sampling caveats. + The service events show safe envelope metadata, the OAuth-app or Key Vault credential path, + request construction, provider send/response, and `response_prepared`. The latter records status + and whether the response contains nonce/correlation fields, not their values; it is not proof the + caller received the response. Credential resolution can use caches. `providerEndpoint` contains the + base URL and API path only, without query strings, userinfo or fragments; support IDs remain raw + so customers can share the exact reference with Microsoft/provider support. diff --git a/dotnet/Functions/SendOtp.cs b/dotnet/Functions/SendOtp.cs index 4c3bc4e..df9c65e 100644 --- a/dotnet/Functions/SendOtp.cs +++ b/dotnet/Functions/SendOtp.cs @@ -1,6 +1,3 @@ -using System.Diagnostics; -using System.Security.Cryptography; -using System.Text; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; using Microsoft.Azure.Functions.Worker; @@ -8,7 +5,7 @@ namespace Epp.Otp; -// Echo the nonce only on acceptance; log one PII-safe summary per invocation. +// Echo the nonce only on acceptance; keep service events and the request summary PII-safe. public sealed class SendOtp { private readonly DispatchEngine _engine; @@ -27,32 +24,43 @@ public SendOtp(DispatchEngine engine, JweDecryptor decryptor, IEnv env, ILogger< // Anonymous at the Functions layer; EasyAuth must remain enabled and require authentication in the cloud. [Function("SendOtp")] public async Task Run( - [HttpTrigger(AuthorizationLevel.Anonymous, "post", Route = "SendOtp")] HttpRequest req) + [HttpTrigger(AuthorizationLevel.Anonymous, "post", Route = "SendOtp")] HttpRequest req, + FunctionContext? functionContext = null) { - var started = Stopwatch.StartNew(); var requestId = Guid.NewGuid().ToString("n"); - var correlationId = requestId; + var msRequestId = req.Headers["x-ms-client-request-id"].FirstOrDefault(); + var headerCorrelationId = req.Headers["x-ms-correlation-id"].FirstOrDefault(); + var log = new RequestLog(_log, requestId, functionContext?.InvocationId, msRequestId, headerCorrelationId); + var correlationId = headerCorrelationId ?? requestId; var httpStatus = 500; var evaluation = false; ObjectResult Reply(int status, object body) { + var response = new ObjectResult(body) { StatusCode = status }; httpStatus = status; - return new ObjectResult(body) { StatusCode = status }; + log.ResponsePrepared(status, body is EndpointSuccessResponse, + body is EndpointSuccessResponse or EndpointErrorResponse { CorrelationId: not null }); + return response; } try { + log.Service("request_received"); var config = AppConfig.Read(_env); - var clientRequestId = req.Headers["x-ms-client-request-id"].FirstOrDefault() ?? requestId; - correlationId = req.Headers["x-ms-correlation-id"].FirstOrDefault() ?? requestId; + var clientRequestId = msRequestId ?? requestId; var (envelope, envelopeError) = await EnvelopeParser.ParseAsync(req.Body, req.HttpContext.RequestAborted); if (envelopeError is not null) + { + log.Failure("request_validation", envelopeError, 400); return Reply(400, new EndpointErrorResponse("bad_request", requestId, Reason: envelopeError)); + } correlationId = envelope!.CorrelationId ?? correlationId; evaluation = envelope.Mode == EnvelopeParser.ModeEvaluation; + log.EnvelopeValidated(envelope, envelope.CorrelationId ?? headerCorrelationId, + envelope.CorrelationId is not null ? "envelope" : "header"); JweResult decrypted; try @@ -61,20 +69,28 @@ ObjectResult Reply(int status, object body) } catch { + log.Failure("decryption", "decryption_failed", 400); return Reply(400, new EndpointErrorResponse("decryption_failed", requestId, CorrelationId: correlationId)); } + log.Service("delivery_context_decrypted"); if (!string.IsNullOrEmpty(config.ExpectedKeyId) && !string.Equals(config.ExpectedKeyId, decrypted.Kid, StringComparison.Ordinal)) - _log.LogWarning("encryption_key_id_mismatch"); + log.KeyIdMismatch(); var context = decrypted.Context; if (!context.IsComplete) + { + log.Failure("delivery_context_validation", "incomplete delivery context", 400); return Reply(400, new EndpointErrorResponse("bad_request", requestId, Reason: "incomplete delivery context", CorrelationId: correlationId)); + } // Evaluation proves validation/decryption without requiring any provider configuration. if (evaluation) + { + log.Service("evaluation_completed"); return Reply(200, new EndpointSuccessResponse(context.Nonce!, correlationId)); + } var channel = EnvelopeParser.ChannelName(envelope.Channel)!; @@ -88,7 +104,7 @@ ObjectResult Reply(int status, object body) TextToVoice: context.TextToVoice); // A nonce acknowledges delivery, not just decryption. Wait for the bounded provider call. - var result = await _engine.DispatchAsync(dispatch, requestId); + var result = await _engine.DispatchAsync(dispatch, requestId, log); if (result.HttpStatus != 200) return Reply(result.HttpStatus, new EndpointErrorResponse("provider_delivery_failed", requestId, CorrelationId: correlationId)); @@ -96,13 +112,12 @@ ObjectResult Reply(int status, object body) } catch { + if (!log.HasFailure) log.Failure("handler", "unexpected_error", 500); return Reply(500, new EndpointErrorResponse("delivery_failed", requestId, CorrelationId: correlationId)); } finally { - var correlationHash = Convert.ToHexString(SHA256.HashData(Encoding.UTF8.GetBytes(correlationId)))[..16].ToLowerInvariant(); - _log.LogInformation("[EPP] RequestId={RequestId} CorrelationId={CorrelationId} HttpStatus={HttpStatus} ElapsedMs={ElapsedMs} Evaluation={Evaluation}", - requestId, correlationHash, httpStatus, started.ElapsedMilliseconds, evaluation); + log.Complete(httpStatus); } } } diff --git a/dotnet/Program.cs b/dotnet/Program.cs index 678961b..42cdd60 100644 --- a/dotnet/Program.cs +++ b/dotnet/Program.cs @@ -10,7 +10,7 @@ builder.ConfigureFunctionsWebApplication(); -// The handler summary is sufficient; provider URLs must not appear in factory logs. +// Application events use selected metadata; provider URLs must not appear in factory logs. builder.Logging.AddFilter("System.Net.Http.HttpClient." + DispatchEngine.ProviderHttpClientName, LogLevel.None); builder.Services.AddHttpClient(DispatchEngine.ProviderHttpClientName) .ConfigurePrimaryHttpMessageHandler(() => new HttpClientHandler { AllowAutoRedirect = false }); diff --git a/dotnet/README.md b/dotnet/README.md index a9a4d4e..05ee4d4 100644 --- a/dotnet/README.md +++ b/dotnet/README.md @@ -96,6 +96,7 @@ six-digit numeric run that is not part of a longer number and repeats the comple | [Functions/SendOtp.cs](Functions/SendOtp.cs) | HTTP handler | | [Src/AppConfig.cs](Src/AppConfig.cs) | Shared deployment settings | | [Src/DispatchEngine.cs](Src/DispatchEngine.cs) | Envelope/JWE handling and dispatch | +| [Src/RequestLog.cs](Src/RequestLog.cs) | Request-scoped [service events and summaries](../docs/CONTRACT.md#application-logs) with explicit ID sources | | [Src/ProviderRegistry.cs](Src/ProviderRegistry.cs), [Src/IProviderAdapter.cs](Src/IProviderAdapter.cs) | Adapter lookup and contract | | [Src/Providers/](Src/Providers/) | Adapter manifests and API-specific implementations | | [Src/SecretResolver.cs](Src/SecretResolver.cs) | Cached Key Vault access via managed identity | diff --git a/dotnet/Src/DispatchEngine.cs b/dotnet/Src/DispatchEngine.cs index 95c6caa..f07c1bf 100644 --- a/dotnet/Src/DispatchEngine.cs +++ b/dotnet/Src/DispatchEngine.cs @@ -4,6 +4,7 @@ using System.Text; using System.Text.Json; using System.Text.Json.Serialization; +using Microsoft.Extensions.Logging; namespace Epp.Otp; @@ -254,31 +255,51 @@ private static ClientAssertionCredentialOptions OAuthOptions() private static bool UsableAccessToken(AccessToken token) => !string.IsNullOrWhiteSpace(token.Token) && token.ExpiresOn > DateTimeOffset.UtcNow.AddSeconds(30); - public async Task DispatchAsync(DispatchRequest dispatch, string requestId) + public async Task DispatchAsync(DispatchRequest dispatch, string requestId, RequestLog? log = null) { + DispatchResult Failure(int status, string stage, string reason, object body) + { + log?.Failure(stage, reason, status); + return new DispatchResult(status, body); + } + var config = AppConfig.Read(_env); var adapter = _registry.Get(config.ProviderName); if (adapter is null) - return new DispatchResult(400, new { status = "error", reason = "unknown provider", requestId }); + return Failure(400, "provider_selection", "unknown_provider", + new { status = "error", reason = "unknown provider", requestId }); var manifest = adapter.Manifest; + log?.ProviderSelected(manifest); var providerId = manifest.Id; var channel = (dispatch.Channel ?? "sms").ToLowerInvariant(); if (!OutcomeMapper.DefaultChannels.Contains(channel)) - return new DispatchResult(400, new { status = "error", provider = providerId, reason = "unsupported channel", requestId }); + return Failure(400, "provider_configuration", "unsupported_channel", + new { status = "error", provider = providerId, reason = "unsupported channel", requestId }); if (channel == "voice" && manifest.RequiresTextToVoice && dispatch.TextToVoice?.IsComplete != true) - return new DispatchResult(400, FailBody(providerId, channel, "incomplete voice context", dispatch, requestId)); + return Failure(400, "provider_request_build", "incomplete_voice_context", + FailBody(providerId, channel, "incomplete voice context", dispatch, requestId)); if (!string.IsNullOrEmpty(config.ProviderChannel) && config.ProviderChannel != channel) - return new DispatchResult(400, new { status = "error", provider = providerId, reason = "channel not configured", requestId }); + return Failure(400, "provider_configuration", "channel_not_configured", + new { status = "error", provider = providerId, reason = "channel not configured", requestId }); if (!string.IsNullOrEmpty(config.ProviderAuthMode) && config.ProviderAuthMode != manifest.Auth.Mode) - return new DispatchResult(502, FailBody(providerId, channel, "provider authentication mismatch", dispatch, requestId)); + return Failure(502, "provider_configuration", "authentication_mode_mismatch", + FailBody(providerId, channel, "provider authentication mismatch", dispatch, requestId)); ProviderCredential credential; - try { credential = await ResolveCredentialAsync(manifest.Auth, config); } - catch { return new DispatchResult(502, FailBody(providerId, channel, "provider credential unavailable", dispatch, requestId)); } + try + { + log?.CredentialResolutionStarted(config); + credential = await ResolveCredentialAsync(manifest.Auth, config); + } + catch + { + return Failure(502, "provider_credentials", "credential_unavailable", + FailBody(providerId, channel, "provider credential unavailable", dispatch, requestId)); + } var identityRequired = credential.Mode == "apiKey" && !string.IsNullOrEmpty(manifest.Auth.IdentityKeyVaultSecretName); var credentialUnavailable = credential.Mode switch @@ -289,27 +310,44 @@ public async Task DispatchAsync(DispatchRequest dispatch, string _ => true, }; if (credentialUnavailable) - return new DispatchResult(502, FailBody(providerId, channel, "provider credential unavailable", dispatch, requestId)); + return Failure(502, "provider_credentials", "credential_unavailable", + FailBody(providerId, channel, "provider credential unavailable", dispatch, requestId)); + log?.CredentialResolved(); var endpoint = config.ProviderEndpoint; if (!IsHttpsEndpoint(endpoint)) - return new DispatchResult(502, FailBody(providerId, channel, "provider endpoint invalid or not configured", dispatch, requestId)); + return Failure(502, "provider_configuration", "invalid_provider_endpoint", + FailBody(providerId, channel, "provider endpoint invalid or not configured", dispatch, requestId)); var timeoutMs = NormalizeProviderTimeoutMs(config.ProviderTimeoutMs); + var stage = "provider_request_build"; try { + log?.Service("provider_request_build_started"); var req = adapter.BuildRequest(channel, endpoint!, dispatch, credential, _env); if (!IsHttpsEndpoint(req.Url)) - return new DispatchResult(502, FailBody(providerId, channel, "provider request endpoint invalid", dispatch, requestId)); + return Failure(502, "provider_request_build", "invalid_provider_request_url", + FailBody(providerId, channel, "provider request endpoint invalid", dispatch, requestId)); + log?.ProviderRequestBuilt(req.Method, req.Url); - var (providerHttpStatus, success, body) = await SendAsync(req, timeoutMs); + stage = "provider_transport"; + var (providerHttpStatus, success, body) = await SendAsync(req, timeoutMs, log); + stage = "provider_response"; JsonElement json; - try { using var responseDocument = JsonDocument.Parse(string.IsNullOrWhiteSpace(body) ? "{}" : body); json = responseDocument.RootElement.Clone(); } - catch { using var emptyDocument = JsonDocument.Parse("{}"); json = emptyDocument.RootElement.Clone(); } + var validJson = true; + try { using var responseDocument = JsonDocument.Parse(body); json = responseDocument.RootElement.Clone(); } + catch (JsonException) + { + validJson = false; + log?.Service("provider_response_invalid_json", level: LogLevel.Warning); + using var emptyDocument = JsonDocument.Parse("{}"); + json = emptyDocument.RootElement.Clone(); + } var parsed = adapter.ParseResponse(providerHttpStatus, success, json); var outcome = OutcomeMapper.ResolveOutcome(manifest, parsed); var httpStatus = OutcomeMapper.ToHttpStatus(outcome, parsed.ProviderHttpStatus); + log?.ProviderResponseProcessed(manifest, parsed, outcome, httpStatus, validJson); return new DispatchResult(httpStatus, new { @@ -324,11 +362,18 @@ public async Task DispatchAsync(DispatchRequest dispatch, string } catch (OperationCanceledException) { - return new DispatchResult(504, FailBody(providerId, channel, $"endpoint timeout after {timeoutMs}ms", dispatch, requestId)); + return Failure(504, stage, "provider_timeout", + FailBody(providerId, channel, $"endpoint timeout after {timeoutMs}ms", dispatch, requestId)); } catch { - return new DispatchResult(502, FailBody(providerId, channel, "provider request failed", dispatch, requestId)); + var reason = stage switch + { + "provider_request_build" => "request_build_failed", + "provider_response" => "response_parse_failed", + _ => "provider_network_error", + }; + return Failure(502, stage, reason, FailBody(providerId, channel, "provider request failed", dispatch, requestId)); } } @@ -401,7 +446,7 @@ internal static bool IsHttpsEndpoint(string? endpoint) => && string.IsNullOrEmpty(uri.UserInfo) && string.IsNullOrEmpty(uri.Fragment); - private async Task<(int HttpStatus, bool Success, string Body)> SendAsync(ProviderHttpRequest req, int timeoutMs) + private async Task<(int HttpStatus, bool Success, string Body)> SendAsync(ProviderHttpRequest req, int timeoutMs, RequestLog? log) { using var cts = new CancellationTokenSource(timeoutMs); using var client = _httpFactory.CreateClient(ProviderHttpClientName); @@ -414,11 +459,20 @@ internal static bool IsHttpsEndpoint(string? endpoint) => if (k.Equals("Content-Type", StringComparison.OrdinalIgnoreCase)) continue; if (!message.Headers.TryAddWithoutValidation(k, v)) message.Content.Headers.TryAddWithoutValidation(k, v); } - using var resp = await client.SendAsync(message, HttpCompletionOption.ResponseHeadersRead, cts.Token); - using var stream = await resp.Content.ReadAsStreamAsync(cts.Token); - using var reader = new StreamReader(stream, Encoding.UTF8); - var text = await reader.ReadToEndAsync(cts.Token); - return ((int)resp.StatusCode, resp.IsSuccessStatusCode, text); + log?.ProviderRequestStarted(timeoutMs); + try + { + using var resp = await client.SendAsync(message, HttpCompletionOption.ResponseHeadersRead, cts.Token); + log?.ProviderResponseReceived((int)resp.StatusCode); + using var stream = await resp.Content.ReadAsStreamAsync(cts.Token); + using var reader = new StreamReader(stream, Encoding.UTF8); + var text = await reader.ReadToEndAsync(cts.Token); + return ((int)resp.StatusCode, resp.IsSuccessStatusCode, text); + } + finally + { + log?.ProviderRequestFinished(); + } } private static object FailBody(string provider, string channel, string reason, DispatchRequest d, string requestId) => diff --git a/dotnet/Src/RequestLog.cs b/dotnet/Src/RequestLog.cs new file mode 100644 index 0000000..6687d70 --- /dev/null +++ b/dotnet/Src/RequestLog.cs @@ -0,0 +1,266 @@ +using System.Diagnostics; +using System.Text.Json; +using System.Text.RegularExpressions; +using Microsoft.Extensions.Logging; + +namespace Epp.Otp; + +// Only explicitly selected metadata enters logs; never serialize delivery/provider models. +public sealed class RequestLog +{ + private static readonly string[] ContextFields = + { + "functionName", "functionRequestId", "functionInvocationId", + "x-ms-client-request-id", "x-ms-correlation-id", "msCorrelationIdSource", "omittedIdFields", + "channel", "evaluation", "providerName", + }; + private static readonly string[] CredentialFields = + { + "providerAuthMode", "providerCredentialSource", "providerTenantId", + "functionOutboundClientId", "functionOutboundManagedIdentityClientId", + }; + private static readonly Regex IdentifierPattern = new(@"\A[A-Za-z0-9][A-Za-z0-9._:-]{0,127}\z", RegexOptions.CultureInvariant); + + private readonly ILogger _logger; + private readonly Stopwatch _started = Stopwatch.StartNew(); + private readonly Dictionary _data; + private readonly List _omittedIdFields = new(); + private Stopwatch? _providerStarted; + private Stopwatch? _credentialStarted; + + public bool HasFailure => _data["failureStage"] is not null; + + public RequestLog(ILogger logger, string requestId, string? invocationId, string? msRequestId, string? msCorrelationId) + { + _logger = logger; + _data = new() + { + ["functionName"] = "SendOtp", + ["functionRequestId"] = requestId, + ["functionInvocationId"] = invocationId, + ["x-ms-client-request-id"] = null, + ["x-ms-correlation-id"] = null, + ["msCorrelationIdSource"] = "none", + ["omittedIdFields"] = Array.Empty(), + ["envelopeType"] = null, + ["ttlSeconds"] = null, + ["channel"] = null, + ["evaluation"] = null, + ["encryptionKeyIdMismatch"] = false, + ["providerName"] = null, + ["providerAuthMode"] = null, + ["providerCredentialSource"] = null, + ["providerCredentialElapsedMs"] = null, + ["providerTenantId"] = null, + ["functionOutboundClientId"] = null, + ["functionOutboundManagedIdentityClientId"] = null, + ["providerHttpMethod"] = null, + ["providerEndpoint"] = null, + ["providerAttempted"] = false, + ["providerHttpStatus"] = null, + ["providerStatus"] = null, + ["providerOutcome"] = null, + ["providerMessageId"] = null, + ["providerElapsedMs"] = null, + ["providerTimeoutMs"] = null, + ["failureStage"] = null, + ["failureReason"] = null, + ["responseContainsNonce"] = null, + ["responseContainsCorrelationId"] = null, + }; + SetIdentifier("x-ms-client-request-id", msRequestId); + SetIdentifier("x-ms-correlation-id", msCorrelationId); + _data["msCorrelationIdSource"] = _data["x-ms-correlation-id"] is null ? "none" : "header"; + } + + private void SetIdentifier(string field, string? value) + { + var valid = value is { Length: <= 128 } && IdentifierPattern.IsMatch(value); + _data[field] = valid ? value : null; + _omittedIdFields.Remove(field); + if (!valid && !string.IsNullOrWhiteSpace(value)) _omittedIdFields.Add(field); + _data["omittedIdFields"] = _omittedIdFields.ToArray(); + } + + public void Service(string eventName, Dictionary? details = null, LogLevel level = LogLevel.Information) + { + var record = new Dictionary { ["logType"] = "service", ["eventName"] = eventName }; + foreach (var field in ContextFields) record[field] = _data[field]; + if (details is not null) + foreach (var (key, value) in details) record[key] = value; + record["elapsedMs"] = _started.ElapsedMilliseconds; + Write(level, eventName, record); + } + + public void EnvelopeValidated(Envelope envelope, string? correlationId, string source) + { + _data["envelopeType"] = envelope.Type; + _data["ttlSeconds"] = envelope.TtlSeconds; + _data["channel"] = EnvelopeParser.ChannelName(envelope.Channel); + _data["evaluation"] = envelope.Mode == EnvelopeParser.ModeEvaluation; + SetIdentifier("x-ms-correlation-id", correlationId); + _data["msCorrelationIdSource"] = _data["x-ms-correlation-id"] is null ? "none" : source; + Service("envelope_validated", new() + { + ["envelopeType"] = _data["envelopeType"], + ["ttlSeconds"] = _data["ttlSeconds"], + ["encryptedDeliveryContextPresent"] = true, + }); + } + + public void KeyIdMismatch() + { + _data["encryptionKeyIdMismatch"] = true; + Service("encryption_key_id_mismatch", level: LogLevel.Warning); + } + + public void ProviderSelected(ProviderManifest manifest) + { + _data["providerName"] = manifest.Id; + _data["providerAuthMode"] = manifest.Auth.Mode is "apiKey" or "oauth" ? manifest.Auth.Mode : "unsupported"; + Service("provider_selected", new() { ["providerAuthMode"] = _data["providerAuthMode"] }); + } + + public void CredentialResolutionStarted(AppConfig config) + { + _credentialStarted = Stopwatch.StartNew(); + _data["providerCredentialSource"] = _data["providerAuthMode"] switch + { + "oauth" => "managed_identity_client_assertion", + "apiKey" => "key_vault", + _ => "unsupported", + }; + if (Equals(_data["providerAuthMode"], "oauth")) + { + SetIdentifier("providerTenantId", config.ProviderTenantId); + SetIdentifier("functionOutboundClientId", config.OutboundClientId); + SetIdentifier("functionOutboundManagedIdentityClientId", config.OutboundManagedIdentityClientId); + } + Service("provider_credential_resolution_started", CredentialDetails()); + } + + private Dictionary CredentialDetails() => + CredentialFields.ToDictionary(key => key, key => _data[key]); + + private void CredentialResolutionFinished() + { + if (_credentialStarted is null) return; + _data["providerCredentialElapsedMs"] = _credentialStarted.ElapsedMilliseconds; + _credentialStarted = null; + } + + public void CredentialResolved() + { + CredentialResolutionFinished(); + var details = CredentialDetails(); + details["providerCredentialElapsedMs"] = _data["providerCredentialElapsedMs"]; + Service("provider_credential_resolved", details); + } + + public void ProviderRequestBuilt(string? method, string endpoint) + { + var normalized = method?.ToUpperInvariant(); + _data["providerHttpMethod"] = normalized is "GET" or "HEAD" or "POST" or "PUT" or "DELETE" + or "CONNECT" or "OPTIONS" or "TRACE" or "PATCH" ? normalized : "other"; + var uri = new Uri(endpoint, UriKind.Absolute); + _data["providerEndpoint"] = uri.GetComponents(UriComponents.SchemeAndServer, UriFormat.UriEscaped) + uri.AbsolutePath; + Service("provider_request_built", new() + { + ["providerHttpMethod"] = _data["providerHttpMethod"], + ["providerEndpoint"] = _data["providerEndpoint"], + ["providerScheme"] = "https", + ["redirectsAllowed"] = false, + }); + } + + public void ProviderRequestStarted(int timeoutMs) + { + _providerStarted = Stopwatch.StartNew(); + _data["providerAttempted"] = true; + _data["providerTimeoutMs"] = timeoutMs; + Service("provider_request_started", new() + { + ["providerTimeoutMs"] = timeoutMs, + ["providerHttpMethod"] = _data["providerHttpMethod"], + ["providerEndpoint"] = _data["providerEndpoint"], + }); + } + + public void ProviderResponseReceived(int status) + { + _data["providerHttpStatus"] = status; + Service("provider_response_received", new() { ["providerHttpStatus"] = status }); + } + + public void ProviderRequestFinished() + { + if (_providerStarted is null) return; + _data["providerElapsedMs"] = _providerStarted.ElapsedMilliseconds; + _providerStarted = null; + } + + public void ProviderResponseProcessed(ProviderManifest manifest, ParsedResponse parsed, Outcome outcome, int httpStatus, bool validJson) + { + var status = parsed.ProviderStatusName ?? parsed.ProviderStatusCode; + var known = status is not null && status != "default" && manifest.ResponseMapping.ContainsKey(status); + _data["providerStatus"] = known ? status : "unmapped"; + _data["providerOutcome"] = outcome.ToString(); + SetIdentifier("providerMessageId", parsed.ProviderMessageId); + if (outcome != Outcome.Continue) + { + _data["failureStage"] = "provider_response"; + _data["failureReason"] = validJson ? "provider_rejected" : "invalid_provider_json"; + } + Service("provider_response_processed", new() + { + ["providerHttpStatus"] = _data["providerHttpStatus"], + ["providerStatus"] = _data["providerStatus"], + ["providerOutcome"] = _data["providerOutcome"], + ["providerMessageId"] = _data["providerMessageId"], + ["providerElapsedMs"] = _data["providerElapsedMs"], + ["httpStatus"] = httpStatus, + ["failureReason"] = _data["failureReason"], + }, httpStatus >= 500 ? LogLevel.Error : httpStatus == 200 ? LogLevel.Information : LogLevel.Warning); + } + + public void Failure(string stage, string reason, int httpStatus) + { + CredentialResolutionFinished(); + ProviderRequestFinished(); + _data["failureStage"] = stage; + _data["failureReason"] = reason; + Service(stage + "_failed", new() { ["failureReason"] = reason, ["httpStatus"] = httpStatus }, + httpStatus >= 500 ? LogLevel.Error : LogLevel.Warning); + } + + public void ResponsePrepared(int httpStatus, bool containsNonce, bool containsCorrelationId) + { + _data["responseContainsNonce"] = containsNonce; + _data["responseContainsCorrelationId"] = containsCorrelationId; + Service("response_prepared", new() + { + ["httpStatus"] = httpStatus, + ["responseContainsNonce"] = containsNonce, + ["responseContainsCorrelationId"] = containsCorrelationId, + }); + } + + public void Complete(int httpStatus) + { + CredentialResolutionFinished(); + ProviderRequestFinished(); + var record = new Dictionary(_data) + { + ["logType"] = "request", + ["eventName"] = "request_completed", + ["httpStatus"] = httpStatus, + ["result"] = httpStatus == 200 ? (Equals(_data["evaluation"], true) ? "evaluated" : "accepted") : "failed", + ["elapsedMs"] = _started.ElapsedMilliseconds, + }; + Write(LogLevel.Information, "request_completed", record); + } + + private void Write(LogLevel level, string eventName, Dictionary record) => + _logger.Log(level, new EventId(0, eventName), record, null, + static (state, _) => JsonSerializer.Serialize(state)); +} diff --git a/dotnet/tests/EngineTests.cs b/dotnet/tests/EngineTests.cs index 4e488c6..94967ed 100644 --- a/dotnet/tests/EngineTests.cs +++ b/dotnet/tests/EngineTests.cs @@ -177,6 +177,8 @@ public async Task HandlerUsesInjectedConfigAwaitsAcceptanceAndKeepsLogsPrivate() { await entered.Task.WaitAsync(TimeSpan.FromSeconds(5)); Assert.False(pending.IsCompleted); + Assert.DoesNotContain(rig.Log.Records, record => record.GetProperty("logType").GetString() == "request"); + Assert.Equal("provider_request_started", rig.Log.Records.Last().GetProperty("eventName").GetString()); } finally { @@ -186,10 +188,22 @@ public async Task HandlerUsesInjectedConfigAwaitsAcceptanceAndKeepsLogsPrivate() using var body = JsonDocument.Parse(rig.Http.Body!); Assert.Equal(Message, body.RootElement.GetProperty("messages")[0].GetProperty("content").GetProperty("text").GetString()); Assert.Equal(1, rig.Http.Calls); - var log = Assert.Single(rig.Log.Messages); - var hash = Convert.ToHexString(SHA256.HashData(Encoding.UTF8.GetBytes(Correlation)))[..16].ToLowerInvariant(); - Assert.Contains("CorrelationId=" + hash, log); - foreach (var value in new[] { Phone, "918273", "001234", Nonce, Correlation, "private-api-key", "private-api-id" }) + var summary = Summary(rig); + using var fixtures = ReadContractFixtures(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("liveEvents").EnumerateArray().Select(value => value.GetString()), + rig.Log.Records.Select(record => record.GetProperty("eventName").GetString())); + Assert.Equal("infobip", summary.GetProperty("providerName").GetString()); + Assert.Equal("apiKey", summary.GetProperty("providerAuthMode").GetString()); + Assert.Equal(200, summary.GetProperty("providerHttpStatus").GetInt32()); + Assert.Equal("PENDING", summary.GetProperty("providerStatus").GetString()); + Assert.Equal("Continue", summary.GetProperty("providerOutcome").GetString()); + Assert.True(summary.GetProperty("providerAttempted").GetBoolean()); + Assert.Equal("id", summary.GetProperty("providerMessageId").GetString()); + Assert.Equal(2500, summary.GetProperty("providerTimeoutMs").GetInt32()); + Assert.InRange(summary.GetProperty("providerElapsedMs").GetInt64(), 0, summary.GetProperty("elapsedMs").GetInt64()); + var log = string.Join("\n", rig.Log.Messages); + Assert.Equal(Correlation, summary.GetProperty("x-ms-correlation-id").GetString()); + foreach (var value in new[] { Phone, "918273", "001234", Nonce, "private-api-key", "private-api-id" }) Assert.DoesNotContain(value, log); } @@ -222,6 +236,13 @@ public async Task ResponseBodyTimeoutCancelsWithoutRetryOrSuccessNonce() AssertFailure(rig, await rig.Invoke().WaitAsync(TimeSpan.FromSeconds(5)), 504); Assert.True(body.SawCancellationToken); Assert.Equal(1, rig.Http.Calls); + var summary = Summary(rig); + Assert.Equal("provider_transport", summary.GetProperty("failureStage").GetString()); + Assert.Equal("provider_timeout", summary.GetProperty("failureReason").GetString()); + Assert.Equal(200, summary.GetProperty("providerHttpStatus").GetInt32()); + Assert.Equal(200, summary.GetProperty("providerTimeoutMs").GetInt32()); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerStatus").ValueKind); + Assert.InRange(summary.GetProperty("providerElapsedMs").GetInt64(), 0, summary.GetProperty("elapsedMs").GetInt64()); } [Fact] @@ -262,8 +283,23 @@ public async Task EvaluationValidatesRealJweWithoutProviderConfiguration() rig.Env["EPP_ENCRYPTION_KEY_ID"] = "configured-key-id"; AssertAccepted(await rig.Invoke("evaluation", tenantId: "untrusted-body-tenant")); Assert.Equal("encryption_key_id_mismatch", - Assert.Single(rig.Log.Entries, entry => entry.Level == LogLevel.Warning).Message); - foreach (var value in new[] { Kid, "configured-key-id", Phone, "918273", Nonce, Correlation, "untrusted-body-tenant" }) + JsonSerializer.Deserialize(Assert.Single(rig.Log.Entries, entry => entry.Level == LogLevel.Warning).Message) + .GetProperty("eventName").GetString()); + var summary = Summary(rig); + Assert.True(summary.GetProperty("encryptionKeyIdMismatch").GetBoolean()); + Assert.True(summary.GetProperty("evaluation").GetBoolean()); + Assert.Equal("evaluated", summary.GetProperty("result").GetString()); + Assert.False(summary.GetProperty("providerAttempted").GetBoolean()); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerName").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerHttpStatus").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerElapsedMs").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerCredentialSource").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerCredentialElapsedMs").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerEndpoint").ValueKind); + using var fixtures = ReadContractFixtures(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("evaluationEvents").EnumerateArray().Select(value => value.GetString()), + rig.Log.Records.Select(record => record.GetProperty("eventName").GetString()).Where(name => name != "encryption_key_id_mismatch")); + foreach (var value in new[] { Kid, "configured-key-id", Phone, "918273", Nonce, "untrusted-body-tenant" }) Assert.DoesNotContain(value, string.Join("\n", rig.Log.Messages)); Assert.Equal((1, 0, 0), (rig.Keys.Calls, rig.Secrets.Calls, rig.Http.Calls)); } @@ -354,6 +390,382 @@ public async Task SharedJwePolicyPermitsOnlyRsaOaep256WithA256Gcm() Assert.Equal((0, 0), (rig.Secrets.Calls, rig.Http.Calls)); } + [Fact] + public async Task MicrosoftIdentifiersHaveExplicitSourcesWithoutSyntheticMicrosoftIds() + { + var headers = new Dictionary + { + ["x-ms-client-request-id"] = "ms-request-id", + ["x-ms-correlation-id"] = "ms-header-correlation-id", + }; + foreach (var correlation in new[] { "ms-envelope-correlation-id", null }) + { + using var rig = new HandlerRig(); + var result = await rig.Invoke(correlationId: correlation, headers: headers); + Assert.Equal(200, result.StatusCode); + var summary = Summary(rig); + Assert.Equal(headers["x-ms-client-request-id"], summary.GetProperty("x-ms-client-request-id").GetString()); + Assert.Equal(correlation ?? headers["x-ms-correlation-id"], summary.GetProperty("x-ms-correlation-id").GetString()); + Assert.Equal(correlation is null ? "header" : "envelope", summary.GetProperty("msCorrelationIdSource").GetString()); + Assert.Equal("header", rig.Log.Records.First().GetProperty("msCorrelationIdSource").GetString()); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("functionInvocationId").ValueKind); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + using var missing = new HandlerRig(); + var response = await missing.Invoke(correlationId: null); + var missingSummary = Summary(missing); + Assert.Equal(missingSummary.GetProperty("functionRequestId").GetString(), + Assert.IsType(response.Value).CorrelationId); + Assert.Equal(JsonValueKind.Null, missingSummary.GetProperty("x-ms-client-request-id").ValueKind); + Assert.Equal(JsonValueKind.Null, missingSummary.GetProperty("x-ms-correlation-id").ValueKind); + Assert.Equal("none", missingSummary.GetProperty("msCorrelationIdSource").GetString()); + } + + [Fact] + public void FunctionInvocationIdIsSeparateFromMicrosoftAndProviderIdentifiersInLogState() + { + var logger = new CapturingLogger(); + var log = new RequestLog(logger, "function-request", "function-invocation", "ms-request-id", "ms-header-correlation-id"); + var manifest = new TelesignProvider().Manifest; + log.ProviderSelected(manifest); + log.ProviderRequestStarted(1500); + log.ProviderResponseReceived(200); + log.ProviderRequestFinished(); + log.ProviderResponseProcessed(manifest, new ParsedResponse(true, 200, "provider-reference-id", + ProviderStatusCode: "3001", ProviderStatusDescription: PrivateError), Outcome.Continue, 200, true); + log.Complete(200); + var summary = logger.States.Last(); + Assert.Equal("function-request", summary["functionRequestId"]); + Assert.Equal("function-invocation", summary["functionInvocationId"]); + Assert.Equal("ms-request-id", summary["x-ms-client-request-id"]); + Assert.Equal("ms-header-correlation-id", summary["x-ms-correlation-id"]); + Assert.Equal("provider-reference-id", summary["providerMessageId"]); + Assert.Equal("3001", summary["providerStatus"]); + Assert.DoesNotContain("PRIVATE", string.Join("\n", logger.Messages)); + Assert.DoesNotContain(PrivateError, string.Join("\n", logger.Messages)); + } + + [Theory] + [InlineData("invalid_json", 400, "request_validation", "invalid JSON body", false)] + [InlineData("invalid_envelope", 400, "request_validation", "unsupported envelope type", false)] + [InlineData("decryption", 400, "decryption", "decryption_failed", false)] + [InlineData("incomplete_context", 400, "delivery_context_validation", "incomplete delivery context", false)] + [InlineData("unknown_provider", 400, "provider_selection", "unknown_provider", false)] + [InlineData("wrong_channel", 400, "provider_configuration", "channel_not_configured", false)] + [InlineData("authentication_mismatch", 502, "provider_configuration", "authentication_mode_mismatch", false)] + [InlineData("invalid_endpoint", 502, "provider_configuration", "invalid_provider_endpoint", false)] + [InlineData("credentials", 502, "provider_credentials", "credential_unavailable", false)] + [InlineData("request_build", 502, "provider_request_build", "request_build_failed", false)] + [InlineData("network", 502, "provider_transport", "provider_network_error", true)] + [InlineData("response_parse", 502, "provider_response", "response_parse_failed", true)] + [InlineData("http_rejection", 429, "provider_response", "provider_rejected", true)] + public async Task FailuresEmitSeparateServiceEventsAndCompleteSummaries(string scenario, int status, string stage, string reason, bool attempted) + { + using var rig = new HandlerRig(); + JsonElement? delivery = null; + switch (scenario) + { + case "decryption": rig.Keys.Error = new InvalidOperationException(PrivateError); break; + case "incomplete_context": delivery = JsonSerializer.SerializeToElement(new { nonce = "" }); break; + case "unknown_provider": rig.Env["EPP_PROVIDER_NAME"] = "PRIVATE-UNKNOWN-PROVIDER"; break; + case "wrong_channel": rig.Env["EPP_PROVIDER_CHANNEL"] = "voice"; break; + case "authentication_mismatch": rig.Env["EPP_PROVIDER_AUTH_MODE"] = "oauth"; break; + case "invalid_endpoint": rig.Env["EPP_PROVIDER_ENDPOINT"] = "http://PRIVATE-ENDPOINT"; break; + case "credentials": rig.Secrets.Error = new InvalidOperationException(PrivateError); break; + case "request_build": + rig.Env["EPP_PROVIDER_NAME"] = "telesign"; + delivery = JsonSerializer.SerializeToElement(new { phoneNumber = "PRIVATE-INVALID-PHONE" }); + break; + case "network": + rig.Http.Respond = _ => Task.FromException(new HttpRequestException(PrivateError)); + break; + case "response_parse": + rig.Http.Respond = _ => Task.FromResult(Json(200, "{\"messages\":[{\"status\":{\"groupName\":123}}]}")); + break; + case "http_rejection": + rig.Http.Respond = _ => Task.FromResult(Json(429, "{\"messages\":[{\"status\":{\"groupName\":\"PENDING\"}}]}")); + break; + } + var headers = new Dictionary + { + ["x-ms-client-request-id"] = "ms-request-id", + ["x-ms-correlation-id"] = "ms-header-correlation-id", + }; + var result = scenario switch + { + "invalid_json" => await rig.InvokeRaw("{", headers), + "invalid_envelope" => await rig.InvokeRaw("{}", headers), + _ => await rig.Invoke(deliveryOverrides: delivery, headers: headers), + }; + Assert.Equal(status, result.StatusCode); + var summary = Summary(rig); + Assert.Equal(Assert.IsType(result.Value).RequestId, summary.GetProperty("functionRequestId").GetString()); + Assert.Equal(status, summary.GetProperty("httpStatus").GetInt32()); + Assert.Equal(stage, summary.GetProperty("failureStage").GetString()); + Assert.Equal(reason, summary.GetProperty("failureReason").GetString()); + Assert.Equal("failed", summary.GetProperty("result").GetString()); + Assert.Equal(headers["x-ms-client-request-id"], summary.GetProperty("x-ms-client-request-id").GetString()); + Assert.Equal(stage == "request_validation" ? "header" : "envelope", summary.GetProperty("msCorrelationIdSource").GetString()); + Assert.Equal(stage == "request_validation" ? headers["x-ms-correlation-id"] : Correlation, + summary.GetProperty("x-ms-correlation-id").GetString()); + Assert.Equal(attempted, summary.GetProperty("providerAttempted").GetBoolean()); + Assert.Equal(attempted ? 1 : 0, rig.Http.Calls); + Assert.Equal(scenario == "http_rejection" ? "provider_response_processed" : stage + "_failed", + rig.Log.Records.ElementAt(rig.Log.Entries.Count - 3).GetProperty("eventName").GetString()); + Assert.False(summary.GetProperty("responseContainsNonce").GetBoolean()); + Assert.Equal(stage != "request_validation", summary.GetProperty("responseContainsCorrelationId").GetBoolean()); + if (scenario == "credentials") + { + Assert.Equal("key_vault", summary.GetProperty("providerCredentialSource").GetString()); + Assert.InRange(summary.GetProperty("providerCredentialElapsedMs").GetInt64(), 0, summary.GetProperty("elapsedMs").GetInt64()); + Assert.DoesNotContain(rig.Log.Records, record => record.GetProperty("eventName").GetString() == "provider_credential_resolved"); + } + Assert.Contains(rig.Log.Entries, entry => entry.Level == (status >= 500 ? LogLevel.Error : LogLevel.Warning)); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + + [Fact] + public async Task SuccessfulLifecycleLogsAllowedBodyMetadataRawOAuthIdsAndEndpointWithoutQuery() + { + using var rig = new HandlerRig(_ => new TestTokenCredential((_, _) => + ValueTask.FromResult(new AccessToken("PRIVATE-ASSERTION", DateTimeOffset.UtcNow.AddHours(1)))), + (_, _, assertion) => new TestTokenCredential(async (_, cancellation) => + { + Assert.Equal("PRIVATE-ASSERTION", await assertion(cancellation)); + return new AccessToken("PRIVATE-TOKEN", DateTimeOffset.UtcNow.AddHours(1)); + })); + ConfigureSoprano(rig); + rig.Env["EPP_PROVIDER_ENDPOINT"] = "https://provider.example/api/send?key=PRIVATE-QUERY"; + rig.Env["EPP_PROVIDER_TENANT_ID"] = "provider-tenant-id"; + rig.Env["EPP_OUTBOUND_CLIENT_ID"] = "outbound-client-id"; + rig.Env["EPP_OUTBOUND_MI_CLIENT_ID"] = "outbound-mi-client-id"; + AssertAccepted(await rig.Invoke(tenantId: "PRIVATE-INBOUND-TENANT", + deliveryOverrides: JsonSerializer.SerializeToElement(new { diagnosticData = "PRIVATE-UNKNOWN-FIELD" }))); + var summary = Summary(rig); + var records = rig.Log.Records.ToArray(); + var validated = Assert.Single(records, record => record.GetProperty("eventName").GetString() == "envelope_validated"); + Assert.Equal(EnvelopeParser.EnvelopeType, validated.GetProperty("envelopeType").GetString()); + Assert.Equal(EnvelopeParser.EnvelopeType, summary.GetProperty("envelopeType").GetString()); + Assert.Equal(60, validated.GetProperty("ttlSeconds").GetInt32()); + Assert.Equal(60, summary.GetProperty("ttlSeconds").GetInt32()); + Assert.True(validated.GetProperty("encryptedDeliveryContextPresent").GetBoolean()); + var credentials = records.Where(record => record.GetProperty("eventName").GetString() + is "provider_credential_resolution_started" or "provider_credential_resolved").ToArray(); + Assert.Equal(2, credentials.Length); + foreach (var record in credentials.Append(summary)) + { + Assert.Equal("managed_identity_client_assertion", record.GetProperty("providerCredentialSource").GetString()); + Assert.Equal(rig.Env["EPP_PROVIDER_TENANT_ID"]!, record.GetProperty("providerTenantId").GetString()); + Assert.Equal(rig.Env["EPP_OUTBOUND_CLIENT_ID"]!, record.GetProperty("functionOutboundClientId").GetString()); + Assert.Equal(rig.Env["EPP_OUTBOUND_MI_CLIENT_ID"]!, record.GetProperty("functionOutboundManagedIdentityClientId").GetString()); + } + Assert.InRange(summary.GetProperty("providerCredentialElapsedMs").GetInt64(), 0, summary.GetProperty("elapsedMs").GetInt64()); + var outbound = records.Where(record => record.GetProperty("eventName").GetString() + is "provider_request_built" or "provider_request_started"); + foreach (var record in outbound.Append(summary)) + { + Assert.Equal("POST", record.GetProperty("providerHttpMethod").GetString()); + Assert.Equal("https://provider.example/api/send", record.GetProperty("providerEndpoint").GetString()); + } + var built = Assert.Single(records, record => record.GetProperty("eventName").GetString() == "provider_request_built"); + Assert.Equal("https", built.GetProperty("providerScheme").GetString()); + Assert.False(built.GetProperty("redirectsAllowed").GetBoolean()); + Assert.True(summary.GetProperty("responseContainsNonce").GetBoolean()); + Assert.True(summary.GetProperty("responseContainsCorrelationId").GetBoolean()); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + using var fixtures = ReadContractFixtures(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("liveEvents").EnumerateArray().Select(value => value.GetString()), + records.Select(record => record.GetProperty("eventName").GetString())); + } + + [Fact] + public async Task ApiKeyLifecycleIdentifiesKeyVaultWithoutLoggingCredentials() + { + using var rig = new HandlerRig(); + rig.Env["EPP_PROVIDER_NAME"] = "telesign"; + rig.Http.Respond = _ => Task.FromResult(Json(200, "{\"status\":{\"code\":3001}}")); + AssertAccepted(await rig.Invoke()); + var summary = Summary(rig); + Assert.Equal("key_vault", summary.GetProperty("providerCredentialSource").GetString()); + Assert.Equal("apiKey", summary.GetProperty("providerAuthMode").GetString()); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("providerTenantId").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("functionOutboundClientId").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("functionOutboundManagedIdentityClientId").ValueKind); + Assert.InRange(summary.GetProperty("providerCredentialElapsedMs").GetInt64(), 0, summary.GetProperty("elapsedMs").GetInt64()); + Assert.Equal(2, rig.Secrets.Calls); + using var fixtures = ReadContractFixtures(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("liveEvents").EnumerateArray().Select(value => value.GetString()), + rig.Log.Records.Select(record => record.GetProperty("eventName").GetString())); + } + + [Fact] + public async Task RequestPreparationLogsTheAdapterFinalUrlNotTheConfiguredBase() + { + using var rig = new HandlerRig(); + rig.Env["EPP_PROVIDER_NAME"] = "sinch"; + rig.Env["SINCH_VOICE_ENDPOINT"] = "https://different-provider.example/api/final"; + AssertAccepted(await rig.Invoke(channel: "voice")); + var summary = Summary(rig); + var expected = rig.Env["SINCH_VOICE_ENDPOINT"] + "/calling/v1/callouts"; + Assert.Equal(expected, summary.GetProperty("providerEndpoint").GetString()); + Assert.NotEqual(rig.Env["EPP_PROVIDER_ENDPOINT"]!, summary.GetProperty("providerEndpoint").GetString()); + Assert.Equal("POST", summary.GetProperty("providerHttpMethod").GetString()); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + + [Fact] + public void RequestPreparationDoesNotLogArbitraryHttpMethods() + { + var logger = new CapturingLogger(); + var log = new RequestLog(logger, "function-request", null, null, null); + log.ProviderRequestBuilt("PRIVATE-METHOD", "https://provider.example/api/send"); + var record = Assert.Single(logger.Records); + Assert.Equal("other", record.GetProperty("providerHttpMethod").GetString()); + Assert.DoesNotContain("PRIVATE", string.Join("\n", logger.Messages)); + } + + [Fact] + public async Task OptionalTtlStaysNullAndInvalidBodyValuesNeverEnterMetadata() + { + using var rig = new HandlerRig(); + var encrypted = Jose.JWT.Encode(JsonSerializer.Serialize(new { nonce = Nonce, phoneNumber = Phone, message = Message }), + rig.Keys.Rsa, Jose.JweAlgorithm.RSA_OAEP_256, Jose.JweEncryption.A256GCM); + var payload = new Dictionary + { + ["type"] = EnvelopeParser.EnvelopeType, ["channel"] = 1, ["mode"] = 2, + ["correlationId"] = Correlation, ["encryptedDeliveryContext"] = encrypted, + ["diagnosticData"] = new { token = "PRIVATE-UNKNOWN-FIELD" }, + }; + AssertAccepted(await rig.InvokeRaw(JsonSerializer.Serialize(payload))); + Assert.Equal(JsonValueKind.Null, Summary(rig).GetProperty("ttlSeconds").ValueKind); + payload["ttlSeconds"] = "PRIVATE-INVALID-TTL"; + Assert.Equal(400, (await rig.InvokeRaw(JsonSerializer.Serialize(payload))).StatusCode); + var summary = Summary(rig); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("ttlSeconds").ValueKind); + Assert.Equal(JsonValueKind.Null, summary.GetProperty("envelopeType").ValueKind); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public async Task UnknownStatusesAndMalformedResponsesStayOutOfLogs(bool validJson) + { + using var rig = new HandlerRig(); + rig.Env["EPP_PROVIDER_NAME"] = "telesign"; + var body = validJson + ? "{\"reference_id\":\"provider-reference-id\",\"status\":{\"code\":999,\"description\":\"PRIVATE-STATUS\"}}" + : "PRIVATE-RESPONSE"; + rig.Http.Respond = _ => Task.FromResult(Json(200, body)); + AssertFailure(rig, await rig.Invoke(), 502); + var summary = Summary(rig); + Assert.Equal("unmapped", summary.GetProperty("providerStatus").GetString()); + Assert.Equal("Fail", summary.GetProperty("providerOutcome").GetString()); + Assert.Equal(validJson ? "provider_rejected" : "invalid_provider_json", summary.GetProperty("failureReason").GetString()); + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + + [Fact] + public async Task InterleavedInvocationsKeepSeparateLogContexts() + { + using var rig = new HandlerRig(); + rig.Http.Respond = async cancellation => + { + await Task.Delay(20, cancellation); + return Json(200, "{\"messages\":[{\"status\":{\"groupName\":\"PENDING\"}}]}"); + }; + var results = await Task.WhenAll(rig.Invoke(correlationId: "correlation-first"), rig.Invoke(correlationId: "correlation-second")); + Assert.All(results, result => Assert.Equal(200, result.StatusCode)); + var summaries = rig.Log.Records.Where(record => record.GetProperty("logType").GetString() == "request").ToArray(); + Assert.Equal(2, summaries.Length); + Assert.Equal(2, summaries.Select(record => record.GetProperty("functionRequestId").GetString()).Distinct().Count()); + using var fixtures = ReadContractFixtures(); + foreach (var summary in summaries) + { + var id = summary.GetProperty("functionRequestId").GetString(); + var events = rig.Log.Records.Where(record => record.GetProperty("functionRequestId").GetString() == id).ToArray(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("liveEvents").EnumerateArray().Select(value => value.GetString()), + events.Select(record => record.GetProperty("eventName").GetString())); + Assert.All(events.Skip(1), record => Assert.Equal(summary.GetProperty("x-ms-correlation-id").GetString(), + record.GetProperty("x-ms-correlation-id").GetString())); + } + Assert.DoesNotContain("PRIVATE", string.Join("\n", rig.Log.Messages)); + } + + [Fact] + public void SharedIdCasesPreserveRawValuesOrExplicitlyOmitInvalidMetadata() + { + using var fixtures = ReadContractFixtures(); + var fields = new[] { "x-ms-client-request-id", "x-ms-correlation-id", "providerTenantId", + "functionOutboundClientId", "functionOutboundManagedIdentityClientId", "providerMessageId" }; + var manifest = new SopranoProvider().Manifest; + foreach (var fixture in fixtures.RootElement.GetProperty("logging").GetProperty("identifiers").EnumerateArray()) + { + var value = fixture.TryGetProperty("length", out var length) + ? new string('A', length.GetInt32()) : fixture.GetProperty("value").GetString(); + var logger = new CapturingLogger(); + var log = new RequestLog(logger, "function-request", null, value, value); + log.ProviderSelected(manifest); + log.CredentialResolutionStarted(new AppConfig + { + ProviderTenantId = value, OutboundClientId = value, OutboundManagedIdentityClientId = value, + }); + log.ProviderResponseProcessed(manifest, new ParsedResponse(true, 200, value, "ENROUTE"), Outcome.Continue, 200, true); + log.Complete(200); + var summary = logger.Records.Last(); + foreach (var field in fields) + Assert.Equal(fixture.GetProperty("accepted").GetBoolean() ? value : null, summary.GetProperty(field).GetString()); + var expectedOmissions = fixture.TryGetProperty("omitted", out var omitted) && omitted.GetBoolean() ? fields : Array.Empty(); + Assert.Equal(expectedOmissions, summary.GetProperty("omittedIdFields").EnumerateArray().Select(item => item.GetString())); + Assert.All(logger.Records, record => Assert.DoesNotContain(record.EnumerateObject(), property => property.Name.EndsWith("Hash"))); + Assert.DoesNotContain("PRIVATE", string.Join("\n", logger.Messages)); + } + } + + [Fact] + public void SharedEndpointCasesKeepOnlySchemeHostPortAndApiPath() + { + using var fixtures = ReadContractFixtures(); + foreach (var fixture in fixtures.RootElement.GetProperty("logging").GetProperty("endpoints").EnumerateArray()) + { + var logger = new CapturingLogger(); + var log = new RequestLog(logger, "function-request", null, null, null); + log.ProviderRequestBuilt("POST", fixture.GetProperty("url").GetString()!); + log.ProviderRequestStarted(1500); + log.Complete(200); + Assert.All(logger.Records, record => Assert.Equal(fixture.GetProperty("logged").GetString(), + record.GetProperty("providerEndpoint").GetString())); + Assert.DoesNotContain("PRIVATE", string.Join("\n", logger.Messages)); + } + } + + private static JsonElement Summary(HandlerRig rig) + { + var summary = rig.Log.Records.Last(); + Assert.Equal("request", summary.GetProperty("logType").GetString()); + Assert.Equal("request_completed", summary.GetProperty("eventName").GetString()); + using var fixtures = ReadContractFixtures(); + Assert.Equal(fixtures.RootElement.GetProperty("logging").GetProperty("summaryFields").EnumerateArray() + .Select(value => value.GetString()).OrderBy(value => value), + summary.EnumerateObject().Select(property => property.Name).OrderBy(value => value)); + var events = rig.Log.Records.Where(record => record.GetProperty("functionRequestId").GetString() + == summary.GetProperty("functionRequestId").GetString()).ToArray(); + Assert.Single(events, record => record.GetProperty("logType").GetString() == "request"); + var prepared = Assert.Single(events, record => record.GetProperty("eventName").GetString() == "response_prepared"); + Assert.Equal("response_prepared", events[^2].GetProperty("eventName").GetString()); + Assert.Equal(summary.GetProperty("httpStatus").GetInt32(), prepared.GetProperty("httpStatus").GetInt32()); + Assert.Equal(summary.GetProperty("httpStatus").GetInt32() == 200, summary.GetProperty("responseContainsNonce").GetBoolean()); + Assert.Equal(summary.GetProperty("responseContainsNonce").GetBoolean(), prepared.GetProperty("responseContainsNonce").GetBoolean()); + Assert.Equal(summary.GetProperty("responseContainsCorrelationId").GetBoolean(), prepared.GetProperty("responseContainsCorrelationId").GetBoolean()); + Assert.All(events[..^1], record => Assert.Equal("service", record.GetProperty("logType").GetString())); + Assert.All(events, record => Assert.Equal("SendOtp", record.GetProperty("functionName").GetString())); + Assert.Equal(summary.EnumerateObject().Select(property => property.Name).OrderBy(value => value), + rig.Log.States.Last().Keys.OrderBy(value => value)); + foreach (var value in new[] { PrivateError, Phone, "918273", Nonce, "private-api-key", "private-api-id" }) + Assert.DoesNotContain(value, string.Join("\n", rig.Log.Messages)); + return summary; + } + private static JsonDocument ReadContractFixtures() => JsonDocument.Parse(File.ReadAllText(Path.Combine(AppContext.BaseDirectory, "fixtures", "contract.json"))); @@ -407,7 +819,7 @@ public HandlerRig(Func? createIdentity = null, public async Task Invoke(object? mode = null, string channel = "sms", string? tenantId = null, Jose.JweAlgorithm algorithm = Jose.JweAlgorithm.RSA_OAEP_256, Jose.JweEncryption encryption = Jose.JweEncryption.A256GCM, JsonElement? deliveryOverrides = null, - string? plaintext = null) + string? plaintext = null, string? correlationId = Correlation, Dictionary? headers = null) { var context = new Dictionary { ["nonce"] = Nonce, ["phoneNumber"] = Phone, ["message"] = Message }; if (deliveryOverrides is { } changes) @@ -416,17 +828,19 @@ public async Task Invoke(object? mode = null, string channel = "sm extraHeaders: new Dictionary { ["kid"] = Kid }); return await InvokeRaw(JsonSerializer.Serialize(new { - type = EnvelopeParser.EnvelopeType, tenantId, correlationId = Correlation, channel, mode = mode ?? "live", + type = EnvelopeParser.EnvelopeType, tenantId, correlationId, channel, mode = mode ?? "live", ttlSeconds = 60, encryptedDeliveryContext = encrypted, - })); + }), headers); } - public async Task InvokeRaw(string body) + public async Task InvokeRaw(string body, Dictionary? headers = null) { using var stream = new MemoryStream(Encoding.UTF8.GetBytes(body)); var request = new DefaultHttpContext().Request; request.Method = "POST"; request.ContentType = "application/json"; request.Body = stream; + if (headers is not null) + foreach (var (key, value) in headers) request.Headers[key] = value; return Assert.IsAssignableFrom(await _function.Run(request)); } public void Dispose() { Keys.Dispose(); Http.Dispose(); } @@ -437,9 +851,11 @@ private sealed class TestSecrets : ISecretResolver public int Calls { get; private set; } public string Secret { get; set; } = "private-api-key"; public string Identity { get; set; } = "private-api-id"; + public Exception? Error { get; set; } public Task ResolveAsync(string? name) { Calls++; + if (Error is not null) throw Error; return Task.FromResult(name == "telesign-customer-id" ? Identity : Secret); } } @@ -463,12 +879,21 @@ protected override async Task SendAsync(HttpRequestMessage private sealed class CapturingLogger : ILogger { + private readonly object _gate = new(); public List<(LogLevel Level, string Message)> Entries { get; } = new(); + public List> States { get; } = new(); public IEnumerable Messages => Entries.Select(entry => entry.Message); + public IEnumerable Records => Messages.Select(message => JsonSerializer.Deserialize(message)); public IDisposable? BeginScope(TState state) where TState : notnull => null; public bool IsEnabled(LogLevel logLevel) => true; - public void Log(LogLevel level, EventId id, TState state, Exception? error, Func formatter) => - Entries.Add((level, formatter(state, error) + (error?.ToString() ?? ""))); + public void Log(LogLevel level, EventId id, TState state, Exception? error, Func formatter) + { + lock (_gate) + { + Entries.Add((level, formatter(state, error) + (error?.ToString() ?? ""))); + States.Add(Assert.IsAssignableFrom>>(state).ToDictionary(pair => pair.Key, pair => pair.Value)); + } + } } // Headers arrive immediately; only reading the response body stalls until cancellation. diff --git a/javascript/README.md b/javascript/README.md index 92d4343..0fa4e04 100644 --- a/javascript/README.md +++ b/javascript/README.md @@ -105,6 +105,7 @@ retries. The shared contract defines validation, HTTP outcomes and privacy-safe | [src/functions/config.js](src/functions/config.js) | Shared deployment settings | | [src/functions/models.js](src/functions/models.js) | Delivery context, normalized `ParsedResponse`, and documented request objects | | [src/functions/dispatch.js](src/functions/dispatch.js) | Envelope/JWE handling, registry and dispatch | +| [src/functions/requestLog.js](src/functions/requestLog.js) | Request-scoped [service events and summaries](../docs/CONTRACT.md#application-logs) with explicit ID sources | | [src/functions/providers/](src/functions/providers/) | Adapter manifests and API-specific implementations | | [test/](test/) | Representative offline checks | diff --git a/javascript/src/functions/SendOtp.js b/javascript/src/functions/SendOtp.js index c207de3..65a466e 100644 --- a/javascript/src/functions/SendOtp.js +++ b/javascript/src/functions/SendOtp.js @@ -14,41 +14,48 @@ const { MODE, } = require('./dispatch'); const { readConfig } = require('./config'); +const { RequestLog } = require('./requestLog'); app.http('SendOtp', { methods: ['POST'], authLevel: 'anonymous', // Protected by platform authentication in Azure. handler: async (request, context) => { - const started = Date.now(); const requestId = crypto.randomUUID(); - let correlationId = requestId; + const msRequestId = request.headers.get('x-ms-client-request-id'); + const headerCorrelationId = request.headers.get('x-ms-correlation-id') || null; + const log = new RequestLog(context, requestId, msRequestId, headerCorrelationId); + let correlationId = headerCorrelationId || requestId; let evaluation = false; let httpStatus = 500; const respond = (status, jsonBody) => { httpStatus = status; + log.responsePrepared(status, Object.hasOwn(jsonBody, 'nonce'), Object.hasOwn(jsonBody, 'correlationId')); return { status, jsonBody }; }; try { + log.service('request_received'); const config = readConfig(); - const clientRequestId = request.headers.get('x-ms-client-request-id') || requestId; - const headerCorrelationId = request.headers.get('x-ms-correlation-id') || null; - correlationId = headerCorrelationId || requestId; + const clientRequestId = msRequestId || requestId; let payload; try { payload = JSON.parse(await request.text()); } catch { + log.failure('request_validation', 'invalid JSON body', 400); return respond(400, { error: 'bad_request', reason: 'invalid JSON body', requestId }); } const parsed = parseEnvelope(payload); if (parsed.error) { + log.failure('request_validation', parsed.error, 400); return respond(400, { error: 'bad_request', reason: parsed.error, requestId }); } const envelope = parsed.envelope; correlationId = envelope.correlationId || headerCorrelationId || requestId; evaluation = envelope.mode === MODE.EVALUATION; + log.envelopeValidated(envelope, envelope.correlationId || headerCorrelationId, + envelope.correlationId ? 'envelope' : 'header'); let delivery; let header; @@ -56,15 +63,18 @@ app.http('SendOtp', { ({ context: delivery, header } = await decryptDeliveryContext( envelope.encryptedDeliveryContext, config)); } catch { + log.failure('decryption', 'decryption_failed', 400); return respond(400, { error: 'decryption_failed', correlationId, requestId }); } + log.service('delivery_context_decrypted'); // Key ID is advisory after authenticated decryption. if (config.expectedKeyId && config.expectedKeyId !== header.kid) { - context.warn('encryption_key_id_mismatch'); + log.keyIdMismatch(); } if (!delivery?.isComplete) { + log.failure('delivery_context_validation', 'incomplete delivery context', 400); return respond(400, { error: 'bad_request', reason: 'incomplete delivery context', correlationId, requestId }); } @@ -72,25 +82,24 @@ app.http('SendOtp', { if (!evaluation) { const dispatch = contextToDispatch(delivery, envelope, clientRequestId); dispatch.correlationId = correlationId; - const result = await dispatchOtp(dispatch, { requestId, config }).catch(() => ({ httpStatus: 500 })); + const result = await dispatchOtp(dispatch, { requestId, config, log }).catch(() => { + if (!log.data.failureStage) log.failure('provider_dispatch', 'unexpected_error', 500); + return { httpStatus: 500 }; + }); if (result.httpStatus !== 200) { return respond(result.httpStatus, { error: 'provider_delivery_failed', correlationId, requestId }); } + } else { + log.service('evaluation_completed'); } // Only a successful delivery (or validated evaluation) may echo the nonce and accepted. return respond(200, { nonce: delivery.nonce, correlationId, providerStatus: 'accepted' }); } catch { + if (!log.data.failureStage) log.failure('handler', 'unexpected_error', 500); return respond(500, { error: 'delivery_failed', correlationId, requestId }); } finally { - const rawId = typeof correlationId === 'string' ? correlationId : JSON.stringify(correlationId); - context.log({ - requestId, - correlationId: crypto.createHash('sha256').update(rawId).digest('hex').slice(0, 16), - httpStatus, - elapsedMs: Date.now() - started, - evaluation, - }); + log.complete(httpStatus); } }, }); diff --git a/javascript/src/functions/dispatch.js b/javascript/src/functions/dispatch.js index 492d165..2ae8971 100644 --- a/javascript/src/functions/dispatch.js +++ b/javascript/src/functions/dispatch.js @@ -315,7 +315,7 @@ function isValidProviderUrl(value) { } } -async function fetchWithTimeout(providerRequest, timeoutMilliseconds) { +async function fetchWithTimeout(providerRequest, timeoutMilliseconds, log) { const abortController = new AbortController(); let timedOut = false; const timeoutTimer = setTimeout(() => { @@ -324,6 +324,7 @@ async function fetchWithTimeout(providerRequest, timeoutMilliseconds) { }, timeoutMilliseconds); try { + log?.providerRequestStarted(timeoutMilliseconds); const response = await fetch(providerRequest.url, { method: providerRequest.method || 'POST', headers: providerRequest.headers, @@ -331,6 +332,7 @@ async function fetchWithTimeout(providerRequest, timeoutMilliseconds) { signal: abortController.signal, redirect: 'manual', // Never forward provider credentials to a redirect target. }); + log?.providerResponseReceived(response.status); const responseText = await response.text(); return { response, responseText }; } catch { @@ -339,6 +341,7 @@ async function fetchWithTimeout(providerRequest, timeoutMilliseconds) { throw error; } finally { clearTimeout(timeoutTimer); + log?.providerRequestFinished(); } } @@ -346,48 +349,58 @@ const failBody = (providerId, channel, reason, dispatch, requestId) => ({ status: 'failed', outcome: OUTCOME.FAIL, provider: providerId, channel, reason, correlationId: dispatch.correlationId, messageId: dispatch.messageId, requestId }); async function sendViaProvider(providerEntry, dispatch, options) { - const { requestId, config } = options; + const { requestId, config, log } = options; const { manifest, adapter } = providerEntry; const providerId = manifest.id; const channel = dispatch.channel === undefined ? 'sms' : (typeof dispatch.channel === 'string' ? dispatch.channel.toLowerCase() : null); if (!['sms', 'voice'].includes(channel)) { + log?.failure('provider_configuration', 'unsupported_channel', 400); return { httpStatus: 400, body: { status: 'error', reason: 'unsupported channel', requestId } }; } if (config.providerChannel && config.providerChannel !== channel) { + log?.failure('provider_configuration', 'channel_not_configured', 400); return { httpStatus: 400, body: { status: 'error', provider: providerId, reason: 'channel not configured', requestId } }; } if (config.providerAuthMode && config.providerAuthMode !== manifest.auth?.mode) { + log?.failure('provider_configuration', 'authentication_mode_mismatch', 502); return { httpStatus: 502, body: failBody(providerId, channel, 'provider authentication mismatch', dispatch, requestId) }; } if (channel === 'voice' && manifest.requiresTextToVoice && (!(dispatch.textToVoice instanceof TextToVoice) || !dispatch.textToVoice.isComplete)) { + log?.failure('provider_request_build', 'incomplete_voice_context', 400); return { httpStatus: 400, body: failBody(providerId, channel, 'incomplete voice context', dispatch, requestId) }; } const endpointBaseUrl = config.providerEndpoint; if (!isValidProviderUrl(endpointBaseUrl)) { + log?.failure('provider_configuration', 'invalid_provider_endpoint', 502); return { httpStatus: 502, body: failBody(providerId, channel, 'provider endpoint missing or invalid', dispatch, requestId) }; } let credential = null; try { + log?.credentialResolutionStarted(config); credential = await resolveProviderCredential(manifest.auth, config); } catch { - // Configuration and secret lookup failures share a generic failure response. + log?.failure('provider_credentials', 'credential_unavailable', 502); + return { httpStatus: 502, body: failBody(providerId, channel, 'provider credential unavailable', dispatch, requestId) }; } const identityRequired = credential?.mode === 'apiKey' && !!manifest.auth?.identityKeyVaultSecretName; const credentialUnavailable = !credential || (credential.mode === 'apiKey' && (!credential.secret || (identityRequired && !credential.identity))) || (credential.mode === 'oauth' && !credential.accessToken); if (credentialUnavailable) { + log?.failure('provider_credentials', 'credential_unavailable', 502); return { httpStatus: 502, body: failBody(providerId, channel, 'provider credential unavailable', dispatch, requestId) }; } + log?.credentialResolved(); let providerRequest; try { + log?.service('provider_request_build_started'); providerRequest = adapter.buildRequest({ channel, endpoint: endpointBaseUrl, @@ -396,38 +409,54 @@ async function sendViaProvider(providerEntry, dispatch, options) { env: config.env, }); } catch { + log?.failure('provider_request_build', 'request_build_failed', 502); return { httpStatus: 502, body: failBody(providerId, channel, 'provider request failed', dispatch, requestId) }; } if (!isValidProviderUrl(providerRequest.url)) { + log?.failure('provider_request_build', 'invalid_provider_request_url', 502); return { httpStatus: 502, body: failBody(providerId, channel, 'provider request URL invalid', dispatch, requestId) }; } + log?.providerRequestBuilt(providerRequest.method || 'POST', providerRequest.url); const timeoutMilliseconds = parseProviderTimeout(config.providerTimeoutMs); let providerResponse; let responseText; try { - ({ response: providerResponse, responseText } = await fetchWithTimeout(providerRequest, timeoutMilliseconds)); + ({ response: providerResponse, responseText } = await fetchWithTimeout(providerRequest, timeoutMilliseconds, log)); } catch (error) { const isTimeout = error.name === 'TimeoutError'; const httpStatus = isTimeout ? 504 : 502; + log?.failure('provider_transport', isTimeout ? 'provider_timeout' : 'provider_network_error', httpStatus); return { httpStatus, body: failBody(providerId, channel, isTimeout ? 'provider request timed out' : 'provider request failed', dispatch, requestId) }; } let responseJson; + let validJson = true; try { responseJson = JSON.parse(responseText); } catch { + validJson = false; + log?.service('provider_response_invalid_json', {}, 'warn'); responseJson = {}; } - const parsedResponse = adapter.parseResponse({ - httpStatus: providerResponse.status, - ok: providerResponse.ok, - json: responseJson, - }); - const outcome = resolveOutcome(manifest, parsedResponse); - const httpStatus = outcomeToHttpStatus(outcome, parsedResponse.providerHttpStatus); + let parsedResponse; + let outcome; + let httpStatus; + try { + parsedResponse = adapter.parseResponse({ + httpStatus: providerResponse.status, + ok: providerResponse.ok, + json: responseJson, + }); + outcome = resolveOutcome(manifest, parsedResponse); + httpStatus = outcomeToHttpStatus(outcome, parsedResponse.providerHttpStatus); + } catch (error) { + log?.failure('provider_response', 'response_parse_failed', 500); + throw error; + } + log?.providerResponseProcessed(manifest, parsedResponse, outcome, httpStatus, validJson); return { httpStatus, @@ -443,15 +472,17 @@ async function sendViaProvider(providerEntry, dispatch, options) { }; } -async function dispatchOtp(dispatch, { config = readConfig(), requestId } = {}) { +async function dispatchOtp(dispatch, { config = readConfig(), requestId, log } = {}) { const providerEntry = getProvider(config.providerName); if (!providerEntry) { + log?.failure('provider_selection', 'unknown_provider', 400); return { httpStatus: 400, body: { status: 'error', reason: 'unknown provider', requestId }, }; } - return sendViaProvider(providerEntry, dispatch, { config, requestId }); + log?.providerSelected(providerEntry.manifest); + return sendViaProvider(providerEntry, dispatch, { config, requestId, log }); } module.exports = { diff --git a/javascript/src/functions/requestLog.js b/javascript/src/functions/requestLog.js new file mode 100644 index 0000000..02e2499 --- /dev/null +++ b/javascript/src/functions/requestLog.js @@ -0,0 +1,234 @@ +// +// Copyright (c) Microsoft Corporation. All rights reserved. +// + +'use strict'; + +const { performance } = require('node:perf_hooks'); + +const contextFields = [ + 'functionName', 'functionRequestId', 'functionInvocationId', + 'x-ms-client-request-id', 'x-ms-correlation-id', 'msCorrelationIdSource', 'omittedIdFields', + 'channel', 'evaluation', 'providerName', +]; +const credentialFields = [ + 'providerAuthMode', 'providerCredentialSource', 'providerTenantId', + 'functionOutboundClientId', 'functionOutboundManagedIdentityClientId', +]; +const httpMethods = new Set(['GET', 'HEAD', 'POST', 'PUT', 'DELETE', 'CONNECT', 'OPTIONS', 'TRACE', 'PATCH']); + +const identifierPattern = /^[A-Za-z0-9][A-Za-z0-9._:-]{0,127}$/; + +// Only explicitly selected metadata enters logs; never serialize request/provider models. +class RequestLog { + constructor(context, requestId, msRequestId, msCorrelationId) { + this.context = context; + this.started = performance.now(); + this.providerStarted = null; + this.credentialStarted = null; + this.data = { + functionName: 'SendOtp', + functionRequestId: requestId, + functionInvocationId: context.invocationId || null, + 'x-ms-client-request-id': null, + 'x-ms-correlation-id': null, + msCorrelationIdSource: 'none', + omittedIdFields: [], + envelopeType: null, + ttlSeconds: null, + channel: null, + evaluation: null, + encryptionKeyIdMismatch: false, + providerName: null, + providerAuthMode: null, + providerCredentialSource: null, + providerCredentialElapsedMs: null, + providerTenantId: null, + functionOutboundClientId: null, + functionOutboundManagedIdentityClientId: null, + providerHttpMethod: null, + providerEndpoint: null, + providerAttempted: false, + providerHttpStatus: null, + providerStatus: null, + providerOutcome: null, + providerMessageId: null, + providerElapsedMs: null, + providerTimeoutMs: null, + failureStage: null, + failureReason: null, + responseContainsNonce: null, + responseContainsCorrelationId: null, + }; + this.setIdentifier('x-ms-client-request-id', msRequestId); + this.setIdentifier('x-ms-correlation-id', msCorrelationId); + this.data.msCorrelationIdSource = this.data['x-ms-correlation-id'] ? 'header' : 'none'; + } + + setIdentifier(field, value) { + const valid = typeof value === 'string' && value.length <= 128 && identifierPattern.exec(value)?.[0] === value; + this.data[field] = valid ? value : null; + this.data.omittedIdFields = this.data.omittedIdFields.filter((name) => name !== field); + if (!valid && value != null && !(typeof value === 'string' && !value.trim())) { + this.data.omittedIdFields.push(field); + } + } + + service(eventName, details = {}, level = 'log') { + const context = Object.fromEntries(contextFields.map((key) => [key, this.data[key]])); + this.context[level](JSON.stringify({ + logType: 'service', eventName, ...context, ...details, + elapsedMs: Math.floor(performance.now() - this.started), + })); + } + + envelopeValidated(envelope, correlationId, source) { + this.data.envelopeType = envelope.type; + this.data.ttlSeconds = envelope.ttlSeconds ?? null; + this.data.channel = envelope.channel === 1 ? 'sms' : 'voice'; + this.data.evaluation = envelope.mode === 2; + this.setIdentifier('x-ms-correlation-id', correlationId); + this.data.msCorrelationIdSource = this.data['x-ms-correlation-id'] ? source : 'none'; + this.service('envelope_validated', { + envelopeType: this.data.envelopeType, + ttlSeconds: this.data.ttlSeconds, + encryptedDeliveryContextPresent: true, + }); + } + + keyIdMismatch() { + this.data.encryptionKeyIdMismatch = true; + this.service('encryption_key_id_mismatch', {}, 'warn'); + } + + providerSelected(manifest) { + this.data.providerName = manifest.id; + this.data.providerAuthMode = ['apiKey', 'oauth'].includes(manifest.auth?.mode) + ? manifest.auth.mode : 'unsupported'; + this.service('provider_selected', { providerAuthMode: this.data.providerAuthMode }); + } + + credentialResolutionStarted(config) { + this.credentialStarted = performance.now(); + const oauth = this.data.providerAuthMode === 'oauth'; + this.data.providerCredentialSource = oauth ? 'managed_identity_client_assertion' + : this.data.providerAuthMode === 'apiKey' ? 'key_vault' : 'unsupported'; + if (oauth) { + this.setIdentifier('providerTenantId', config.providerTenantId); + this.setIdentifier('functionOutboundClientId', config.outboundClientId); + this.setIdentifier('functionOutboundManagedIdentityClientId', config.outboundManagedIdentityClientId); + } + this.service('provider_credential_resolution_started', this.credentialDetails()); + } + + credentialDetails() { + return Object.fromEntries(credentialFields.map((key) => [key, this.data[key]])); + } + + credentialResolutionFinished() { + if (this.credentialStarted !== null) { + this.data.providerCredentialElapsedMs = Math.floor(performance.now() - this.credentialStarted); + this.credentialStarted = null; + } + } + + credentialResolved() { + this.credentialResolutionFinished(); + this.service('provider_credential_resolved', { + ...this.credentialDetails(), + providerCredentialElapsedMs: this.data.providerCredentialElapsedMs, + }); + } + + providerRequestBuilt(method, endpoint) { + const normalizedMethod = typeof method === 'string' ? method.toUpperCase() : null; + this.data.providerHttpMethod = httpMethods.has(normalizedMethod) ? normalizedMethod : 'other'; + const url = new URL(endpoint); + this.data.providerEndpoint = `${url.protocol}//${url.host}${url.pathname}`; + this.service('provider_request_built', { + providerHttpMethod: this.data.providerHttpMethod, + providerEndpoint: this.data.providerEndpoint, + providerScheme: 'https', + redirectsAllowed: false, + }); + } + + providerRequestStarted(timeoutMs) { + this.providerStarted = performance.now(); + this.data.providerAttempted = true; + this.data.providerTimeoutMs = timeoutMs; + this.service('provider_request_started', { + providerTimeoutMs: timeoutMs, + providerHttpMethod: this.data.providerHttpMethod, + providerEndpoint: this.data.providerEndpoint, + }); + } + + providerResponseReceived(status) { + this.data.providerHttpStatus = status; + this.service('provider_response_received', { providerHttpStatus: status }); + } + + providerRequestFinished() { + if (this.providerStarted !== null) { + this.data.providerElapsedMs = Math.floor(performance.now() - this.providerStarted); + this.providerStarted = null; + } + } + + providerResponseProcessed(manifest, parsed, outcome, httpStatus, validJson) { + const status = parsed.providerStatusName || parsed.providerStatusCode; + const knownStatus = (typeof status === 'string' || typeof status === 'number') + && status !== 'default' && Object.hasOwn(manifest.responseMapping || {}, status); + this.data.providerStatus = knownStatus ? String(status) : 'unmapped'; + this.data.providerOutcome = outcome; + this.setIdentifier('providerMessageId', parsed.providerMessageId); + if (outcome !== 'Continue') { + this.data.failureStage = 'provider_response'; + this.data.failureReason = validJson ? 'provider_rejected' : 'invalid_provider_json'; + } + this.service('provider_response_processed', { + providerHttpStatus: this.data.providerHttpStatus, + providerStatus: this.data.providerStatus, + providerOutcome: outcome, + providerMessageId: this.data.providerMessageId, + providerElapsedMs: this.data.providerElapsedMs, + httpStatus, + failureReason: this.data.failureReason, + }, httpStatus >= 500 ? 'error' : httpStatus === 200 ? 'log' : 'warn'); + } + + failure(stage, reason, httpStatus) { + this.credentialResolutionFinished(); + this.providerRequestFinished(); + this.data.failureStage = stage; + this.data.failureReason = reason; + this.service(`${stage}_failed`, { failureReason: reason, httpStatus }, + httpStatus >= 500 ? 'error' : 'warn'); + } + + responsePrepared(httpStatus, containsNonce, containsCorrelationId) { + this.data.responseContainsNonce = containsNonce; + this.data.responseContainsCorrelationId = containsCorrelationId; + this.service('response_prepared', { + httpStatus, + responseContainsNonce: containsNonce, + responseContainsCorrelationId: containsCorrelationId, + }); + } + + complete(httpStatus) { + this.credentialResolutionFinished(); + this.providerRequestFinished(); + this.context.log(JSON.stringify({ + logType: 'request', + eventName: 'request_completed', + ...this.data, + httpStatus, + result: httpStatus === 200 ? (this.data.evaluation ? 'evaluated' : 'accepted') : 'failed', + elapsedMs: Math.floor(performance.now() - this.started), + })); + } +} + +module.exports = { RequestLog }; diff --git a/javascript/test/sendotp.test.js b/javascript/test/sendotp.test.js index 5ff12d7..14454af 100644 --- a/javascript/test/sendotp.test.js +++ b/javascript/test/sendotp.test.js @@ -8,6 +8,8 @@ const { CompactEncrypt } = require('jose'); const { ClientAssertionCredential, ManagedIdentityCredential } = require('@azure/identity'); const { SecretClient } = require('@azure/keyvault-secrets'); const fixtures = require('../../tests/fixtures/contract.json'); +const { getProvider } = require('../src/functions/dispatch'); +const { RequestLog } = require('../src/functions/requestLog'); // Capture the real handler; keys stay in memory and all external I/O is mocked. const { publicKey, privateKey } = crypto.generateKeyPairSync('rsa', { modulusLength: 2048 }); @@ -25,7 +27,7 @@ try { registration.mock.restore(); } -const envKeys = ['EPP_ENCRYPTION_KEY_ID', 'AZURE_CLIENT_ID', 'EPP_PROVIDER_NAME', 'EPP_PROVIDER_ENDPOINT', +const envKeys = ['EPP_ENCRYPTION_KEY_ID', 'AZURE_CLIENT_ID', 'EPP_PROVIDER_NAME', 'EPP_PROVIDER_ENDPOINT', 'EPP_PROVIDER_CHANNEL', 'EPP_PROVIDER_TIMEOUT_MS', 'EPP_PROVIDER_AUTH_MODE', 'EPP_PROVIDER_TENANT_ID', 'EPP_PROVIDER_SCOPE', 'EPP_OUTBOUND_CLIENT_ID', 'EPP_OUTBOUND_MI_CLIENT_ID', 'EPP_LOG_PLAINTEXT', 'KEY_VAULT_URL', 'EPP_DECRYPTION_KEY_PEM']; @@ -34,6 +36,7 @@ let fetchMock; let getSecret; let logs; let warnings; +let records; let getToken; beforeEach(() => { savedEnv = Object.fromEntries(envKeys.map((key) => [key, process.env[key]])); @@ -55,7 +58,7 @@ beforeEach(() => { }); getSecret = mock.method(SecretClient.prototype, 'getSecret', async () => ({ value: 'PRIVATE-API-KEY' })); fetchMock = mock.method(global, 'fetch', async () => ({ ok: true, status: 201, - text: async () => JSON.stringify({ status: 'ENROUTE', id: 'PRIVATE-ID', description: 'PRIVATE-STATUS' }) })); + text: async () => JSON.stringify({ status: 'ENROUTE', id: 'provider-reference-id', description: 'PRIVATE-STATUS' }) })); }); afterEach(() => { mock.restoreAll(); @@ -77,10 +80,46 @@ async function envelope(overrides = {}, context = delivery, header = {}) { const invoke = (body, headers = {}) => { logs = []; warnings = []; + records = []; + const capture = (level) => (value) => { + const record = JSON.parse(value); + records.push(record); + if (level === 'log') logs.push(record); + if (level === 'warn') warnings.push(record); + }; return handler({ headers: { get: (name) => headers[name.toLowerCase()] || null }, text: async () => typeof body === 'string' ? body : JSON.stringify(body) }, - { log: (value) => logs.push(value), warn: (...values) => warnings.push(values) }); + { invocationId: 'function-invocation-id', log: capture('log'), warn: capture('warn'), error: capture('error') }) + .then((result) => { + const record = summary(); + assert.deepEqual(Object.keys(record).sort(), [...fixtures.logging.summaryFields].sort()); + assert.equal(records.at(-1), record); + assert.equal(record.httpStatus, result.status); + assert.equal(record.responseContainsNonce, Object.hasOwn(result.jsonBody, 'nonce')); + assert.equal(record.responseContainsCorrelationId, Object.hasOwn(result.jsonBody, 'correlationId')); + const prepared = records.filter((event) => event.eventName === 'response_prepared'); + assert.equal(prepared.length, 1); + assert.equal(prepared[0], records.at(-2)); + assert.equal(prepared[0].httpStatus, result.status); + assert.equal(prepared[0].responseContainsNonce, record.responseContainsNonce); + assert.equal(prepared[0].responseContainsCorrelationId, record.responseContainsCorrelationId); + assert.ok(record.elapsedMs >= 0); + for (const event of records) { + assert.equal(event.functionRequestId, record.functionRequestId); + assert.equal(event.functionInvocationId, 'function-invocation-id'); + assert.equal(event.functionName, 'SendOtp'); + } + assert.doesNotMatch(JSON.stringify(records), /PRIVATE|FORGED|918273|15551234567/); + return result; + }); }; +function summary() { + const summaries = records.filter((record) => record.logType === 'request'); + assert.equal(summaries.length, 1); + assert.equal(summaries[0].eventName, 'request_completed'); + assert.equal(records.filter((record) => record.logType === 'service').length, records.length - 1); + return summaries[0]; +} function assertFailure(result, status, error = 'provider_delivery_failed') { assert.equal(result.status, status); assert.equal(result.jsonBody.error, error); @@ -114,7 +153,7 @@ test('real JWE requires five segments and rejects a bad tag', async () => { for (const invalid of [{ ...body, encryptedDeliveryContext: parts.join('.') }, { ...body, encryptedDeliveryContext: parts.slice(0, 4).join('.') }]) { assertFailure(await invoke(invalid), 400, 'decryption_failed'); - assert.deepEqual(warnings, []); + assert.equal(warnings.some((record) => record.eventName === 'encryption_key_id_mismatch'), false); } assert.deepEqual([getSecret.mock.callCount(), fetchMock.mock.callCount()], [0, 0]); }); @@ -162,8 +201,20 @@ test('evaluation decrypts without provider config or I/O and checks the advisory const result = await invoke(await envelope({ mode: 'evaluation', provider: 'unknown' })); assert.equal(result.status, 200); assert.deepEqual(result.jsonBody, { nonce: delivery.nonce, correlationId: 'correlation-id', providerStatus: 'accepted' }); - assert.equal(logs[0].evaluation, true); - assert.deepEqual(warnings, expectedKeyId === 'private-kid' ? [['encryption_key_id_mismatch']] : []); + assert.equal(summary().evaluation, true); + assert.equal(summary().result, 'evaluated'); + assert.equal(summary().providerAttempted, false); + assert.equal(summary().providerName, null); + assert.equal(summary().providerHttpStatus, null); + assert.equal(summary().providerElapsedMs, null); + assert.equal(summary().providerCredentialSource, null); + assert.equal(summary().providerCredentialElapsedMs, null); + assert.equal(summary().providerEndpoint, null); + assert.deepEqual(warnings.map((record) => record.eventName), + expectedKeyId === 'private-kid' ? ['encryption_key_id_mismatch'] : []); + assert.equal(summary().encryptionKeyIdMismatch, expectedKeyId === 'private-kid'); + assert.deepEqual(records.filter((record) => record.eventName !== 'encryption_key_id_mismatch') + .map((record) => record.eventName), fixtures.logging.evaluationEvents); } assert.deepEqual([getSecret.mock.callCount(), fetchMock.mock.callCount()], [0, 0]); assert.equal(getToken.mock.callCount(), 0); @@ -175,13 +226,18 @@ test('Soprano OAuth failures never fall back to keys or forward an inbound token getToken.mock.mockImplementation(failure); assertFailure(await invoke(await envelope({}, { ...delivery, providerJwt: 'FORGED-PAYLOAD' }), { authorization: 'Bearer FORGED-INBOUND' }), 502); - assert.doesNotMatch(JSON.stringify([logs, warnings]), /PRIVATE|FORGED/); + assert.equal(summary().failureStage, 'provider_credentials'); + assert.equal(summary().failureReason, 'credential_unavailable'); + assert.equal(summary().providerAttempted, false); + assert.equal(summary().providerCredentialSource, 'managed_identity_client_assertion'); + assert.ok(summary().providerCredentialElapsedMs >= 0); + assert.equal(records.some((record) => record.eventName === 'provider_credential_resolved'), false); } assert.deepEqual([getSecret.mock.callCount(), fetchMock.mock.callCount()], [0, 0]); }); test('SMS/voice preserve content and correlation without reflecting headers or logging PII', async () => { - const correlationId = 'PRIVATE-CORRELATION'; + const correlationId = 'support-correlation-id'; const forgedHeaders = { authorization: 'Bearer FORGED-BEARER', 'x-ms-client-principal': Buffer.from(JSON.stringify({ claims: [{ typ: 'appid', val: 'FORGED-CALLER' }], @@ -212,9 +268,19 @@ test('SMS/voice preserve content and correlation without reflecting headers or l assert.deepEqual(init.headers, { 'Content-Type': 'application/json', Accept: 'application/json', Authorization: 'Bear' + 'er PRIVATE-OAUTH-TOKEN' }); assert.equal(init.redirect, 'manual'); - assert.equal(logs.length, 1); - assert.deepEqual(Object.keys(logs[0]).sort(), ['correlationId', 'elapsedMs', 'evaluation', 'httpStatus', 'requestId']); - assert.equal(logs[0].correlationId, crypto.createHash('sha256').update(correlationId).digest('hex').slice(0, 16)); + assert.deepEqual(records.map((record) => record.eventName), fixtures.logging.liveEvents); + assert.equal(summary()['x-ms-correlation-id'], correlationId); + assert.equal(summary().providerName, 'soprano'); + assert.equal(summary().providerAuthMode, 'oauth'); + assert.equal(summary().providerMessageId, 'provider-reference-id'); + assert.equal(summary().providerHttpStatus, 201); + assert.equal(summary().providerStatus, 'ENROUTE'); + assert.equal(summary().providerOutcome, 'Continue'); + assert.equal(summary().channel, name); + assert.equal(summary().providerAttempted, true); + assert.equal(summary().providerTimeoutMs, 1500); + assert.ok(summary().providerElapsedMs >= 0 && summary().providerElapsedMs <= summary().elapsedMs); + assert.equal(summary().failureStage, null); assert.doesNotMatch(JSON.stringify(logs), /PRIVATE|918273|001234|15551234567/); const output = JSON.stringify([result.jsonBody, logs, warnings]); assert.doesNotMatch(output, /FORGED/); @@ -230,7 +296,7 @@ test('Telesign EPP sends decrypted SMS and voice content with Basic auth and pri for (const [channel, name, code] of [[1, 'sms', 290], [2, 'voice', 100], [1, 'sms', 3001], [2, 'voice', 3001]]) { fetchMock.mock.mockImplementation(async () => ({ ok: true, status: 200, - text: async () => JSON.stringify({ reference_id: 'PRIVATE-REFERENCE', correlation_id: 'provider-correlation', + text: async () => JSON.stringify({ reference_id: 'telesign-reference-id', correlation_id: 'provider-correlation', status: { code, description: 'PRIVATE-STATUS' } }) })); const result = await invoke(await envelope({ channel }), { authorization: 'Bearer FORGED-TOKEN', 'x-shutter-mode': 'true' }); assert.deepEqual(result.jsonBody, { nonce: delivery.nonce, correlationId: 'correlation-id', providerStatus: 'accepted' }); @@ -247,6 +313,8 @@ test('Telesign EPP sends decrypted SMS and voice content with Basic auth and pri assert.equal(init.redirect, 'manual'); assert.doesNotMatch(JSON.stringify(logs), /PRIVATE|918273|15551234567|FORGED/); assert.equal(result.jsonBody.reference_id, undefined); + assert.equal(summary().providerStatus, String(code)); + assert.equal(summary().providerMessageId, 'telesign-reference-id'); } assert.equal(fetchMock.mock.callCount(), 4); }); @@ -273,6 +341,10 @@ test('Telesign missing status or upstream failure never acknowledges delivery', [401, { status: { code: 3001 } }, 401], [429, { status: { code: 3001 } }, 429]]) { fetchMock.mock.mockImplementation(async () => ({ ok: status === 200, status, text: async () => JSON.stringify(payload) })); assertFailure(await invoke(await envelope()), expected); + assert.equal(summary().providerHttpStatus, status); + assert.equal(summary().providerOutcome, 'Fail'); + assert.equal(summary().failureStage, 'provider_response'); + assert.equal(summary().failureReason, 'provider_rejected'); } assert.equal(fetchMock.mock.callCount(), 6); }); @@ -290,7 +362,9 @@ test('handler awaits the provider body and returns 502/429 without a nonce or re try { await started; assert.equal(settled, false); - assert.deepEqual(logs, []); + assert.equal(records.some((record) => record.logType === 'request'), false); + assert.equal(records.at(-1).eventName, 'provider_response_received'); + assert.ok(records.some((record) => record.eventName === 'provider_request_started')); } finally { release(JSON.stringify({ status: 'ENROUTE', description: 'PRIVATE-STATUS' })); } @@ -312,4 +386,241 @@ test('the real abort timer covers response-body reading: 504, no retry and no no assertFailure(await invoke(await envelope()), 504); assert.equal(fetchMock.mock.callCount(), 1); assert.equal(fetchMock.mock.calls[0].arguments[1].signal.aborted, true); + assert.equal(summary().failureStage, 'provider_transport'); + assert.equal(summary().failureReason, 'provider_timeout'); + assert.equal(summary().providerHttpStatus, 200); + assert.equal(summary().providerTimeoutMs, 1); + assert.equal(summary().providerStatus, null); + assert.ok(summary().providerElapsedMs >= 0); +}); + +test('Microsoft, function and provider identifiers have distinct sources and no synthetic Microsoft IDs', async () => { + const headers = { 'x-ms-client-request-id': 'ms-request-id', 'x-ms-correlation-id': 'ms-header-correlation-id' }; + for (const correlationId of ['ms-envelope-correlation-id', null]) { + await invoke(await envelope({ correlationId }), headers); + assert.equal(summary()['x-ms-client-request-id'], headers['x-ms-client-request-id']); + assert.equal(summary()['x-ms-correlation-id'], correlationId || headers['x-ms-correlation-id']); + assert.equal(summary().msCorrelationIdSource, correlationId ? 'envelope' : 'header'); + assert.equal(records[0].msCorrelationIdSource, 'header'); + assert.notEqual(summary().functionRequestId, summary()['x-ms-client-request-id']); + assert.notEqual(summary().functionRequestId, summary().functionInvocationId); + } + const result = await invoke(await envelope({ correlationId: null })); + assert.equal(result.jsonBody.correlationId, summary().functionRequestId); + assert.equal(summary()['x-ms-client-request-id'], null); + assert.equal(summary()['x-ms-correlation-id'], null); + assert.equal(summary().msCorrelationIdSource, 'none'); +}); + +test('early failures keep incoming Microsoft trace IDs and a fixed failure stage', async () => { + const headers = { 'x-ms-client-request-id': 'ms-request-id', 'x-ms-correlation-id': 'ms-header-correlation-id' }; + for (const [body, stage, reason] of [ + ['{', 'request_validation', 'invalid JSON body'], + [{}, 'request_validation', 'unsupported envelope type'], + [await envelope({ encryptedDeliveryContext: 'PRIVATE-NOT-A-JWE' }), 'decryption', 'decryption_failed'], + [await envelope({}, { ...delivery, nonce: '' }), 'delivery_context_validation', 'incomplete delivery context'], + ]) { + const result = await invoke(body, headers); + assert.equal(result.status, 400); + assert.equal(summary().functionRequestId, result.jsonBody.requestId); + assert.equal(summary()['x-ms-client-request-id'], headers['x-ms-client-request-id']); + assert.equal(summary().failureStage, stage); + assert.equal(summary().msCorrelationIdSource, stage === 'request_validation' ? 'header' : 'envelope'); + assert.equal(summary()['x-ms-correlation-id'], + stage === 'request_validation' ? headers['x-ms-correlation-id'] : 'correlation-id'); + assert.equal(summary().failureReason, reason); + assert.equal(summary().providerAttempted, false); + assert.equal(records.at(-3).eventName, `${stage}_failed`); + } +}); + +test('invalid correlation metadata cannot become a raw log field or prevent the request summary', async () => { + for (const correlationId of [42, { detail: 'support-correlation-id' }, ['support-correlation-id'], '']) { + const result = await invoke(await envelope({ mode: 2, correlationId })); + assert.equal(result.status, 200); + assert.equal(summary()['x-ms-correlation-id'], null); + assert.equal(summary().msCorrelationIdSource, 'none'); + } +}); + +for (const [name, configure, stage, reason, status] of [ + ['unknown provider', () => { process.env.EPP_PROVIDER_NAME = 'PRIVATE-UNKNOWN-PROVIDER'; }, + 'provider_selection', 'unknown_provider', 400], + ['wrong channel', () => { process.env.EPP_PROVIDER_CHANNEL = 'voice'; }, + 'provider_configuration', 'channel_not_configured', 400], + ['authentication mismatch', () => { process.env.EPP_PROVIDER_AUTH_MODE = 'apiKey'; }, + 'provider_configuration', 'authentication_mode_mismatch', 502], + ['invalid endpoint', () => { process.env.EPP_PROVIDER_ENDPOINT = 'http://PRIVATE-ENDPOINT'; }, + 'provider_configuration', 'invalid_provider_endpoint', 502], + ['request build failure', () => { + mock.method(getProvider('soprano').adapter, 'buildRequest', () => { throw new Error('PRIVATE-BUILD-ERROR'); }); + }, 'provider_request_build', 'request_build_failed', 502], + ['network failure', () => { + fetchMock.mock.mockImplementation(async () => { throw new Error('PRIVATE-NETWORK-ERROR'); }); + }, 'provider_transport', 'provider_network_error', 502], + ['adapter response failure', () => { + mock.method(getProvider('soprano').adapter, 'parseResponse', () => { throw new Error('PRIVATE-PARSE-ERROR'); }); + }, 'provider_response', 'response_parse_failed', 500], +]) { + test(`${name} emits its own service failure and a complete request summary`, async () => { + configure(); + assertFailure(await invoke(await envelope()), status); + assert.equal(summary().failureStage, stage); + assert.equal(summary().failureReason, reason); + assert.equal(records.at(-3).eventName, `${stage}_failed`); + const attempted = ['provider_transport', 'provider_response'].includes(stage); + assert.equal(summary().providerAttempted, attempted); + assert.equal(fetchMock.mock.callCount(), attempted ? 1 : 0); + }); +} + +test('unknown provider status and malformed provider JSON never become raw diagnostic fields', async () => { + for (const body of [JSON.stringify({ id: 'provider-reference-id', status: 'PRIVATE-STATUS\nFORGED', description: 'PRIVATE-DESCRIPTION' }), + 'PRIVATE-RESPONSE']) { + fetchMock.mock.mockImplementation(async () => ({ ok: true, status: 200, text: async () => body })); + assertFailure(await invoke(await envelope()), 502); + assert.equal(summary().providerStatus, 'unmapped'); + assert.equal(summary().providerOutcome, 'Fail'); + assert.equal(summary().failureReason, body.startsWith('{') ? 'provider_rejected' : 'invalid_provider_json'); + } +}); + +test('interleaved invocations retain their own log context and emit service events before completion', async () => { + const eventSets = [[], []]; + const invocations = ['function-one', 'function-two']; + const contexts = eventSets.map((events, index) => ({ + invocationId: invocations[index], + log: (value) => events.push(JSON.parse(value)), + warn: (value) => events.push(JSON.parse(value)), + error: (value) => events.push(JSON.parse(value)), + })); + const bodies = await Promise.all(['correlation-first', 'correlation-second'].map((correlationId) => envelope({ correlationId }))); + await Promise.all(bodies.map((body, index) => handler({ + headers: { get: () => null }, + text: async () => JSON.stringify(body), + }, contexts[index]))); + for (const [index, events] of eventSets.entries()) { + assert.deepEqual(events.map((event) => event.eventName), fixtures.logging.liveEvents); + const summary = events.at(-1); + assert.equal(summary['x-ms-correlation-id'], bodies[index].correlationId); + assert.ok(events.every((event) => event.functionRequestId === summary.functionRequestId + && event.functionInvocationId === invocations[index])); + } + assert.notEqual(eventSets[0].at(-1).functionRequestId, eventSets[1].at(-1).functionRequestId); + assert.doesNotMatch(JSON.stringify(eventSets), /PRIVATE/); +}); + +test('successful lifecycle logs allowed body fields, raw OAuth IDs and an endpoint without its query', async () => { + process.env.EPP_PROVIDER_ENDPOINT = 'https://provider.example/api/send?key=PRIVATE-QUERY'; + const body = await envelope({ + tenantId: 'PRIVATE-TENANT', + diagnosticData: { token: 'PRIVATE-UNKNOWN-FIELD' }, + }); + await invoke(body, { 'x-ms-client-principal': 'PRIVATE-PRINCIPAL', authorization: 'PRIVATE-INBOUND-AUTH' }); + const validated = records.find((record) => record.eventName === 'envelope_validated'); + assert.equal(validated.envelopeType, body.type); + assert.equal(validated.ttlSeconds, 60); + assert.equal(validated.encryptedDeliveryContextPresent, true); + assert.equal(summary().envelopeType, body.type); + assert.equal(summary().ttlSeconds, 60); + const source = 'managed_identity_client_assertion'; + for (const record of [summary(), ...records.filter((record) => + ['provider_credential_resolution_started', 'provider_credential_resolved'].includes(record.eventName))]) { + assert.equal(record.providerCredentialSource, source); + assert.equal(record.functionOutboundClientId, process.env.EPP_OUTBOUND_CLIENT_ID); + assert.equal(record.functionOutboundManagedIdentityClientId, process.env.EPP_OUTBOUND_MI_CLIENT_ID); + assert.equal(record.providerTenantId, process.env.EPP_PROVIDER_TENANT_ID); + } + assert.ok(summary().providerCredentialElapsedMs >= 0 && summary().providerCredentialElapsedMs <= summary().elapsedMs); + for (const record of [summary(), ...records.filter((record) => + ['provider_request_built', 'provider_request_started'].includes(record.eventName))]) { + assert.equal(record.providerHttpMethod, 'POST'); + assert.equal(record.providerEndpoint, 'https://provider.example/api/send'); + } + const built = records.find((record) => record.eventName === 'provider_request_built'); + assert.equal(built.providerScheme, 'https'); + assert.equal(built.redirectsAllowed, false); + const output = JSON.stringify(records); + for (const value of [body.encryptedDeliveryContext, process.env.EPP_PROVIDER_ENDPOINT]) { + assert.equal(output.includes(value), false); + } + assert.deepEqual(records.map((record) => record.eventName), fixtures.logging.liveEvents); +}); + +test('API-key resolution is identified as Key Vault even when a later request uses cached credentials', async () => { + process.env.EPP_PROVIDER_NAME = 'telesign'; + process.env.EPP_PROVIDER_AUTH_MODE = 'apiKey'; + process.env.KEY_VAULT_URL = 'https://logging-cache-test.vault.azure.net'; + fetchMock.mock.mockImplementation(async () => ({ ok: true, status: 200, + text: async () => JSON.stringify({ status: { code: 3001 } }) })); + for (let attempt = 0; attempt < 2; attempt++) { + await invoke(await envelope()); + assert.equal(summary().providerCredentialSource, 'key_vault'); + assert.equal(summary().providerAuthMode, 'apiKey'); + assert.equal(summary().providerTenantId, null); + assert.equal(summary().functionOutboundClientId, null); + assert.equal(summary().functionOutboundManagedIdentityClientId, null); + assert.ok(summary().providerCredentialElapsedMs >= 0); + assert.deepEqual(records.map((record) => record.eventName), fixtures.logging.liveEvents); + assert.equal(getSecret.mock.callCount(), 2); + } + assert.equal(getToken.mock.callCount(), 0); +}); + +test('optional TTL stays null and invalid body values never enter body metadata', async () => { + const body = await envelope({ mode: 2 }); + delete body.ttlSeconds; + assert.equal((await invoke(body)).status, 200); + assert.equal(summary().ttlSeconds, null); + assert.equal(records.find((record) => record.eventName === 'envelope_validated').ttlSeconds, null); + assert.equal((await invoke({ ...body, ttlSeconds: 'PRIVATE-INVALID-TTL' })).status, 400); + assert.equal(summary().envelopeType, null); + assert.equal(summary().ttlSeconds, null); + assert.equal(records.some((record) => record.eventName === 'envelope_validated'), false); +}); + +test('request preparation records the adapter final URL, not the configured base or an arbitrary HTTP verb', async () => { + const adapter = getProvider('soprano').adapter; + const buildRequest = adapter.buildRequest; + const finalUrl = 'https://different-provider.example/api/final?token=PRIVATE-TOKEN'; + mock.method(adapter, 'buildRequest', (options) => ({ + ...buildRequest(options), url: finalUrl, method: 'PRIVATE-METHOD', + })); + await invoke(await envelope()); + assert.equal(summary().providerEndpoint, 'https://different-provider.example/api/final'); + assert.equal(summary().providerHttpMethod, 'other'); + assert.notEqual(summary().providerEndpoint, process.env.EPP_PROVIDER_ENDPOINT); + assert.equal(fetchMock.mock.calls[0].arguments[0], finalUrl); +}); + +test('shared ID cases preserve raw support values or explicitly omit invalid metadata', () => { + const fields = ['x-ms-client-request-id', 'x-ms-correlation-id', 'providerTenantId', + 'functionOutboundClientId', 'functionOutboundManagedIdentityClientId', 'providerMessageId']; + const manifest = getProvider('soprano').manifest; + for (const fixture of fixtures.logging.identifiers) { + const value = fixture.length ? 'A'.repeat(fixture.length) : fixture.value; + const events = []; + const log = new RequestLog({ log: (record) => events.push(JSON.parse(record)) }, 'function-request', value, value); + log.providerSelected(manifest); + log.credentialResolutionStarted({ providerTenantId: value, outboundClientId: value, outboundManagedIdentityClientId: value }); + log.providerResponseProcessed(manifest, { providerStatusName: 'ENROUTE', providerMessageId: value }, 'Continue', 200, true); + log.complete(200); + const summary = events.at(-1); + for (const field of fields) assert.equal(summary[field], fixture.accepted ? value : null); + assert.deepEqual(summary.omittedIdFields, fixture.omitted ? fields : []); + assert.equal(events.some((event) => Object.keys(event).some((key) => key.endsWith('Hash'))), false); + assert.doesNotMatch(JSON.stringify(events), /PRIVATE/); + } +}); + +test('shared endpoint cases retain scheme host port and API path without credentials query or fragment', () => { + for (const fixture of fixtures.logging.endpoints) { + const events = []; + const log = new RequestLog({ log: (record) => events.push(JSON.parse(record)) }, 'function-request', null, null); + log.providerRequestBuilt('POST', fixture.url); + log.providerRequestStarted(1500); + log.complete(200); + assert.ok(events.every((event) => event.providerEndpoint === fixture.logged)); + assert.doesNotMatch(JSON.stringify(events), /PRIVATE/); + } }); diff --git a/python/README.md b/python/README.md index b9cc577..8702ead 100644 --- a/python/README.md +++ b/python/README.md @@ -96,6 +96,7 @@ six-digit numeric run that is not part of a longer number and repeats the comple | [src/config.py](src/config.py) | Shared deployment settings | | [src/models.py](src/models.py) | Envelope, delivery-context, dispatch and normalized `ParsedResponse` dataclasses | | [src/dispatch.py](src/dispatch.py) | Boundary validation, JWE, provider registry and outcome mapping | +| [src/request_log.py](src/request_log.py) | Request-scoped [service events and summaries](../docs/CONTRACT.md#application-logs) with explicit ID sources | | [src/providers/](src/providers/) | Adapter manifests and API-specific implementations | | [src/secrets.py](src/secrets.py) | Cached Key Vault access via managed identity | diff --git a/python/function_app.py b/python/function_app.py index 61ab41d..1bdb30e 100644 --- a/python/function_app.py +++ b/python/function_app.py @@ -1,8 +1,5 @@ -import hashlib import json -import logging import os -import time import uuid import azure.functions as func @@ -21,10 +18,9 @@ from src.providers.sinch import SinchProvider from src.providers.soprano import SopranoProvider from src.providers.telesign import TelesignProvider +from src.request_log import RequestLog from src.secrets import SecretResolver -TAG = "[EPP]" - app = func.FunctionApp() _registry = ProviderRegistry([InfobipProvider(), TelesignProvider(), SopranoProvider(), SinchProvider()]) @@ -35,11 +31,13 @@ # Azure Easy Auth must enforce authentication; local handler calls are anonymous. @app.route(route="SendOtp", methods=["POST"], auth_level=func.AuthLevel.ANONYMOUS) -def send_otp(req: func.HttpRequest) -> func.HttpResponse: - started = time.monotonic() +def send_otp(req: func.HttpRequest, context: func.Context = None) -> func.HttpResponse: request_id = str(uuid.uuid4()) - client_request_id = req.headers.get("x-ms-client-request-id") or request_id + ms_request_id = req.headers.get("x-ms-client-request-id") + client_request_id = ms_request_id or request_id header_correlation_id = req.headers.get("x-ms-correlation-id") + log = RequestLog(request_id, context.invocation_id if context else None, + ms_request_id, header_correlation_id, context.function_name if context else "send_otp") correlation_id = header_correlation_id or request_id http_status = 500 evaluation = False @@ -48,42 +46,53 @@ def respond(status, body): nonlocal http_status response = func.HttpResponse(json.dumps(body), status_code=status, mimetype="application/json") http_status = status + log.response_prepared(status, "nonce" in body, "correlationId" in body) return response try: + log.service("request_received") config = read_config() try: payload = req.get_json() except ValueError: + log.failure("request_validation", "invalid JSON body", 400) return respond(400, {"error": "bad_request", "reason": "invalid JSON body", "requestId": request_id}) envelope, error = parse_envelope(payload) if error: + log.failure("request_validation", error, 400) return respond(400, {"error": "bad_request", "reason": error, "requestId": request_id}) correlation_id = envelope.correlation_id or header_correlation_id or request_id + log.envelope_validated(envelope, envelope.correlation_id or header_correlation_id, + "envelope" if envelope.correlation_id else "header") envelope.correlation_id = correlation_id evaluation = envelope.mode == MODE_EVALUATION try: header, delivery = decrypt_delivery_context(envelope.encrypted_delivery_context, _key_provider) except Exception: + log.failure("decryption", "decryption_failed", 400) return respond(400, {"error": "decryption_failed", "correlationId": correlation_id, "requestId": request_id}) + log.service("delivery_context_decrypted") if config.expected_key_id and header.get("kid") != config.expected_key_id: - logging.warning('encryption_key_id_mismatch') + log.key_id_mismatch() if delivery is None or not delivery.is_complete: + log.failure("delivery_context_validation", "incomplete delivery context", 400) return respond(400, {"error": "bad_request", "reason": "incomplete delivery context", "correlationId": correlation_id, "requestId": request_id}) # Evaluation skips provider lookup, configuration, secrets and HTTP. if not evaluation: dispatch = context_to_dispatch(delivery, envelope, client_request_id) - status, _ = _engine.dispatch(dispatch, request_id) + status, _ = _engine.dispatch(dispatch, request_id, log) if status != 200: return respond(status, {"error": "provider_delivery_failed", "correlationId": correlation_id, "requestId": request_id}) + else: + log.service("evaluation_completed") # Live delivery must finish before nonce acceptance. return respond(200, { @@ -92,13 +101,8 @@ def respond(status, body): "providerStatus": "accepted", }) except Exception: + if not log.data["failureStage"]: + log.failure("handler", "unexpected_error", 500) return respond(500, {"error": "delivery_failed", "correlationId": correlation_id, "requestId": request_id}) finally: - # Hash even generated correlations; wire IDs stay raw. - logging.info("%s result %s", TAG, json.dumps({ - "requestId": request_id, - "correlationId": hashlib.sha256(str(correlation_id).encode("utf-8")).hexdigest()[:16], - "httpStatus": http_status, - "elapsedMs": int((time.monotonic() - started) * 1000), - "evaluation": evaluation, - })) + log.complete(http_status) diff --git a/python/src/dispatch.py b/python/src/dispatch.py index f65c0d1..f91191d 100644 --- a/python/src/dispatch.py +++ b/python/src/dispatch.py @@ -18,6 +18,7 @@ from .config import read_config from .models import DeliveryContext, DispatchRequest, Envelope, ParsedResponse, TextToVoice +from .request_log import RequestLog DEFAULT_TIMEOUT_MS = 1500 DEFAULT_CHANNELS = ["sms", "voice"] @@ -270,59 +271,89 @@ def __init__(self, registry, secrets, env=None): self._oauth_credential_config = None self._oauth_lock = Lock() - def dispatch(self, dispatch, request_id): + def dispatch(self, dispatch, request_id, log: RequestLog | None = None): + def failure(status, stage, reason, body): + if log: + log.failure(stage, reason, status) + return status, body + config = read_config(self.env) adapter = self.registry.get(config.provider_name) if adapter is None: - return 400, {"status": "error", "reason": "unknown provider", "requestId": request_id} + return failure(400, "provider_selection", "unknown_provider", + {"status": "error", "reason": "unknown provider", "requestId": request_id}) manifest = adapter.manifest + if log: + log.provider_selected(manifest) provider_id = manifest["id"] channel = dispatch.channel if dispatch.channel is not None else "sms" if not isinstance(channel, str): - return 400, {"status": "error", "provider": provider_id, "reason": "unsupported channel", "requestId": request_id} + return failure(400, "provider_configuration", "unsupported_channel", + {"status": "error", "provider": provider_id, "reason": "unsupported channel", "requestId": request_id}) channel = channel.lower() if channel not in DEFAULT_CHANNELS: - return 400, {"status": "error", "provider": provider_id, "reason": "unsupported channel", "requestId": request_id} + return failure(400, "provider_configuration", "unsupported_channel", + {"status": "error", "provider": provider_id, "reason": "unsupported channel", "requestId": request_id}) if config.provider_channel and config.provider_channel != channel: - return 400, {"status": "error", "provider": provider_id, "reason": "channel not configured", "requestId": request_id} + return failure(400, "provider_configuration", "channel_not_configured", + {"status": "error", "provider": provider_id, "reason": "channel not configured", "requestId": request_id}) if channel == "voice" and manifest.get("requires_text_to_voice") and ( not isinstance(dispatch.text_to_voice, TextToVoice) or not dispatch.text_to_voice.is_complete ): - return 400, self._fail_body(provider_id, channel, "incomplete voice context", dispatch, request_id) + return failure(400, "provider_request_build", "incomplete_voice_context", + self._fail_body(provider_id, channel, "incomplete voice context", dispatch, request_id)) auth = manifest["auth"] if config.provider_auth_mode and config.provider_auth_mode != auth.get("mode"): - return 502, self._fail_body(provider_id, channel, "provider authentication mismatch", dispatch, request_id) + return failure(502, "provider_configuration", "authentication_mode_mismatch", + self._fail_body(provider_id, channel, "provider authentication mismatch", dispatch, request_id)) try: + if log: + log.credential_resolution_started(config) credential = self._resolve_credential(auth, config) except Exception: - return 502, self._fail_body(provider_id, channel, "provider credential unavailable", dispatch, request_id) + return failure(502, "provider_credentials", "credential_unavailable", + self._fail_body(provider_id, channel, "provider credential unavailable", dispatch, request_id)) credential_unavailable = ( credential.get("mode") == "apiKey" and (not credential.get("secret") or (auth.get("identity_key_vault_secret_name") and not credential.get("identity"))) ) or (credential.get("mode") == "oauth" and not credential.get("access_token")) if credential_unavailable: - return 502, self._fail_body(provider_id, channel, "provider credential unavailable", dispatch, request_id) + return failure(502, "provider_credentials", "credential_unavailable", + self._fail_body(provider_id, channel, "provider credential unavailable", dispatch, request_id)) + if log: + log.credential_resolved() endpoint = config.provider_endpoint if not endpoint: - return 502, self._fail_body(provider_id, channel, "provider endpoint not configured", dispatch, request_id) + return failure(502, "provider_configuration", "invalid_provider_endpoint", + self._fail_body(provider_id, channel, "provider endpoint not configured", dispatch, request_id)) if not _valid_provider_url(endpoint): - return 502, self._fail_body(provider_id, channel, "invalid provider endpoint", dispatch, request_id) + return failure(502, "provider_configuration", "invalid_provider_endpoint", + self._fail_body(provider_id, channel, "invalid provider endpoint", dispatch, request_id)) try: + if log: + log.service("provider_request_build_started") provider_request = adapter.build_request(channel, endpoint, dispatch, credential, config.env) except Exception: - return 502, self._fail_body(provider_id, channel, "provider request failed", dispatch, request_id) + return failure(502, "provider_request_build", "request_build_failed", + self._fail_body(provider_id, channel, "provider request failed", dispatch, request_id)) if not _valid_provider_url(provider_request.get("url")): - return 502, self._fail_body(provider_id, channel, "invalid provider request URL", dispatch, request_id) + return failure(502, "provider_request_build", "invalid_provider_request_url", + self._fail_body(provider_id, channel, "invalid provider request URL", dispatch, request_id)) + if log: + log.provider_request_built(provider_request.get("method"), provider_request["url"]) timeout_ms = _provider_timeout_ms(config.provider_timeout_ms) response = None + stage = "provider_transport" try: + if log: + log.provider_request_started(timeout_ms) response = requests.request( provider_request["method"], provider_request["url"], @@ -333,16 +364,27 @@ def dispatch(self, dispatch, request_id): allow_redirects=False, # Never forward credentials to a redirect target. stream=True, # Own the response for cleanup if body reading fails. ) + if log: + log.provider_response_received(response.status_code) + valid_json = True try: body_json = response.json() except ValueError: + valid_json = False + if log: + log.service("provider_response_invalid_json", level=logging.WARNING) body_json = {} + if log: + log.provider_request_finished() + stage = "provider_response" ok = 200 <= response.status_code < 300 parsed = adapter.parse_response(response.status_code, ok, body_json) outcome = resolve_outcome(manifest, parsed) http_status = to_http_status(outcome, parsed.provider_http_status or response.status_code) + if log: + log.provider_response_processed(manifest, parsed, outcome, http_status, valid_json) return http_status, { "status": "accepted" if outcome == CONTINUE else "failed", @@ -359,17 +401,23 @@ def dispatch(self, dispatch, request_id): if isinstance(error, requests.exceptions.Timeout) or ( isinstance(error, requests.exceptions.ConnectionError) and _has_read_timeout(error) ): - return 504, self._fail_body(provider_id, channel, "provider timeout", dispatch, request_id) - return 502, self._fail_body(provider_id, channel, "provider request failed", dispatch, request_id) + return failure(504, "provider_transport", "provider_timeout", + self._fail_body(provider_id, channel, "provider timeout", dispatch, request_id)) + return failure(502, "provider_transport", "provider_network_error", + self._fail_body(provider_id, channel, "provider request failed", dispatch, request_id)) except Exception: - return 502, self._fail_body(provider_id, channel, "provider response failed", dispatch, request_id) + return failure(502, stage, "response_parse_failed" if stage == "provider_response" else "provider_network_error", + self._fail_body(provider_id, channel, "provider response failed", dispatch, request_id)) finally: + if log: + log.provider_request_finished() close = getattr(response, "close", None) if callable(close): try: close() except Exception: - pass + if log: + log.service("provider_response_cleanup_failed", level=logging.WARNING) def _resolve_credential(self, auth, config): if auth.get("mode") == "apiKey": diff --git a/python/src/request_log.py b/python/src/request_log.py new file mode 100644 index 0000000..2ad4bdd --- /dev/null +++ b/python/src/request_log.py @@ -0,0 +1,210 @@ +import json +import logging +import re +import time +from urllib.parse import urlsplit, urlunsplit + +_CONTEXT_FIELDS = ( + "functionName", "functionRequestId", "functionInvocationId", + "x-ms-client-request-id", "x-ms-correlation-id", "msCorrelationIdSource", "omittedIdFields", + "channel", "evaluation", "providerName", +) +_CREDENTIAL_FIELDS = ( + "providerAuthMode", "providerCredentialSource", "providerTenantId", + "functionOutboundClientId", "functionOutboundManagedIdentityClientId", +) +_HTTP_METHODS = {"GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH"} + + +_IDENTIFIER_PATTERN = re.compile(r"[A-Za-z0-9][A-Za-z0-9._:-]{0,127}") + + +class RequestLog: + """Request-scoped, explicitly selected metadata; never serialize delivery/provider models.""" + + def __init__(self, request_id, invocation_id, ms_request_id, ms_correlation_id, function_name="send_otp"): + self.started = time.monotonic() + self.provider_started = None + self.credential_started = None + self.data = { + "functionName": function_name, + "functionRequestId": request_id, + "functionInvocationId": invocation_id or None, + "x-ms-client-request-id": None, + "x-ms-correlation-id": None, + "msCorrelationIdSource": "none", + "omittedIdFields": [], + "envelopeType": None, + "ttlSeconds": None, + "channel": None, + "evaluation": None, + "encryptionKeyIdMismatch": False, + "providerName": None, + "providerAuthMode": None, + "providerCredentialSource": None, + "providerCredentialElapsedMs": None, + "providerTenantId": None, + "functionOutboundClientId": None, + "functionOutboundManagedIdentityClientId": None, + "providerHttpMethod": None, + "providerEndpoint": None, + "providerAttempted": False, + "providerHttpStatus": None, + "providerStatus": None, + "providerOutcome": None, + "providerMessageId": None, + "providerElapsedMs": None, + "providerTimeoutMs": None, + "failureStage": None, + "failureReason": None, + "responseContainsNonce": None, + "responseContainsCorrelationId": None, + } + self._set_identifier("x-ms-client-request-id", ms_request_id) + self._set_identifier("x-ms-correlation-id", ms_correlation_id) + self.data["msCorrelationIdSource"] = "header" if self.data["x-ms-correlation-id"] else "none" + + def _set_identifier(self, field, value): + valid = isinstance(value, str) and len(value) <= 128 and _IDENTIFIER_PATTERN.fullmatch(value) is not None + self.data[field] = value if valid else None + self.data["omittedIdFields"] = [name for name in self.data["omittedIdFields"] if name != field] + if not valid and value is not None and not (isinstance(value, str) and not value.strip()): + self.data["omittedIdFields"].append(field) + + def service(self, event_name, details=None, level=logging.INFO): + record = { + "logType": "service", "eventName": event_name, + **{key: self.data[key] for key in _CONTEXT_FIELDS}, + **(details or {}), + "elapsedMs": int((time.monotonic() - self.started) * 1000), + } + logging.log(level, "%s", json.dumps(record)) + + def envelope_validated(self, envelope, correlation_id, source): + self.data["envelopeType"] = envelope.type + self.data["ttlSeconds"] = envelope.ttl_seconds + self.data["channel"] = "sms" if envelope.channel == 1 else "voice" + self.data["evaluation"] = envelope.mode == 2 + self._set_identifier("x-ms-correlation-id", correlation_id) + self.data["msCorrelationIdSource"] = source if self.data["x-ms-correlation-id"] else "none" + self.service("envelope_validated", { + "envelopeType": self.data["envelopeType"], + "ttlSeconds": self.data["ttlSeconds"], + "encryptedDeliveryContextPresent": True, + }) + + def key_id_mismatch(self): + self.data["encryptionKeyIdMismatch"] = True + self.service("encryption_key_id_mismatch", level=logging.WARNING) + + def provider_selected(self, manifest): + self.data["providerName"] = manifest["id"] + mode = manifest["auth"].get("mode") + self.data["providerAuthMode"] = mode if mode in ("apiKey", "oauth") else "unsupported" + self.service("provider_selected", {"providerAuthMode": self.data["providerAuthMode"]}) + + def credential_resolution_started(self, config): + self.credential_started = time.monotonic() + oauth = self.data["providerAuthMode"] == "oauth" + self.data["providerCredentialSource"] = ("managed_identity_client_assertion" if oauth + else "key_vault" if self.data["providerAuthMode"] == "apiKey" else "unsupported") + if oauth: + self._set_identifier("providerTenantId", config.provider_tenant_id) + self._set_identifier("functionOutboundClientId", config.outbound_client_id) + self._set_identifier("functionOutboundManagedIdentityClientId", config.outbound_managed_identity_client_id) + self.service("provider_credential_resolution_started", self._credential_details()) + + def _credential_details(self): + return {key: self.data[key] for key in _CREDENTIAL_FIELDS} + + def _credential_resolution_finished(self): + if self.credential_started is not None: + self.data["providerCredentialElapsedMs"] = int((time.monotonic() - self.credential_started) * 1000) + self.credential_started = None + + def credential_resolved(self): + self._credential_resolution_finished() + self.service("provider_credential_resolved", { + **self._credential_details(), + "providerCredentialElapsedMs": self.data["providerCredentialElapsedMs"], + }) + + def provider_request_built(self, method, endpoint): + normalized = method.upper() if isinstance(method, str) else None + self.data["providerHttpMethod"] = normalized if normalized in _HTTP_METHODS else "other" + url = urlsplit(endpoint) + host = f"[{url.hostname}]" if ":" in url.hostname else url.hostname + authority = host if url.port in (None, 443) else f"{host}:{url.port}" + self.data["providerEndpoint"] = urlunsplit((url.scheme, authority, url.path or "/", "", "")) + self.service("provider_request_built", { + "providerHttpMethod": self.data["providerHttpMethod"], + "providerEndpoint": self.data["providerEndpoint"], + "providerScheme": "https", + "redirectsAllowed": False, + }) + + def provider_request_started(self, timeout_ms): + self.provider_started = time.monotonic() + self.data["providerAttempted"] = True + self.data["providerTimeoutMs"] = timeout_ms + self.service("provider_request_started", { + "providerTimeoutMs": timeout_ms, + "providerHttpMethod": self.data["providerHttpMethod"], + "providerEndpoint": self.data["providerEndpoint"], + }) + + def provider_response_received(self, status): + self.data["providerHttpStatus"] = status + self.service("provider_response_received", {"providerHttpStatus": status}) + + def provider_request_finished(self): + if self.provider_started is not None: + self.data["providerElapsedMs"] = int((time.monotonic() - self.provider_started) * 1000) + self.provider_started = None + + def provider_response_processed(self, manifest, parsed, outcome, http_status, valid_json): + status = parsed.provider_status_name or parsed.provider_status_code + known = type(status) in (str, int) and status != "default" and status in manifest["response_mapping"] + self.data["providerStatus"] = str(status) if known else "unmapped" + self.data["providerOutcome"] = outcome + self._set_identifier("providerMessageId", parsed.provider_message_id) + if outcome != "Continue": + self.data["failureStage"] = "provider_response" + self.data["failureReason"] = "provider_rejected" if valid_json else "invalid_provider_json" + self.service("provider_response_processed", { + "providerHttpStatus": self.data["providerHttpStatus"], + "providerStatus": self.data["providerStatus"], + "providerOutcome": outcome, + "providerMessageId": self.data["providerMessageId"], + "providerElapsedMs": self.data["providerElapsedMs"], + "httpStatus": http_status, + "failureReason": self.data["failureReason"], + }, logging.ERROR if http_status >= 500 else logging.INFO if http_status == 200 else logging.WARNING) + + def failure(self, stage, reason, http_status): + self._credential_resolution_finished() + self.provider_request_finished() + self.data["failureStage"] = stage + self.data["failureReason"] = reason + self.service(f"{stage}_failed", {"failureReason": reason, "httpStatus": http_status}, + logging.ERROR if http_status >= 500 else logging.WARNING) + + def response_prepared(self, http_status, contains_nonce, contains_correlation_id): + self.data["responseContainsNonce"] = contains_nonce + self.data["responseContainsCorrelationId"] = contains_correlation_id + self.service("response_prepared", { + "httpStatus": http_status, + "responseContainsNonce": contains_nonce, + "responseContainsCorrelationId": contains_correlation_id, + }) + + def complete(self, http_status): + self._credential_resolution_finished() + self.provider_request_finished() + logging.info("%s", json.dumps({ + "logType": "request", "eventName": "request_completed", + **self.data, + "httpStatus": http_status, + "result": ("evaluated" if self.data["evaluation"] else "accepted") if http_status == 200 else "failed", + "elapsedMs": int((time.monotonic() - self.started) * 1000), + })) diff --git a/python/tests/test_function_app.py b/python/tests/test_function_app.py index 5dc6301..5a62ec0 100644 --- a/python/tests/test_function_app.py +++ b/python/tests/test_function_app.py @@ -1,10 +1,10 @@ import base64 -import hashlib import json import logging from concurrent.futures import ThreadPoolExecutor from pathlib import Path from threading import Event +from types import SimpleNamespace from unittest.mock import Mock import azure.functions as func @@ -13,6 +13,7 @@ import function_app import src.dispatch as dispatch_module +from src.request_log import RequestLog _KEY = jwk.JWK.generate(kty="RSA", size=2048) _PRIVATE_PEM = _KEY.export_to_pem(private_key=True, password=None).decode() @@ -24,7 +25,9 @@ _FIXTURES = json.loads((Path(__file__).resolve().parents[2] / "tests/fixtures/contract.json").read_text(encoding="utf-8")) # get_functions() cannot be called twice on the same app. -_HANDLER = function_app.app.get_functions()[0].get_user_function() +_FUNCTION = function_app.app.get_functions()[0] +_HANDLER = _FUNCTION.get_user_function() +_FUNCTION_NAME = _FUNCTION.get_function_name() @pytest.fixture(autouse=True) @@ -63,6 +66,34 @@ def _envelope(**overrides): return payload +def _records(caplog): + return [json.loads(record.getMessage()) for record in caplog.records] + + +def _summary(caplog): + records = _records(caplog) + summaries = [record for record in records if record["logType"] == "request"] + assert len(summaries) == 1 + summary = summaries[0] + assert summary == records[-1] + assert summary["eventName"] == "request_completed" + assert set(summary) == set(_FIXTURES["logging"]["summaryFields"]) + assert all(record["logType"] == "service" for record in records[:-1]) + assert all(record["functionRequestId"] == summary["functionRequestId"] for record in records) + assert all(record["functionInvocationId"] == summary["functionInvocationId"] for record in records) + assert all(record["functionName"] == _FUNCTION_NAME for record in records) + assert summary["elapsedMs"] >= 0 + prepared = [record for record in records if record["eventName"] == "response_prepared"] + assert len(prepared) == 1 and prepared[0] == records[-2] + assert prepared[0]["httpStatus"] == summary["httpStatus"] + assert prepared[0]["responseContainsNonce"] is summary["responseContainsNonce"] + assert prepared[0]["responseContainsCorrelationId"] is summary["responseContainsCorrelationId"] + assert summary["responseContainsNonce"] is (summary["httpStatus"] == 200) + for private in (_NONCE, _PHONE, _MESSAGE, "PRIVATE", "test-key", "provider-token"): + assert private not in caplog.text + return summary + + def test_jwe_tag_tampering_and_missing_segments_fail_before_provider_io(monkeypatch, caplog): monkeypatch.setenv("EPP_ENCRYPTION_KEY_ID", "configured-key-id") segments = _encrypt().split(".") @@ -71,7 +102,7 @@ def test_jwe_tag_tampering_and_missing_segments_fail_before_provider_io(monkeypa for compact in (".".join(segments), ".".join(segments[:4])): response = _HANDLER(_request(_envelope(encryptedDeliveryContext=compact))) assert response.status_code == 400 and json.loads(response.get_body())["error"] == "decryption_failed" - assert not any(record.getMessage() == "encryption_key_id_mismatch" for record in caplog.records) + assert "encryption_key_id_mismatch" not in caplog.text function_app._engine.secrets.resolve.assert_not_called() dispatch_module.requests.request.assert_not_called() @@ -141,8 +172,17 @@ def test_evaluation_decrypts_without_provider_configuration_or_work(monkeypatch, "nonce": _NONCE, "correlationId": _CORRELATION, "providerStatus": "accepted", } function_app._key_provider.assert_called_once_with("test-kid") - warnings = [record.getMessage() for record in caplog.records if record.levelno == logging.WARNING] + warnings = [json.loads(record.getMessage())["eventName"] for record in caplog.records if record.levelno == logging.WARNING] assert warnings == ["encryption_key_id_mismatch"] + assert [record["eventName"] for record in _records(caplog) + if record["eventName"] != "encryption_key_id_mismatch"] == _FIXTURES["logging"]["evaluationEvents"] + summary = _summary(caplog) + assert summary["encryptionKeyIdMismatch"] is True + assert summary["evaluation"] is True and summary["result"] == "evaluated" + assert summary["providerName"] is None and summary["providerAttempted"] is False + assert summary["providerHttpStatus"] is None and summary["providerElapsedMs"] is None + assert summary["providerCredentialSource"] is None and summary["providerCredentialElapsedMs"] is None + assert summary["providerEndpoint"] is None assert all(value not in caplog.text for value in ("configured-key-id", "test-kid", "untrusted-body-provider")) lookup.assert_not_called() function_app._engine.secrets.resolve.assert_not_called() @@ -170,6 +210,8 @@ def wait_for_acceptance(*args, **kwargs): try: assert entered.wait(5), "handler did not reach provider" assert not pending.done() + assert not any(record["logType"] == "request" for record in _records(caplog)) + assert _records(caplog)[-1]["eventName"] == "provider_request_started" finally: release.set() response = pending.result(timeout=5) @@ -189,11 +231,17 @@ def wait_for_acceptance(*args, **kwargs): "loop": 2, }} assert "text" not in wire and wire["messageTypes"] == ["voice"] and wire["correlationId"] == _CORRELATION - summary = json.loads(caplog.records[-1].getMessage().removeprefix("[EPP] result ")) - assert len(caplog.records) == 1 - assert set(summary) == {"requestId", "correlationId", "httpStatus", "elapsedMs", "evaluation"} - assert summary["correlationId"] == hashlib.sha256(_CORRELATION.encode()).hexdigest()[:16] - for private in (_NONCE, _PHONE, _MESSAGE, "123456", "001234", _CORRELATION, "wire-message", "test-key"): + summary = _summary(caplog) + assert [record["eventName"] for record in _records(caplog)] == _FIXTURES["logging"]["liveEvents"] + assert summary["x-ms-correlation-id"] == _CORRELATION + assert summary["x-ms-client-request-id"] == "wire-message" + assert summary["providerName"] == "soprano" and summary["providerAuthMode"] == "oauth" + assert summary["providerHttpStatus"] == 202 and summary["providerStatus"] == "ENROUTE" + assert summary["providerOutcome"] == "Continue" and summary["providerAttempted"] is True + assert summary["channel"] == "voice" and summary["failureStage"] is None + assert summary["providerTimeoutMs"] == 1500 + assert 0 <= summary["providerElapsedMs"] <= summary["elapsedMs"] + for private in (_NONCE, _PHONE, _MESSAGE, "123456", "001234", "test-key"): assert private not in caplog.text @@ -211,10 +259,293 @@ def test_provider_failure_preserves_status_without_retry_or_nonce(monkeypatch): def test_unexpected_handler_error_is_generic_and_does_not_send(monkeypatch, caplog): + caplog.set_level(logging.INFO) monkeypatch.setattr(function_app, "read_config", Mock(side_effect=RuntimeError("PRIVATE-ERROR"))) response = _HANDLER(_request({})) body = json.loads(response.get_body()) assert response.status_code == 500 and body["error"] == "delivery_failed" assert set(body) == {"error", "correlationId", "requestId"} assert "PRIVATE-ERROR" not in response.get_body().decode() + caplog.text + assert _summary(caplog)["failureStage"] == "handler" + assert _summary(caplog)["failureReason"] == "unexpected_error" dispatch_module.requests.request.assert_not_called() + + +def test_identifier_sources_are_explicit_and_missing_microsoft_ids_are_not_generated(monkeypatch, caplog): + caplog.set_level(logging.INFO) + upstream = Mock(status_code=201, json=Mock(return_value={ + "status": "ENROUTE", "id": "provider-reference-id", "description": "PRIVATE-DESCRIPTION", + })) + monkeypatch.setattr(dispatch_module.requests, "request", Mock(return_value=upstream)) + headers = {"x-ms-client-request-id": "ms-request-id", "x-ms-correlation-id": "ms-header-correlation-id"} + for correlation_id in ("ms-envelope-correlation-id", None): + caplog.clear() + context = SimpleNamespace(invocation_id="function-invocation-id", function_name=_FUNCTION_NAME) + response = _HANDLER(_request(_envelope(correlationId=correlation_id), headers), context) + assert response.status_code == 200 + summary = _summary(caplog) + assert summary["x-ms-client-request-id"] == headers["x-ms-client-request-id"] + assert summary["x-ms-correlation-id"] == (correlation_id or headers["x-ms-correlation-id"]) + assert summary["msCorrelationIdSource"] == ("envelope" if correlation_id else "header") + assert _records(caplog)[0]["msCorrelationIdSource"] == "header" + assert summary["functionInvocationId"] == "function-invocation-id" + assert summary["providerMessageId"] == "provider-reference-id" + assert summary["functionRequestId"] not in (summary["x-ms-client-request-id"], summary["functionInvocationId"]) + caplog.clear() + response = _HANDLER(_request(_envelope(correlationId=None))) + summary = _summary(caplog) + assert json.loads(response.get_body())["correlationId"] == summary["functionRequestId"] + assert summary["x-ms-client-request-id"] is None and summary["x-ms-correlation-id"] is None + assert summary["msCorrelationIdSource"] == "none" and summary["functionInvocationId"] is None + + +@pytest.mark.parametrize("scenario,status,stage,reason,attempted", [ + ("invalid_json", 400, "request_validation", "invalid JSON body", False), + ("invalid_envelope", 400, "request_validation", "unsupported envelope type", False), + ("decryption", 400, "decryption", "decryption_failed", False), + ("incomplete_context", 400, "delivery_context_validation", "incomplete delivery context", False), + ("unknown_provider", 400, "provider_selection", "unknown_provider", False), + ("wrong_channel", 400, "provider_configuration", "channel_not_configured", False), + ("authentication_mismatch", 502, "provider_configuration", "authentication_mode_mismatch", False), + ("invalid_endpoint", 502, "provider_configuration", "invalid_provider_endpoint", False), + ("credentials", 502, "provider_credentials", "credential_unavailable", False), + ("request_build", 502, "provider_request_build", "request_build_failed", False), + ("timeout", 504, "provider_transport", "provider_timeout", True), + ("body_timeout", 504, "provider_transport", "provider_timeout", True), + ("network", 502, "provider_transport", "provider_network_error", True), + ("response_parse", 502, "provider_response", "response_parse_failed", True), + ("http_rejection", 429, "provider_response", "provider_rejected", True), +]) +def test_failures_emit_separate_events_and_complete_summaries(monkeypatch, caplog, scenario, status, stage, reason, attempted): + caplog.set_level(logging.INFO) + payload = _envelope() + upstream = Mock(status_code=201, json=Mock(return_value={"status": "ENROUTE"})) + send = Mock(return_value=upstream) + monkeypatch.setattr(dispatch_module.requests, "request", send) + engine = function_app._engine + adapter = engine.registry.get("soprano") + if scenario == "invalid_json": + payload = b"{" + elif scenario == "invalid_envelope": + payload = {} + elif scenario == "decryption": + payload["encryptedDeliveryContext"] = "PRIVATE-NOT-A-JWE" + elif scenario == "incomplete_context": + payload["encryptedDeliveryContext"] = _encrypt(context={**_CONTEXT, "nonce": ""}) + elif scenario == "unknown_provider": + engine.env["EPP_PROVIDER_NAME"] = "PRIVATE-UNKNOWN-PROVIDER" + elif scenario == "wrong_channel": + engine.env["EPP_PROVIDER_CHANNEL"] = "voice" + elif scenario == "authentication_mismatch": + engine.env["EPP_PROVIDER_AUTH_MODE"] = "apiKey" + elif scenario == "invalid_endpoint": + engine.env["EPP_PROVIDER_ENDPOINT"] = "http://PRIVATE-ENDPOINT" + elif scenario == "credentials": + engine._resolve_credential.side_effect = RuntimeError("PRIVATE-CREDENTIAL-ERROR") + elif scenario == "request_build": + monkeypatch.setattr(adapter, "build_request", Mock(side_effect=RuntimeError("PRIVATE-BUILD-ERROR"))) + elif scenario == "timeout": + send.side_effect = dispatch_module.requests.exceptions.Timeout("PRIVATE-TIMEOUT") + elif scenario == "body_timeout": + upstream.json.side_effect = dispatch_module.requests.exceptions.Timeout("PRIVATE-BODY-TIMEOUT") + elif scenario == "network": + send.side_effect = dispatch_module.requests.exceptions.ConnectionError("PRIVATE-NETWORK-ERROR") + elif scenario == "response_parse": + monkeypatch.setattr(adapter, "parse_response", Mock(side_effect=RuntimeError("PRIVATE-PARSE-ERROR"))) + elif scenario == "http_rejection": + upstream.status_code = 429 + headers = {"x-ms-client-request-id": "ms-request-id", "x-ms-correlation-id": "ms-header-correlation-id"} + response = _HANDLER(_request(payload, headers)) + summary = _summary(caplog) + assert response.status_code == status == summary["httpStatus"] + assert summary["functionRequestId"] == json.loads(response.get_body())["requestId"] + assert summary["failureStage"] == stage and summary["failureReason"] == reason + assert summary["x-ms-client-request-id"] == headers["x-ms-client-request-id"] + assert summary["msCorrelationIdSource"] == ("header" if stage == "request_validation" else "envelope") + assert summary["x-ms-correlation-id"] == ( + headers["x-ms-correlation-id"] if stage == "request_validation" else _CORRELATION) + assert summary["providerAttempted"] is attempted and send.call_count == int(attempted) + assert summary["result"] == "failed" + assert _records(caplog)[-3]["eventName"] == ("provider_response_processed" if scenario == "http_rejection" else f"{stage}_failed") + assert summary["responseContainsNonce"] is False + assert summary["responseContainsCorrelationId"] is ("correlationId" in json.loads(response.get_body())) + if scenario == "credentials": + assert summary["providerCredentialSource"] == "managed_identity_client_assertion" + assert 0 <= summary["providerCredentialElapsedMs"] <= summary["elapsedMs"] + assert not any(record["eventName"] == "provider_credential_resolved" for record in _records(caplog)) + assert any(record.levelno == (logging.ERROR if status >= 500 else logging.WARNING) for record in caplog.records) + if attempted: + assert summary["providerTimeoutMs"] == 1500 + assert 0 <= summary["providerElapsedMs"] <= summary["elapsedMs"] + if scenario == "body_timeout": + assert summary["providerHttpStatus"] == 201 and summary["providerStatus"] is None + + +@pytest.mark.parametrize("correlation", [42, {"detail": "support-correlation-id"}, ["support-correlation-id"], ""]) +def test_invalid_correlation_metadata_cannot_leak_or_prevent_summary(caplog, correlation): + caplog.set_level(logging.INFO) + response = _HANDLER(_request(_envelope(mode=2, correlationId=correlation))) + assert response.status_code == 200 + summary = _summary(caplog) + assert summary["x-ms-correlation-id"] is None and summary["msCorrelationIdSource"] == "none" + + +@pytest.mark.parametrize("valid_json", [True, False]) +def test_provider_diagnostics_never_log_unknown_statuses_or_response_bodies(monkeypatch, caplog, valid_json): + caplog.set_level(logging.INFO) + upstream = Mock(status_code=200, json=Mock(return_value={ + "status": "PRIVATE-STATUS\nFORGED", "id": "provider-reference-id", "description": "PRIVATE-DESCRIPTION", + })) + if not valid_json: + upstream.json.side_effect = ValueError("PRIVATE-RESPONSE") + monkeypatch.setattr(dispatch_module.requests, "request", Mock(return_value=upstream)) + response = _HANDLER(_request(_envelope())) + summary = _summary(caplog) + assert response.status_code == 502 + assert summary["providerStatus"] == "unmapped" and summary["providerOutcome"] == "Fail" + assert summary["failureReason"] == ("provider_rejected" if valid_json else "invalid_provider_json") + assert "FORGED" not in caplog.text + + +def test_interleaved_invocations_keep_separate_log_contexts(monkeypatch, caplog): + caplog.set_level(logging.INFO) + monkeypatch.setattr(dispatch_module.requests, "request", Mock( + side_effect=lambda *args, **kwargs: Mock(status_code=201, json=Mock(return_value={"status": "ENROUTE"})))) + requests = [_request(_envelope(correlationId=value)) for value in ("correlation-first", "correlation-second")] + with ThreadPoolExecutor(max_workers=2) as executor: + results = list(executor.map(_HANDLER, requests)) + assert all(result.status_code == 200 for result in results) + records = _records(caplog) + summaries = [record for record in records if record["logType"] == "request"] + assert len(summaries) == 2 + assert len({record["functionRequestId"] for record in summaries}) == 2 + assert {record["x-ms-correlation-id"] for record in summaries} == {"correlation-first", "correlation-second"} + for summary in summaries: + events = [record for record in records if record["functionRequestId"] == summary["functionRequestId"]] + assert [record["eventName"] for record in events] == _FIXTURES["logging"]["liveEvents"] + assert all(record["x-ms-correlation-id"] == summary["x-ms-correlation-id"] for record in events[1:]) + assert "PRIVATE" not in caplog.text + + +def test_successful_lifecycle_logs_only_allowed_body_fields_oauth_ids_and_final_endpoint(monkeypatch, caplog): + caplog.set_level(logging.INFO) + engine = function_app._engine + engine.env.update({ + "EPP_PROVIDER_ENDPOINT": "https://provider.example/api/send?key=PRIVATE-QUERY", + "EPP_PROVIDER_TENANT_ID": "provider-tenant-id", + "EPP_OUTBOUND_CLIENT_ID": "outbound-client-id", + "EPP_OUTBOUND_MI_CLIENT_ID": "outbound-mi-client-id", + }) + monkeypatch.setattr(dispatch_module.requests, "request", Mock(return_value=Mock( + status_code=201, json=Mock(return_value={"status": "ENROUTE"})))) + payload = _envelope(tenantId="PRIVATE-TENANT", diagnosticData={"token": "PRIVATE-UNKNOWN-FIELD"}) + response = _HANDLER(_request(payload, {"authorization": "PRIVATE-INBOUND-AUTH"})) + assert response.status_code == 200 + summary = _summary(caplog) + records = _records(caplog) + validated = next(record for record in records if record["eventName"] == "envelope_validated") + assert validated["envelopeType"] == summary["envelopeType"] == payload["type"] + assert validated["ttlSeconds"] == summary["ttlSeconds"] == 60 + assert validated["encryptedDeliveryContextPresent"] is True + credentials = [record for record in records if record["eventName"] in ( + "provider_credential_resolution_started", "provider_credential_resolved")] + assert len(credentials) == 2 + for record in [summary, *credentials]: + assert record["providerCredentialSource"] == "managed_identity_client_assertion" + assert record["providerTenantId"] == engine.env["EPP_PROVIDER_TENANT_ID"] + assert record["functionOutboundClientId"] == engine.env["EPP_OUTBOUND_CLIENT_ID"] + assert record["functionOutboundManagedIdentityClientId"] == engine.env["EPP_OUTBOUND_MI_CLIENT_ID"] + assert 0 <= summary["providerCredentialElapsedMs"] <= summary["elapsedMs"] + for record in [summary, *[record for record in records if record["eventName"] in ( + "provider_request_built", "provider_request_started")]]: + assert record["providerHttpMethod"] == "POST" + assert record["providerEndpoint"] == "https://provider.example/api/send" + built = next(record for record in records if record["eventName"] == "provider_request_built") + assert built["providerScheme"] == "https" and built["redirectsAllowed"] is False + assert payload["encryptedDeliveryContext"] not in caplog.text + assert summary["responseContainsNonce"] is True and summary["responseContainsCorrelationId"] is True + assert [record["eventName"] for record in records] == _FIXTURES["logging"]["liveEvents"] + + +def test_api_key_lifecycle_identifies_key_vault_resolution_without_logging_credentials(monkeypatch, caplog): + caplog.set_level(logging.INFO) + engine = function_app._engine + engine.env.update({"EPP_PROVIDER_NAME": "telesign", "EPP_PROVIDER_AUTH_MODE": "apiKey"}) + monkeypatch.setattr(engine, "_resolve_credential", + dispatch_module.DispatchEngine._resolve_credential.__get__(engine)) + monkeypatch.setattr(dispatch_module.requests, "request", Mock(return_value=Mock( + status_code=200, json=Mock(return_value={"status": {"code": 3001}})))) + assert _HANDLER(_request(_envelope())).status_code == 200 + summary = _summary(caplog) + assert summary["providerCredentialSource"] == "key_vault" and summary["providerAuthMode"] == "apiKey" + assert summary["providerTenantId"] is None + assert summary["functionOutboundClientId"] is None and summary["functionOutboundManagedIdentityClientId"] is None + assert 0 <= summary["providerCredentialElapsedMs"] <= summary["elapsedMs"] + assert [call.args[0] for call in engine.secrets.resolve.call_args_list] == ["telesign-api-key", "telesign-customer-id"] + assert [record["eventName"] for record in _records(caplog)] == _FIXTURES["logging"]["liveEvents"] + + +def test_optional_ttl_stays_null_and_invalid_body_values_never_enter_metadata(caplog): + caplog.set_level(logging.INFO) + payload = _envelope(mode=2) + del payload["ttlSeconds"] + assert _HANDLER(_request(payload)).status_code == 200 + assert _summary(caplog)["ttlSeconds"] is None + caplog.clear() + assert _HANDLER(_request({**payload, "ttlSeconds": "PRIVATE-INVALID-TTL"})).status_code == 400 + summary = _summary(caplog) + assert summary["ttlSeconds"] is None and summary["envelopeType"] is None + assert not any(record["eventName"] == "envelope_validated" for record in _records(caplog)) + + +def test_request_preparation_uses_the_adapter_final_url_and_allowlisted_method(monkeypatch, caplog): + caplog.set_level(logging.INFO) + adapter = function_app._engine.registry.get("soprano") + build_request = adapter.build_request + final_url = "https://different-provider.example/api/final?token=PRIVATE-TOKEN" + monkeypatch.setattr(adapter, "build_request", lambda *args: { + **build_request(*args), "url": final_url, "method": "PRIVATE-METHOD", + }) + send = Mock(return_value=Mock(status_code=201, json=Mock(return_value={"status": "ENROUTE"}))) + monkeypatch.setattr(dispatch_module.requests, "request", send) + assert _HANDLER(_request(_envelope())).status_code == 200 + summary = _summary(caplog) + assert summary["providerEndpoint"] == "https://different-provider.example/api/final" and summary["providerHttpMethod"] == "other" + assert summary["providerEndpoint"] != function_app._engine.env["EPP_PROVIDER_ENDPOINT"] + assert send.call_args.args[:2] == ("PRIVATE-METHOD", final_url) + + +def test_shared_id_cases_preserve_raw_values_or_explicitly_omit_invalid_metadata(caplog): + caplog.set_level(logging.INFO) + fields = ["x-ms-client-request-id", "x-ms-correlation-id", "providerTenantId", + "functionOutboundClientId", "functionOutboundManagedIdentityClientId", "providerMessageId"] + manifest = function_app._registry.get("soprano").manifest + for fixture in _FIXTURES["logging"]["identifiers"]: + caplog.clear() + value = "A" * fixture["length"] if "length" in fixture else fixture["value"] + log = RequestLog("function-request", None, value, value) + log.provider_selected(manifest) + log.credential_resolution_started(SimpleNamespace( + provider_tenant_id=value, outbound_client_id=value, outbound_managed_identity_client_id=value)) + log.provider_response_processed(manifest, SimpleNamespace( + provider_status_name="ENROUTE", provider_status_code=None, provider_message_id=value), "Continue", 200, True) + log.complete(200) + records = _records(caplog) + summary = records[-1] + for field in fields: + assert summary[field] == (value if fixture["accepted"] else None) + assert summary["omittedIdFields"] == (fields if fixture.get("omitted") else []) + assert not any(key.endswith("Hash") for record in records for key in record) + assert "PRIVATE" not in caplog.text + + +def test_shared_endpoint_cases_keep_only_scheme_host_port_and_api_path(caplog): + caplog.set_level(logging.INFO) + for fixture in _FIXTURES["logging"]["endpoints"]: + caplog.clear() + log = RequestLog("function-request", None, None, None) + log.provider_request_built("POST", fixture["url"]) + log.provider_request_started(1500) + log.complete(200) + assert all(record["providerEndpoint"] == fixture["logged"] for record in _records(caplog)) + assert "PRIVATE" not in caplog.text diff --git a/tests/fixtures/contract.json b/tests/fixtures/contract.json index 4d6c5cd..2cf0561 100644 --- a/tests/fixtures/contract.json +++ b/tests/fixtures/contract.json @@ -1,4 +1,66 @@ { + "logging": { + "liveEvents": [ + "request_received", + "envelope_validated", + "delivery_context_decrypted", + "provider_selected", + "provider_credential_resolution_started", + "provider_credential_resolved", + "provider_request_build_started", + "provider_request_built", + "provider_request_started", + "provider_response_received", + "provider_response_processed", + "response_prepared", + "request_completed" + ], + "evaluationEvents": [ + "request_received", + "envelope_validated", + "delivery_context_decrypted", + "evaluation_completed", + "response_prepared", + "request_completed" + ], + "summaryFields": [ + "logType", "eventName", "functionName", "functionRequestId", "functionInvocationId", + "x-ms-client-request-id", "x-ms-correlation-id", "msCorrelationIdSource", "omittedIdFields", "channel", "evaluation", + "envelopeType", "ttlSeconds", + "encryptionKeyIdMismatch", "providerName", "providerAuthMode", "providerAttempted", + "providerCredentialSource", "providerCredentialElapsedMs", "providerTenantId", + "functionOutboundClientId", "functionOutboundManagedIdentityClientId", + "providerHttpMethod", "providerEndpoint", + "providerHttpStatus", "providerStatus", "providerOutcome", "providerMessageId", + "providerElapsedMs", "providerTimeoutMs", "failureStage", "failureReason", + "httpStatus", "result", "elapsedMs", "responseContainsNonce", "responseContainsCorrelationId" + ], + "identifiers": [ + { "value": "AB12CD34-1234-4567-890A-ABCDEF123456", "accepted": true }, + { "value": "ref_AbC:19.2-XY", "accepted": true }, + { "value": "1234567890", "accepted": true }, + { "length": 128, "accepted": true }, + { "length": 129, "accepted": false, "omitted": true }, + { "value": null, "accepted": false }, + { "value": "", "accepted": false }, + { "value": " ", "accepted": false }, + { "value": "support-id\n", "accepted": false, "omitted": true }, + { "value": "support-id\r\n", "accepted": false, "omitted": true }, + { "value": "id\tPRIVATE-DATA", "accepted": false, "omitted": true }, + { "value": "id\u0000PRIVATE-DATA", "accepted": false, "omitted": true }, + { "value": "id\u2028PRIVATE-DATA", "accepted": false, "omitted": true }, + { "value": "PRIVATE MESSAGE TEXT", "accepted": false, "omitted": true }, + { "value": "+15551234567", "accepted": false, "omitted": true }, + { "value": "https://example.com/?key=PRIVATE-KEY", "accepted": false, "omitted": true } + ], + "endpoints": [ + { "url": "https://provider.example/epp/voice?key=PRIVATE-KEY&phone=PRIVATE-PHONE#PRIVATE-FRAGMENT", "logged": "https://provider.example/epp/voice" }, + { "url": "https://provider.example:8443/epp/voice?key=PRIVATE-KEY", "logged": "https://provider.example:8443/epp/voice" }, + { "url": "https://PRIVATE-USER:PRIVATE-PASSWORD@provider.example/api/send?key=PRIVATE-KEY", "logged": "https://provider.example/api/send" }, + { "url": "https://provider.example:443?key=PRIVATE-KEY", "logged": "https://provider.example/" }, + { "url": "https://[2001:db8::1]:8443/api/send?key=PRIVATE-KEY", "logged": "https://[2001:db8::1]:8443/api/send" } + ] + }, "jwe": [ { "alg": "RSA-OAEP-256", "enc": "A256GCM", "accepted": true }, { "alg": "RSA-OAEP", "enc": "A256GCM", "accepted": false },