Python

Tox: Testing Multiple Python Versions with Pyenv

Adam Burns

Hello!

I use Python’s tox to orchestrate a lot of my tests. It lets you set a list of versions in a tox.ini file (in the same directory as your setup.py), like this:

[tox]
envlist = py37, py38
 
[testenv]
allowlist_externals = echo
commands = echo "success"

Then you can run the tox command, it’ll create a venv for each version, and run your tests in each of those environments. It’s an easy way to ensure your code works across all the versions of Python you want to support.

But, if I install tox into a 3.8 environment and run the tox command in the directory where we created the tox.ini above, I get this:

tox
GLOB sdist-make: /Users/adam/Local/fiddle/setup.py
py37 create: /Users/adam/Local/fiddle/.tox/py37
ERROR: InterpreterNotFound: python3.7
py38 create: /Users/adam/Local/fiddle/.tox/py38
py38 inst: /Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py38 installed: example @ file:///Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py38 run-test-pre: PYTHONHASHSEED='2325607949'
py38 run-test: commands[0] | echo success
success
___________________________________________________________________________ summary ____________________________________________________________________________
ERROR:  py37: InterpreterNotFound: python3.7
  py38: commands succeeded

It found the 3.8 interpreter I ran it with, but it couldn’t find 3.7.

pyenv can get you past this. It’s a utility for installing and switching between multiple Python versions. I use it on OS X (⬅️ instructions to get set up, if you’re not already). Here’s how it looks when I have Python 3.6, 3.7, and 3.8 installed, and I’m using 3.8:

pyenv versions
  system
  3.6.11
  3.7.9
* 3.8.5 (set by /Users/adam/.pyenv/version)

Just having those versions installed isn’t enough, though. You still get the error from tox about missing versions. You have to specifically enable each version:

pyenv local 3.8.5 3.7.9
pyenv versions
  system
  3.6.11
* 3.7.9 (set by /Users/adam/Local/fiddle/.python-version)
* 3.8.5 (set by /Users/adam/Local/fiddle/.python-version)

This will create a .python-version file in the current directory that sets your Python versions. pyenv will read that file whenever you’re in that directory. You can also set versions that’ll be picked up in any folder with the pyenv global command.

Now, tox will pick up both versions:

tox
GLOB sdist-make: /Users/adam/Local/fiddle/setup.py
py37 inst-nodeps: /Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py37 installed: example @ file:///Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py37 run-test-pre: PYTHONHASHSEED='1664367937'
py37 run-test: commands[0] | echo success
success
py38 inst-nodeps: /Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py38 installed: example @ file:///Users/adam/Local/fiddle/.tox/.tmp/package/1/example-0.0.0.zip
py38 run-test-pre: PYTHONHASHSEED='1664367937'
py38 run-test: commands[0] | echo success
success
___________________________________________________________________________ summary ____________________________________________________________________________
  py37: commands succeeded
  py38: commands succeeded
  congratulations :)

That’s it! Now you can run your tests in as many verions of Python as you need.

Happy testing,

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

PowerShell: Python venv Missing Activate.ps1

Adam Burns

Hello!

Ran in to a weird problem this week: I created a Python 3.7.9 venv, but I couldn’t activate it in PoweShell (my shell of choice). The Activate.ps1 script was missing.

The core docs for 3.7 list VENV/Scripts/Activate.ps1 as the command to activate venvs in PowerShell (which seemed odd because I’m used to VENV/bin/activate from Bash, but whatever). The Scripts directory didn’t even exist:

gci ./test_venv_379/
 
    Directory: /Users/adam/Local/fiddle/test_venv_379
 
Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
d----          10/22/2020  9:28 AM                bin
d----          10/22/2020  9:28 AM                include
d----          10/22/2020  9:28 AM                lib
-----          10/22/2020  9:28 AM             98 pyvenv.cfg

I recreated the venv and got the same results. I made new venvs with 3.7.8 and 3.6.11, and again the same results. When I made a 3.8.5 venv, though, it had a VENV/bin/Activate.ps1 (which works great).

gci ./test_venv_385/bin
 
    Directory: /Users/adam/Local/fiddle/test_venv_385/bin
 
Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-----          10/22/2020  9:13 AM           2236 activate
-----          10/22/2020  9:13 AM           1288 activate.csh
-----          10/22/2020  9:13 AM           2440 activate.fish
-----          10/22/2020  9:13 AM           8834 Activate.ps1
-----          10/22/2020  9:13 AM            263 easy_install
...

Then I read the docs for 3.8: VENV/Scripts/Activate.ps1 is the PowerShell activation script but VENV/bin/Activate.ps1 is the PowerShell Core activation script. The 3.7 and 3.6 docs don’t make this distinction, which I’d bet is because PowerShell Core wasn’t supported until 3.8. I’m running Posh on Mac, so of course I’m running Posh Core (only Core supports Mac and Linux).

I suspect the VENV/Scripts/Activate.ps1 file was missing from both venvs because Python detected my shell was Posh Core, which it didn’t support. That would also explain why my 3.8 venv only had a VENV/bin/Activate.ps1 file, the file needed by Posh Core.

Anyway, if you upgrade to 3.8 (I used 3.8.5) you should be good to go.

If you can’t upgrade. Upgrade! But if you really really can’t, you can still use a 3.7 venv in Posh Core. Just call the executables by path instead of activating:

./test_venv_385/bin/python --version
Python 3.8.5

Hope that gets you past the problem!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

CodePipeline lambda Function: Complete Example

Adam Burns

Hello!

It takes a few pieces to assemble a working lambda action for CodePipeline. I like to start from a simple example and build up to what I need. Here’s the code I use as a starting point.

First, a few notes:

  • My pipeline lambda functions are usually small, often only a few dozen lines (more than that is usually a signal that I’m implementing an anti-pattern). Because my resources are small, I just drop the code into CloudFormation’s ZipFile. That saves me from building a package. In more complex cases you may want to expand your lambda function resource.
  • One of the most common problems I see in lambda action development is unhandled exceptions. Read more in my article here.
  • This example focuses on the minimum resources, permissions, and code for a healthy lambda action. I skipped some of the usual good practices like template descriptions and parameterized config.
  • I put the S3 Bucket and CloudWatch Logs Log Group in the same template as the function so it was easy to see for this example. Usually I put them in a separate template because they don’t share the same lifecycle. I don’t want rollbacks or reprovisions to delete my artifacts or logs.
  • My demo function doesn’t do anything with the pipeline artifact, it just logs the user parameter string passed to it. When I’m using custom actions like these it’s often for non-artifact tasks like passing notifications to outside systems and this is all I need.
  • You’ll have to upload a file as my_artifact to the bucket this creates so the pipeline’s source action has something to pull. The bucket will be named for your account ID and region to prevent collisions with other people’s bucket (S3’s namespace is global to all AWS customers).

Now, the code:

---
AWSTemplateFormatVersion: '2010-09-09'
Resources:
  PipelineBucket:
    Type: AWS::S3::Bucket
    Properties:
      BucketEncryption:
        ServerSideEncryptionConfiguration:
        - ServerSideEncryptionByDefault:
            SSEAlgorithm: AES256
      BucketName: !Sub '${AWS::AccountId}-${AWS::Region}-pipeline'
      PublicAccessBlockConfiguration:
        BlockPublicAcls: true
        BlockPublicPolicy: true
        IgnorePublicAcls: true
        RestrictPublicBuckets: true
      VersioningConfiguration:
        Status: Enabled
 
  LambdaLogs:
    Type: AWS::Logs::LogGroup
    Properties:
      LogGroupName: /aws/lambda/log-user-parameters
      RetentionInDays: 30
 
  LambdaRole:
    Type: AWS::IAM::Role
    Properties:
      AssumeRolePolicyDocument:
        Version: '2012-10-17'
        Statement:
        - Effect: Allow
          Principal:
            Service:
            - lambda.amazonaws.com
          Action:
          - sts:AssumeRole
      Path: '/'
      Policies:
      - PolicyName: execution-role
        PolicyDocument:
          Version: '2012-10-17'
          Statement:
          - Effect: Allow
            Action:
            - logs:CreateLogStream
            - logs:DescribeLogGroup
            - logs:PutLogEvents
            Resource: !GetAtt LambdaLogs.Arn
          - Effect: Allow
            Action:
            - codepipeline:PutJobFailureResult
            - codepipeline:PutJobSuccessResult
            # When this was written, CP's IAM policies required '*' for job results permissions.
            # https://docs.aws.amazon.com/IAM/latest/UserGuide/list_awscodepipeline.html#awscodepipeline-actions-as-permissions
            Resource: '*'
 
  PipelineRole:
    Type: AWS::IAM::Role
    Properties:
      AssumeRolePolicyDocument:
        Version: '2012-10-17'
        Statement:
        - Effect: Allow
          Principal:
            Service:
            - codepipeline.amazonaws.com
          Action:
          - sts:AssumeRole
      Path: '/'
      Policies:
      - PolicyName: actions
        PolicyDocument:
          Version: '2012-10-17'
          Statement:
          - Effect: Allow
            Action:
            - s3:Get*
            - s3:Put*
            - s3:ListBucket
            Resource:
            - !Sub
              - ${BucketArn}/*
              - BucketArn: !GetAtt PipelineBucket.Arn
            - !GetAtt PipelineBucket.Arn
          - Effect: Allow
            Action:
            - lambda:InvokeFunction
            # ARN manually constructed to avoid circular dependencies in CloudFormation.
            Resource: !Sub 'arn:aws:lambda:${AWS::Region}:${AWS::AccountId}:function:log-user-parameters'
 
  Function:
    Type: AWS::Lambda::Function
    Properties:
      Code:
        ZipFile: |
          # https://operatingops.com/2019/08/03/codepipeline-python-aws-lambda-functions-without-timeouts/
          import json
          import logging
          import boto3
 
          def lambda_handler(event, context):
              logger = logging.getLogger()
              logger.setLevel(logging.INFO)
              logger.debug(json.dumps(event))
 
              codepipeline = boto3.client('codepipeline')
              s3 = boto3.client('s3')
              job_id = event['CodePipeline.job']['id']
 
              try:
                  user_parameters = event['CodePipeline.job']['data']['actionConfiguration']['configuration']['UserParameters']
                  logger.info(f'User parameters: {user_parameters}')
                  response = codepipeline.put_job_success_result(jobId=job_id)
                  logger.debug(response)
              except Exception as error:
                  logger.exception(error)
                  response = codepipeline.put_job_failure_result(
                      jobId=job_id,
                      failureDetails={
                        'type': 'JobFailed',
                        'message': f'{error.__class__.__name__}: {str(error)}'
                      }
                  )
                  logger.debug(response)
      FunctionName: log-user-parameters
      Handler: index.lambda_handler
      Role: !GetAtt LambdaRole.Arn
      Runtime: python3.7
      Timeout: 30
 
  Pipeline:
    Type: AWS::CodePipeline::Pipeline
    Properties:
      ArtifactStore:
        Location: !Ref PipelineBucket
        Type: 'S3'
      Name: log-user-parameters
      RoleArn: !GetAtt PipelineRole.Arn
      Stages:
      - Name: Source
        Actions:
        - Name: Source
          ActionTypeId:
            Category: Source
            Owner: AWS
            Provider: 'S3'
            Version: '1'
          # Docs say 'Configuration' has to be JSON but you can use YAML.
          # CloudFormation will convert it to JSON.
          Configuration:
            S3Bucket: !Ref PipelineBucket
            S3ObjectKey: my_artifact
            PollForSourceChanges: false
          InputArtifacts: []
          OutputArtifacts:
          - Name: Artifact
          Region: !Ref 'AWS::Region'
      - Name: LogUserData
        Actions:
        - Name: LogUserData
          ActionTypeId:
            Category: Invoke
            Owner: AWS
            Provider: Lambda
            Version: '1'
          # Docs say 'Configuration' has to be JSON but you can use YAML.
          # CloudFormation will convert it to JSON.
          Configuration:
            FunctionName: !Ref Function
            UserParameters: Hello!
          InputArtifacts:
          - Name: Artifact
          Region: !Ref 'AWS::Region'
          RunOrder: 1

This creates a pipeline:

Pipeline2

With an action that logs our user parameters string:

Logs

With a few CloudFormation parameters and a little extra code in my function and this pattern almost always solves my problem. Hope it helps!

Happy automating,

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

CloudFormation Custom Resource: Complete Example

Adam Burns

Hello!

It takes a few pieces to assemble a working CloudFormation Custom Resource. I like to start from a simple example and build up to what I need. Here’s the code I use as a starting point.

First, a few notes:

  • My custom resources are usually small, often only a few dozen lines (more than that is usually a signal that I’m implementing an anti-pattern). Because my resources are small, I just drop the code into CloudFormation’s ZipFile. That saves me from building a package and from porting my own version of cfn-response. In more complex cases you may want to expand your lambda function resource.
  • When I tested the code in this article, the current version of AWS’s cfn-response module threw this warning into logs: DeprecationWarning: You are using the put() function from 'botocore.vendored.requests'. The vendored version of requests in botocore was never really meant for use outside of botocore itself, and it was recently deprecated. AWS knows about this, but they haven’t updated their cfn-response code yet.
  • One of the most common problems I see in custom resource development is unhandled exceptions. Read more in my article here.
  • This example focuses on the minimum resources, permissions, and code for a healthy custom resource. I skipped some of the usual good practices like template descriptions and parameterized config.
  • I put the CloudWatch Logs Log Group in the same template as the custom resource so it was easy to see for this example. Usually I put them in a separate template because they don’t share the same lifecycle. I don’t want rollbacks or reprovisions to delete my logs.
  • The custom resource Type can have several different values. Check out the details here.

Now, the code:

---
AWSTemplateFormatVersion: '2010-09-09'
Resources:
  Logs:
    Type: AWS::Logs::LogGroup
    Properties:
      LogGroupName: /aws/lambda/custom-resource
      RetentionInDays: 30
 
  ExecutionRole:
    Type: AWS::IAM::Role
    Properties:
      AssumeRolePolicyDocument:
        Version: '2012-10-17'
        Statement:
        - Effect: Allow
          Principal:
            Service:
            - lambda.amazonaws.com
          Action:
          - sts:AssumeRole
      Path: '/'
      Policies:
      - PolicyName: custom-resource-execution-role
        PolicyDocument:
          Version: '2012-10-17'
          Statement:
          - Effect: Allow
            Action:
            - logs:CreateLogStream
            - logs:DescribeLogGroup
            - logs:PutLogEvents
            Resource: !GetAtt Logs.Arn
 
  Function:
    Type: AWS::Lambda::Function
    Properties:
      Code:
        ZipFile: |
          # https://operatingops.com/2018/10/13/cloudformation-custom-resources-avoiding-the-two-hour-exception-timeout/
          import logging
          import cfnresponse
 
          def handler(event, context):
              logger = logging.getLogger()
              logger.setLevel(logging.INFO)
              try:
                  if event['RequestType'] == 'Delete':
                      logger.info('Deleted!')
                      cfnresponse.send(event, context, cfnresponse.SUCCESS, {})
                      return
 
                  logger.info('It worked!')
                  cfnresponse.send(event, context, cfnresponse.SUCCESS, {})
              except Exception:
                  logger.exception('Signaling failure to CloudFormation.')
                  cfnresponse.send(event, context, cfnresponse.FAILED, {})
      FunctionName: custom-resource
      Handler: index.handler
      Role: !GetAtt ExecutionRole.Arn
      Runtime: python3.7
      Timeout: 30
 
  CustomResource:
    Type: Custom::Function
    Properties:
      ServiceToken: !GetAtt Function.Arn

With a few parameters and a little extra code this pattern almost always solves my problem. Hope it helps!

Happy automating,

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

Boto3: NoRegionError

Adam Burns

Hello!

Read on if your boto3 code is throwing this error:

botocore.exceptions.NoRegionError: You must specify a region.

But first, two reasons why you might only get this error in some situations.

AWS lambda sets the region automatically. Code that works in lambda may still throw NoRegionError locally.

Some AWS services are global (don’t have regions). Like S3:

import boto3
 
s3 = boto3.resource('s3')
bucket = s3.Bucket('my-buycket')
for object in bucket.objects.all():
    print(object.key)

This code will work without setting a region.

Those are edge cases. You’ll usually get a NoRegionError unless you set a region. Like from this script on a laptop (it would work in lambda):

import boto3
 
cloudformation = boto3.client('cloudformation')
cloudformation.list_stacks()

The docs have all the details of setting a region, but the cheap and easy answer is to add this to the top of your ~/.aws/config file (create it if it doesn’t exist):

[default]
region = us-west-2

This sets us-west-2 as an example. Replace that with the region you’re using.

There are more robust options and as you get farther with boto3 I recommend checking out the details in the link above, but this should get you moving again.

Happy automating!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

Don’t Import requests From botocore.vendored

Adam Burns

Hello!

I’ve seen this anti-pattern scattered around plenty DevOps code, especially in AWS lambda functions:

from botocore.vendored import requests

Vendoring libraries like requests into other libraries like botocore is arguably an anti-pattern in general, but reaching in to botocore and importing it in your own code is definitely one. Here are some of the reasons.

The maintainers may un-vendor it. This just happened! In newer versions of botocore you can still import requests but all that’s left are some bits of the error handling system. If you upgrade botocore your imports will still work but you’ll get errors when you try to use requests. Like this in version 1.13.15:

>>> from botocore.vendored import requests
>>> print(requests.get('https://google.com'))
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
AttributeError: module 'botocore.vendored.requests' has no attribute 'get'

I saw an import like this running in an AWS lambda function a few days ago and it worked but was showing deprecation warnings. When AWS upgrades it’ll break entirely.

The vendored version may be outdated and have security vulnerabilities that have been patched in newer versions. Even if maintainers realize there’s a vulnerability, if they know they’re not using a vulnerable module of the package they may still not upgrade. Unless you check every usage to ensure you’re not using vulnerable modules at the vendored version, you should assume you are.

The vendored package may have been customized. This shouldn’t happen, but I’ve seen it in other packages plenty of times. Once the code has been copied into the repo it’s super easy for someone to tweak it for convenience. Vendored packages may no longer behave how you expect.

Instead of relying on botocore’s vendoring, add requests to your dependency chain like usual. Add a line to your requirements.txt file or update your setup.py. To package code with dependencies for AWS lambda functions, check out this. To add dependencies to your setup.py check out this.

Happy automating!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

Python: JSON Structured Logging

Adam Burns

Hello!

If you’re setting up JSON logging in AWS lambda, check out this instead. You need some extra code to prevent duplicate log messages.

Recently, I’ve been switching to logs structured as JSON. Using the sample command in my pattern for production-ready Python scripts, that means we replace delimited-strings like these:

2019-09-29 19:54:44,243 | INFO | sample_scripts.good | Acting.
2019-09-29 19:54:49,244 | INFO | sample_scripts.good | Action complete.

With JSON objects like these:

{"asctime": "2019-09-29 19:53:28,654", "levelname": "INFO", "name": "sample_scripts.good", "message": "Acting."}
{"asctime": "2019-09-29 19:53:33,654", "levelname": "INFO", "name": "sample_scripts.good", "message": "Action complete."}

Or, pretty-printed for human-readability:

{
  "asctime": "2019-09-29 19:53:28,654",
  "levelname": "INFO",
  "name": "sample_scripts.good",
  "message": "Acting."
}
{
  "asctime": "2019-09-29 19:53:33,654",
  "levelname": "INFO",
  "name": "sample_scripts.good",
  "message": "Action complete."
}

This way, your log processor can reference keys in a JSON object instead of splitting strings and hoping the split works right. Modern log processors are pretty good with delimited strings, but I’ve still seen them break because of things like unexpected whitespace or messages that happen to contain delimiter characters.

The Python logging library doesn’t have native JSON support, so I use the python-json-logger library. Here’s how I set it up:

from pythonjsonlogger import jsonlogger
 
def setup_logging(log_level):
    logger = logging.getLogger(__name__)
    logger.setLevel(log_level)
    json_handler = logging.StreamHandler()
    formatter = jsonlogger.JsonFormatter(
        fmt='%(asctime)s %(levelname)s %(name)s %(message)s'
    )
    json_handler.setFormatter(formatter)
    logger.addHandler(json_handler)

That’s it! Just call setup_logging and then you can get loggers with logging.getLogger(__name__) as usual. If you’re not sure how to get and call loggers, check out the sample script in the production-readiness pattern I mentioned above. It has some code you can copy/paste.

Technically you could do this in raw Python if you set up your loggers right, but you’d basically be re-implementing what the python-json-logger library already does so I don’t recommend that approach.

I recommend switching to logs structured as JSON. It can reduce failures and complexity in log processing, and the output is cleaner overall.

Happy automating!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

Lambda: Building Python 3 Packages

Adam Burns

Hello!

This is a guide for building lambda zip packages with pip dependencies in Python 3. It expands the AWS guide to:

  • Build your code if it’s either a single-file Python module or a pip-installable Python package (e.g. contains a setup.py).
  • Track pip dependencies for single-file Python modules in the standard requirements.txt file.
  • Show the file tree for each case and the lambda handler path that results from it.
  • Provide a copy/paste-able script for each case.

Notes:

  • Each package.sh can be run from any directory, but will always produce a function.zip in the same directory as itself.
  • Shell tested in the Apple Mac OS X 10.14.6 terminal.
  • Lambda packages tested in Python 3.7 functions.

Single-File Modules

File tree:

.
├── function.py  (defines a 'lambda_handler' function)
├── package.sh
└── requirements.txt

Lambda handler path: function.lambda_handler

package.sh:

#!/usr/bin/env bash
 
# Builds a lambda package from a single Python 3 module with pip dependencies.
# This is a modified version of the AWS packaging instructions:
# https://docs.aws.amazon.com/lambda/latest/dg/lambda-python-how-to-create-deployment-package.html#python-package-dependencies
 
# https://stackoverflow.com/a/246128
SCRIPT_DIRECTORY="$( cd "$( dirname "${BASH_SOURCE[0]}" )" >/dev/null 2>&1 && pwd )"
 
pushd $SCRIPT_DIRECTORY > /dev/null
 
rm -rf .package function.zip
mkdir .package
 
pip install --target .package --requirement requirements.txt
 
pushd .package > /dev/null
zip --recurse-paths ${SCRIPT_DIRECTORY}/function.zip .
popd > /dev/null
 
zip --grow function.zip function.py
 
popd > /dev/null

Pip-Installable Python Packages

In lambda with Python 2 this used to be harder, but in lambda with Python 3 it’s as easy as a flat module. If you’re still on Python 2, it’s time to upgrade.

File tree:

.
├── function
│   ├── __init__.py
│   └── function.py  (defines a 'lambda_handler' function)
├── package.sh
└── setup.py

Lambda handler path: function.function.lambda_handler

package.sh:

#!/usr/bin/env bash
 
# Builds a lambda package from a pip-installable Python 3 package.
# This is a modified version of the AWS packaging instructions:
# https://docs.aws.amazon.com/lambda/latest/dg/lambda-python-how-to-create-deployment-package.html#python-package-dependencies
 
# https://stackoverflow.com/a/246128
SCRIPT_DIRECTORY="$( cd "$( dirname "${BASH_SOURCE[0]}" )" >/dev/null 2>&1 && pwd )"
 
pushd $SCRIPT_DIRECTORY > /dev/null
 
rm -rf .package function.zip
mkdir .package
 
pip install --target .package .
 
pushd .package > /dev/null
zip --recurse-paths ${SCRIPT_DIRECTORY}/function.zip .
popd > /dev/null
 
popd > /dev/null

That’s it! In the latest versions of lambda it’s pretty easy, you just have to do a little fiddling to make the scripts easy to use and to figure out the handler paths.

Happy automating!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

CloudWatch Logs Structured as JSON with Python Lambda Functions

Adam Burns

Hello!

If you’re setting up JSON logging in a script and instead of a lambda function, check out this instead. The pattern is a little simpler.

Update 2020-08-30: Replaced the explanation of the missing aws_request_id with a link to a new article explaining how to pass that value.

Recently, I’ve been switching to logs structured as JSON. That means output like this:

{
    "asctime": "2019-09-20 13:55:13,604",
    "levelname": "INFO",
    "name": "root",
    "message": "Huzzah!"
}

Instead of this:

2019-09-21 15:52:43,240 INFO root Huzzah!

This way, your log processor can reference keys in a JSON object instead of splitting strings and hoping the split works right. Modern log processors are pretty good with delimited strings, but I’ve still seen them break because of things like unexpected whitespace or messages that happen to contain delimiter characters.

CloudWatch Logs reads JSON out of box. To send it JSON from a Python lambda function, we need to do to two things:

  • Configure a JSON handler for the root logger. I use the python-json-logger library.
  • Remove lambda’s default log handler (to prevent duplicate messages).

First, the full example. Then the details. Here’s the code:

import logging
from pythonjsonlogger import jsonlogger
 
def setup_logging(log_level):
    logger = logging.getLogger()
 
    # Testing showed lambda sets up one default handler. If there are more,
    # something has changed and we want to fail so an operator can investigate.
    assert len(logger.handlers) == 1
 
    logger.setLevel(log_level)
    json_handler = logging.StreamHandler()
    formatter = jsonlogger.JsonFormatter(
        fmt='%(asctime)s %(levelname)s %(name)s %(message)s'
    )
    json_handler.setFormatter(formatter)
    logger.addHandler(json_handler)
    logger.removeHandler(logger.handlers[0])
 
def lambda_handler(event, context):
    setup_logging(logging.DEBUG)
    logger = logging.getLogger()
    logger.info('Huzzah!')

For more details on what that assert is and how it works, check out this.

By default, CloudWatch renders this function’s JSON messages on one line:

log_output_collapsed.png

But you can expand them into pretty-printed objects:

log_output_expanded.png

The expanded form is extra nice when you have large log messages or lots of fields.

Like we saw in my previous post, lambda’s out-of-box setup logs delimited strings. I figured out from testing that it does this with a handler on the root logger. If we added a JSON handler and did nothing else, we’d get duplicate log messages; one from each handler. We have to call removeHandler() on the default one.

To see how this works, let’s add debug messages to our setup function (and switch to logging.DEBUG level, of course):

...
def setup_logging(log_level):
    logger = logging.getLogger()
 
    # Testing showed lambda sets up one default handler. If there are more,
    # something has changed and we want to fail so an operator can investigate.
    assert len(logger.handlers) == 1
 
    logger.setLevel(log_level)
    json_handler = logging.StreamHandler()
    formatter = jsonlogger.JsonFormatter(
        fmt='%(asctime)s %(levelname)s %(name)s %(message)s'
    )
    json_handler.setFormatter(formatter)
    logger.debug(f'Number of handlers: {len(logger.handlers)}')
    logger.debug('Adding JSON handler.')
    logger.addHandler(json_handler)
    logger.debug(f'Number of handlers: {len(logger.handlers)}')
    logger.debug('This message logs twice because there are two handlers.')
    logger.debug('Removing original handler.')
    logger.removeHandler(logger.handlers[0])
    logger.debug('This message logs once because we removed the original handler.')
    ...

Now our output shows what’s happening with the handlers:

debug_output_collapsed.png

The default handler logs an aws_request_id that our JSON handler doesn’t. My functions didn’t need that ID. If yours do, check out this article.

Like we also saw in another previous post, one of the reasons to use Python’s logging library is it automatically captures messages from third-party tools like boto. We still get that:

boto_output_collapsed

I recommend switching to logs structured as JSON. It can reduce failures and complexity in log processing, and the output is cleaner overall.

Happy logging!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles:

Replace Conditions with Instructions

Adam Burns

Hello!

This pattern is loosely based on Martin Fowler’s article on Adaptive Models.

I often find that my code needs to handle a bunch of different cases. It can be tempting (but ultimately painful) to just write a bunch of if conditions to handle those cases. Imagine converting HTML files into markdown:

file_names = [
    'a.md',
    'a.html',
    'b.html'
]
 
def should_convert(file_name):
    extension = file_name.split('.')[1]
    if extension == 'md':
        return False
    elif extension == 'html':
        return True
 
def convert(file_name):
    print(f'{file_name} > converted_{file_name}')
 
if __name__ == '__main__':
    for file_name in file_names:
        if should_convert(file_name):
            convert(file_name)

We have to write logic that understands each case. This simplified example doesn’t look too bad, but in real life it’ll be worse.

Instead, I like to write an object that encodes the right action for each case and then look up that action as each case is processed:

should_convert = {
    'md': False,
    'html': True
}
 
file_names = [
    'a.md',
    'a.html',
    'b.html'
]
 
def convert(file_name):
    print(f'{file_name} > converted_{file_name}')
 
if __name__ == '__main__':
    for file_name in file_names:
        if should_convert[file_name.split('.')[1]]:
            convert(file_name)

Replacing the should_convert() function with a dictionary simplifies several things:

  • There’s less code to understand. We don’t have to read through implementation for every case, we just read through the cases.
  • To support new cases, we just update the dictionary. We don’t have to write new code.
  • Because we don’t have to write new code to support new cases, we don’t need to write tests to assert the new code works. The logic is the same, it just processes more instructions.

This also handles errors cleanly. Suppose we add a file with an extension we don’t know if we should convert (.doc) and run the script:

Traceback (most recent call last):
  File "./adaptive.py", line 18, in <module>
    if should_convert[file_name.split('.')[1]]:
KeyError: 'doc'

It’s immediately clear that it didn’t know if it should convert the .doc extension.

If you encode desired behavior into objects, you only need to write code that can follow those instructions. Here’s the principle I try to follow:

Conditions are for processing instructions, not for implementing them.

This has simplified a ton of my code. I highly recommend it.

Happy automating!

Adam

Need more than just this article? We’re available to consult.

You might also want to check out these related articles: