Joseph Doherty
dc2df628e3
The remediation reviews approved every task but left a tail of small notes. This lands the gateway-side half of them. Hardening (behavior changes, all narrow): - BuildFilteredWriteBulkCommand's unreachable default case failed OPEN: a fifth bulk-write kind added upstream without a filter case here would have shipped the DENIED entries to the worker while reporting them denied to the caller. It now throws UnreachableException. - SqliteCanonicalAuditStore.ListRecentAsync no longer throws on a row it cannot date. The retention sweep deliberately preserves such rows (SQLite's datetime() yields NULL, so the DELETE never matches), which guaranteed the dashboard's recent-audit view would meet one eventually and lose the whole page to it. The row is now reported at DateTimeOffset.MinValue with every other column intact, behind an optional logger. - The audit drain loop's finally now completes the channel writer alongside detaching the drain, so a producer that raced past the attached check takes the write-through branch instead of stranding its event in a buffer nobody reads until shutdown. TryComplete is idempotent, so StopAsync is unaffected. Tests: - MapCommandReply ownership (Assert.Same on the inner reply), mirroring the existing MapEvent ownership test. - Redactor key-id length boundary at exactly 64 and 65 characters, pinning which way it fails. Nothing validates key-id length at creation, so docs/Diagnostics.md's "which no issued key id does" is now stated as the heuristic it is. - ApiKeyFailureLimiter.Reset with a PartitionResolution whose partition was evicted between the Check and the Reset: inert, and clears nobody else's block. - Constraint-cache concurrency stress: the cap is enforced by the inserting thread, so overshoot must be transient and proportional to the in-flight inserters, and the cache must settle at or under the cap. - ListRecentAsync against a raw-SQL undateable row. Comment/doc accuracy: - EventsHubViewerRegistry.ReleaseConnection records that it relies on SignalR's default sequential per-connection dispatch (MaximumParallelInvocationsPerClient = 1). - A PERF(followup) note on Invoke's double session resolve and why removing it needs a SessionManager overload. - SessionEventDistributor: the volatile-field comment named the pump as the lock-free reader, but the pump's single capture point is inside _replayLock; the genuinely lock-free reader is SubscriberCount. OnSubscriberOverflow's "cannot be observed here" now excepts the DisposeAsync abandon path. The churn test names its ConcurrentDictionary bucket-order assumption and that a violation surfaces as a read timeout, not a silent pass. - The two "restores the sequential drain's behavior" claims (SessionManager, docs/Sessions.md) were wrong: the sequential drain leaked too, because KillWorkerAsync's entry ThrowIfCancellationRequested aborted the whole loop on the first session for zero kills. Reworded to "fixes a leak the sequential drain also had", with the sweep-bound/shutdown-unbound ParallelOptions asymmetry explained. - ISessionManager.ShutdownAsync's token doc: it degrades the drain to a kill sweep rather than cancelling it, with the bounded overrun stated. SessionShutdownHostedService.StopAsync records that its cancellation-logging branch is now unreachable.
244 lines
14 KiB
Markdown
244 lines
14 KiB
Markdown
# Gateway Diagnostics
|
|
|
|
The diagnostics subsystem provides structured logging, credential redaction, and request-scoped log enrichment for the gateway. It lives under `src/ZB.MOM.WW.MxGateway.Server/Diagnostics/` and is wired into the ASP.NET Core pipeline so every gRPC and HTTP request carries the same correlation fields.
|
|
|
|
## Goals
|
|
|
|
The subsystem exists to satisfy two security rules from `gateway.md`: never log passwords or raw credential values for `AuthenticateUser`, `WriteSecured`, or related secured operations, and never log full MXAccess values by default. Code paths that touch credentials or tag values must therefore route through `GatewayLogRedactor` rather than emitting them directly.
|
|
|
|
A second goal is parity-test diagnosability. Because MXAccess sessions, workers, correlation ids, and command methods are the units of comparison, every log entry produced inside a request scope must carry those identifiers without each call site having to format them.
|
|
|
|
## Log Scopes
|
|
|
|
`GatewayLogScope` is a record that captures the fields attached to a logger scope. It only emits keys whose values are non-null, so callers can supply just the identifiers they know about:
|
|
|
|
```csharp
|
|
public sealed record GatewayLogScope(
|
|
string? SessionId = null,
|
|
int? WorkerProcessId = null,
|
|
ulong? CorrelationId = null,
|
|
string? CommandMethod = null,
|
|
string? ClientIdentity = null)
|
|
{
|
|
public IReadOnlyDictionary<string, object?> ToDictionary()
|
|
{
|
|
Dictionary<string, object?> values = [];
|
|
|
|
AddIfPresent(values, "SessionId", SessionId);
|
|
AddIfPresent(values, "WorkerProcessId", WorkerProcessId);
|
|
AddIfPresent(values, "CorrelationId", CorrelationId);
|
|
AddIfPresent(values, "CommandMethod", CommandMethod);
|
|
AddIfPresent(values, "ClientIdentity", GatewayLogRedactor.RedactClientIdentity(ClientIdentity));
|
|
|
|
return values;
|
|
}
|
|
```
|
|
|
|
`ClientIdentity` is passed through `GatewayLogRedactor.RedactClientIdentity` inside `ToDictionary` rather than at the call site. This guarantees that any logger scope built from a `GatewayLogScope` cannot accidentally surface a raw API key, even when a caller forgets to redact before constructing the scope.
|
|
|
|
### How scopes are pushed
|
|
|
|
`GatewayLoggerExtensions` exposes a single method that converts a `GatewayLogScope` into the dictionary form expected by `ILogger.BeginScope`:
|
|
|
|
```csharp
|
|
public static class GatewayLoggerExtensions
|
|
{
|
|
public static IDisposable? BeginGatewayScope(
|
|
this ILogger logger,
|
|
GatewayLogScope scope)
|
|
{
|
|
ArgumentNullException.ThrowIfNull(logger);
|
|
ArgumentNullException.ThrowIfNull(scope);
|
|
|
|
return logger.BeginScope(scope.ToDictionary());
|
|
}
|
|
}
|
|
```
|
|
|
|
The returned `IDisposable?` follows the standard `BeginScope` contract: callers wrap it in a `using` to bound the scope to a request, command, or worker interaction.
|
|
|
|
## Redaction Rules
|
|
|
|
`GatewayLogRedactor` centralizes every redaction decision so that policy changes live in one file. Three categories of input are handled differently because each has different "safe to log" prefixes.
|
|
|
|
### Sensitive command methods
|
|
|
|
A static set names the MXAccess commands that are known to carry credentials in their payloads:
|
|
|
|
```csharp
|
|
private static readonly HashSet<string> SensitiveCommandMethods = new(StringComparer.OrdinalIgnoreCase)
|
|
{
|
|
"AuthenticateUser",
|
|
"WriteSecured",
|
|
"WriteSecured2"
|
|
};
|
|
|
|
public static bool IsCredentialBearingCommand(string? commandMethod)
|
|
{
|
|
return commandMethod is not null
|
|
&& SensitiveCommandMethods.Contains(commandMethod);
|
|
}
|
|
```
|
|
|
|
The names match the MXAccess command list in `gateway.md` exactly. `Write` and `Write2` are not in the set because their payloads are tag values, not credentials, and are governed by the `valueLoggingEnabled` flag described below.
|
|
|
|
### API key redaction
|
|
|
|
`RedactClientIdentity` is the single redaction path for identity-bearing values; `RedactApiKey` is a
|
|
name-preserving alias for it. Redaction **fails closed**: the only value that survives with any of its
|
|
content is a gateway-issued `mxgw_<key-id>_<secret>` key, whose key id is kept so operators can
|
|
correlate a log entry to a specific principal.
|
|
|
|
| Input | Output | Why |
|
|
|-------|--------|-----|
|
|
| `Bearer mxgw_operator01_super-secret` | `Bearer mxgw_operator01_[redacted]` | Recognized gateway key; key id identifies the principal |
|
|
| `Bearer eyJhbGciOi…` (any foreign token) | `Bearer [redacted]` | Structure is unknown, so the whole credential goes |
|
|
| `Basic dXNlcjpwYXNz` | `Basic [redacted]` | Same, for any recognized scheme |
|
|
| `Bearer mxgw_operator01` (no secret separator) | `Bearer mxgw_[redacted]` | No trustworthy key-id boundary |
|
|
| `Bearer` (scheme only), `anonymous`, `some junk` | `[redacted]` | No scheme/credential split that can be trusted |
|
|
| `null`, `""`, whitespace | unchanged | Nothing to redact |
|
|
|
|
A scheme word survives only when it is one of the recognized authorization schemes (`Bearer`,
|
|
`Basic`, `Digest`, `Negotiate`, `NTLM`, `ApiKey`, `Token`). An unrecognized leading word is as likely
|
|
to be credential material as it is to be a scheme, so it is dropped along with the rest. The key id is
|
|
also dropped when it runs longer than 64 characters — a long run before the first `_` is more likely to
|
|
be secret material than an identifier. Neither key-creation path (`ApiKeyAdminCommandLineParser.IsValidKeyId`,
|
|
`DashboardApiKeyManagementService.ValidateKeyId`) enforces a length, so this is a redaction heuristic
|
|
rather than a guarantee: operators should keep key ids under 64 characters, or the id stops appearing
|
|
in logs and only the `mxgw_[redacted]` shape survives. The direction of the failure is deliberate —
|
|
losing an identifier is cheap, logging a secret is not.
|
|
|
|
The parse is span-based (no regex, no `Split` allocation): the value is split once at the first space,
|
|
and the key id is read up to the first `_` of the remainder.
|
|
|
|
The consequence for callers is that a non-key identity (for example a Windows account name) reaching
|
|
`RedactClientIdentity` is now replaced rather than passed through. `DashboardRedactor` routes only
|
|
values containing the `mxgw_` marker here, so dashboard display names are unaffected.
|
|
|
|
### Command value redaction
|
|
|
|
> **Redaction seam wired; value logging still has no opt-in knob** (updated 2026-08-07). Since commit `47c0b64` (2026-07-27), `RedactCommandValue` **is** wired: `GatewayLogRedactorSeam` (`Diagnostics/GatewayLogRedactorSeam.cs`) calls it for any non-null `CommandValue` log property, gated on `CommandMethod`, so a command payload that reaches a log event is masked on every sink through the shared `ILogRedactor` seam. What remains true from the original note: there is still no `MxGateway:Diagnostics:LogCommandValues` (or equivalent) configuration knob — the seam exposes no opt-in, `valueLoggingEnabled` is never passed `true`, so **every** non-null command value is redacted, credential-bearing or not. In practice no log statement currently emits a `CommandValue` property, but one that does can no longer leak a payload in the clear.
|
|
|
|
`RedactCommandValue` enforces the "values are opt-in and redacted by default" rule:
|
|
|
|
```csharp
|
|
public static object? RedactCommandValue(
|
|
string? commandMethod,
|
|
object? value,
|
|
bool valueLoggingEnabled = false)
|
|
{
|
|
if (value is null)
|
|
{
|
|
return null;
|
|
}
|
|
|
|
if (!valueLoggingEnabled || IsCredentialBearingCommand(commandMethod))
|
|
{
|
|
return RedactedValue;
|
|
}
|
|
|
|
return value;
|
|
}
|
|
```
|
|
|
|
Two rules combine here. First, when `valueLoggingEnabled` is `false` (the default), every value is replaced with `[redacted]`. Second, even when value logging is enabled, credential-bearing commands still redact. The credential check is therefore unconditional and cannot be overridden by configuration.
|
|
|
|
The shared `RedactedValue` constant is `"[redacted]"`. `DashboardRedactor` reuses it so that gateway logs and dashboard renders use the same placeholder.
|
|
|
|
## Request Logging Middleware
|
|
|
|
`GatewayRequestLoggingMiddlewareExtensions.UseGatewayRequestLoggingScope` registers the middleware that pushes a `GatewayLogScope` for the duration of every request:
|
|
|
|
```csharp
|
|
public static IApplicationBuilder UseGatewayRequestLoggingScope(this IApplicationBuilder app)
|
|
{
|
|
ArgumentNullException.ThrowIfNull(app);
|
|
|
|
ILogger logger = app.ApplicationServices
|
|
.GetRequiredService<ILoggerFactory>()
|
|
.CreateLogger("MxGateway.Request");
|
|
|
|
return app.Use(async (context, next) =>
|
|
{
|
|
using IDisposable? scope = logger.BeginGatewayScope(new GatewayLogScope(
|
|
SessionId: ReadHeader(context, SessionIdHeaderName),
|
|
WorkerProcessId: ReadInt32Header(context, WorkerProcessIdHeaderName),
|
|
CorrelationId: ReadUInt64Header(context, CorrelationIdHeaderName),
|
|
CommandMethod: ReadHeader(context, CommandMethodHeaderName),
|
|
ClientIdentity: ReadHeader(context, "authorization")));
|
|
|
|
await next(context);
|
|
});
|
|
}
|
|
```
|
|
|
|
The scope is keyed off four custom headers and the standard `authorization` header:
|
|
|
|
| Header | Scope field | Type |
|
|
|--------|-------------|------|
|
|
| `x-session-id` | `SessionId` | string |
|
|
| `x-worker-process-id` | `WorkerProcessId` | int |
|
|
| `x-correlation-id` | `CorrelationId` | ulong |
|
|
| `x-command-method` | `CommandMethod` | string |
|
|
| `authorization` | `ClientIdentity` | string (redacted) |
|
|
|
|
The numeric headers use `int.TryParse` and `ulong.TryParse`; missing or unparseable values become `null` and are dropped by `GatewayLogScope.ToDictionary`. This keeps the middleware tolerant of clients that do not yet emit every header, which matters because the earliest call in a session (`OpenSession`) has no `SessionId` to send.
|
|
|
|
The logger category is `MxGateway.Request`, which lets operators filter the request scope events independently from per-component categories. The logger is resolved once at registration rather than per request: the category is fixed, so a per-request `IServiceProvider` resolve and `ILoggerFactory.CreateLogger` (which takes the factory lock) bought nothing. Scope construction itself stays unconditional — gating it on `ILogger.IsEnabled` would drop scope state for providers and scope consumers registered after startup.
|
|
|
|
### Pipeline ordering
|
|
|
|
`GatewayApplication.Build` registers the middleware before authentication, authorization, and endpoint mapping:
|
|
|
|
```csharp
|
|
app.UseGatewayRequestLoggingScope();
|
|
app.UseStaticFiles();
|
|
app.UseAuthentication();
|
|
app.UseAuthorization();
|
|
app.UseAntiforgery();
|
|
app.MapGatewayEndpoints();
|
|
```
|
|
|
|
The order matters: putting the logging scope first ensures that authentication failures, authorization denials, and endpoint exceptions all run inside the request scope, so failure logs still carry the correlation id and session id headers that the caller sent. The `ClientIdentity` field is redacted before logging, so reading the `authorization` header at this stage does not leak the bearer secret into authentication failure logs.
|
|
|
|
## Consumers
|
|
|
|
`GatewayLoggerExtensions.BeginGatewayScope` is consumed by `GatewayRequestLoggingMiddlewareExtensions` to attach the per-request scope. Component-level call sites build narrower `GatewayLogScope` instances (for example, with a known `WorkerProcessId` after a worker launch) and push a nested scope on top of the request scope.
|
|
|
|
`GatewayLogRedactor` is consumed in three places:
|
|
|
|
- `GatewayLogScope.ToDictionary` redacts `ClientIdentity` whenever a scope is materialized.
|
|
- `DashboardRedactor.Redact` delegates to `RedactClientIdentity` for any value containing the `mxgw_` marker, then falls back to a marker-keyword check for fields like `password` or `token`. This keeps dashboard renders aligned with log redaction.
|
|
- `ZB.MOM.WW.MxGateway.Tests/Diagnostics/GatewayLogRedactorTests.cs` covers each redaction branch, including the assertion that `WriteSecured` values stay redacted even when `valueLoggingEnabled` is true.
|
|
|
|
## Health Checks
|
|
|
|
The shared `ZB.MOM.WW.Health` package maps three endpoints — `/healthz` (live), `/health/ready`, and
|
|
`/health/active` — and each registered check opts into a tier by tag. The gateway registers two:
|
|
|
|
| Check | Endpoint tier | Fails when |
|
|
|---|---|---|
|
|
| `auth-store` | `ready` | The SQLite auth store cannot be opened. Every gRPC call authenticates against it, so its reachability genuinely gates whether the process should receive traffic. |
|
|
| `mxaccess-sessions` | `active` | Sessions exist and their workers have faulted. Reports `total` / `ready` / `faulted` / `starting` / `closing` as entry `data`. |
|
|
|
|
**Zero sessions is Healthy, and the tier choice follows from that.** The gateway opens an MXAccess
|
|
session when a client asks for one and holds none otherwise, so an idle gateway is working normally,
|
|
not broken. A count threshold ("unhealthy below N") would sit red forever on a host nothing dials
|
|
yet, and a permanently red probe is one operators stop reading — which leaves them worse off than no
|
|
probe at all. `mxaccess-sessions` is therefore graded on whether the sessions that exist are usable:
|
|
|
|
- nothing faulted → **Healthy** (including no sessions at all)
|
|
- some faulted, some still ready or starting → **Degraded**
|
|
- every session faulted → **Unhealthy**
|
|
|
|
For the same reason it is tagged `active` rather than `ready`. Readiness decides whether the process
|
|
should be sent traffic, and a gateway with no sessions is ready to serve; failing readiness there
|
|
would pull a working gateway out of rotation over a condition its clients create.
|
|
|
|
## Related Documentation
|
|
|
|
- [Identifying A Deployed Build](./runbooks/IdentifyingADeployedBuild.md) — mapping a running binary back to a commit, and why the `InformationalVersion` stamp cannot be trusted on Windows builds from 2026-07-09 to 2026-08-10
|
|
- [Sessions](./Sessions.md)
|
|
- [gRPC](./Grpc.md)
|
|
- [Authentication](./Authentication.md)
|