swift-aws-lambda-runtime
swift-aws-lambda-runtime copied to clipboard
Add tracing of request events + mention LOG_LEVEL in README
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
@tomerd wdyt ? (probably worth to squash the commits :-) )
Thank you @MahdiBM for your suggestions - they are all in.
@tomerd should we reconsider merging this one too ?
@sebsto I believe https://github.com/swift-server/swift-aws-lambda-runtime/pull/315/files#r1429195527 needs to be addressed first
@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
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