Structured Logging in Node.js: How a Business ID Became My correlationId

I’ve been working in software for more than 15 years. This is the first piece I’ve decided to write about the job. I picked this topic because it was a small, real problem that cost me time more than once, until I finally stopped and fixed it properly.

Quick disclaimer: this isn’t distributed tracing or multi-service observability. It’s a targeted fix for one specific problem: correlating logs within a single Step Function execution. If your scenario is different, the problem takes a different shape. What matters here is the reasoning, not the recipe.

Quick context for anyone who doesn’t work with serverless: AWS Step Functions is an orchestration service. You design a workflow as a state machine (JSON), and each state usually triggers an AWS Lambda (a function that runs on demand, no server to manage). In my case, a request kicks off a state machine execution that passes through several Lambdas in sequence: some do validation, others call external services, and one waits on a callback response before moving on.

The fix turned out to be simpler than it sounds: a field Step Functions already offered for free, and I just wasn’t using it.

A request was processed 120 days ago. The customer calls: “Did you receive my request? I never heard back.”

You open the AWS Console. The Step Functions execution is already gone. Execution history only sticks around for 90 days, and even within that window, finding one specific execution among thousands is already a hassle. That leaves CloudWatch, with logs from every Lambda in the pipeline.

You have one piece of data: the case ID. But every Lambda logged its own way: no standard, no correlation between them. To reconstruct what happened, you have to open each function’s logs in the order the workflow probably ran, and piece it together by hand.

It wasn’t the error itself that hurt. It was the time lost just organizing the logs before you could actually start investigating.

The Chaos

The pipeline wasn’t huge, but it wasn’t trivial either: a few decision steps with branches (the path changed depending on the flow type), and a callback step (a Lambda waiting on an external response before continuing).

Each Lambda logged on its own, with console.log() scattered through the code. The bare minimum identifier (the case ID) did show up in some logs, but there was no consistency across functions. One Lambda logged a plain string, another logged an object, and none of them followed the same format.

The result: no real correlation. To reconstruct what had happened, you had to guess the workflow’s likely execution order and open the log groups one by one, trying to piece the timeline together by hand.

And the short retention window made things worse: without the execution history, all that was left were the raw CloudWatch logs, and since they had no shared structure, you couldn’t use one to make up for the absence of the other. The one missing piece was exactly the link that would have made the two complete each other.

The Turning Point

One option would be to generate a fresh correlationId (a UUID) at the start of each execution and pass it manually through every Lambda. It’s the more obvious solution, and it works. But in my case it didn’t make sense: I already had the case ID, which identified the execution from start to finish. Creating a second ID just to correlate logs would mean keeping two identifiers for the same thing, and every investigation would turn into a translation exercise: find the case ID first, then look up its associated correlationId, and only then search the logs.

It wasn’t a complicated realization. AWS Step Functions already lets you name each execution (name) when it starts, and that name is available in every state in the workflow through the $$.Execution.Name context variable, with nothing to pass manually between steps. All I had to do was use what was already there: instead of generating a random UUID as the execution name, I used the case ID itself:

const input: StartExecutionCommandInput = {
  stateMachineArn: getStateMachineArn(),
  name: data.id, // the case ID becomes the execution name
  input: JSON.stringify(data),
};

Enter fullscreen mode Exit fullscreen mode

From there, any state in the state machine can access that ID with zero effort:

"Parameters": {
  "data.$": "$",
  "correlationId.$": "$$.Execution.Name"
}

Enter fullscreen mode Exit fullscreen mode

One single identifier, from start to finish: the same case ID that shows up in the database is what shows up in the logs of every Lambda in the pipeline. No extra UUID, no mapping table, no translation needed.

The Implementation

The solution has a few pieces that fit together.

1) The Logger: structured, with context per layer

The core is a createLogger(layer, category) function that returns a logger that’s already “pre-configured,” aware of where it’s being called from. This eliminates the repetition of manual fields in every log call:

export type LogLevel = 'info' | 'warn' | 'error';
export type LogLayer = 'handler' | 'service' | 'wrapper' | 'authorizer' | 'util';

export interface LogEntry {
  message: string;
  eventCode: string;
  category: string;
  layer: LogLayer;
  correlationId?: string;
  [key: string]: unknown;
}

const REDACTED_KEYS = ['token', 'authorization', 'password', 'secret', 'apikey', 'x-api-key'];
const REDACTED_VALUE = '[REDACTED]';

export const redact = (value: unknown): unknown => {
  if (Array.isArray(value)) return value.map(redact);

  if (value !== null && typeof value === 'object') {
    return Object.entries(value as Record<string, unknown>).reduce<Record<string, unknown>>(
      (acc, [key, nestedValue]) => {
        const shouldRedact = REDACTED_KEYS.some((k) => key.toLowerCase().includes(k));
        acc[key] = shouldRedact ? REDACTED_VALUE : redact(nestedValue);
        return acc;
      },
      {},
    );
  }

  return value;
};

const writeLog = (level: LogLevel, entry: LogEntry): void => {
  const redacted = redact(entry) as Record<string, unknown>;
  console[level === 'warn' ? 'warn' : level === 'error' ? 'error' : 'info'](redacted);
};

export const createLogger = (layer: LogLayer, category: string) => ({
  info: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('info', { ...entry, layer, category }),
  warn: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('warn', { ...entry, layer, category }),
  error: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('error', { ...entry, layer, category }),
});

Enter fullscreen mode Exit fullscreen mode

Three details worth calling out:

• Automatic redaction: any field with a name resembling token, password, secret, etc. gets replaced before it hits the console, without relying on manual discipline in every log call.
• layer + category: every log entry already knows where it came from (handler, service, wrapper…) without having to write that out every time.
• Generic enough: entry accepts any additional field ([key: string]: unknown), so you can log practically any object (request, response, a query result, an error payload) without adapting the logger for every data type. The same logger works for handlers, services, wrappers, or utils.

2) Entry via the workflow: the wrapper for each step

Each state in the state machine passes $$.Execution.Name along as the correlationId in the payload for the next Lambda:

{
  "Type": "Task",
  "Resource": "${SomeFunctionArn}",
  "Parameters": {
    "data.$": "$",
    "correlationId.$": "$$.Execution.Name"
  },
  "ResultPath": "$.someResult"
}

Enter fullscreen mode Exit fullscreen mode

A generic wrapper in each Lambda in the flow handles the entry/exit/error logging automatically:

export function stepFunctionWrapper<TIn, TOut>(stepName: string, fn: (arg: TIn) => Promise<TOut>) {
  return async (data: TIn): Promise<TOut> => {
    const log = createLogger('wrapper', stepName);
    const correlationId = (data as { correlationId?: string })?.correlationId;

    try {
      log.info({ message: 'Starting step execution', eventCode: 'StepStarted', correlationId });
      const result = await fn(data);
      log.info({ message: 'Step execution successful', eventCode: 'StepCompleted', correlationId });
      return result;
    } catch (err) {
      log.error({ message: 'Step execution failed', eventCode: 'StepFailed', correlationId, error: String(err) });
      throw err;
    }
  };
}

Enter fullscreen mode Exit fullscreen mode

3) The logger inside the handler

The wrapper handles the generic “step started / completed / failed” logging. But inside the business logic, it makes sense to log specific points too: not just “started and finished,” but also decisions and IDs that will matter in a future investigation.

The pattern that repeats in every handler:

import { createLogger } from '../../../util/logger';
import { stepFunctionWrapper } from '../stepFunctionWrapper';

// Logger created once, at the top of the module, reused throughout the function
const log = createLogger('handler', 'createRecord');

export const handler = async ({
  data: request,
  correlationId,
}: {
  data: CreateRecordRequest;
  correlationId?: string;
}): Promise<number> => {
  log.info({
    message: 'Creating record',
    eventCode: 'HandlerStarted',
    correlationId,
    externalId: request.externalId, // the case ID, always attached
  });

  // ...business logic (validation, creation, etc.)

  const { id: recordId } = await models.Record.create({ /* ... */ });

  log.info({
    message: 'Record created',
    eventCode: 'HandlerSuccess',
    correlationId,
    externalId: request.externalId,
    recordId, // the internal ID too, for cross-referencing with the database later
  });

  return recordId;
};

export const createRecord = stepFunctionWrapper('createRecordHandler', handler);

Enter fullscreen mode Exit fullscreen mode

Three small decisions that make a difference when it’s time to investigate:

1. log is created once, outside the function: this avoids recreating the logger on every call and makes it clear, just by glancing at the top of the file, which layer/category that module represents.
2. correlationId is always present, but never generated here: the handler only receives it and passes it along; the wrapper, in this case the Step Functions one, is what creates it. This keeps anyone from accidentally generating a new ID somewhere in the middle of the code and breaking the correlation.
3. eventCode as an implicit enum (HandlerStarted, HandlerSuccess, HandlerError…): this lets you filter in CloudWatch by event type without depending on the free-text message.

The main payoff: even in a business investigation (not just a technical error, like “why did this record end up with the wrong status?”), the logs already have the right IDs attached from the moment they were created. There’s no need to instrument anything when the incident happens; it’s already there.

4) Propagating the correlationId outward: calls to external services

The correlationId doesn’t stay confined to the pipeline itself. When a handler calls an external API, the correlationId gets passed as a parameter to the service function, which logs the request and response around the call:

export const searchExternalService = async (
  request: SearchRequest,
  correlationId?: string,
  isRetry = false,
): Promise<SearchResponse> => {
  try {
    log.info({
      message: 'Requesting external service',
      eventCode: 'ServiceRequest',
      correlationId,
      requestBody: request,
    });

    const { data } = await axios.post<SearchResponse>(/* ... */);

    log.info({
      message: 'External service responded successfully',
      eventCode: 'ServiceResponse',
      correlationId,
      responseBody: data,
    });

    return data;
  } catch (error: unknown) {
    handleError(error, isRetry, correlationId);
    return searchExternalService(request, correlationId, true);
  }
};

Enter fullscreen mode Exit fullscreen mode

It’s not the correlationId traveling as a header to the third-party service. The external system has no idea it exists. It’s the request and response for that specific call getting tied to the same correlation ID used across the rest of the pipeline. In practice, this means that when you investigate a case, you also see exactly what was sent and received for each external integration, in the right spot on the timeline, not just what happened inside your own Lambdas.

Bonus: entry via API (the correlationId comes for free)

The main case in this post is the Step Functions-orchestrated workflow, but it’s worth noting: for regular HTTP endpoints (outside a state machine context), there’s nothing to generate. API Gateway itself already provides a unique requestId per request, which can play the same role:

export function apiWrapper<TIn, TOut>(
  handlerName: string,
  fn: (arg: TIn, event: APIGatewayProxyEvent, correlationId?: string) => Promise<TOut>,
) {
  return async (event: APIGatewayProxyEvent): Promise<APIGatewayProxyResult> => {
    const correlationId = event.requestContext?.requestId;
    const log = createLogger('wrapper', handlerName);

    log.info({ message: 'Request started', eventCode: 'HandlerStarted', correlationId });

    try {
      const inputData = event.body ? JSON.parse(event.body) as TIn : ({} as TIn);
      const result = await fn(inputData, event, correlationId);

      log.info({ message: 'Request handled successfully', eventCode: 'EndpointSuccess', correlationId });
      return { statusCode: 200, body: JSON.stringify(result) };
    } catch (err) {
      log.error({ message: 'Request failed', eventCode: 'EndpointError', correlationId, error: String(err) });
      return { statusCode: 500, body: JSON.stringify({ message: 'Internal error' }) };
    }
  };
}

Enter fullscreen mode Exit fullscreen mode

The same principle from the previous section (use an identifier that already exists, instead of creating a new one) applies here too.

The Result: What the Search Looks Like Today

The customer calls again, same scenario: “Did you receive my request?” Except now the investigation flow is different.

The ID the customer gives me is the correlationId. There’s nothing to figure out beforehand. In CloudWatch Logs Insights, I group all the pipeline’s log groups into a single query and filter by the message:

fields @timestamp, @message, @logStream
| filter @message like "correlationId: 'YOUR-ID-HERE'"
| sort @timestamp asc

Enter fullscreen mode Exit fullscreen mode

The result comes back in chronological order, with the whole journey: which Lambda ran, in what order, what each one decided, and, if something failed, exactly which step and what error.

What used to take several minutes of mentally reconstructing the execution order and opening log group after log group is now a single query, with the right ID and the whole timeline right there on screen.

Lessons

There wasn’t a real trade-off here. Quite the opposite. Once the pattern was designed (logger + wrappers + eventCode convention), applying it became trivial. Three things helped keep it that way:

1. Documentation in the README: anyone new on the team (or me, six months later) knows exactly how to log at each layer, without having to ask or dig through example code.
2. A lint rule banning console.log: the architecture decision became an automated rule. Nobody has to remember to use the logger; CI already rejects anyone who doesn’t.
3. Wrappers covering the repetitive part: stepFunctionWrapper already handles the start/end/error logging for every step, so that never needs to be rewritten for a new handler. What still takes deliberate effort is logging inside the business logic and in calls to external services, but at that point the pattern is already set, you just follow it.

In the end, the pattern doesn’t survive because people remember to follow it. It survives because following it became easier than not following it.