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 },