swift-aws-lambda-runtime icon indicating copy to clipboard operation
swift-aws-lambda-runtime copied to clipboard

Add tracing of request events + mention LOG_LEVEL in README

Open sebsto opened this issue 1 year ago • 5 comments

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 avatar Dec 17 '23 00:12 sebsto

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

sebsto avatar Dec 18 '23 13:12 sebsto

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

sebsto avatar Dec 18 '23 13:12 sebsto

@tomerd should we reconsider merging this one too ?

sebsto avatar Apr 15 '24 09:04 sebsto

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

tomerd avatar Apr 15 '24 17:04 tomerd

@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 avatar Apr 15 '24 18:04 sebsto

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

sebsto avatar May 13 '24 09:05 sebsto