diff --git a/docs/.vuepress/config.js b/docs/.vuepress/config.js index 71e0199b..3be44e83 100644 --- a/docs/.vuepress/config.js +++ b/docs/.vuepress/config.js @@ -206,6 +206,7 @@ module.exports = { ['standards/versioning', 'Versioning'], ['standards/creating-new-features', 'Creating New Features'], ['standards/triaging-bugs', 'Triaging Bugs'], + ['standards/logging-std', 'Logging Standards'], ] }, { diff --git a/docs/community/standards/logging-std.md b/docs/community/standards/logging-std.md new file mode 100644 index 00000000..6b9081fa --- /dev/null +++ b/docs/community/standards/logging-std.md @@ -0,0 +1,53 @@ +# Mojaloop Logging Standard + +**Version:** 1.0.0 + +## Purpose + +This document defines the logging standard for Mojaloop projects to ensure: +- **Consistent log levels** across all services +- **OpenTelemetry compatibility** for unified observability +- **Distributed tracing integration** via trace context propagation +- **Actionable logs** in production environments +- **Efficient debugging** without log noise +- **Performance optimization** through appropriate log levels +- **Security** by preventing sensitive data exposure + +## Standard Components + +The standard is broken down into the following sections: + +* [Log Levels](./logging/log_levels.md) - Definitions, OTel mapping, and decision trees. +* [Data Model](./logging/data_model.md) - JSON structure, required fields, and naming conventions. +* [Trace Context](./logging/trace_context.md) - Propagation and correlation rules. +* [Security](./logging/security.md) - PII and sensitive data handling. +* [Best Practices](./logging/best_practices.md) - Performance, anti-patterns, and implementation guidelines. + +## Quick Reference Summary + +| Level | OTel Severity | Production | Use Case | Example | +|-------|---------------|-----------|----------|---------| +| FATAL | 21-24 | ✅ Always | Service outage | DB unreachable, panic | +| ERROR | 17-20 | ✅ Always | Operation failures | Transaction failed | +| WARN | 13-16 | ✅ Always | Recoverable issues | Validation failure, retry | +| INFO | 9-12 | ✅ Always | Business events | Transfer completed | +| VERBOSE | 7-8 | ⚠️ Sampled| Operational noise | Health check, keep-alive | +| DEBUG | 5-6 | ⚠️ Temporarily | Troubleshooting | Function calls, logic | +| TRACE | 1-4 | ❌ Rarely | Deep diagnosis | Variable state, loop dump | + + +**Default production setting: INFO level (SeverityNumber >= 9)** +- Captures all important business events +- Minimizes performance impact +- Reduces log noise +- Can be changed to DEBUG temporarily for troubleshooting +- Compatible with OpenTelemetry severity filtering + +## Extended Scenarios + +Specific standards for common scenarios are available in the specific standards documents: + +* [HTTP Requests](./logging/scenarios/http_requests.md) - Standard for incoming and outgoing HTTP logging. +* [Error Handling](./logging/scenarios/error_handling.md) - Rules for logging exceptions and propagating errors. +* [Database Queries](./logging/scenarios/sql_queries.md) - Guidelines for logging SQL and DB interactions. +* [Kafka Messaging](./logging/scenarios/kafka_messaging.md) - Guidelines for producing and consuming Kafka messages. diff --git a/docs/community/standards/logging/best_practices.md b/docs/community/standards/logging/best_practices.md new file mode 100644 index 00000000..929725e0 --- /dev/null +++ b/docs/community/standards/logging/best_practices.md @@ -0,0 +1,240 @@ +# Best Practices and Guidelines + +This document provides guidelines on implementation, performance optimization, and common anti-patterns to avoid. + +## Production Logging Guidelines + +### Performance Considerations +- **Avoid expensive operations at DEBUG/TRACE** - These should be cheap since they may be enabled temporarily +- **Use `loggerFactory` from contextLogger** - It checks `isEnabled` internally before calling Winston, so log arguments are only serialized when the level is active +- **Use `isDebugEnabled()` only for expensive computation** - Guard with `isDebugEnabled()` only when the arguments themselves require expensive work that exists solely for debugging +- **Structured logging** - Log objects, not concatenated strings +- **Avoid JSON.stringify** - Let the logging library handle serialization + +### Examples of Performance-Aware Logging + +**Bad:** +```javascript +// Always executes stringify even if DEBUG is disabled +logger.debug(`Processing: ${JSON.stringify(largeObject)}`); +``` + +**Good:** +```javascript +// contextLogger handles level checks internally — just log +logger.debug('Processing transfer', { transfer }); + +// Use isDebugEnabled() ONLY when guarding expensive computation +if (logger.isDebugEnabled()) { + logger.debug('Detailed state', { computedState: computeExpensiveState() }); +} +``` + +### Metrics vs. Logs + +Do **NOT** use logs for counting volume or calculating success rates. Use **Metrics** (Counters, Histograms) for throughput, latency, and error rate tracking. +Use **Logs** for high-cardinality details that cannot be captured in metrics (e.g., specific transaction IDs, error reasons). + + +## Infrastructure and Observability + +### Correlation IDs and Trace Context + +Winston's OTel auto-instrumentation (`@opentelemetry/instrumentation-winston`) automatically injects `trace_id`, `span_id`, and `trace_flags` into every log entry. Do **not** add them manually — duplicate or stale IDs cause correlation errors. + +Use child loggers for **business-level** correlation IDs only (request ID, transfer ID, batch ID): + +```javascript +// trace_id and span_id are injected automatically by OTel instrumentation +// Only add business identifiers via child loggers +const log = logger.child({ requestId: req.id, transferId: req.params.id }) +log.info('Processing request') +``` + +### Log to Stdout + +Write all logs to stdout. Do **not** use `console.log` or write to files directly. Delegate collection, rotation, and shipping to external tools (Fluentd, Vector, OTel Collector). In containerized environments, a sidecar or daemonset picks up stdout, enriches it with pod/host metadata, and ships it to a centralized store. + +### OpenTelemetry Semantic Conventions + +Use OTel's standard attribute names so logs, traces, and metrics correlate without per-service mapping: + +| Domain | Attributes | +|--------|-----------| +| HTTP | `http.request.method`, `url.path`, `http.response.status_code` | +| Database | `db.system`, `db.statement`, `db.operation.name` | +| Errors | `error.type`, `error.message`, `error.stack_trace` | +| Messaging | `messaging.system`, `messaging.destination.name` | + +When OTel renames or deprecates an attribute, update logging code to match. + +### Canonical Log Lines + +Emit one wide log entry per request at the HTTP boundary. Include method, route, status code, duration, and key business identifiers. This single entry supports latency analysis, error rate calculation, and audit without aggregation. + +```javascript +logger.info(`${req.method} ${req.path} ${res.statusCode}`, { + 'http.request.method': req.method, + 'url.path': req.path, + 'http.response.status_code': res.statusCode, + 'http.server.request.duration': duration, + transferId +}) +``` + +### Redaction at Logger Level + +Apply redaction at the logger configuration — not at each call site — so new fields cannot leak by accident. Declare paths to mask (e.g., `authorization`, `password`, `token` fields). Log user IDs and entity references instead of full user objects. Dump sanitized configuration at startup: mark sensitive fields so they display as asterisks. + +### Per-Component Log Levels + +Use `setLevel()` on a child logger to change its verbosity without affecting the parent or siblings. This lets you debug one subsystem without raising the noise floor for everything else. + +```javascript +// Only database logs go to debug; parent and siblings stay at their original level +const dbLog = logger.child({ component: 'database' }) +dbLog.setLevel('debug') +``` + +### Dedicated `LOG_LEVEL_{DOMAIN}` Env Vars + +When a shared library creates its own internal logger, control its level via a `LOG_LEVEL_{DOMAIN}` env var with a default of `'info'`. This lets operators tune library verbosity without changing the service's log level. + +```javascript +const { LOG_LEVEL_KAFKA = 'info' } = require('node:process').env +const logger = loggerFactory('ml-kafka') +logger.setLevel(LOG_LEVEL_KAFKA) + +// Usage: LOG_LEVEL_KAFKA=debug npm start +// Service stays at 'info', Kafka internals log at 'debug' +``` + +## Anti-Patterns to Avoid + +### 1. Using console.log +```javascript +// ❌ BAD +console.log('Some message') + +// ✅ GOOD +logger.info('Some message') +``` + +### 2. Logging Everything at INFO +```javascript +// ❌ BAD - Internal details at INFO, generic messages +logger.info('Entering validateTransfer function'); +logger.info('Retrieved account from database'); +logger.info('Balance check passed'); + +// ✅ GOOD - Only significant events at INFO with context +logger.info(`Transfer ${transferId} validated successfully for ${amount} ${currency}`, { + operation: 'validateTransfer', + eventName: 'TransferValidated', + transferId: transferId, + 'transfer.amount': amount, + 'transfer.currency': currency +}); +``` + +### 3. Missing Context in Message +```javascript +// ❌ BAD - Message doesn't explain what happened +logger.error('Validation failed'); + +// ✅ GOOD - Descriptive message with inline context plus structured attributes +// Trace context is automatic, don't add manually! +logger.error(`Transfer ${transfer.id} validation failed at step '${step}': ${validationErrors.join(', ')}`, { + operation: 'validateTransfer', + eventName: 'ValidationFailed', + transferId: transfer.id, + validationStep: step, + validationErrors: validationErrors +}); +``` + +### 4. Missing Error Stack +**Requirement:** "Verify that Errors are logged with Error Code, Error Stack defined". + +```javascript +// ❌ BAD - Losing the stack trace +logger.error(`Failed: ${error.message}`); + +// ✅ GOOD - Passing the error object ensures stack is captured +logger.error(`Transfer failed: `, error) // Logger serializer should handle 'exception.stacktrace' and 'exception.type' +``` + +### 5. Sensitive Data Exposure +```javascript +// ❌ BAD +logger.debug('User authentication', { password: user.password }); + +// ✅ GOOD +logger.debug('User authentication', { + userId: user.id, + method: 'password' +}); +``` + +### 6. Over-Logging +```javascript +// ❌ BAD - Logging inside tight loops with repeated generic messages +for (const transfer of transfers) { + logger.info('Processing transfer', transfer); // Could be thousands +} + +// ✅ GOOD - Aggregate with descriptive summary +logger.info(`Processing batch of ${transfers.length} transfers for batch ${batch.id}`, { + operation: 'processBatch', + eventName: 'BatchProcessingStarted', + 'batch.id': batch.id, + 'batch.transferCount': transfers.length, + 'batch.totalAmount': transfers.reduce((sum, t) => sum + t.amount, 0) +}); +``` + +## Where to Log (Avoiding Duplication) + +**Goal:** Avoid "Errors captured in more than one place (often three times)". + +### The "Catch and Log" Anti-Pattern +Do **NOT** catch an error just to log it and throw it again, unless you are adding significant context that cannot be added anywhere else. + +```javascript +// ❌ BAD - Duplicates logs up the stack +try { + await performAction(); +} catch (error) { + logger.error(error); // Log 1 + throw error; +} + +// ... caller ... +try { + await service.action(); +} catch (error) { + logger.error(error); // Log 2 (Duplicate) + throw error; +} +``` + +### The "Catch, Context, and Bubble" Pattern +If you catch an error to add context, wrap it or attach properties, but do NOT log it until the "Edge" of the application. + +```javascript +// ✅ GOOD - Add context, don't log yet +try { + await db.query(); +} catch (error) { + throw new DatabaseError('Failed to query', { cause: error }); +} + +// ... Global Error Handler (The Edge) ... +// Log ONLY here +logger.error(finalError); +``` + +### Exceptions +- **Background Jobs**: Log errors inside the job as they have no caller to bubble to. +- **Async Event Handlers**: Log errors inside consumers/handlers if they don't have a standardized global error handler. + diff --git a/docs/community/standards/logging/data_model.md b/docs/community/standards/logging/data_model.md new file mode 100644 index 00000000..f007e5e5 --- /dev/null +++ b/docs/community/standards/logging/data_model.md @@ -0,0 +1,123 @@ +# Data Model + +This document defines the structure and field conventions for Mojaloop logs, ensuring alignment with OpenTelemetry standards. + +## OpenTelemetry Alignment + +This standard aligns with the following OpenTelemetry specifications: +* [Logs Data Model](https://opentelemetry.io/docs/specs/otel/logs/data-model/) +* [Semantic Conventions (Attributes)](https://opentelemetry.io/docs/specs/semconv/) + +This alignment ensures: +- Logs can be correlated with traces and metrics +- Compatibility with OpenTelemetry collectors and backends +- Standardized severity levels and structured format +- Automatic context propagation in distributed systems + +## Standard Field Mapping + +| Mojaloop Concept | OTel Field Name | Description | +|------------------|-----------------|-------------| +| Log Level | `SeverityNumber`| Numerical value of the severity (1-24) | +| Level Name | `SeverityText` | The text string representation (e.g., "INFO") | +| Message | `Body` | The human-readable message content | +| Context | `Attributes` | Structured key-value pairs (event specific) | +| Service Info | `Resource` | Source description (Service Name, Version, Env) | +| Scope | `InstrumentationScope` | The library/module emitting the log | + +## Structured Logging Format + +### Log Message Best Practices + +**The message (Body) should be human-readable and self-explanatory:** +- Include specific values inline (IDs, amounts, states) +- Describe what happened, not just the operation name +- Be detailed enough to understand the issue without looking at attributes +- Use complete sentences with context + +**Examples of good messages:** +- ✅ `"Transfer abc-123 validation failed during balance check. Account balance is 100.00 USD but transfer amount is 150.00 USD"` +- ✅ `"Payment xyz-789 processing completed successfully from PayerFSP to PayeeFSP in 250ms"` +- ✅ `"Database connection to mysql://prod-db:3306 failed after 3 retry attempts: Connection timeout"` + +**Examples of poor messages:** +- ❌ `"Validation failed"` (too generic, no context) +- ❌ `"Processing transfer"` (not clear what happened) +- ❌ `"Error occurred"` (provides no information) + +**The attributes provide structured data for querying:** +- Use attributes for filtering, grouping, and aggregation +- Attributes enable queries like "all transfers > $1000" or "errors from service X" +- Attributes support correlation (traceId, spanId, transferId) + +### OpenTelemetry Log Record Structure + +Following OpenTelemetry conventions, logs should include: + +**Core Fields (automatic):** +- **Timestamp**: Time when event occurred (ISO 8601 format) +- **SeverityText**: Human-readable level (ERROR, WARN, INFO, DEBUG, TRACE) +- **SeverityNumber**: Numeric severity (17=ERROR, 13=WARN, 9=INFO, 5=DEBUG, 1=TRACE) +- **Body**: Human-readable message describing the event + +**Trace Context Fields (for distributed tracing):** +- **TraceId**: W3C Trace Context trace ID (**automatic** when using OTel-instrumented logging) +- **SpanId**: Current span ID (**automatic** when using OTel-instrumented logging) +- **TraceFlags**: W3C trace flags (**automatic**, typically set by tracing SDK) + +**Important:** You should **NOT** manually add traceId/spanId to log calls. These are automatically injected by the logging library when properly configured with OpenTelemetry instrumentation. + +**Resource Fields (describes the source):** +- `service.name`: Service name (e.g., 'central-ledger') +- `service.version`: Service version (e.g., '1.2.3') +- `deployment.environment`: Environment (e.g., 'production', 'staging') +- `host.name`: Hostname or container ID +- `process.pid`: Process ID + +**Attributes (business context):** +- `operation`: Function or operation name +- `duration.ms`: For completed operations (milliseconds) +- `transferId`, `userId`, `accountId`: Business entity IDs +- `error.type`: Error class name (for errors) +- `error.message`: Error message (for errors) +- `error.stack`: Stack trace (for errors) +- `eventName`: For business events (e.g., 'TransferCompleted', 'PaymentFailed') + +### Distinction: Resource vs Attributes + +- **Resource**: Describes WHERE the log came from (service, host, environment) - static per service instance +- **Attributes**: Describes WHAT happened (operation, IDs, business data) - varies per log entry + +**Example with OpenTelemetry Structure:** +```javascript +// Resource (set once at service startup) +const resource = { + 'service.name': 'central-ledger', + 'service.version': '1.2.3', + 'deployment.environment': 'production', + 'host.name': 'pod-xyz-123' +}; + +// Log entry with descriptive message, trace context, and attributes +logger.error( + `Transfer ${transfer.id} processing failed during ${operation} operation from ${transfer.payerFsp} to ${transfer.payeeFsp}: ${error.message}`, + { + // Trace context (automatic if using OTel SDK) + traceId: '4bf92f3577b34da6a3ce929d0e0e4736', + spanId: '00f067aa0ba902b7', + + // Attributes (business context) + operation: 'processTransfer', + eventName: 'TransferFailed', + transferId: transfer.id, + 'payer.fspId': transfer.payerFsp, + 'payee.fspId': transfer.payeeFsp, + 'transfer.amount': transfer.amount.amount, + 'transfer.currency': transfer.amount.currency, + 'error.type': 'ValidationError', + 'exception.message': error.message, + 'exception.stacktrace': error.stack, + 'duration.ms': 250 + } +); +``` diff --git a/docs/community/standards/logging/log_levels.md b/docs/community/standards/logging/log_levels.md new file mode 100644 index 00000000..170c850b --- /dev/null +++ b/docs/community/standards/logging/log_levels.md @@ -0,0 +1,337 @@ +# Log Levels + +This document details the standard log levels, their mapping to OpenTelemetry, and decision guidelines for when to use each. + +## OpenTelemetry Severity Mapping + +Mojaloop log levels map to OpenTelemetry SeverityNumber ranges for compatibility: + +| Mojaloop Level | ML numeric value | OTel SeverityNumber | OTel Range | Numeric Value | +|----------------|------------------|---------------------|------------|---------------| +| FATAL | - | FATAL | 21-24 | 21 | +| ERROR | 0 | ERROR | 17-20 | 17 | +| WARN | 1 | WARN | 13-16 | 13 | +| AUDIT | 2 | ??? | | | +| TRACE | 3 | ??? (see TRACE) | | | +| INFO | 4 | INFO | 9-12 | 9 | +| PERF | 5 | ??? | | | +| VERBOSE | 6 | INFO (Low-priority) | 7-8 | 7 | +| DEBUG | 7 | DEBUG | 5-6 | 5 | +| SILLY | 8 | TRACE | 1-4 | 1 | + +When emitting logs via OpenTelemetry SDK, use the corresponding SeverityNumber. Most logging libraries will handle this mapping automatically. + +## Level Definitions + +### FATAL - Uncoverable System Failures + +**When to use:** +- System cannot continue to function +- Critical dependency failure preventing startup +- Security breach detected requiring shutdown +- Unrecoverable data corruption + +**What to include:** +- Cause of fatal error +- Shut down status +- Immediate action required + +**Examples:** +```javascript +logger.fatal(`Central Ledger service shutting down: Database unreachable at startup after ${maxRetries} attempts`, { + eventName: 'ServiceShutdown', + reason: 'DatabaseUnreachable', + 'db.host': dbHost, + 'exception.message': error.message +}); +``` + +### ERROR - Critical Issues Requiring Immediate Attention + +**When to use:** +- Unhandled exceptions or errors +- Database connection failures +- External service failures (payment processor down) +- Data corruption or integrity issues +- Authentication/authorization failures +- Critical business rule violations +- Any condition that prevents normal operation + +**What to include:** +- Error message and stack trace +- Operation context (function name, operation type) +- Request/transaction IDs for tracing +- User/account IDs (if applicable) +- Timestamp + +**Examples:** +```javascript +// Trace context is AUTOMATIC - don't add manually! +logger.error(`Transfer ${transfer.id} processing failed in processTransfer operation: ${error.message}`, { + // Attributes only - trace context added automatically by OTel + operation: 'processTransfer', + eventName: 'TransferFailed', + transferId: transfer.id, + 'exception.type': error.name, + 'exception.message': error.message, + 'exception.stacktrace': error.stack +}); + +logger.error(`Database connection to ${dbConfig.host}:${dbConfig.port} failed after ${retryCount} retry attempts: ${error.message}`, { + operation: 'connectDatabase', + eventName: 'DatabaseConnectionFailed', + 'db.host': dbConfig.host, + 'db.port': dbConfig.port, + 'db.name': dbConfig.database, + retryCount: retryCount, + 'exception.type': error.name, + 'exception.message': error.message +}); +``` + +**Do NOT use for:** +- Expected validation failures (use WARN) +- Retry-able operations that succeed on retry +- User input errors (use WARN) + +### WARN - Recoverable Issues or Degraded Operation + +**When to use:** +- Expected validation failures +- Retry attempts (before final failure) +- Deprecated API usage +- Configuration issues with fallback values +- Business rule violations that can be handled +- Rate limiting triggered +- Temporary service unavailability with fallback +- Performance degradation warnings + +**What to include:** +- Warning description +- Context of what triggered the warning +- Action taken (fallback, retry, skip) +- Request/transaction IDs + +**Examples:** +```javascript +logger.warn(`Transfer ${transfer.id} validation failed during balance check. Account balance is ${account.balance} ${account.currency} but transfer amount is ${transfer.amount} ${transfer.currency}`, { + operation: 'validateTransfer', + eventName: 'TransferRejected', + transferId: transfer.id, + accountId: account.id, + 'account.balance': account.balance, + 'account.currency': account.currency, + 'transfer.amount': transfer.amount, + 'transfer.currency': transfer.currency, + validationErrors: errors, + reason: 'InsufficientFunds' +}); + +logger.warn(`API rate limit of ${limit} requests per ${period} reached for endpoint ${endpoint}. Throttling subsequent requests`, { + operation: 'rateLimit', + eventName: 'RateLimitTriggered', + endpoint: endpoint, + limit: limit, + period: period, + currentCount: requestCount +}); +``` + +**Do NOT use for:** +- Normal business operations +- Successful validation +- Debug information + +### INFO - Significant Business Events + +**When to use:** +- Service startup/shutdown (Major lifecycle events) +- Successful completion of major operations (Transfers) +- State transitions (transfer approved, settlement completed) +- API request/response (Significant entry points only) +- Authentication success + +**What to include:** +- Event description +- Key identifiers (IDs, names) +- Relevant business data (amounts, status changes) +- Duration for completed operations + +**Examples:** +```javascript +logger.info(`Transfer ${transfer.id} completed successfully from ${transfer.payerFsp} to ${transfer.payeeFsp} for ${transfer.amount.amount} ${transfer.amount.currency} in ${duration}ms`, { + operation: 'processTransfer', + eventName: 'TransferCompleted', + transferId: transfer.id, + 'payer.fspId': transfer.payerFsp, + 'payee.fspId': transfer.payeeFsp, + 'transfer.amount': transfer.amount.amount, + 'transfer.currency': transfer.amount.currency, + 'duration.ms': duration +}); + +logger.info(`Service ${serviceName} v${version} started successfully on port ${port} in ${env} environment`, { + eventName: 'ServiceStarted', + 'service.name': serviceName, + 'service.version': version, + 'deployment.environment': env, + 'server.port': port +}); +``` + +**Do NOT use for:** +- High frequency operational noise (use VERBOSE) +- Internal function calls (use DEBUG) + +### VERBOSE - Operational High-Volume Events + +**When to use:** +- Health checks and keep-alives (often sampled) +- Minor configuration updates +- Periodic background tasks that are routine +- High-frequency API calls that are not "Significant Business Events" + +**What to include:** +- Minimal context to verify activity +- Status of routine check + +**Examples:** +```javascript +logger.verbose('Health check passed', { + operation: 'healthCheck', + uptime: process.uptime(), + memoryUsage: process.memoryUsage().heapUsed +}); +``` + +### DEBUG - Detailed Operational Information + +**When to use (in non-production or when debugging):** +- Function entry/exit with parameters +- Intermediate calculation results +- State changes during operation +- Conditional branch taken +- Loop iterations (sparingly) +- Cache hits/misses +- Validation steps + +**What to include:** +- Detailed context +- Variable values +- Flow indicators +- Internal state + +**Examples:** +```javascript +logger.debug(`Processing transfer ${transfer.id} validation at step ${step}. Account balance is ${balance} and transfer amount is ${amount}`, { + operation: 'validateTransfer', + transferId: transfer.id, + step: 'checkBalance', + 'account.balance': balance, + 'transfer.amount': amount, + accountId: account.id +}); + +logger.debug(`Cache miss for key ${cacheKey}. Fetching participant ${participantId} from database`, { + operation: 'getParticipant', + cacheKey: cacheKey, + participantId: participantId, + entity: 'participant' +}); +``` + +**Do NOT use for:** +- Sensitive data (passwords, tokens, full card numbers) +- Excessive logging in tight loops +- Information available elsewhere + +### TRACE - Very Detailed Diagnostic Information + +**When to use (only when explicitly needed for troubleshooting):** +- Every function entry/exit +- All variable mutations +- Detailed execution flow +- Performance profiling +- Protocol-level details + +**What to include:** +- Maximum detail for diagnosis +- Full context including all parameters +- Execution timestamps + +**Examples:** +```javascript +logger.trace(`Entering validateTransfer function with transfer ${transfer.id}, applying ${rules.length} validation rules in context ${context.requestId}`, { + operation: 'validateTransfer', + transferId: transfer.id, + 'validation.rulesCount': rules.length, + requestId: context.requestId, + args: { transfer, rules, context }, + timestamp: Date.now() +}); +``` + +**Do NOT use:** +- In production by default (too verbose) +- For sensitive data + +## Log Level Decision Tree + +``` +Is the application unable to continue? + YES → FATAL + +Can the application continue with degraded functionality? + YES → WARN + +Is this a significant business event (Transfer Completed)? + YES → INFO + +Is this a routine operational event (Health Check)? + YES → VERBOSE + +Is this needed for troubleshooting but not in production? + YES → DEBUG + +Is this only needed for deep diagnostic analysis? + YES → TRACE +``` + +## Verbosity and Sampling Rules + +### Per-Level Configuration +The complexity and structure of logs depend on their level. + +* **WARN / ERROR / FATAL**: Always logged, regardless of configuration. + * **Must** include full stack traces for exceptions. + * **Must** include relevant context (IDs) to make the error actionable. +* **INFO**: Standard operational level. Logged by default in Production. + * Should describe *what* happened (business events). + * Should *not* describe *how* (internal implementation details). +* **VERBOSE**: Optional in Production. + * Captures high-frequency noise like health checks. + * Often sampled or disabled to save storage. +* **DEBUG**: Disabled by default in Production. + * Contains detailed state changes, full payload (body content), and logic flow. + * Intended for developers debugging non-production environments. +* **TRACE**: Disabled by default. + * Loop iterations, and variable values. + * Should only be enabled explicitly for deep diagnostics. + +### Dynamic Tracing Override (Force-Logging) +To support debugging specific transactions in production without increasing the global log verbosity: + +* If an incoming request indicates tracing is enabled (e.g., via `X-Trace-Enabled` header or sampled flag in OTel context): + * **WARN / ERROR / FATAL**: Automatically logged for that request context. + * **INFO / VERBOSE / DEBUG**: Automatically promoted to be logged even if the service default is set to `WARN` or `INFO`. + * *Goal:* Allow end-to-end tracing of a specific request through the entire system at high fidelity while keeping the rest of the system quiet. + +> **See also:** [Per-Request Log Override](./scenarios/per_request_log_override.md) for implementation details. + + +## Dynamic Log Level Configuration + +Services should support changing log levels without restart: +- Via environment variables: `LOG_LEVEL=debug` +- Per-component configuration: `LOG_LEVEL_MYSQL=debug` +- Via configuration endpoint: `PUT /admin/log-level` diff --git a/docs/community/standards/logging/scenarios/error_handling.md b/docs/community/standards/logging/scenarios/error_handling.md new file mode 100644 index 00000000..597f39e1 --- /dev/null +++ b/docs/community/standards/logging/scenarios/error_handling.md @@ -0,0 +1,86 @@ +# Error Handling and Propagation Standard + +## Overview +This standard defines how to log and propagate errors to ensure that the root cause is preserved and that logs remain actionable without being redundant. + +## Logging Exceptions + +When an exception occurs that cannot be handled immediately (or is being handled by a final error handler), it must be logged with specific context. Trace context (`trace_id`, `span_id`) is automatically injected by the OTel SDK — do not set these manually. + +### Exception Log Attributes + +These attributes follow [OTel Exception Semantic Conventions](https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-logs/). + +> **Automatic via contextLogger:** When you pass an Error object as the second argument (e.g., `logger.error('msg', err)`), contextLogger's `formatError` automatically sets all `exception.*` and `error.type` attributes via `otelDto.exceptionDto`. It also recursively formats the `cause` chain. Do not set these attributes manually when passing the Error object directly. + +| Field Name | Requirement Level | Type | Description | Example | +|------------------------|-------------------|------|-------------|---------| +| `exception.type` | Conditionally Required [1] | string | The error class name or slug | "ValidationError", "TypeError" | +| `exception.message` | Conditionally Required [1] | string | The technical error message | "Account not found" | +| `exception.stacktrace` | Required | string | The full stack trace (incl. causes) | "Error: ... at verify (file.js:10)..." | + +[1] At least one of `exception.type` or `exception.message` MUST be set. Both SHOULD be set when available. + +> **Sensitive data:** `exception.message` may contain PII (user IDs, account numbers, input values). Review messages before logging and redact where necessary. + +### Operational Error Classifier + +For operational logs (HTTP responses, DB operations), use `error.type` as a **low-cardinality** classifier separate from the `exception.*` attributes. Do not set both `exception.type` and `error.type` on the same log record unless they carry genuinely different values. + +| Field Name | Requirement Level | Type | Description | Example | +|------------------------|-------------------|------|-------------|---------| +| `error.type` | Conditionally Required | string | Error classification: `err.code` -> `err.name` -> `"UnknownError"` | "ECONNREFUSED", "ValidationError" | + +See [HTTP Requests](http_requests.md) and [SQL Queries](sql_queries.md) for `error.type` usage in operational logs. + +### Project-Specific Attributes + +| Field Name | Requirement Level | Type | Description | Example | +|------------------------|-------------------|------|-------------|---------| +| `error.user_message` | Recommended | string | User-facing notification (not an OTel attribute) | "Operation failed, contact provider" | + +### Log Level Guidelines +For detailed definitions of log levels, refer to the [Log Levels Standard](../log_levels.md). + +* **FATAL**: The process will likely exit immediately. +* **ERROR**: The request failed, but the process continues. +* **WARN**: The error was handled/recovered, or is a validation issue. + +## Propagating Errors + +Do **NOT** simply log and re-throw the same error without context. +Do **NOT** swallow the stack trace when wrapping errors. + +### Correct Pattern +Wrap the error, preserving the original cause. +```javascript +try { + await db.query(); +} catch (originalError) { + // Wrap and throw, do NOT log here if a higher level handler will log it. + throw new DatabaseError("Failed to query user", { cause: originalError }); +} +``` + +### Top-Level Error Handler +Only the top-level handler (e.g., API middleware, worker loop) should log the final error with the full stack trace. + +```javascript +// ✅ GOOD — pass the Error object directly; contextLogger adds all OTel attributes automatically +logger.error('Request failed: ', err) + +// Also valid — manual attributes when you need extra context beyond the error +logger.error(`Request failed: ${err.message}`, { + 'exception.type': err.name, + 'exception.message': err.message, + 'exception.stacktrace': err.stack, + 'error.user_message': err.notice // project-specific, if available +}) +``` + +## Review Checklist +* Are **FATAL** errors causing a process exit? +* Are **stack traces** strictly excluded from API responses in Production? +* Are **wrapped errors** preserving the `cause` chain? +* Does `exception.message` avoid leaking PII? +* Are `exception.*` and `error.type` used in the correct contexts (exception logs vs operational logs)? diff --git a/docs/community/standards/logging/scenarios/http_requests.md b/docs/community/standards/logging/scenarios/http_requests.md new file mode 100644 index 00000000..2cceca14 --- /dev/null +++ b/docs/community/standards/logging/scenarios/http_requests.md @@ -0,0 +1,201 @@ +# HTTP Request Logging Standard + +## Overview +This standard defines the required fields and practices for logging HTTP requests (both incoming and outgoing). Adhering to this standard ensures consistent observability of API traffic and service interactions. + +Attribute requirement levels follow the [OTel Semantic Conventions](https://opentelemetry.io/docs/specs/semconv/http/http-spans/) structure: Required, Conditionally Required, Recommended, and Opt-In. + +> **Duration as log attribute:** `http.server.request.duration` and `http.client.request.duration` are OTel histogram metric names, not span attributes. We borrow these names as structured log attributes (in seconds) as a Mojaloop convention, to align with OTel tooling and dashboards. + +> **Method normalization:** Non-standard HTTP methods should be mapped to `_OTHER` in `http.request.method`, with the original value preserved in `http.request.method_original`. + +> **URL redaction:** Sensitive query parameters (e.g., tokens, signatures) in `url.full` and `url.query` must be redacted before logging. + +## Incoming Requests (Server Side) + +All incoming HTTP requests must be logged at the completion of the request. + +### Required Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `http.request.method` | string | HTTP request method (canonical form) | "POST", "GET", "_OTHER" | +| `url.path` | string | The target path | "/transfers" | +| `url.scheme` | string | The URI scheme component identifying the used protocol | "https" | +| `request.id` | string | Unique request identifier (Trace ID). **ML-specific, not an OTel attribute.** | "req-123xyz" | +| `http.server.request.duration` | number | Duration of the request in seconds. **ML convention** (see Overview). | 0.150 | + +### Conditionally Required Attributes + +| Field Name | Type | Condition | Description | Example | +|------------|------|-----------|-------------|---------| +| `http.response.status_code` | int | If response was sent | HTTP response status code | 200, 400, 500 | +| `http.route` | string | If available | The matched route path (low cardinality) | "/transfers/:id" | +| `error.type` | string | If request ended with error | Error identifier (see [error.type values](#errortype-values)) | "500", "timeout" | +| `server.port` | int | If available and `server.address` is set | Server port number | 443 | +| `url.query` | string | If present in the request | URL query string (redact sensitive params) | "type=MSISDN&id=123" | +| `http.request.method_original` | string | If differs from `http.request.method` | Original HTTP method before normalization | "PATCH" | +| `network.protocol.name` | string | If not `http` and `network.protocol.version` is set | Application layer protocol | "http", "spdy" | + +### Recommended Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `server.address` | string | The server address (Host) | "api.mojaloop.io" | +| `user_agent.original` | string | User agent string | "Mozilla/5.0..." | +| `client.address` | string | IP address of the client | "192.168.1.1" | +| `url.full` | string | Full request URL. **ML extension** (OTel does not define this for server spans). | "https://api.mojaloop.io/transfers" | +| `network.protocol.version` | string | HTTP protocol version | "1.1", "2" | +| `network.peer.address` | string | Peer address (actual TCP peer, may differ from `client.address` behind proxies) | "10.0.0.5" | +| `network.peer.port` | int | Peer port number | 54321 | + +### Opt-In Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `http.request.body.size` | int | Size of the request body in bytes | 1024 | +| `http.response.body.size` | int | Size of the response body in bytes | 2048 | + +### FSPIOP Headers +For Mojaloop-specific API calls, the following FSPIOP headers must be logged as attributes if present. + +| Header | Attribute Key | Description | Handling | +|--------|---------------|-------------|----------| +| `FSPIOP-Source` | `fspiop.source` | Sender FSP ID | Log value. | +| `FSPIOP-Destination` | `fspiop.destination` | Recipient FSP ID | Log value. | +| `FSPIOP-Signature` | `fspiop.signature` | Request Integrity Signature | **Hash** the value (do not log full JWS). | +| `FSPIOP-URI` | `fspiop.uri` | Service URI used for signature | Log value. | +| `FSPIOP-HTTP-Method` | `fspiop.method` | Service Method used for signature | Log value. | +| `FSPIOP-Encryption` | `fspiop.encryption` | Encryption header | Log metadata/algorithm only. | + +### Example + +```json +{ + "level": "INFO", + "message": "Incoming request POST /transfers", + "attributes": { + "http.request.method": "POST", + "url.path": "/transfers", + "url.scheme": "https", + "http.route": "/transfers", + "http.response.status_code": 201, + "http.server.request.duration": 0.045, + "request.id": "abc-123-def", + "server.address": "api.mojaloop.io" + } +} +``` + +### Example (Error) + +```json +{ + "level": "ERROR", + "message": "Incoming request POST /transfers", + "attributes": { + "http.request.method": "POST", + "url.path": "/transfers", + "url.scheme": "https", + "http.route": "/transfers", + "http.response.status_code": 500, + "error.type": "500", + "http.server.request.duration": 0.120, + "request.id": "abc-456-ghi" + } +} +``` + +### Logs example: +```bash +2026-03-09T16:59:40.334Z - info: [==> req] POST /fxQuotes [10008] - {"attributes":{"client.address":"172.19.0.1","http.request.method":"POST","http.route":"/{p*}","request.id":"1773075580333:37c01683ce70:30:mmjfbo4w:10008__undefined","server.address":"localhost","server.port":3002,"url.full":"http://localhost:13002/fxQuotes","url.path":"/fxQuotes","url.scheme":"http","user_agent.original":"axios/1.13.6"},"context":"QS","headers":{"accept":"application/vnd.interoperability.iso20022.fxQuotes+json;version=2.0","accept-encoding":"gzip, compress, deflate, br","connection":"keep-alive","content-length":"816","content-type":"application/vnd.interoperability.iso20022.fxQuotes+json;version=2.0","date":"Mon, 09 Mar 2026 16:59:40 GMT","fspiop-destination":"greenbank","fspiop-source":"pinkbank","host":"localhost:13002","user-agent":"axios/1.13.6"},"requestId":"1773075580333:37c01683ce70:30:mmjfbo4w:10008__undefined"} +... +2026-03-09T16:59:40.336Z - info: [<== 202] POST /fxQuotes [10008] 0.003s - {"attributes":{"client.address":"172.19.0.1","http.request.method":"POST","http.response.status_code":202,"http.route":"/fxQuotes","http.server.request.duration":0.003,"request.id":"1773075580333:37c01683ce70:30:mmjfbo4w:10008__undefined","server.address":"localhost","server.port":3002,"url.full":"http://localhost:13002/fxQuotes","url.path":"/fxQuotes","url.scheme":"http","user_agent.original":"axios/1.13.6"},"context":"QS","headers":{}} + +``` + +## Outgoing Requests (Client Side) + +All outgoing HTTP requests made by the service must be logged. + +### Required Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `http.request.method` | string | HTTP request method (canonical form) | "GET", "POST", "_OTHER" | +| `url.full` | string | Full request URL (redact sensitive query params) | "https://external-service.com/api" | +| `server.address` | string | Target host | "als.mojaloop.io" | +| `server.port` | int | Target port | 80, 443 | +| `http.client.request.duration` | number | Duration of the call in seconds. **ML convention** (see Overview). | 0.230 | + +### Conditionally Required Attributes + +| Field Name | Type | Condition | Description | Example | +|------------|------|-----------|-------------|---------| +| `http.response.status_code` | int | If response was received | HTTP response status code | 200, 500 | +| `error.type` | string | If request ended with error | Error identifier (see [error.type values](#errortype-values)) | "500", "ECONNREFUSED" | +| `http.request.method_original` | string | If differs from `http.request.method` | Original HTTP method before normalization | "PATCH" | +| `network.protocol.name` | string | If not `http` and `network.protocol.version` is set | Application layer protocol | "http" | + +### Recommended Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `service.peer.name` | string | Logical name of the remote service being called. **ML-required convention** (see note below). | "account-lookup-service" | +| `network.protocol.version` | string | HTTP protocol version | "1.1", "2" | +| `network.peer.address` | string | Peer address | "10.0.0.5" | +| `network.peer.port` | int | Peer port number | 8080 | +| `http.request.resend_count` | int | Ordinal number of request resend attempt | 2 | + +> **Note on `service.peer.name`:** This attribute has experimental (Development) status in OTel and is elevated to a Mojaloop convention because identifying the logical target service is essential for Mojaloop observability. It replaces the deprecated `peer.service` attribute, but its OTel status may change in future releases. + +### Example (Success) +```json +{ + "level": "INFO", + "message": "Outgoing request to Account Lookup", + "attributes": { + "http.request.method": "GET", + "url.full": "http://als.mojaloop.io/participants/123", + "server.address": "als.mojaloop.io", + "server.port": 80, + "http.response.status_code": 200, + "service.peer.name": "account-lookup", + "http.client.request.duration": 0.120 + } +} +``` + +### Example (Error) +```json +{ + "level": "ERROR", + "message": "Outgoing request to Account Lookup failed", + "attributes": { + "http.request.method": "GET", + "url.full": "http://als.mojaloop.io/participants/123", + "server.address": "als.mojaloop.io", + "server.port": 80, + "error.type": "ECONNREFUSED", + "service.peer.name": "account-lookup", + "http.client.request.duration": 5.001 + } +} +``` + + +### Logs example: +```bash +2026-03-09T16:59:40.352Z - info: [<-- 200] POST http://mock-hub:7777/greenbank/fxQuotes [0.001 s]: - {"attributes":{"http.client.request.duration":0.001,"http.request.method":"POST","http.response.status_code":200,"server.address":"mock-hub","server.port":7777,"url.full":"http://mock-hub:7777/greenbank/fxQuotes"},"component":"sendBaseRequest","context":"CSSh"} +``` + +## error.type Values + +The `error.type` attribute identifies what caused a request to fail. Use this resolution order: + +1. **HTTP status code as string** — for HTTP-level errors (e.g., `"500"`, `"503"`) +2. **Exception/error class name** — for connection or runtime errors (e.g., `"ECONNREFUSED"`, `"TimeoutError"`) +3. **Stable low-cardinality identifier** — descriptive code (e.g., `"timeout"`, `"circuit_open"`) +4. **`"UnknownError"`** — fallback when no specific type can be determined + +> **Note:** OTel uses `_OTHER` as the fallback value. Mojaloop uses `"UnknownError"` instead, consistent with the [Error Handling Standard](./error_handling.md). This is an intentional divergence. diff --git a/docs/community/standards/logging/scenarios/kafka_messaging.md b/docs/community/standards/logging/scenarios/kafka_messaging.md new file mode 100644 index 00000000..6a4943d3 --- /dev/null +++ b/docs/community/standards/logging/scenarios/kafka_messaging.md @@ -0,0 +1,362 @@ +# Kafka Messaging Logging Standard + +## Overview +This standard defines the required span attributes and logging practices for Kafka producer and consumer operations. It aligns with [OpenTelemetry Messaging Semantic Conventions](https://opentelemetry.io/docs/specs/semconv/messaging/) and covers trace context propagation, batch vs single-message attribute differences, and error handling. + +## Producer Operations + +When a service produces a message to a Kafka topic, a `PRODUCER` span must be created with the attributes below. + +### Span Naming + +Span name format: `SEND:{topicName}` + +Example: `SEND:topic-transfer-prepare` + +### Required Span Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `server.address` | string | Kafka broker address (host or IP, without port) | `"kafka"` | +| `server.port` | int | Kafka broker port | `9092` | +| `messaging.system` | string | Messaging system identifier | `"kafka"` | +| `messaging.destination.name` | string | Kafka topic name | `"topic-transfer-prepare"` | +| `messaging.operation.name` | string | Operation type | `"send"` | +| `messaging.client.id` | string | Kafka client identifier | `"ml-api-adapter"` | + +### Conditionally Required Attributes + +Include these when the value is available (non-null): + +| Field Name | Type | Condition | Example | +|------------|------|-----------|---------| +| `messaging.destination.partition.id` | string | When partition is explicitly specified | `"0"` | +| `messaging.kafka.message.key` | string | When message key is provided | `"transferId-abc-123"` | + +### Error Attributes + +When the produce operation fails, these attributes must be set on the span: + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `error.type` | string | Error code, name, or `"UnknownError"` | `"ERR_BROKER_NOT_AVAILABLE"` | + +Additionally: +- Span status must be set to `ERROR` +- The exception must be recorded on the span via `span.recordException(err)` + +### Trace Context Injection + +The producer must inject W3C Trace Context headers into the Kafka message headers before sending. The following headers are injected: + +| Header | Purpose | +|--------|---------| +| `traceparent` | W3C Trace Context trace-parent header | +| `tracestate` | W3C Trace Context trace-state header | +| `baggage` | W3C Baggage header | + +These headers enable the consumer to continue the distributed trace started by the producer. See [Trace Context](../trace_context.md) for general propagation rules. + +### Example (Success) + +```json +{ + "span.name": "SEND:topic-transfer-prepare", + "span.kind": "PRODUCER", + "span.status": "OK", + "server.address": "kafka:9092", + "messaging.system": "kafka", + "messaging.destination.name": "topic-transfer-prepare", + "messaging.operation.name": "send", + "messaging.client.id": "ml-api-adapter", + "messaging.destination.partition.id": "0", + "messaging.kafka.message.key": "transferId-abc-123" +} +``` + +### Example (Error) + +```json +{ + "span.name": "SEND:topic-transfer-prepare", + "span.kind": "PRODUCER", + "span.status": "ERROR", + "server.address": "kafka:9092", + "messaging.system": "kafka", + "messaging.destination.name": "topic-transfer-prepare", + "messaging.operation.name": "send", + "messaging.client.id": "ml-api-adapter", + "error.type": "ERR_BROKER_NOT_AVAILABLE" +} +``` + +### Logs Example +```bash +2026-03-06T11:15:21.623Z - verbose: [msg =>>] producing is done: - {"attributes":{"messaging.client.id":"default-client","messaging.destination.name":"test","messaging.kafka.message.key":"1234","messaging.operation.name":"send","messaging.system":"kafka","server.address":"localhost:9092"},"context":"ml-kafka","offset":1,"topicConf":{"key":"[REDACTED]","topicName":"test"}} +``` + +--- + +## Consumer Operations + +When a service consumes messages from a Kafka topic, a `CONSUMER` span must be created with the attributes below. + +### Span Naming + +Span name format: `RECEIVE:{topicName}` + +Example: `RECEIVE:topic-transfer-prepare` + +### Required Span Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `server.address` | string | Kafka broker address | `"kafka:9092"` | +| `messaging.system` | string | Messaging system identifier | `"kafka"` | +| `messaging.destination.name` | string | Kafka topic name | `"topic-transfer-prepare"` | +| `messaging.operation.name` | string | Operation type | `"receive"` | +| `messaging.client.id` | string | Kafka client identifier | `"ml-api-adapter"` | +| `messaging.consumer.group.name` | string | Consumer group name | `"ml-api-adapter-group"` | + +### Conditionally Required Attributes + +These attributes differ based on whether a single message or a batch is being processed. See [Batch vs Single Message Attributes](#batch-vs-single-message-attributes) below. + +### Error Attributes + +Same as producer -- see [Producer Error Attributes](#error-attributes) above. + +### Trace Context Extraction + +The consumer must extract W3C Trace Context headers from the first message in the payload to establish the parent span context: + +| Header | Purpose | +|--------|---------| +| `traceparent` | Establishes parent-child relationship with the producer span | +| `tracestate` | Preserves vendor-specific trace data | +| `baggage` | Propagates application-defined key-value pairs | + +**Multi-message batches:** Only the first message's `traceparent` establishes the parent context. Additional messages with distinct `traceparent` values are added as **span links**, preserving the association without creating a parent-child relationship. See [Trace Context](../trace_context.md) for general propagation rules. + +### Example (Single Message) + +```json +{ + "span.name": "RECEIVE:topic-transfer-prepare", + "span.kind": "CONSUMER", + "span.status": "OK", + "server.address": "kafka:9092", + "messaging.system": "kafka", + "messaging.destination.name": "topic-transfer-prepare", + "messaging.operation.name": "receive", + "messaging.client.id": "ml-api-adapter", + "messaging.consumer.group.name": "ml-api-adapter-group", + "messaging.destination.partition.id": "0", + "messaging.kafka.offset": 42, + "messaging.kafka.message.key": "transferId-abc-123" +} +``` + +### Example (Batch) + +```json +{ + "span.name": "RECEIVE:topic-transfer-prepare", + "span.kind": "CONSUMER", + "span.status": "OK", + "server.address": "kafka:9092", + "messaging.system": "kafka", + "messaging.destination.name": "topic-transfer-prepare", + "messaging.operation.name": "receive", + "messaging.client.id": "ml-api-adapter", + "messaging.consumer.group.name": "ml-api-adapter-group", + "messaging.batch.message_count": 5 +} +``` + +### Example (Error) + +```json +{ + "span.name": "RECEIVE:topic-transfer-prepare", + "span.kind": "CONSUMER", + "span.status": "ERROR", + "server.address": "kafka:9092", + "messaging.system": "kafka", + "messaging.destination.name": "topic-transfer-prepare", + "messaging.operation.name": "receive", + "messaging.client.id": "ml-api-adapter", + "messaging.consumer.group.name": "ml-api-adapter-group", + "messaging.destination.partition.id": "0", + "messaging.kafka.offset": 42, + "error.type": "ValidationError" +} +``` + +### Logs Example +```bash +2026-03-06T09:33:05.717Z - info: [<#> msg] message processing end [durationSec: 1.003, batchId: p0.42-p0.42] - {"context":"ml-kafka"} +2026-03-06T09:33:07.535Z - verbose: kafka span attributes: - {"attributes":{"messaging.client.id":"quotes-handler-post_c","messaging.consumer.group.name":"group-quotes-handler-post","messaging.destination.name":"topic-quotes-post","messaging.destination.partition.id":"0","messaging.kafka.offset":43,"messaging.operation.name":"receive","messaging.system":"kafka","server.address":"kafka:29092"},"context":"ml-kafka"} +2026-03-06T09:33:07.535Z - info: [=>> msg] message processing start [batchSize: 1, batchId: p0.43-p0.43]... - {"context":"ml-kafka"} +``` + +## Batch vs Single Message Attributes + +The consumer span attributes differ depending on whether a single message or a batch of messages is being processed. + +### Single Message (payload length = 1) + +When exactly one message is consumed, include per-message attributes: + +| Field Name | Type | Condition | Example | +|------------|------|-----------|---------| +| `messaging.destination.partition.id` | string | When partition is available | `"0"` | +| `messaging.kafka.offset` | number | When offset is available | `42` | +| `messaging.kafka.message.key` | string | When message key is available | `"transferId-abc-123"` | + +### Batch (payload length > 1) + +When multiple messages are consumed, include the batch count instead: + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `messaging.batch.message_count` | number | Number of messages in the batch | `5` | + +> **Rationale:** Per-message attributes (partition, offset, key) are not meaningful when multiple messages are processed as a unit. The batch count provides the relevant cardinality information. Individual messages with distinct trace contexts are linked via span links rather than attributes. + +## Log Level Guidelines + +For detailed definitions of log levels, refer to the [Log Levels Standard](../log_levels.md). + +### Kafka-Specific Log Level Mapping + +| Level | When to Use | Example | +|-------|-------------|---------| +| **ERROR** | Consumer or producer failures; unrecoverable Kafka errors | `"Producer failed to send message to topic-transfer-prepare: ERR_BROKER_NOT_AVAILABLE"` | +| **WARN** | Broker disconnection, consumer group rebalancing, retry-able failures | `"Kafka broker disconnected, attempting reconnect"` | +| **INFO** | Consumer group joined, producer connected, major lifecycle events | `"Consumer group ml-api-adapter-group joined, assigned 4 partitions"` | +| **VERBOSE** | Span attributes diagnostic logging; routine health checks | `"kafka span attributes: { messaging.system: 'kafka', ... }"` | +| **DEBUG** | Individual message processing details; message content inspection | `"Processing message from topic-transfer-prepare partition 0 offset 42"` | + +### Examples + +```javascript +// ERROR - Producer failure +logger.error('Producer failed to send message to topic-transfer-prepare: ERR_BROKER_NOT_AVAILABLE', { + attributes: { + 'messaging.system': 'kafka', + 'messaging.destination.name': 'topic-transfer-prepare', + 'error.type': 'ERR_BROKER_NOT_AVAILABLE' + } +}); + +// WARN - Broker disconnection +logger.warn('Kafka broker disconnected, attempting reconnect', { + attributes: { + 'server.address': 'kafka:9092', + 'messaging.client.id': 'ml-api-adapter' + } +}); + +// INFO - Consumer group joined +logger.info('Consumer group ml-api-adapter-group joined, assigned 4 partitions', { + attributes: { + 'messaging.consumer.group.name': 'ml-api-adapter-group', + 'messaging.system': 'kafka', + partitionCount: 4 + } +}); + +// VERBOSE - Span attributes diagnostic (as implemented in central-services-stream) +logger.verbose('kafka span attributes: ', { attributes: spanAttrs }); + +// DEBUG - Individual message processing +logger.debug('Processing message from topic-transfer-prepare partition 0 offset 42', { + attributes: { + 'messaging.destination.name': 'topic-transfer-prepare', + 'messaging.destination.partition.id': '0', + 'messaging.kafka.offset': 42 + } +}); +``` + +## Error Handling in Spans + +When a Kafka operation (produce or consume) fails, the span must capture the error with the following steps: + +1. **Set span status** to `ERROR`: + ```javascript + span.setStatus({ code: SpanStatusCode.ERROR }) + ``` +2. **Record the exception** on the span: + ```javascript + span.recordException(err) + ``` +3. **Set `error.type` attribute** with the error classification: + ```javascript + span.setAttribute('error.type', err?.code || err?.name || 'UnknownError') + ``` + +The error type resolution order (`err.code` -> `err.name` -> `'UnknownError'`) ensures that: +- Node.js system errors use their code (e.g., `ECONNREFUSED`, `ERR_BROKER_NOT_AVAILABLE`) +- Application errors use their class name (e.g., `ValidationError`, `TimeoutError`) +- Unknown errors get a fallback classification + +See [Error Handling Standard](./error_handling.md) for general error logging rules. + +## Mojaloop-Specific Considerations + +### Automatic Span Creation in `central-services-stream` + +The `@mojaloop/central-services-stream` library (Mojaloop's Kafka wrapper) handles OTel span creation automatically for both producers and consumers. Services using this library do **not** need to manually: + +- Create producer/consumer spans +- Inject or extract trace context headers +- Set span attributes from the tables above +- Handle span status on success/error + +The library's `startProducerTracingSpan()` and `startConsumerTracingSpan()` functions manage all of this. + +**When to add custom attributes:** If service-specific context is needed beyond the standard messaging attributes (e.g., `transferId`, `payerFsp`), add them to the active span manually: + +```javascript +const { trace } = require('@opentelemetry/api') + +// Inside a consumer handler (span is already active) +const activeSpan = trace.getActiveSpan() +if (activeSpan) { + activeSpan.setAttribute('transfer.id', transferId) + activeSpan.setAttribute('payer.fspId', payerFsp) +} +``` + +### Disabling Automatic Spans + +If a service needs to manage spans manually, set `disableOtelSpanAutoCreation: true` in the consumer/producer configuration. When disabled, the service is responsible for implementing all the attributes and error handling described in this document. + +### `otelSpanPerMessage` Mode + +When `otelSpanPerMessage: true` is set on a consumer, the library creates a separate span for each message in a batch (instead of one span for the entire batch). This changes the callback signature to receive a single message and enables fail-fast behavior -- if any message handler throws, remaining messages in the batch are skipped. + +### Diagnostic Logging + +The library logs span attributes at `VERBOSE` level for diagnostic purposes: +```javascript +logger.verbose('kafka span attributes: ', { attributes: spanAttrs }) +``` + +### `LOG_LEVEL_KAFKA` + +The `central-services-stream` library runs its own logger (`ml-kafka` context), separate from the service's application logger. The `LOG_LEVEL_KAFKA` environment variable controls this logger's level independently. It defaults to `info`. Set it to `verbose` or `debug` in staging to trace span attributes and message flow without changing the service's log level. Valid values: `error`, `warn`, `info`, `verbose`, `debug`, `silly`. + +## Review Checklist + +- Are all required span attributes (`messaging.system`, `messaging.destination.name`, `messaging.operation.name`) set on every Kafka span? +- Is `messaging.consumer.group.name` included on all consumer spans? +- Is `error.type` set on spans when operations fail, with the resolution order `err.code` -> `err.name` -> `"UnknownError"`? +- Are W3C Trace Context headers (`traceparent`, `tracestate`, `baggage`) being injected into producer message headers? +- Are W3C Trace Context headers being extracted from consumer message headers to establish parent context? +- For batches with multiple distinct `traceparent` values, are additional trace contexts added as span links (not parent contexts)? +- Are batch spans using `messaging.batch.message_count` instead of per-message attributes? +- Are single-message spans including `messaging.destination.partition.id`, `messaging.kafka.offset`, and `messaging.kafka.message.key` when available? +- Is `disableOtelSpanAutoCreation` documented if the service manages spans manually? diff --git a/docs/community/standards/logging/scenarios/per_request_log_override.md b/docs/community/standards/logging/scenarios/per_request_log_override.md new file mode 100644 index 00000000..eafbaa6b --- /dev/null +++ b/docs/community/standards/logging/scenarios/per_request_log_override.md @@ -0,0 +1,366 @@ +# Per-Request Log Override — Overview + +## What It Is + +Per-request log level override. A single flagged request gets verbose logging across every service it touches, while everything else stays at the production level. The current spec (`log_levels.md` lines 321-328) describes the goal but not the mechanism. + +--- + +## How the Signal Propagates + +### W3C Baggage (OTel-native) + +The W3C `baggage` header carries arbitrary key-value pairs. The OTel SDK propagates it automatically across HTTP (and Kafka, when configured). + +**Example:** `baggage: mojaloop.debug=true` + +**Pros:** Automatic propagation — no manual forwarding. +**Cons:** Baggage travels in plaintext. Security must be enforced at the gateway (see [Security](#security)). + +**Reading baggage in Node.js:** +```javascript +const { propagation } = require('@opentelemetry/api') +const debugFlag = propagation.getActiveBaggage()?.getEntry('mojaloop.debug')?.value +``` + +> The codebase already uses `getActiveBaggage()` in the `errorExpect` format (`createMlLogger.js` line 53). + +### What About the `traceparent` Sampled Flag? + +The sampled flag controls *span sampling*, not log verbosity. Overloading it conflates two concerns and has side effects on trace backends. + +### Comparison + +| Aspect | OTel Baggage | Sampled Flag | +|--------|--------------|-------------| +| Propagation | Automatic (OTel SDK) | Automatic (OTel SDK) | +| Kafka support | Requires baggage propagator config | Automatic | +| Security | Plaintext (gateway must validate) | Not designed for this | +| Semantic fit | Good fit | Wrong purpose | + +### Recommendation + +Use **OTel Baggage** with a dedicated key (e.g., `mojaloop.debug`). For authentication, embed a signed token (JWT) as the baggage value. + +--- + +## How to Filter Logs Per-Request in Node.js + +Three approaches, ordered from most feasible to least. Approach 1 is recommended for `central-services-logger`. + +### Existing Infrastructure in `central-services-logger` + +- **`AsyncLocalStorage`** — `contextLogger.js` exports an `asyncStorage` instance (line 35). `formatLog()` reads `asyncStorage.getStore()` and spreads it into metadata: `{ ...store, ...this.context, ...metaData }`. Control keys (like `_logLevelOverride`) must be destructured out to prevent leaking into output (see Approach 1). +- **`errorExpect` format** — `createMlLogger.js` (lines 51-69) reads OTel baggage at format evaluation time and reclassifies log levels. Reading propagated context inside a Winston format is an established pattern. +- **`ContextLogger.setLevel()`** — creates a new Winston logger and replaces `this.mlLogger`. Provides per-component isolation but mutates the instance for all calls — not per-request. +- **Static `isXxxEnabled` flags** — cached booleans (`isDebugEnabled`, etc.) that short-circuit log calls before Winston processing: + ```javascript + debug(message, meta) { + this.isDebugEnabled && this.mlLogger.debug(...) + } + ``` +- **Custom log levels** — `allLevels` in `constants.js`: `{ error: 0, warn: 1, audit: 2, trace: 3, info: 4, perf: 5, verbose: 6, debug: 7, silly: 8 }`. Lower number = higher priority. Any level comparison must use `allLevels`. + +### Approach 1: ContextLogger-Native Filtering with Dual Logger (Recommended) + +Extend `ContextLogger`'s level guards to be context-aware. Use a second Winston logger at `silly` level to accept override entries, preserving the fast path for normal traffic. + +#### The Winston-level problem + +If `mlLogger.level` is `info` (priority 4) and a debug call (priority 7) passes the override check, Winston's transport-level filtering compares `4 >= 7` → `false` and silently drops the entry. Two naive fixes fail: +- Setting `mlLogger` to `silly` globally disables the fast path for every request (collapses into Approach 2). +- Winston `child()` cannot change the level threshold (see "What Does Not Work"). + +#### Solution: shared override logger + +Keep `mlLogger` at its configured level. Create a process-wide singleton `overrideLogger` at `silly` level. Override calls route there instead. The process runs two sets of transports (production + override), but the singleton limits this to one extra set. + +```javascript +// Module-level singleton — created once, shared by all ContextLogger instances. +// createMlLogger() takes no arguments; set level after creation (same pattern as setLevel()). +let _overrideLogger +function getOverrideLogger () { + if (!_overrideLogger) { + _overrideLogger = createMlLogger() + _overrideLogger.level = 'silly' + // Remove exception/rejection handlers to prevent duplicate logging — the production mlLogger already handles these. + _overrideLogger.exceptions?.unhandle() + _overrideLogger.rejections?.unhandle() + } + return _overrideLogger +} + +debug (message, meta) { + if (this.isDebugEnabled) { + this.mlLogger.debug(...this.formatLog(message, meta)) + } else if (this._hasOverride('debug')) { + getOverrideLogger().log('debug', ...this.formatLog(message, meta)) + } +} + +_hasOverride (level) { + const store = asyncStorage.getStore() + const override = store?._logLevelOverride + if (!override) return false + return allLevels[level] <= allLevels[override] +} +``` + +All 9 log methods need the same `_hasOverride` check. In practice, only methods below the production level invoke it. + +> The override branch uses `.log('debug', ...)` rather than `.debug(...)` — see the `customLevels` caveat below. + +#### `customLevels` caveat + +`createMlLogger()` replaces excluded level methods with no-ops (`createMlLogger.js` line 102): + +```javascript +ignoredLevels.forEach(level => { Logger[level] = () => {} }) +``` + +If production configures `customLevels=error,warn,info`, then `overrideLogger.debug` is `() => {}`. Three options: + +- **(a) Use `.log(level, ...)`** — `ignoredLevels` replaces `.debug()` etc. but not `.log()`. No changes to `createMlLogger` needed. This is the approach shown above. +- **(b) Modify `createMlLogger()`** to accept an option that skips the replacement. Breaking change to a shared library. +- **(c) `delete _overrideLogger.debug`** to restore the prototype method. Fragile — depends on Winston internals. + +#### `isXxxEnabled` flags on the override logger + +`createMlLogger()` sets these flags based on the initial config level, not `silly`. Setting `.level = 'silly'` after creation does not update them. These flags are never consulted — `ContextLogger` reads its own flags, and the override logger is only used via `.log()`. + +#### Modified `formatLog()` + +`_logLevelOverride` lives in the store, which `formatLog()` spreads into metadata. Without exclusion, the key leaks into output: + +```javascript +formatLog (message, meta) { + const store = asyncStorage.getStore() + if (!meta && !this.context && !store) return [message] + + const { _logLevelOverride, ...storeData } = store || {} + const metaData = meta instanceof Error + ? ContextLogger.formatError(meta) + : typeof meta === 'object' ? meta : { meta } + + return [message, { ...storeData, ...this.context, ...metaData }] +} +``` + +#### Performance analysis + +**No override (common case):** `_hasOverride()` calls `getStore()`, finds no `_logLevelOverride`, returns `false`. One `getStore()` call per below-threshold log invocation. `AsyncLocalStorage.getStore()` is O(1) V8 context slot access (~20-50ns). No Winston processing occurs. + +**Override active:** two `getStore()` calls per entry (one in `_hasOverride`, one in `formatLog()`). Both sub-microsecond. Override entries get the same context, metadata, and error formatting as normal logs. + +#### Identifying override logs in output + +The override logger writes to the same transports as the production logger. To distinguish override-triggered entries (needed for the [separate log pipeline](#mojaloop-specific-mitigations) recommendation), add a metadata marker in the override branch: + +```javascript +} else if (this._hasOverride('debug')) { + const [msg, metadata] = this.formatLog(message, meta) + getOverrideLogger().log('debug', msg, { ...metadata, 'debug.override': true }) +} +``` + +This avoids adding a third parameter to `formatLog()`. Log routers (OTel Collector, Fluentd) can filter on `debug.override` to route these entries to an access-controlled index. + +#### Interaction with `setLevel()` + +- `setLevel('debug')` → `isDebugEnabled` is `true` → normal path fires, override never reached. +- `setLevel('warn')` → `isInfoEnabled` is `false` → override activates for info/verbose/debug/silly. Uses process-level transports, not the per-component logger. + +#### Format chain on the override logger + +Inherits `format.combine(format.timestamp(), errorExpect())` from `createMlLogger()`. Override entries get timestamps and `errorExpect` reclassification. + +**Pros:** Preserves fast-path for non-flagged requests. Integrates with existing `asyncStorage` and `formatLog()`. No global logger level change. +**Cons:** Modifies `ContextLogger` and `formatLog()`. Adds one `getStore()` call per below-threshold log invocation. Adds one extra set of transports to the process. + +### Approach 2: Application-Level Filtering (Format or Wrapper) + +Two variants of the same idea: set the Winston logger to `silly` globally, and filter log entries before they reach the transports. + +**Variant A — Custom Winston format.** A format function reads `AsyncLocalStorage` and returns `false` to drop entries below the request's effective level. Returning `false` from a format drops the entry (verified in `logform/combine.js` lines 19-24). + +```javascript +const { allLevels } = require('./lib/constants') + +const perRequestLevelFilter = winston.format((info) => { + const store = asyncStorage.getStore() + const effectiveLevel = store?._logLevelOverride || 'info' + if (allLevels[info.level] > allLevels[effectiveLevel]) { + return false + } + return info +}) +``` + +**Variant B — Wrapper logger.** A thin wrapper checks the async context before delegating to Winston. + +```javascript +function log (level, message, meta) { + const store = asyncStorage.getStore() + const effectiveLevel = store?._logLevelOverride || configuredLevel + if (allLevels[level] <= allLevels[effectiveLevel]) { + winstonLogger.log(level, message, meta) + } +} +``` + +Both variants require the Winston logger to run at `silly` level globally, which makes all `isXxxEnabled` flags `true` — disabling the fast path for every request, not just flagged ones. Without global `silly`, Winston's transports silently drop entries below the configured level (same problem as Approach 1). + +**Pros:** Single logger instance. +**Cons:** Disables fast-path for all traffic. Variant A has a circular dependency: importing `asyncStorage` from `contextLogger` into `createMlLogger.js` creates a cycle (fix: extract `asyncStorage` to a shared module or use OTel baggage as `errorExpect` does). + +### Approach 3: Collector-Level Filter + +The application emits all logs. The OTel Collector's `filterprocessor` drops debug logs for non-flagged requests based on attributes. + +```yaml +# Pseudocode — severity_number values: INFO=9, DEBUG=5 +processors: + filter/drop-debug-untraced: + logs: + log_record: + - 'severity_number < 9 and attributes["debug.override"] == nil' +``` + +**Pros:** Centralized policy, no application code changes. +**Cons:** Same fast-path problem as Approach 2. Ships verbose logs from every request over the network, then discards most at the Collector. Better suited as a supplementary safety net than a primary filter. + +### What Does Not Work + +**Winston `child()`** adds metadata but inherits the parent's level. Cannot change verbosity per-request. + +**`ContextLogger.setLevel()`** mutates the instance for all calls — not per async context. Would affect all concurrent requests and create a new Winston logger each time. + +**OTel Logs SDK `LoggerConfigurator`** — `minimum_severity` and `trace_based` are configured at startup, not per-request. + +--- + +## Security + +An unsecured debug header is a DoS vector — external callers can force verbose logging across the mesh, inflating storage and exposing PII. + +### Real-World Security Patterns + +| Pattern | Used by | Mechanism | Strength | +|---------|---------|-----------|----------| +| **JWT-signed header** | SAP `cf-nodejs-logging-support` | Caller signs a JWT containing the desired level + expiry. Service verifies with public key. Only private-key holders can trigger override. | Strongest | +| **Pre-shared secret** | Magento 2 (`X-Verbose-Log`) | Header value must match a configured secret. | Moderate (static secret, manual rotation) | +| **Gateway stripping** | General pattern | API gateway strips debug headers from external requests. Internal operators inject via admin tooling. | Baseline (no per-request auth) | + +### Mojaloop-Specific Mitigations + +1. **Gateway enforcement.** Strip `baggage` debug keys from external DFSP requests. Only internal operators initiate debug sessions. +2. **Signed tokens.** Embed a JWT as the baggage value. Each service verifies before honoring the override. +3. **Session limits.** Cap concurrent overrides (e.g., max 5 system-wide). Include TTL in JWT claims (5-15 minutes). +4. **Separate log pipeline.** Route `debug.override: true` entries to an access-controlled index — DEBUG logs often contain account numbers and request bodies. +5. **Audit trail.** Log override activation: who, when, which trace ID. + +### OTel Baggage Security Warning + +The OTel spec warns: *"Avoid putting sensitive information in baggage, as it might be logged or sent to untrusted downstream services."* + +--- + +## Interaction with OTel Trace Sampling + +Head-based and tail-based sampling are **trace-only** concepts in the OTel spec. `ParentBasedSampler` controls span creation — it does not affect log emission. The force-logging mechanism described in this document (Baggage + `AsyncLocalStorage` + dual logger) operates independently of trace sampling. + +The one connection point is the **`trace_based` LoggerConfig parameter**: when `true`, the Logs SDK drops log records from unsampled traces (those where `TraceFlags` indicates not sampled). It reads the already-decided sampled flag — it does not invoke any Sampler. + +### Potential conflict with force-logging + +If `trace_based: true` is configured and a force-logged request happens to be on an **unsampled trace**, the Logs SDK will drop the override logs before they reach any transport — even though the debug baggage flag is set. Two mitigations: + +- **Set `trace_based: false`** (the default). Force-logging then works regardless of trace sampling state. +- **Ensure force-logged requests are also trace-sampled.** The admin tool can set both the debug baggage and the `traceparent` sampled flag. Downstream services using `ParentBasedSampler` will honor the sampled flag for spans, and the debug baggage for logs — but these are independent decisions on independent signals. + +### `minimum_severity` (LoggerConfig) + +Sets the lowest severity the Logger processes. Configured at startup; cannot change per-request. Not relevant to force-logging, which operates at the application layer before the OTel Logs SDK. + +--- + +## Implementation Sketch + +Combines three recommendations: OTel Baggage for propagation, JWT signing for security (Security section), and the dual-logger pattern for filtering (Approach 1). + +### End-to-end flow + +``` +┌──────────────┐ baggage: mojaloop.debug= +│ Admin Tool │──────┐ +└──────────────┘ │ + ▼ +┌──────────┐ ┌─────────────┐ ┌─────────────┐ ┌─────────────┐ +│ External │───>│ API Gateway │───>│ Service A │───>│ Service B │ +│ DFSP │ │ (strips │ │ │ │ │ +│ │ │ external │ │ │ │ │ +└──────────┘ │ debug keys,│ └─────────────┘ └─────────────┘ + │ passes │ + │ internal) │ Each service: reads baggage, + └─────────────┘ verifies JWT, seeds asyncStorage, + ContextLogger routes override + entries to overrideLogger +``` + +### Prerequisites + +- **`asyncStorage.run()` must be called by the consuming service.** `contextLogger.js` creates and exports `asyncStorage` but never calls `asyncStorage.run()`. Each service must wrap request handlers in `asyncStorage.run(store, handler)` to establish the per-request store. Whether Mojaloop services already do this determines the scope of the change. +- **JWT verification is new infrastructure.** The codebase has no JWT code — requires a library, public key distribution, and rotation strategy. +- **Cleanup is automatic.** The store is garbage-collected when the async context exits. + +### Steps + +1. **Admin tool** creates a signed JWT with `{ level: 'debug', exp: <15min> }` and sends an HTTP request to the target service with `baggage: mojaloop.debug=`. + +2. **API gateway** strips the `mojaloop.debug` baggage key (and any `X-Debug-*` headers) from external DFSP requests. Passes them through from internal sources. + +3. **Hapi `onPreHandler` extension** (new code in each service) bridges the propagated signal to the per-request async context: + + ```javascript + const { propagation } = require('@opentelemetry/api') + const { asyncStorage } = require('@mojaloop/central-services-logger').ContextLogger + + server.ext('onPreHandler', (request, h) => { + const token = propagation.getActiveBaggage()?.getEntry('mojaloop.debug')?.value + if (!token) return h.continue + + let payload + try { + payload = verifyJwt(token) // { level: 'debug', exp: ... } + } catch (err) { + request.log(['warn'], `Debug override JWT rejected: ${err.message}`) + return h.continue // fail-open for request, fail-closed for debug + } + + const store = asyncStorage.getStore() || {} + store._logLevelOverride = payload.level + if (!asyncStorage.getStore()) asyncStorage.enterWith(store) + + return h.continue + }) + ``` + + The modified `formatLog()` (see Approach 1) destructures `_logLevelOverride` out of the store spread. + +4. **`ContextLogger` level guards** (Approach 1) check `asyncStorage.getStore()` when the static `isXxxEnabled` flag is `false`: + + - **4a.** If `isXxxEnabled` is `true` (level at or above production threshold), the normal path fires. Override logic is not involved. + - **4b.** If `isXxxEnabled` is `false`, `_hasOverride(level)` reads `asyncStorage.getStore()._logLevelOverride`. If the override permits the level (entry priority `<=` override priority per `allLevels`, where lower number = higher priority), the call routes to the shared `overrideLogger` via `.log(level, ...)`. The `.log()` method bypasses both the production logger's transport-level filtering and the `customLevels` no-op methods (see Approach 1, `customLevels` caveat). + - Override entries carry `debug.override: true` metadata for log pipeline routing (see "Identifying override logs in output"). + +5. **OTel SDK** propagates baggage automatically to downstream HTTP calls. For Kafka, `central-services-stream` already injects/extracts all three W3C headers (`traceparent`, `tracestate`, `baggage`) via `OTEL_HEADERS` (`src/constants.js:20`). The consumer's `executeInsideSpanContext` restores OTel context via `context.with()`, so `propagation.getActiveBaggage()` works inside the handler. However, `context.with()` does not call `asyncStorage.run()` — the consumer handler needs its own bridge: + + ```javascript + // Inside the Kafka consumer handler (workDoneCb) + const token = propagation.getActiveBaggage()?.getEntry('mojaloop.debug')?.value + if (token && verifyJwt(token)) { + asyncStorage.enterWith({ ...asyncStorage.getStore(), _logLevelOverride: 'debug' }) + } + ``` + +--- diff --git a/docs/community/standards/logging/scenarios/sql_queries.md b/docs/community/standards/logging/scenarios/sql_queries.md new file mode 100644 index 00000000..50118484 --- /dev/null +++ b/docs/community/standards/logging/scenarios/sql_queries.md @@ -0,0 +1,154 @@ +# SQL and Database Logging Standard + +## Overview + +This standard defines how to log database interactions. It aligns with [OpenTelemetry Database Semantic Conventions](https://opentelemetry.io/docs/specs/semconv/database/) and [MySQL-specific conventions](https://opentelemetry.io/docs/specs/semconv/db/mysql/). + +Full query logging is reserved for DEBUG level or specific audit requirements to avoid leaking sensitive data (PII). + +## Query Logging + +### Log Level + +* **DEBUG**: Log all queries for development/debugging. +* **WARN**: Log slow queries (exceeding a defined threshold) / expected errors. +* **ERROR**: Log failed queries. + +### Required Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `db.system.name` | string | The DBMS product identifier | `"mysql"`, `"postgresql"` | + +### Conditionally Required Attributes + +Include these when the stated condition is met. + +| Field Name | Type | Condition | Description | Example | +|------------|------|-----------|-------------|---------| +| `db.namespace` | string | If available | Database name | `"central_ledger"` | +| `db.collection.name` | string | If readily available and single-table operation | Table name | `"transfers"` | +| `error.type` | string | If operation failed | Error classification | `"ER_DUP_ENTRY"`, `"TimeoutError"` | +| `db.response.status_code` | string | If operation failed and code available | Database vendor error code (MySQL error number) | `"1062"`, `"1045"` | +| `server.port` | integer | If non-default and `server.address` is set | Server port number | `3307` | + +### Recommended Attributes + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `db.operation.name` | string | SQL command being executed (uppercase) | `"SELECT"`, `"INSERT"` | +| `db.query.text` | string | Sanitized/parameterized SQL statement | `"SELECT * FROM transfers WHERE id = ?"` | +| `db.query.summary` | string | Low-cardinality query summary (max 255 chars) | `"SELECT transfers"`, `"GetTransferById"` | +| `server.address` | string | Database host | `"mysql-primary"` | +| `db.client.operation.duration` | number | Execution time in **seconds** | `0.023` | + +> **Note:** We use `db.client.operation.duration` (in seconds) instead of a custom `duration.ms` attribute because OTel semantic conventions define duration as the measured value of a histogram metric, not an attribute. This matches the convention used in [HTTP Request Logging](./http_requests.md). + +> **Note:** When using knex, the `db.query.summary` can be provided by the `.comment()` method + +### Opt-In Attributes (DEBUG/TRACE only) + +These attributes are expensive or sensitive. Log them only at DEBUG/TRACE level or when tracing is explicitly enabled. + +| Field Name | Type | Description | Example | +|------------|------|-------------|---------| +| `db.query.parameter.` | string | Individual query parameter, keyed by name or zero-based index. Must be masked for PII. | `db.query.parameter.0`: `"abc-123"` | +| `db.response.returned_rows` | integer | Count of rows returned (read operations) | `42` | +| `db.response.rows_affected` | integer | Count of rows affected (write operations) — project extension, not in OTel | `1` | + +### Security Warning + +* **Never** log `db.query.parameter.*` or result data by default in Production. +* **Never** include raw values in `db.query.text`. Use placeholders (`?`, `$1`). +* **Masking**: Even at TRACE, redact sensitive fields (passwords, PINs) from parameters and results. + +### Example (Success) + +```json +{ + "level": "DEBUG", + "message": "GetTransferById completed in 23ms on central_ledger.transfers", + "attributes": { + "db.system.name": "mysql", + "db.namespace": "central_ledger", + "db.operation.name": "SELECT", + "db.collection.name": "transfers", + "db.query.text": "SELECT * FROM transfers WHERE id = ?", + "db.query.summary": "SELECT transfers", + "server.address": "mysql-primary", + "server.port": 3306, + "db.client.operation.duration": 0.023, + "db.response.returned_rows": 1 + } +} +``` + +### Example (Error) + +```json +{ + "level": "ERROR", + "message": "InsertTransfer failed: Duplicate entry 'abc-123' for key 'PRIMARY'", + "attributes": { + "db.system.name": "mysql", + "db.namespace": "central_ledger", + "db.operation.name": "INSERT", + "db.collection.name": "transfers", + "db.query.text": "INSERT INTO transfers (id, amount) VALUES (?, ?)", + "db.query.summary": "INSERT transfers", + "server.address": "mysql-primary", + "server.port": 3306, + "db.client.operation.duration": 0.005, + "error.type": "ER_DUP_ENTRY", + "db.response.status_code": "1062" + } +} +``` + +### Log examples + +```bash +2026-03-09T11:23:16.917Z - debug: knex query response: - {"attributes":{"db.client.operation.duration":0.570,"db.collection.name":"quote","db.namespace":"central_ledger","db.operation.name":"INSERT","db.query.summary":"INSERT quote","db.query.text":"insert into `quote` (`amount`, `amountTypeId`, `balanceOfPaymentsId`, `currencyId`, `expirationDate`, `note`, `quoteId`, `transactionInitiatorId`, `transactionInitiatorTypeId`, `transactionReferenceId`, `transactionRequestId`, `transactionScenarioId`, `transactionSubScenarioId`) values (?, ?, ?, ?, ?, DEFAULT, ?, ?, ?, ?, ?, ?, DEFAULT)","db.response.returned_rows":1,"db.system.name":"mysql","server.address":"mysql","server.port":3306},"context":"CachedDatabase","knexTxId":"trx2"} + +2026-03-09T11:23:55.415Z - error: knex query error: - {"attributes":{"db.client.operation.duration":0.007,"db.collection.name":"quoteError","db.namespace":"central_ledger","db.operation.name":"INSERT","db.query.summary":"INSERT quoteError","db.query.text":"insert into `quoteError` (`errorCode`, `errorDescription`, `quoteId`) values (?, ?, ?)","db.response.status_code":"1452","db.system.name":"mysql","error.type":"ER_NO_REFERENCED_ROW_2","server.address":"mysql","server.port":3306},"context":"CachedDatabase","knexTxId":"__knexUid12"} +``` + + +## Error Handling + +When a database operation fails, capture the error with these steps: + +1. **Set span status** to `ERROR`: + ```javascript + span.setStatus({ code: SpanStatusCode.ERROR }) + ``` +2. **Record the exception** on the span: + ```javascript + span.recordException(err) + ``` +3. **Set `error.type`** with the error classification: + ```javascript + span.setAttribute('error.type', err?.code || err?.name || 'UnknownError') + ``` +4. **Set `db.response.status_code`** with the database error code (when available): + ```javascript + span.setAttribute('db.response.status_code', String(err?.errno)) + ``` + +The error type resolution order (`err.code` → `err.name` → `'UnknownError'`) ensures that: +- MySQL errors use their error code (e.g., `ER_DUP_ENTRY`, `ER_ACCESS_DENIED_ERROR`) +- Node.js system errors use their code (e.g., `ECONNREFUSED`, `ETIMEDOUT`) +- Application errors use their class name (e.g., `ValidationError`, `TimeoutError`) +- Unknown errors get a fallback classification + +See [Error Handling Standard](./error_handling.md) for general error logging rules. + +## Review Checklist + +* Does every database log include `db.system.name`? +* Is `db.query.text` sanitized (placeholders only, no raw values)? +* Is `db.client.operation.duration` in seconds (not milliseconds)? +* Is `error.type` set when queries fail, with resolution order `err.code` → `err.name` → `"UnknownError"`? +* Is `db.response.status_code` set with the MySQL error number on failure? +* Are `db.query.parameter.*` fields excluded from production logs unless explicitly enabled? +* Are sensitive values (passwords, PINs) redacted even at TRACE level? diff --git a/docs/community/standards/logging/security.md b/docs/community/standards/logging/security.md new file mode 100644 index 00000000..6fad2376 --- /dev/null +++ b/docs/community/standards/logging/security.md @@ -0,0 +1,21 @@ +# Security and Sensitive Information + +This document defines the requirements for handling sensitive data in logs to insure compliance and security. + +## Sensitive Information (PII) + +**Requirement:** Strictly avoid logging sensitive information. + +**Never Log:** +- Passwords / Secrets / Keys +- Bank Account Numbers (Mask: `****1234`) +- MSISDNs (Mask: `****5678`) +- Personally Identifiable Information (PII) like Names, Phone Numbers, Addresses (unless authorized and necessary for debugging in secure envs) +- Authentication Tokens (Bearer tokens) + +## Compliance Exceptions + +Exceptions to these redaction rules for emergency debugging (e.g., "Break Glass" scenarios) must be handled via **Configuration** (e.g., temporary environment variable changes), never by code changes. + +* These exceptions must follow the organization's Incident Management process. +* There should be no permanent code paths that bypass PII masking. diff --git a/docs/community/standards/logging/trace_context.md b/docs/community/standards/logging/trace_context.md new file mode 100644 index 00000000..c1014a62 --- /dev/null +++ b/docs/community/standards/logging/trace_context.md @@ -0,0 +1,74 @@ +# Trace Context Propagation + +This document describes how distributed tracing context is propagated through logs to enable correlation across microservices. + + +## Manual Otel Context Usage + +When using **OpenTelemetry auto-instrumentation** for `winston` logging library, `trace_id` and `span_id` are injected in all logs automatically, so we need to add Otel span attributes only. + +OpenTelemetry API Span is WRITE-ONLY - no getAttribute() method exists. The API is for instrumentation (writing), not reading. +To read span attributes, we'll need SDK's ReadableSpan. But in this case we can’t use auto-instrumentation approach (no code changes, just pass needed env vars). +Because of that the proposed solution is to implement OTel logging inside common wrappers: for outgoing http requests, Hapi logging plugin (for incoming requests), ML Kafka stream lib and DB lib (Knex wrapper), and reuse those wrappers across all services. + +```javascript +const otel = require('@opentelemetry/semantic-conventions') + +/** @returns OTelAttributes */ +const outgoingRequestAttributesDto = ({ + method, url, durationSec, statusCode, errorType, peerService +}) => ({ + attributes: { + [otel.ATTR_HTTP_REQUEST_METHOD]: method, + [otel.ATTR_URL_FULL]: url, + [otel.METRIC_HTTP_CLIENT_REQUEST_DURATION]: durationSec, + ...(statusCode && { [otel.ATTR_HTTP_RESPONSE_STATUS_CODE]: statusCode }), + ...(errorType && { [otel.ATTR_ERROR_TYPE]: errorType }), + ...(peerService && { [otel.ATTR_SERVICE_PEER_NAME]: peerService }) + // peerService - logical service name, must be explicitly provided by caller (not derived from URL hostname) + // think if we should extract it for internal http://... calls from url hostname + } +}) + +// Usage in http wrapper for outgoing requests: +const axios = require('axios') +const { outgoingRequestAttributesDto } = require('./otelDto') +// ... +const sendBaseRequest = async (reqOptions) => { + const { method, url } = reqOptions + const methodUrl = `${method?.toUpperCase()} ${url}` + const startTime = Date.now() + + let statusCode + let errorType + + try { + // ... + const response = await axios(reqOptions) + statusCode = response?.status + + return response + } catch (error) { + statusCode = error.response?.status + errorType = error.code + // ... + } finally { + const durationSec = (Date.now() - startTime) / 1000 + log.info(`[<-- ${statusCode || errorType || ''}] ${methodUrl} [${durationSec} s]:`, outgoingRequestAttributesDto({ + method, + url, + statusCode, + durationSec, + errorType, + peerService + })) + } +} +``` + +## Benefits of Trace Context in Logs + +1. **Cross-service correlation**: Find all logs related to a single request across multiple services +2. **Trace-to-log navigation**: Jump from trace spans to related logs in observability tools +3. **Root cause analysis**: See exact sequence of events leading to errors +4. **Performance debugging**: Correlate slow traces with detailed logs diff --git a/docs/product/features/iso20022.md b/docs/product/features/iso20022.md index 457bb314..73c7593f 100644 --- a/docs/product/features/iso20022.md +++ b/docs/product/features/iso20022.md @@ -15,7 +15,7 @@ The ISO 20022 Market Practice for Mojaloop provides a standardized messaging fra The Mojaloop ISO 20022 implementation provides: -- **(JSON Message Format**: Adopts a JSON variant of ISO 20022 messages for enhanced API compatibility +- **JSON Message Format**: Adopts a JSON variant of ISO 20022 messages for enhanced API compatibility - **Three-Phase Transaction Flow**: Maintains Mojaloop's Discovery, Agreement, and Transfer phases - **Currency Conversion Support**: Handles cross-currency transactions with FX provider integration - **Cryptographic Security**: Implements ILP v4 for secure message signing and non-repudiation