swift-server / swift-aws-lambda-runtime

Swift implementation of AWS Lambda Runtime
Apache License 2.0
1.12k stars 100 forks source link

Add tracing of request events + mention LOG_LEVEL in README #315

Closed sebsto closed 1 month ago

sebsto commented 6 months ago

This PR adds a logger.trace() in LambdaRuntime just before calling user's handler. It allows to see in the trace logs a string representation of the event passed by the AWS Service.

Motivation:

When there is no or poor documentation of the event passed to a lambda function, is it super hard to figure out the exact Codable struct to implement for the LambdaHandler.

With other programming languages, such as Python or Typescript, developers typically add a print(event) or console.log(event) at the start of the lambda handler function to figure out the exact type of data to deal with.

When using the Swift AWS Lambda Runtime, it's not possible because the bytes received are encoded to a struct before the user's code is called.

When there is a mismatch between the received bytes and the Codable struct, the user is left with very few information to figure out what was wrong. The encode() error messages are cryptic. They don't provide enough information to debug this type of error.

Modifications:

I added one line in LambdaRuntime to trace a string representation of the request before calling the user's handler.

            logger.trace("Request", metadata: ["bytes": .string(String(buffer: bytes))])

I also modified the README to document the use of the LOG_LEVEL environemnt variable. While I was modifying the README, I noticed there was no mention of local test, I therefore added a small section about local testing (which is a subject related to this PR, hence a single PR for the two new sections in the README)

Result:

When invoking the runtime with LOG_LEVEL=trace, we receive information such as

Build complete! (15.97s)
2023-12-16T18:43:33-0500 info LocalLambdaServer : [AWSLambdaRuntimeCore] LocalLambdaServer started and listening on 127.0.0.1:7000, receiving events on /invoke
2023-12-16T18:43:33-0500 info Lambda : [AWSLambdaRuntimeCore] lambda runtime starting with LambdaConfiguration
  General(logLevel: trace))
  Lifecycle(id: 345519645762583, maxTimes: 0, stopSignal: TERM)
  RuntimeEngine(ip: 127.0.0.1, port: 7000, requestTimeout: nil
2023-12-16T18:43:33-0500 debug Lambda : lifecycleId=345519645762583 [AWSLambdaRuntimeCore] initializing lambda
2023-12-16T18:43:33-0500 debug Lambda : lifecycleIteration=0 [AWSLambdaRuntimeCore] lambda invocation sequence starting
2023-12-16T18:43:33-0500 debug Lambda : lifecycleIteration=0 [AWSLambdaRuntimeCore] requesting work from lambda runtime engine using /2018-06-01/runtime/invocation/next
2023-12-16T18:44:18-0500 debug Lambda : lifecycleIteration=0 [AWSLambdaRuntimeCore] sending invocation to lambda handler
2023-12-16T18:44:18-0500 trace Lambda : bytes={ "rawQueryString": "",   "headers": {        "host": "b2k1t8fon7.execute-api.us-east-1.amazonaws.com",   "x-forwarded-port": "443",      "content-length": "0",      "x-amzn-trace-id": "Root=1-6571d134-63dbe8ee21efa87555d59265",      "x-forwarded-for": "191.95.148.219",        "x-forwarded-proto": "https",       "accept": "*/*",        "user-agent": "curl/8.1.2"  },  "requestContext": {     "apiId": "b2k1t8fon7",      "http": {           "sourceIp": "191.95.148.219",           "userAgent": "curl/8.1.2",  "method": "POST",           "path": "/liveness/create",         "protocol": "HTTP/1.1"      },      "timeEpoch": 1701957940365,     "domainPrefix": "b2k1t8fon7",       "accountId": "012345678912",        "time": "07/Dec/2023:14:05:40 +0000",       "stage": "$default",        "domainName": "b2k1t8fon7.execute-api.us-east-1.amazonaws.com",     "requestId": "Pk2gOia2IAMEPOw=",        "authorizer": {     "iam": {                "accessKey": "ASIA-redacted",               "accountId": "012345678912",                "callerId": "AIDA-redacted",                "cognitoIdentity": null,                "principalOrgId": "aws:PrincipalOrgID",             "userArn": "arn:aws:iam::012345678912:user/sst",                "userId": "AIDA-redacted"           }       }   },  "isBase64Encoded": false,   "version": "2.0",   "routeKey": "$default", "rawPath": "/liveness/create"} lifecycleIteration=0 [AWSLambdaRuntimeCore] Request
2023-12-16T18:44:21-0500 debug Lambda : lifecycleIteration=0 [AWSLambdaRuntimeCore] reporting results to lambda runtime engine using /2018-06-01/runtime/invocation/345564850687750/response
2023-12-16T18:44:21-0500 debug Lambda : lifecycleIteration=0 [AWSLambdaRuntimeCore] lambda invocation sequence completed successfully
2023-12-16T18:44:21-0500 debug Lambda : lifecycleIteration=1 [AWSLambdaRuntimeCore] lambda invocation sequence starting
2023-12-16T18:44:21-0500 debug Lambda : lifecycleIteration=1 [AWSLambdaRuntimeCore] requesting work from lambda runtime engine using /2018-06-01/runtime/invocation/next
sebsto commented 6 months ago

@tomerd wdyt ? (probably worth to squash the commits :-) )

sebsto commented 6 months ago

Thank you @MahdiBM for your suggestions - they are all in.

sebsto commented 2 months ago

@tomerd should we reconsider merging this one too ?

tomerd commented 2 months ago

@sebsto I believe https://github.com/swift-server/swift-aws-lambda-runtime/pull/315/files#r1429195527 needs to be addressed first

sebsto commented 2 months ago

@tomerd done. I merged the two statements with a if logger.logLevel <= .trace as you suggested and I sliced the buffer to print only the first Kb

sebsto commented 1 month ago

Hello @tomerd Ar ewe good to merge with this last comment ? Or you still prefer code to enforce the content type ?

According to the AWS Lambda service API documentation, the payload is always a string https://docs.aws.amazon.com/lambda/latest/dg/API_Invoke.html