Feature request: Event Handler Request Logging

[perpil]

Use case

I'm attempting to emit a request log (also known as canonical log) per request. Using global middleware I've got something working but I have a few bits of feedback.

Per request, I'd like to be able to emit key metadata like source ip, user-agent, requestId, http method, route, path, status code, error message, error type, error stack and useful information I pick out of the request.

I've hacked something together that kind of works, but it's not quite 100%. The code below has 3 routes, /ping returns a 200. /error throws a 400 BadRequestError and /fault throws an uncaught Error resulting in a 500 Internal Server Error.

import { BadRequestError, Router } from '@aws-lambda-powertools/event-handler/experimental-rest';
import { Metrics, MetricUnit } from '@aws-lambda-powertools/metrics';
import { Logger } from '@aws-lambda-powertools/logger';
import {
  correlationPaths,
  search,
} from '@aws-lambda-powertools/logger/correlationId';
import type { Context } from 'aws-lambda';

let startTime: number;

const logger = new Logger({
  correlationIdSearchFn: search,
});
const metrics = new Metrics({
  namespace: 'testing',
  serviceName: 'powertools-event-handler',
});

const app = new Router({ logger });
app.use(async ({ reqCtx, next }) => {
  try {
    metrics.addMetadata('route', reqCtx.route); //note route doesn't exist on context
    metrics.addMetadata('path', reqCtx.event.path);
    metrics.addMetadata('method', reqCtx.req.method);
    metrics.addMetadata('ip', reqCtx.event.headers['X-Forwarded-For'].split(',')[0]);
    metrics.addMetadata('userAgent', reqCtx.event.headers['User-Agent']);
    metrics.addMetadata('apiGRequestId', reqCtx.event.requestId);
    metrics.addMetadata('apiGExtendedRequestId', reqCtx.event.extendedRequestId);
    metrics.addMetadata('cfRequestId', reqCtx.event.headers['X-Amz-Cf-Id']);
    metrics.addMetadata('requestId', reqCtx.context.awsRequestId);
    metrics.addMetadata('functionVersion', reqCtx.context.functionVersion);
    metrics.addMetadata('traceId', reqCtx.event.headers['X-Amzn-Trace-Id']?.replace('Root=', ''));
  }catch(error){
    logger.error('Error adding metadata', { error });
  }
  try {
    await next();
  } catch(error) {
    if(error){
      metrics.addMetadata('errorDetails', error.message);
      metrics.addMetadata('errorType', error.name);
      metrics.addMetadata('errorStack', error.cause ? error.cause.stack : error.stack);
      if (reqCtx.res.status >= 500) {
        throw error;
      }
    }
  }
  finally {
    metrics.addMetadata('responseCode', reqCtx.res.status + "");
    metrics.addMetric('fault', MetricUnit.Count, reqCtx.res.status >= 500 ? 1 : 0);
    metrics.addMetric('error', MetricUnit.Count, (reqCtx.res.status >= 400 && reqCtx.res.status < 500) ? 1 : 0);
    metrics.addMetric('latency', MetricUnit.Milliseconds, Date.now() - startTime);
    metrics.publishStoredMetrics();
  }
});

app.get('/ping', async () => {
  return { message: 'pong' };
});

app.get('/error', async () => {
  throw new BadRequestError("This is an error");
});

app.get('/fault', async () => {
  throw new Error('This is a fault');
});

export const handler = async (event: unknown, context: Context) => {
  startTime = Date.now();
  logger.addContext(context);
  logger.setCorrelationId(event, correlationPaths.API_GATEWAY_REST);
  return app.resolve(event, context);
};

Below are some sample log outputs for the exposed routes:

/ping

{
    "_aws": {
        "Timestamp": 1759372476245,
        "CloudWatchMetrics": [
            {
                "Namespace": "testing",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "fault",
                        "Unit": "Count"
                    },
                    {
                        "Name": "error",
                        "Unit": "Count"
                    },
                    {
                        "Name": "latency",
                        "Unit": "Milliseconds"
                    }
                ]
            }
        ]
    },
    "service": "powertools-event-handler",
    "fault": 0,
    "error": 0,
    "latency": 241,
    "path": "/ping",
    "method": "GET",
    "ip": "71.212.29.6",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:143.0) Gecko/20100101 Firefox/143.0",
    "apiGRequestId": "8300e8f6-45ca-467c-92ee-fac812d54f1d",
    "apiGExtendedRequestId": "RzCtYHR8iYcEu2A=",
    "cfRequestId": "viQrbfwMYaFhUEEkozh1ykmtBbixdN0JzRBMx-oNMpAH5sLzcszLaA==",
    "requestId": "cf60e110-fe37-4a6b-8ab4-ac251c3f7271",
    "functionVersion": "39",
    "traceId": "1-68dde4bb-44b8df72029d7fff1208aba3",
    "responseCode": "200"
}

/error

{
    "_aws": {
        "Timestamp": 1759372479479,
        "CloudWatchMetrics": [
            {
                "Namespace": "testing",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "fault",
                        "Unit": "Count"
                    },
                    {
                        "Name": "error",
                        "Unit": "Count"
                    },
                    {
                        "Name": "latency",
                        "Unit": "Milliseconds"
                    }
                ]
            }
        ]
    },
    "service": "powertools-event-handler",
    "fault": 1,
    "error": 0,
    "latency": 2,
    "path": "/error",
    "method": "GET",
    "ip": "71.212.29.6",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:143.0) Gecko/20100101 Firefox/143.0",
    "apiGRequestId": "5385f574-dc12-476a-a3b2-616f39e83b41",
    "apiGExtendedRequestId": "RzCt-HVCCYcEv5Q=",
    "cfRequestId": "XLdWKQSJAsw1-6E4_qKfeghpxlixMVL6MNcUz_h2TnNnBlTE8w2dYg==",
    "requestId": "894ee350-9444-4b49-bf2c-9f095ee8b875",
    "functionVersion": "39",
    "traceId": "1-68dde4bf-4bc7c50f7cd809de016d0508",
    "errorDetails": "This is an error",
    "errorType": "BadRequestError",
    "errorStack": "BadRequestError: This is an error\n    at /var/task/index.js:6903:9\n    at handlerMiddleware (/var/task/index.js:1683:39)\n    at dispatch (/var/task/index.js:1019:38)\n    at nextFn (/var/task/index.js:1014:23)\n    at /var/task/index.js:6881:11\n    at dispatch (/var/task/index.js:1019:38)\n    at /var/task/index.js:1030:11\n    at Router.resolve (/var/task/index.js:1694:38)\n    at Runtime.handler (/var/task/index.js:6912:14)\n    at Runtime.handleOnceNonStreaming (file:///var/runtime/index.mjs:1306:29)",
    "responseCode": "500"
}

Note this has the responseCode set to 500 even though the request returns a 400 so the fault and error counters are wrong.

/fault

{
    "_aws": {
        "Timestamp": 1759372482624,
        "CloudWatchMetrics": [
            {
                "Namespace": "testing",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "fault",
                        "Unit": "Count"
                    },
                    {
                        "Name": "error",
                        "Unit": "Count"
                    },
                    {
                        "Name": "latency",
                        "Unit": "Milliseconds"
                    }
                ]
            }
        ]
    },
    "service": "powertools-event-handler",
    "fault": 1,
    "error": 0,
    "latency": 5,
    "path": "/fault",
    "method": "GET",
    "ip": "71.212.29.6",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:143.0) Gecko/20100101 Firefox/143.0",
    "apiGRequestId": "6b762937-0ca9-4406-b2fe-2f93c856cd2d",
    "apiGExtendedRequestId": "RzCueEv6iYcEFlg=",
    "cfRequestId": "p-ODGZvBOTfvfYIfjXcOvwbu6X7FWgpG0viM8rjjEo4wcyoCs9kvZA==",
    "requestId": "1af4b006-09b7-4770-823a-15ddab8af6e3",
    "functionVersion": "39",
    "traceId": "1-68dde4c2-7a71c6d017b69c45550b64b7",
    "errorDetails": "This is a fault",
    "errorType": "Error",
    "errorStack": "Error: This is a fault\n    at /var/task/index.js:6906:9\n    at handlerMiddleware (/var/task/index.js:1683:39)\n    at dispatch (/var/task/index.js:1019:38)\n    at nextFn (/var/task/index.js:1014:23)\n    at /var/task/index.js:6881:11\n    at dispatch (/var/task/index.js:1019:38)\n    at /var/task/index.js:1030:11\n    at Router.resolve (/var/task/index.js:1694:38)\n    at Runtime.handler (/var/task/index.js:6912:14)\n    at Runtime.handleOnceNonStreaming (file:///var/runtime/index.mjs:1306:29)",
    "responseCode": "500"
}

/notfound

{
    "_aws": {
        "Timestamp": 1759372493850,
        "CloudWatchMetrics": [
            {
                "Namespace": "testing",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "fault",
                        "Unit": "Count"
                    },
                    {
                        "Name": "error",
                        "Unit": "Count"
                    },
                    {
                        "Name": "latency",
                        "Unit": "Milliseconds"
                    }
                ]
            }
        ]
    },
    "service": "powertools-event-handler",
    "fault": 0,
    "error": 1,
    "latency": 9,
    "path": "/notfound",
    "method": "GET",
    "ip": "71.212.29.6",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:143.0) Gecko/20100101 Firefox/143.0",
    "apiGRequestId": "a3ccaaef-1673-453e-9886-f414ead740e7",
    "apiGExtendedRequestId": "RzCwOFQ-CYcEpvQ=",
    "cfRequestId": "6Cc8LZyzOOhGVAbndbYXYGAFN8d6LawxHNSw-9IIQaWRlOrhUtDgRQ==",
    "requestId": "287cbfd3-a533-4c5f-b78d-eec34b26d56a",
    "functionVersion": "39",
    "traceId": "1-68dde4cd-656de8ab1e1bdfcf550e9f06",
    "responseCode": "404"
}

Solution/User Experience

After doing this exercise I have 4 requests.

1. Normalize common metadata and expose it in a consistent way regardless of source, i.e. regardless of whether it's APIG or a Function URL, expose things like ip, path and user-agent with context.ip or some other mechanism so the user doesn't need to extract them from headers. lambda-api has a good example of this
2. Expose the matched route to middleware on the context, I didn't see it surfaced.
3. In global middleware, when throwing pre-defined errors, the status on the response should not be 500, it should be the status code for the actual error. When the response is returned to the browser it is the correct value, just in the global middleware it is 500 (see /error log above). Note, this is not the case on /notfound so I'm not sure whether this is user error. I did read the errorHandling docs but I don't want a separate handler per error type. I just want to throw the predefined error from the route and have the default propogate to the end user.
4. Expose a way to set values on the context from middleware. For example if I had a JWT middleware, I might want to add username to the context. Both hono and lambda-api allow you to do something like context.set('username', username) so you can access it later in the request.

Alternative solutions

Acknowledgment

• This feature request meets Powertools for AWS Lambda (TypeScript) Tenets
• Should this be considered in other Powertools for AWS Lambda languages? i.e. Python, Java, and .NET

Future readers

Please react with 👍 and your use case to help us understand customer demand.

[svozza]

Hi there, thank you for the feedback!

1. This is interesting, I was hoping to not have an AWS specific request object and rely purely on web standards like Request. So for example, rather than getting headers from the lambda event you would do req.headers.get('myHeader'), which would work across all invocation types. But I can see the case for convenience functions to extract common headers into an easily accessible place. What I don't want though, is a common object with a set of fields that may or may not be undefined based on what the incoming event was. Another option could be that we could create a middleware that people could use that selects fields/does transformations with a set of defaults that are also customisable/etc that get added to reqCxt. This would let it be opt-in and keep the core lean. Keen to hear others' thoughts though @dreamorosi @swopnildangol.
2. Do you mean the actual string of path passed in to the handler? So something like reqCtx.routePath = '/todo/:todoId'?
3. This appears to be an issue with the ordering of how the middleware gets executed. When a request comes in, we create a placeholder web Response object. The status gets set to 500 because this placeholder should always be over-written and if it hasn't it means something has gone wrong. I need to investigate when this is happening, because looking at your middleware, it is being called after the next handler so the request should have been updated by then.
4. We are planning on adding this feature, see discussion here: Feature request: Split routes with Router - includeRouter method #4481 (comment). We will be creating an issue around this store where we can gather feedback before implementation.

[perpil]

Thanks @svozza!

1. This is interesting, I was hoping to not have an AWS specific request object and rely purely on web standards like Request. So for example, rather than getting headers from the lambda event you would do req.headers.get('myHeader'), which would work across all invocation types. But I can see the case for convenience functions to extract common headers into an easily accessible place. What I don't want though, is a common object with a set of fields that may or may not be undefined based on what the incoming event was. Another option could be that we could create a middleware that people could use that selects fields/does transformations with a set of defaults that are also customisable/etc that get added to reqCxt. This would let it be opt-in and keep the core lean. Keen to hear others' thoughts though @dreamorosi @swopnildangol.

reqCtx is a good place for these things and a middleware is acceptable. I've found that depending on the event source (apig w/cloudfront, alb, functionurl) important pieces like request ids and source ips come from different places. It's most useful to me to extract and expose them in a normalized place so doing things like parsing out the leftmost ip in x-forwarded-for is left to the user. Exposing them as a convenience function has precedent in other powertools libraries (xray-trace-id) but I'd rank that second.

2. Do you mean the actual string of path passed in to the handler? So something like reqCtx.routePath = '/todo/:todoId'?

Yes, when you want to publish latency/fault/error metrics that are one per api route this is a key piece to do that. Sometimes you also need the http verb, but that is already accessible.

3. This appears to be an issue with the ordering of how the middleware gets executed. When a request comes in, we create a placeholder web Response object. The status gets set to 500 because this placeholder should always be over-written and if it hasn't it means something has gone wrong. I need to investigate when this is happening, because looking at your middleware, it is being called after the next handler so the request should have been updated by then.

The other thing that I don't quite understand is that if I remove this code:

if (reqCtx.res.status >= 500) {
        throw error;
}

It throws a 500 when you hit the /error endpoint.

4. We are planning on adding this feature, see discussion here: Feature request: Split routes with Router - includeRouter method #4481 (comment). We will be creating an issue around this store where we can gather feedback before implementation.

Great! I'd missed this.

[svozza]

Apologies for the delay, I'm only getting a chance to analyse point 3 properly now.

What's actually happening here is to do with how error handling in middleware works. The example middleware above is handling errors in the middleware that are thrown from next but the way to do custom handling of errors thrown during the request lifecycle is to use the errorHandler method (Hono also works similarly). This is because the whole middleware stack is ultimately wrapped in a try-catch that will propagate the error to the centralised error handling location.

sequenceDiagram
    participant Request
    participant Router
    participant EH as Error Handler
    participant M1 as Middleware 1
    participant M2 as Middleware 2
    participant Handler as Route Handler

    Request->>Router: Incoming Request
    Router->>M1: Execute ({ reqCtx, next })
    Note over M1: Pre-processing
    M1->>M2: Call await next()
    Note over M2: Throws Error
    M2-->>M1: Error propagated
    M1-->>Router: Error propagated
    Router->>EH: Handle error
    EH-->>Router: HTTP 500 Response
    Router-->>Request: HTTP 500 Error
    Note over Handler: Never executed

Loading

I made a mistake initially when I said that the processing in your middleware was happening after the await next(), in fact, everything was happening before the await next() because of the try/catch/finally block. And as you can see from the diagram above, once a middleware throws, no post-processing steps occur.

This will be clearer with an example. Using your middleware we could do something like this

const app = new Router({ logger });
app.use(async ({ reqCtx, next }) => {
  metrics.addMetadata('route', reqCtx.route);
  metrics.addMetadata('path', reqCtx.event.path);
  // ...
  await next();
  // everything after next() will only be called if it does not throw
  metrics.addMetadata('responseCode', reqCtx.res.status + "");
  // no need for the error checking code here as we know the request succeeded
  metrics.addMetric('latency', MetricUnit.Milliseconds, Date.now() - startTime);
  metrics.publishStoredMetrics();
})

app.errorHandler(Error,  (error, reqCtx) => {
  metrics.addMetadata('errorDetails', error.message);
  metrics.addMetadata('errorType', error.name);
  metrics.addMetadata('errorStack', error.cause ? error.cause.stack : error.stack); 

  const result = error instanceof ServiceError 
    ? error.toJSON()  
    : {
        statusCode: 500,
        body: JSON.stringify(error),
        headers: { 'Content-Type': 'application/json' }
      };
   
  metrics.addMetric('fault', MetricUnit.Count, result.statusCode >= 500 ? 1 : 0);
  metrics.addMetric('error', MetricUnit.Count, (result.statusCode>= 400 && result.statusCode < 500) ? 1 : 0);
  // we need to make sure the metrics get sent because the post-processing for the middleware above stops on an error
  metrics.addMetric('latency', MetricUnit.Milliseconds, Date.now() - startTime);
  metrics.publishStoredMetrics();

  return result;
});

The trade-off here is that with this custom error handler, the user is now responsible for converting errors to responses as well. This example uses the Error class to catch all errors, but what if you want to have mutliple error handlers for different Error types? You'd have to repeat the metric logic in every one of them. I'm wondering is there a way we could allow users to run some error logic that always runs at the end with the response that is about to be returned to the client, something like app.errorFinally.

I am hesitant about this idea though as the issue with adding more error handling like this in general is that you get into a spiral of error handling code that can itself also throw errors. The error handling logic is already quite complex and we have to draw the line somewhere.

[dreamorosi]

I think there's a simpler option to do work after the Event Handler has resolved or thrown, as long as we're willing to go out of the Event Handler abstraction.

It's not as slick, but probably workable:

export const handler = async (event: unknown, context: Context) => {
  startTime = Date.now();
  logger.addContext(context);
  logger.setCorrelationId(event, correlationPaths.API_GATEWAY_REST);
  
  const response = app.resolve(event, context);

  if (response.statusCode < 300 && response.statusCode >= 200) {
    return response;
  } else if (response.statusCode < 500 && response.statusCode >= 400) {
     // do work, emit metrics, log things
  } else {
    // other cases
  }
};

Other than that, I think the app.errorHandler(Error as "final" error handler is a cool idea - the current error resolution logic in the ErrorHandlerRegistry.ts only checks for instanceof and as soon as it finds a match it runs the handler.

So in practice I don't think it takes in account inheritance or specificity, and I can't think on top of my head of any non-O^2 way of avoiding looking up the entire registry multiple times to accomplish that.

[perpil]

Thanks both! I'll take a bit of time to digest this and try these options. It would be ideal if this could be done with middleware only, but now I understand the flow better. @svozza I didn't realize errorHandler could take Error as a parameter. I think I can combine that with what @dreamorosi suggests so I only need to publish metrics in one place. I don't quite understand this:

const result = error instanceof ServiceError 
    ? error.toJSON()  
    : {
        statusCode: 500,
        body: JSON.stringify(error),
        headers: { 'Content-Type': 'application/json' }
      };

I think statusCode should come from the error if it isn't a ServiceError and not be hardcoded to 500, but I'll experiment and report back.

[svozza]

So all instances that extend the ServiceError abstract class will have a statusCode field but for the other branch in this ternary which covers any other JS Error object, the only field you can be sure will be there is message.

I guess you could do this if you that any of your non-ServiceError derived error objects had statusCode field

const result = error instanceof ServiceError 
    ? error.toJSON()  
    : {
        statusCode: error.statusCode ?? 500,
        body: JSON.stringify(error),
        headers: { 'Content-Type': 'application/json' }
      };

[perpil]

Ah that makes sense, I mistook ServiceError to be the wrapper around InternalServiceError, not that other way around.

[svozza]

Yeah, I wonder should we call it HttpError to make it more clear?