DEV Community

Cover image for Decorate the Python function - Logs
Paweł Piwosz
Paweł Piwosz

Posted on

Decorate the Python function - Logs

All right! We have two elements implemented - Traces and Metrics. Let's do the same with the last element of Observability - Logs

Preparations

We did it previously, and we need to repeat the step with updating the SAM template. The variables we need this time are:

LOG_LEVEL: "INFO"
POWERTOOLS_SERVICE_NAME: simpleFunctionService
Enter fullscreen mode Exit fullscreen mode

POWERTOOLS_SERVICE_NAME we already have. LOG_LEVEL set the level of the "logging intensity". We can use INFO, which is default value, or DEBUG.

Decorate the handler

Logs

We have this part:

from aws_lambda_powertools import Tracer, Metrics
from aws_lambda_powertools.metrics import MetricUnit

tracer = Tracer()
metrics = Metrics()
Enter fullscreen mode Exit fullscreen mode

Let's update it with logging functionality.

from aws_lambda_powertools import Tracer, Metrics, Logger
from aws_lambda_powertools.metrics import MetricUnit

tracer = Tracer()
metrics = Metrics()
logger = Logger()
Enter fullscreen mode Exit fullscreen mode

Ok, we have this part, now it is time to add decorator.

@metrics.log_metrics(capture_cold_start_metric=True)
@tracer.capture_lambda_handler
@logger.inject_lambda_context(log_event=True)
def handler(event, context):
Enter fullscreen mode Exit fullscreen mode

Let's deploy it and take a look on CloudWatch Logs.


Wow, now we have the logs!

Instrumented logs

Do you remember the three entries with very little information from the beginning of this tutorial? now it looks... better.

Let's take a look on a few examples of logs:

{
    "level": "INFO",
    "location": "decorate:345",
    "message": {
        "resource": "/",
        "path": "/",
        "httpMethod": "GET",
        "headers": {
            "CloudFront-Forwarded-Proto": "https",
            "CloudFront-Is-Desktop-Viewer": "true",
            "CloudFront-Is-Mobile-Viewer": "false",
            "CloudFront-Is-SmartTV-Viewer": "false",
            "CloudFront-Is-Tablet-Viewer": "false",
            "CloudFront-Viewer-Country": "PL",
            "Host": "xxxx.execute-api.eu-central-1.amazonaws.com",
            "User-Agent": "Mozilla/5.0 (Windows NT; Windows NT 10.0; pl-PL) WindowsPowerShell/5.1.19041.1320",
            "Via": "1.1 xxxxxx.cloudfront.net (CloudFront)",
            "X-Amz-Cf-Id": "xxxxxxxxxx==",
            "X-Amzn-Trace-Id": "Root=1-61ae4ae5-0e2127a8181ee95663f955f5",
            "X-Forwarded-For": "xx.xx.xx.xx",
            "X-Forwarded-Port": "443",
            "X-Forwarded-Proto": "https"
        },
        "multiValueHeaders": {
            "CloudFront-Forwarded-Proto": [
                "https"
            ],
            "CloudFront-Is-Desktop-Viewer": [
                "true"
            ],
            "CloudFront-Is-Mobile-Viewer": [
                "false"
            ],
            "CloudFront-Is-SmartTV-Viewer": [
                "false"
            ],
            "CloudFront-Is-Tablet-Viewer": [
                "false"
            ],
            "CloudFront-Viewer-Country": [
                "PL"
            ],
            "Host": [
                "xxxxxx.execute-api.eu-central-1.amazonaws.com"
            ],
            "User-Agent": [
                "Mozilla/5.0 (Windows NT; Windows NT 10.0; pl-PL) WindowsPowerShell/5.1.19041.1320"
            ],
            "Via": [
                "1.1 xxxxxf.cloudfront.net (CloudFront)"
            ],
            "X-Amz-Cf-Id": [
                "xxxxxxxx=="
            ],
            "X-Amzn-Trace-Id": [
                "Root=1-61ae4ae5-0e2127a8181ee95663f955f5"
            ],
            "X-Forwarded-For": [
                "xx.xx.xx.xx"
            ],
            "X-Forwarded-Port": [
                "443"
            ],
            "X-Forwarded-Proto": [
                "https"
            ]
        },
        "queryStringParameters": null,
        "multiValueQueryStringParameters": null,
        "pathParameters": null,
        "stageVariables": null,
        "requestContext": {
            "resourceId": "xxxxxxxx",
            "resourcePath": "/",
            "httpMethod": "GET",
            "extendedRequestId": "J8Cj9GXJFiAFWww=",
            "requestTime": "06/Dec/2021:17:39:49 +0000",
            "path": "/Prod",
            "accountId": "xxxxxxxxx",
            "protocol": "HTTP/1.1",
            "stage": "Prod",
            "domainPrefix": "xxxxxxx",
            "requestTimeEpoch": 1638812389988,
            "requestId": "9b468736-310c-4b0d-8326-1ac19897435a",
            "identity": {
                "cognitoIdentityPoolId": null,
                "accountId": null,
                "cognitoIdentityId": null,
                "caller": null,
                "sourceIp": "xx.xx.xx.xx",
                "principalOrgId": null,
                "accessKey": null,
                "cognitoAuthenticationType": null,
                "cognitoAuthenticationProvider": null,
                "userArn": null,
                "userAgent": "Mozilla/5.0 (Windows NT; Windows NT 10.0; pl-PL) WindowsPowerShell/5.1.19041.1320",
                "user": null
            },
            "domainName": "xxxxx.execute-api.eu-central-1.amazonaws.com",
            "apiId": "xxxxx"
        },
        "body": null,
        "isBase64Encoded": false
    },
    "timestamp": "2021-12-06 17:39:50,675+0000",
    "service": "simpleFunctionService",
    "cold_start": true,
    "function_name": "lambdaDemo-lambdaFunction-sfSnGT61RScH",
    "function_memory_size": "128",
    "function_arn": "arn:aws:lambda:eu-central-1:xxxxxx:function:lambdaDemo-lambdaFunction-sfSnGT61RScH:live",
    "function_request_id": "de20ea17-289e-4475-88a1-d8b165b24e6f",
    "xray_trace_id": "1-61ae4ae5-0e2127a8181ee95663f955f5"
}
Enter fullscreen mode Exit fullscreen mode

This looks better, doesn't it?

Correlation ID

Let's add something what is called correlation ID. What it is? Well, simply speaking it is a GUID (Globally Unique IDentifier) of the request, automatically generated by API Gateway.

Add to our imports:

from aws_lambda_powertools.logging import correlation_paths
Enter fullscreen mode Exit fullscreen mode

And update our decorator:

@logger.inject_lambda_context(log_event=True, correlation_id_path=correlation_paths.API_GATEWAY_REST)
Enter fullscreen mode Exit fullscreen mode

We should confirm it after deployment... And yes, we have it:

{
"function_request_id": "0aa7cecf-1488-4ed1-95a6-0c5bbaf24cba",
"correlation_id": "e91b1f50-f96f-44c8-be62-0d6c1dc95833",
"xray_trace_id": "1-61ae4f32-52f3b3b64de440660f262783"
}
Enter fullscreen mode Exit fullscreen mode

Instrument functions

Now it is time for the last experiment. Let's instrument each function and have a log from each of them. Update the code to this form for each mathematical functions of our example:

@tracer.capture_method
def sumnumbers(a, b):
    """ simple function """
    logger.info("Executing sumNumbers")
    result = a + b
    tracer.put_annotation("operationStatus", "success")
    tracer.put_annotation("operationResult", result)
    metrics.add_metric(name="sumNumbers", unit=MetricUnit.Count, value=1)
    message = "sumNumbers result is: {}".format(result)
    logger.info(message)
    return result
Enter fullscreen mode Exit fullscreen mode

Ok, let's take a look on the log now. We can see mulitple lines of structurized log, where we have not only the message we designed, but more information.

Instrumented logs

How useful is it?

You may ask "Why we did all of that?" Well, the answer is simple.

  • We know exactly what our function is doing
  • We know exactly how our function is performing
  • We are able to catch easily every single bottleneck in the system
  • We can track every single request through the whole system

And more, but let me leave you here :)


How to track requests? I am sure you remember when we added correlation_id to our log. This information is taken from API, using this setting in decorator correlation_id_path=correlation_paths.API_GATEWAY_REST. And we are able to track it through multiple functions. Of course in this example we have only one, but nothing stops us from use it in more wider scope.

For now, let's go to AWS CloudWatch Logs Insights, select all logs you have (yeah, why not :) ) and run this simple query (change the value of correlation_id, of course!)

filter correlation_id="98160ea8-ea2e-4e3f-a322-ea30b945b066"
Enter fullscreen mode Exit fullscreen mode

And... we have all occurences of this specific id through the system!

Instrumented logs


Now you can go crazy with logging. The topic here is very wide, so... go and play with it!


Cover image by Hebi B. from Pixabay

Discussion (0)