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

sebsto · 2023-12-17T00:14:01Z

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

fabianfett · 2023-12-17T15:47:35Z

Sources/AWSLambdaRuntimeCore/LambdaRunner.swift

+            logger.trace("Request", metadata: ["bytes": .string(String(buffer: bytes))])
            logger.debug("sending invocation to lambda handler")


I think we should combine those two. debug is the right level imo.
What happens with payloads that aren't string representable. IIRC I can send any payload to lambda.

Thank you @fabianfett for the feedback.

I think we should combine those two. debug is the right level imo.

I like the idea of separating debug output from tracing. Trace adds more info, potentially long data trace, which is the case here.
But maybe it's a matter of personal preference.
I can see user preferences for having just the debug logs, while some others want to have the trace level for a limited period of time.
Given the potentially sensitive nature of the data contained in the payload (such as JWT tokens or PII), I think it is a good idea to decouple the debug and trace levels in this case.

What happens with payloads that aren't string representable

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

Furthermore, the max payload size for synchronous invocations is 6Mb. They wont be huge payloads passed as input to the swift AWS Lambda Runtime.
https://docs.aws.amazon.com/lambda/latest/dg/gettingstarted-limits.html

we can also do something as follow if we want to eliminate the two logging statements

if logger.logLevel <= .trace { logger.trace("...") } else { logger.debug("...") } }

Furthermore, the max payload size for synchronous invocations is 6Mb

perhaps we want to trim it?

MahdiBM

Mostly some nits 🙂

readme.md

Co-authored-by: Mahdi Bahrami <[email protected]>

sebsto · 2023-12-18T13:49:16Z

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

sebsto · 2023-12-18T13:49:42Z

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

sebsto · 2024-04-15T09:45:07Z

@tomerd should we reconsider merging this one too ?

tomerd · 2024-04-15T17:39:01Z

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

sebsto · 2024-04-15T18:29:04Z

@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

tomerd · 2024-04-16T17:23:59Z

Sources/AWSLambdaRuntimeCore/LambdaRunner.swift

+            // when log level is trace or lower, print the first Kb of the payload
+            if logger.logLevel <= .trace, let buffer = bytes.getSlice(at: 0, length: max(bytes.readableBytes, 1024)) {
+                logger.trace("sending invocation to lambda handler",
+                             metadata: ["1024 first bytes": .string(String(buffer: buffer))])


I suspect String(buffer: buffer) may fail if buffer is not a string, please make sure it does not crash

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 · 2024-05-13T09:54:15Z

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

add tracing of request events + mention LOG_LEVEL in README

258d4d5

fabianfett reviewed Dec 17, 2023

View reviewed changes

MahdiBM reviewed Dec 17, 2023

View reviewed changes

readme.md Outdated Show resolved Hide resolved

readme.md Outdated Show resolved Hide resolved

readme.md Outdated Show resolved Hide resolved

readme.md Show resolved Hide resolved

readme.md Outdated Show resolved Hide resolved

readme.md Outdated Show resolved Hide resolved

sebsto and others added 5 commits December 18, 2023 08:20

fix typo

47beb22

Co-authored-by: Mahdi Bahrami <[email protected]>

clarify the use of env variable and the swift cli

123f0a4

Co-authored-by: Mahdi Bahrami <[email protected]>

clarify language about HTTP server

d7fa5a7

Co-authored-by: Mahdi Bahrami <[email protected]>

formatting

252f083

Co-authored-by: Mahdi Bahrami <[email protected]>

factor in additional suggestions from @MahdiBM

923092c

sebsto added 2 commits April 15, 2024 19:58

Merge branch 'main' into sebsto/request_tracing

e267bed

combine two logger statement into one and print only for Kb of payload

abb9f1d

tomerd approved these changes Apr 16, 2024

View reviewed changes

tomerd reviewed Apr 16, 2024

View reviewed changes

tomerd approved these changes May 13, 2024

View reviewed changes

sebsto merged commit 2219782 into swift-server:main May 15, 2024
7 of 8 checks passed

sebsto deleted the sebsto/request_tracing branch May 15, 2024 07:57

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

sebsto commented Dec 17, 2023 •

edited

Loading

fabianfett Dec 17, 2023

sebsto Dec 17, 2023 •

edited

Loading

tomerd Dec 20, 2023

tomerd Dec 20, 2023 •

edited

Loading

MahdiBM left a comment

sebsto commented Dec 18, 2023 •

edited

Loading

sebsto commented Dec 18, 2023 •

edited

Loading

sebsto commented Apr 15, 2024

tomerd commented Apr 15, 2024

sebsto commented Apr 15, 2024

tomerd Apr 16, 2024

sebsto Apr 16, 2024

sebsto commented May 13, 2024

		logger.trace("Request", metadata: ["bytes": .string(String(buffer: bytes))])
		logger.debug("sending invocation to lambda handler")

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

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

Conversation

sebsto commented Dec 17, 2023 • edited Loading

Motivation:

Modifications:

Result:

fabianfett Dec 17, 2023

Choose a reason for hiding this comment

sebsto Dec 17, 2023 • edited Loading

Choose a reason for hiding this comment

tomerd Dec 20, 2023

Choose a reason for hiding this comment

tomerd Dec 20, 2023 • edited Loading

Choose a reason for hiding this comment

MahdiBM left a comment

Choose a reason for hiding this comment

sebsto commented Dec 18, 2023 • edited Loading

sebsto commented Dec 18, 2023 • edited Loading

sebsto commented Apr 15, 2024

tomerd commented Apr 15, 2024

sebsto commented Apr 15, 2024

tomerd Apr 16, 2024

Choose a reason for hiding this comment

sebsto Apr 16, 2024

Choose a reason for hiding this comment

sebsto commented May 13, 2024

sebsto commented Dec 17, 2023 •

edited

Loading

sebsto Dec 17, 2023 •

edited

Loading

tomerd Dec 20, 2023 •

edited

Loading

sebsto commented Dec 18, 2023 •

edited

Loading

sebsto commented Dec 18, 2023 •

edited

Loading