SilasFletcher5857

Posted on Oct 15

Node.js Structured Application Logging Schema for Healthtech Request Trace Correlation

#observability #node #sre

A healthtech notification can be clinically important without its application log containing any clinical data. That constraint changes the design: log an immutable sequence of delivery decisions and attempts, join it with request and trace context, and treat patient content as forbidden input.

TL;DR: emit one JSON event for each durable state transition and delivery attempt. Include a generated request ID, W3C trace ID, stable internal tenant and actor references, notification and attempt IDs, channel, outcome, error class, retry state, and schema version. Never log message bodies, email addresses, phone numbers, access tokens, or arbitrary error objects. This produces an incident timeline without making the log store a second patient-record system.

I've been paged for both missed scheduled work and duplicate deliveries. The hard question during either page is not “did the endpoint return 200?” It is “which durable decision happened, which attempt followed it, and did another worker make the same decision?” A request log alone cannot answer that.

What should a structured SaaS application log record for each request?

An inbound request is only the start of an asynchronous notification. The API may accept a scheduling command, commit work, and return before a queue consumer claims it. A later worker can time out after the downstream provider accepts a message. Another worker can then retry. If the logs share only a URL and timestamp, those validly separate operations look unrelated.

Retries blur the trail.

The invariant I use is narrow: every record needed for reconstruction carries the same notification ID, while every physical delivery carries a distinct attempt ID. Request and trace identifiers describe execution context; they do not replace business identifiers.

IDs are evidence, not answers.

That distinction matters during a duplicate-delivery investigation. Two delivery_attempt_finished events with different attempt IDs may indicate a retry, concurrent claims, or an intentional second channel. Two completion events for one attempt ID point somewhere else, such as duplicate event emission. The log does not pronounce a cause. It preserves enough ordered evidence to test causes against queue and provider records.

A useful event envelope looks like this:

Field	Purpose	Cardinality and privacy rule
`event_name`	Names a bounded operational fact	Controlled vocabulary
`occurred_at`	Places the fact on a UTC timeline	RFC 3339 timestamp
`schema_version`	Makes old records interpretable	Small integer
`notification_id`	Joins the notification lifecycle	Opaque internal ID
`attempt_id`	Separates physical delivery attempts	Opaque internal ID
`request_id`	Joins work accepted in one application request	Generated or validated at ingress
`trace_id`	Joins distributed execution	W3C Trace Context format
`tenant_id`	Scopes an investigation	Opaque internal ID, not a tenant name
`actor_id`	Attributes a user-initiated decision	Opaque internal ID; omit for system actions
`channel`	Distinguishes email, SMS, push, or another path	Controlled vocabulary
`outcome`	Records success, retry, rejection, or terminal failure	Controlled vocabulary
`error_class`	Groups actionable failure modes	Sanitized taxonomy, not raw text
`retry_count`	Shows the scheduler's current decision	Integer, starting from a documented convention

Do not overload user_id. In a healthtech system, “user” might mean the patient receiving a message, a clinician who scheduled it, or an operator who changed policy. Use role-specific opaque references such as recipient_ref and actor_id, document their meanings, and omit them when they are not needed for the investigation.

Build the event chain around committed facts

The safest place to emit a lifecycle event is after the corresponding state change is durable. Logging notification_scheduled before a database transaction commits can leave a convincing record of work that never existed. Logging it after the commit from unrelated best-effort application code creates the opposite gap: work exists, but its event can disappear if the process exits.

For transitions that must agree with database state, use a transactional outbox or an equivalent atomic handoff. Store the notification change and an outbox row in one database transaction. A relay can publish the row later and mark it processed. Consumers must still be idempotent because delivery from the relay can repeat.

This is the incident sequence I want to recover:

The API accepted a scheduling command and committed notification_scheduled.
A worker claimed the durable job and emitted delivery_attempt_started with a new attempt ID.
The worker recorded a bounded result: delivery_attempt_succeeded, delivery_attempt_retrying, or delivery_attempt_failed.
A terminal notification state was committed once policy said no more attempts should occur.

The words matter less than the contracts. Each name should describe a completed fact, not an intention such as sending_notification. Each event should have a defined producer, required fields, and point in the transaction lifecycle. Keep a small schema registry in source control and review changes like an API.

Ordering needs similar restraint. Wall-clock timestamps are useful for navigation, but clocks across processes are not a correctness mechanism. Add a monotonically increasing notification_version when the database aggregate supports one. During reconstruction, sort by that version inside a notification and use timestamps to relate the sequence to external systems. A version gap is visible. So is a repeated transition.

Short version: log facts after they become facts.

Mask before serialization, then allowlist

Redaction applied after JSON serialization is fragile. Secrets can appear under a new field name, nested inside an error, or embedded in a URL query string. An allowlisted event type prevents those values from entering the logging pipeline in the first place. A final sanitizer is still useful as defense in depth, but it should not be the primary data model.

The following Go example shows the preventative boundary. It accepts typed operational fields rather than an arbitrary object, hashes an optional recipient reference with a keyed HMAC, validates identifiers, and emits JSON. The same boundary can sit behind a Node.js logger: application code calls a typed event constructor, not a free-form logger.info(payload).

package deliverylog

import (
    "crypto/hmac"
    "crypto/sha256"
    "encoding/hex"
    "encoding/json"
    "errors"
    "io"
    "regexp"
    "time"
)

var opaqueID = regexp.MustCompile(`^[A-Za-z0-9_-]{8,128}$`)

type AttemptEvent struct {
    EventName       string `json:"event_name"`
    OccurredAt      string `json:"occurred_at"`
    SchemaVersion   int    `json:"schema_version"`
    NotificationID string `json:"notification_id"`
    AttemptID      string `json:"attempt_id"`
    RequestID      string `json:"request_id,omitempty"`
    TraceID        string `json:"trace_id,omitempty"`
    TenantID       string `json:"tenant_id"`
    RecipientRef   string `json:"recipient_ref,omitempty"`
    Channel        string `json:"channel"`
    Outcome        string `json:"outcome"`
    ErrorClass     string `json:"error_class,omitempty"`
    RetryCount     int    `json:"retry_count"`
}

type AttemptInput struct {
    NotificationID string
    AttemptID      string
    RequestID      string
    TraceID        string
    TenantID       string
    RecipientID    string
    Channel        string
    Outcome        string
    ErrorClass     string
    RetryCount     int
}

func WriteAttempt(w io.Writer, key []byte, in AttemptInput, now time.Time) error {
    for _, id := range []string{in.NotificationID, in.AttemptID, in.TenantID} {
        if !opaqueID.MatchString(id) {
            return errors.New("invalid opaque identifier")
        }
    }
    if in.RetryCount < 0 {
        return errors.New("retry count cannot be negative")
    }

    event := AttemptEvent{
        EventName:       "delivery_attempt_finished",
        OccurredAt:      now.UTC().Format(time.RFC3339Nano),
        SchemaVersion:   1,
        NotificationID: in.NotificationID,
        AttemptID:      in.AttemptID,
        RequestID:      in.RequestID,
        TraceID:        in.TraceID,
        TenantID:       in.TenantID,
        RecipientRef:   pseudonym(key, in.RecipientID),
        Channel:        in.Channel,
        Outcome:        in.Outcome,
        ErrorClass:     in.ErrorClass,
        RetryCount:     in.RetryCount,
    }
    return json.NewEncoder(w).Encode(event)
}

func pseudonym(key []byte, value string) string {
    if value == "" {
        return ""
    }
    mac := hmac.New(sha256.New, key)
    _, _ = mac.Write([]byte(value))
    return hex.EncodeToString(mac.Sum(nil))
}

This code deliberately has no message body, destination address, raw provider response, stack trace, or generic metadata map. HMAC pseudonymization does not make the source data harmless: anyone with the key can recompute values, and repeated inputs remain linkable. Protect and rotate the key under the system's security policy, restrict log access, and omit the reference entirely if incident response does not need it.

Do not accept a client-supplied request ID blindly. Constrain its length and character set or replace it at ingress, then return the effective value to the caller. For traces, follow W3C Trace Context parsing and propagation rules. A trace ID is correlation context, not authentication and not proof that two events are authorized to see each other.

What should stay out of the log?

Start with content: message subjects, templates after rendering, appointment details, diagnosis terms, medication names, free-form support notes, email addresses, and phone numbers. Authorization headers, cookies, reset links, one-time codes, and API credentials also have no place in an application event.

Raw exceptions are risky because library messages often interpolate request values. Convert expected failures at the boundary into a compact taxonomy such as provider_timeout, provider_rejected, rate_limited, or invalid_destination. Keep a bounded error_code only when its source and meaning are documented. Unexpected failures can retain a controlled stack fingerprint for grouping while the full diagnostic material goes through a separately governed path.

Data minimization wins over clever masking. Replacing an email address with stars still advertises its shape and may leave enough information to identify someone. Omission is easier to reason about. Where correlation is essential, use an opaque internal identifier or a keyed pseudonym and set retention according to the investigation window and applicable policy.

This advice does not apply unchanged to a legally mandated audit record. Audit evidence may require different fields, integrity controls, access rules, and retention. Keep that record as a separately designed system; copying application logs into a long-retention bucket does not turn them into a compliant audit trail. The limitation of this event model is intentional: it favors operational reconstruction with minimized data, so it is also the wrong primary store for message-content disputes, regulatory evidence, or analytics that require historical recipient attributes. Those jobs need separately governed records with their own purpose, access model, integrity guarantees, and deletion policy. Combining all three purposes in one log index makes access broader and retention harder to justify.

Make reconstruction a tested operational capability

A schema is useful only if responders can query it under pressure. Write a runbook around a single starting value, usually notification_id. The first query should return lifecycle events ordered by notification_version, with attempt ID, outcome, retry count, trace ID, and sanitized error class visible. From there, an operator can pivot to one attempt or trace without searching message content.

Test the questions, not just the encoder. In staging, create a scheduled notification, force a retryable delivery result, allow a retry, and verify that the resulting records distinguish the two attempt IDs while retaining one notification ID. Exercise a duplicate queue delivery and confirm the idempotency boundary prevents a second external side effect. Test rejected identifiers and seeded sensitive strings, then fail the build if any forbidden value reaches captured output.

There is a metrics boundary too. Do not turn notification_id, request_id, trace_id, actor references, or recipient references into metric labels. Prometheus naming guidance recommends labels for dimensions, but each unique label combination creates another time series. Use bounded labels such as channel and outcome for aggregate alerting; pivot from an alert time window into logs for individual IDs.

Sample carefully. Success events may be sampled for broad diagnostics, but the authoritative lifecycle record for incident reconstruction cannot depend on probabilistic sampling. If storage pressure forces a choice, preserve terminal failures, retry decisions, and state transitions before verbose request detail. Make the policy explicit so “no event found” has a known meaning.

Deployment deserves a gate. Additive optional fields are usually easier to roll out than renamed or retyped fields. Producers should emit a schema version, consumers should tolerate the supported versions, and dashboards or saved queries should be checked before removing a field. During a rolling deployment, assume old and new producers coexist.

The final design test is plain: given one notification ID, can an on-call engineer explain the committed schedule state, enumerate every delivery attempt, identify the retry decision, and show the terminal outcome without reading patient content? If yes, the logs are doing operational work. If not, adding more payload will probably make the risk larger before it makes the incident clearer.

DEV Community