Decorate the Python function - Logs
Tags: aws, serverless, observability, devops
Published: 2021-12-07 15:22:31

---
title: Decorate the Python function - Logs
series: [Lambda Observability]
published: true
description: Use the AWS Lambda Powertools to decorate Python functions
tags: #AWS #Serverless #Observability #DevOps
cover_image: https://www.pawelpiwosz.net/assets/lambdaObservability/sherlock-holmes.jpg
---

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:

```yaml
LOG_LEVEL: "INFO"
POWERTOOLS_SERVICE_NAME: simpleFunctionService
```

`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:

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

tracer = Tracer()
metrics = Metrics()
```

Let's update it with logging functionality.

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

tracer = Tracer()
metrics = Metrics()
logger = Logger()
```

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

```python
@metrics.log_metrics(capture_cold_start_metric=True)
@tracer.capture_lambda_handler
@logger.inject_lambda_context(log_event=True)
def handler(event, context):
```

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

***

Wow, now we have the logs!

![Instrumented logs](https://www.pawelpiwosz.net/assets/lambdaObservability/Powertools-logs1.jpg)

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:

```json
{
    "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"
}
```

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:

```python
from aws_lambda_powertools.logging import correlation_paths
```

And update our decorator:

```python
@logger.inject_lambda_context(log_event=True, correlation_id_path=correlation_paths.API_GATEWAY_REST)
```

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

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

## 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:

```python
@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
```

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](https://www.pawelpiwosz.net/assets/lambdaObservability/Powertools-logs2.jpg)

## 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!)

```sql
filter correlation_id="98160ea8-ea2e-4e3f-a322-ea30b945b066"
```

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

![Instrumented logs](https://www.pawelpiwosz.net/assets/lambdaObservability/Powertools-logs3.jpg)

***

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

***

Cover image by <a href="https://pixabay.com/users/422737-422737/?utm_source=link-attribution&amp;utm_medium=referral&amp;utm_campaign=image&amp;utm_content=462957">Hebi B.</a> from <a href="https://pixabay.com/?utm_source=link-attribution&amp;utm_medium=referral&amp;utm_campaign=image&amp;utm_content=462957">Pixabay</a>