CodePipeline lambda Function: Complete Example

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

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

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

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:

CloudWatch Logs Structured as JSON with Python Lambda Functions

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:

CodePipeline: Python AWS Lambda Functions Without Timeouts

Hello!

If you’re new to CodePipeline lambda actions check out this complete example first.

There’s a gotcha when writing CodePipeline lambda functions that’s easy to miss and if you miss it your pipeline can get stuck in timeout loops that you can’t cancel. Here’s how to avoid that.

This article assumes you’re familiar with CodePipeline and lambda and that you’ve granted the right IAM permissions to both. You may also want to check out lambda function logging.

This is Python 3. Python 2 is out of support.

CodePipeline uses a callback pattern for running lambda functions: it invokes the function and then waits for that function to call back with either put_job_success_result or put_job_failure_result.

Here’s an empty lambda action:

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')
    job_id = event['CodePipeline.job']['id']
 
    logger.info('Doing cool stuff!')
    response = codepipeline.put_job_success_result(jobId=job_id)
    logger.debug(response)

It’s a successful no-op:

SimpleWorking

Now let’s add an exception:

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')
    job_id = event['CodePipeline.job']['id']
 
    logger.info('Doing cool stuff!')
    raise ValueError('Fake error for testing!')
    response = codepipeline.put_job_success_result(jobId=job_id)
    logger.debug(response)

The log shows the exception, like we’d expect:

SimpleFailing

But, the pipeline action takes 20 minutes to time out. The CodePipeline limits doc says it takes 1 hour for lambda functions to time out and that used to apply to functions that didn’t send results, I tested it. Sadly, I didn’t think to keep screenshots back then. In my latest tests it took 20 minutes: ConsistentTwentyMinuteTimeout

It doesn’t matter what the lambda function’s timeout is. Mine was set to 3 seconds. We’re hitting a timeout that’s internal to CodePipeline.

At least the action’s details link give an error saying specifically that it didn’t receive a result: NoResultReturnedErrorMinimal.png

There’s a workaround. You should usually only catch specific errors that you know how to handle. It’s an anti-pattern to use except Exception. But, in this case we need to guarantee that the callback always happens. In this one situation (not in general) we need to catch all exceptions:

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')
    job_id = event['CodePipeline.job']['id']
 
    try:
        raise ValueError('This message will appear in the CodePipeline UI.')
        logger.info('Doing cool stuff!')
        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)

(logger.exception(error) logs the exception and its stack trace. Even though we’re catching all errors, we shouldn’t let them pass silently.)

Now the failure will be visible to CodePipeline and the action won’t get stuck waiting.

The failureDetails message will appear in the CodePipeline UI. We send the exception message so it’s visible to operators:

HealthyError2

Of course, you’ll want to remove that ValueError. It’s just to demonstrate the handling.

You should use this pattern in every lambda action: catch all exceptions and return a JobFailed result to the pipeline. You can still catch more specific exceptions inside the catchall try/except, ones specific to the feature you’re implementing, but you need that catchall to ensure the result returns when the unexpected happens.

Happy automating!

Adam

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

You might also want to check out these related articles:

How to Paginate in boto3: Use Collections Instead

Hello!

When working with boto3, you’ll often find yourself looping. Like if you wanted to get the names of all the objects in an S3 bucket, you might do this:

import boto3
 
s3 = boto3.client('s3')
 
response = s3.list_objects_v2(Bucket='my-bucket')
for object in response['Contents']:
    print(object['Key'])

But, methods like list_objects_v2 have limits on how many objects they’ll return in one call (up to 1000 in this case). If you reach that limit, or if you know you eventually will, the solution used to be pagination. Like this:

import boto3
 
s3 = boto3.client('s3')
 
paginator = s3.get_paginator('list_objects_v2')
pages = paginator.paginate(Bucket='my-bucket')
 
for page in pages:
    for object in page['Contents']:
        print(object['Key'])

I always forget how to do this. I also feel like it clutters up my code with API implementation details that don’t have anything to do with the objects I’m trying to list.

There’s a better way! Boto3 has semi-new things called collections, and they are awesome:

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

If they look familiar, it’s probably because they’re modeled after the QuerySets in Django’s ORM. They work like an object-oriented interface to a database. It’s convenient to think about AWS like that when you’re writing code: it’s a database of cloud resources. You query the resources you want to interact with and read their properties (e.g. object.key like we did above) or call their methods.

You can do more than list, too. For example, in S3 you can empty a bucket in one line (this works even if there are pages and pages of objects in the bucket):

import boto3
 
s3 = boto3.resource('s3')
bucket = s3.Bucket('my-buycket')
bucket.objects.all().delete()

Boom 💥. One line, no loop. Use wisely.

I recommend collections whenever you need to iterate. I’ve found the code is easier to read and their usage is easier to remember than paginators. Some notes:

  • This is just an introduction, collections can do a lot more. Check out filtering. It’s excellent.
  • Collections aren’t available for every resource (yet). Sometimes you have to fall back to a paginator.
  • There are cases where using a collection can result in more API calls than you expect. Most of the time this isn’t a problem, but if you’re seeing performance problems you might want to dig into the nuances in the doc.

Hopefully, this helps simplify your life in the AWS API.

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 Best Practices: Assert to Stop Silent Failures

Good morning!

A variation of this article was given as a lighting talk at the San Diego Python Meetup:

This article covers a pattern I use to increase my confidence that my infrastructure code is working. It turns silent errors into loud ones. I’ve handled plenty of code that runs without errors but still ends up doing the wrong thing, so I’m never really sure if it’s safe to go to sleep at night. I don’t like that. I want silence to be a real indicator that everything is fine. Like The Zen of Python says:

Errors should never pass silently.

It’s easy to write assumptions that’ll create silent errors into boto code. Imagine you have an EBS volume called awesome-stuff and you need to snapshot it for backups. You might write something like this:

import datetime
 
import boto3
 
ec2 = boto3.resource('ec2')
volume_filters = [{'Name': 'tag:Name', 'Values': ['awesome-stuff']}]
volumes = list(ec2.volumes.filter(Filters=volume_filters))
volume = volumes[0]
now = datetime.datetime.now(datetime.timezone.utc).strftime("%Y-%m-%dT%H-%M-%S%Z")
volume.create_snapshot(Description=f'awesome-stuff-backup-{now}')

Simple enough. We know our volume is named awesome-stuff, so we look up volumes with that name. There should only be one, so we snapshot the first item in that list. I’ve seen this pattern all over the boto code I’ve read.

What if there are two volumes called “awesome-stuff”? That could easily happen. Another admin makes a copy and tags it the same way. An unrelated project in the same account creates a volume with the same name because awesome-stuff isn’t super unique. It’s very possible to have two volumes with the same name, and you should assume it’ll happen. When it does, this script will run without errors. It will create a snapshot, too, but only of one volume. There is no luck in operations, so you can be 100% certain it will snapshot the wrong one. You will have zero backups but you won’t know it.

There’s an easy pattern to avoid this. First, let me show you Python’s assert statement:

awesome_list = ['a', 'b']
assert len(awesome_list) == 1

We’re telling Python we expect awesome_list to contain one item. If we run this, it errors:

Traceback (most recent call last):
    File "error.py", line 2, in <module>
assert len(awesome_list) == 1
AssertionError

This is a sane message. Anyone reading it can see we expected there to be exactly one object in awesome_list but there wasn’t.

Back to boto. Let’s add an assert to our backup script:

import datetime

import boto3

ec2 = boto3.resource('ec2')
volume_filters = [{'Name': 'tag:Name', 'Values': ['awesome-stuff']}]
volumes = list(ec2.volumes.filter(Filters=volume_filters))
assert len(volumes) == 1
volume = volumes[0]
now = datetime.datetime.now(datetime.timezone.utc).strftime("%Y-%m-%dT%H-%M-%S%Z")
volume.create_snapshot(Description=f'awesome-stuff-backup-{now}')

Now, if there are two awesome-stuff volumes, our script will error:

Traceback (most recent call last):
    File "test.py", line 8, in <module>
assert len(volumes) == 1
AssertionError

Boom. That’s all you have to do. Now the script either does what we expect (backs up our awesome stuff) or it fails with a clear message. We know we don’t have any backups yet and we need to take action. Because we assert that there should be exactly one volume, this even covers us for the cases where that volume has been renamed or there’s a typo in our filters.

Here’s a good practice to follow in all of your code:

If your code assumes something, assert that the assumption is true so you’ll get a clear, early failure message if it isn’t.

If you’re interested in further reading or more sources for this practice, check out Jim Shore’s Fail Fast article.

In general, these are called logic errors. Problems with the way the code thinks (its “logic”). Often they won’t even cause errors, they’ll just create behavior you didn’t expect and that might be harmful. Writing code that’s resilient to these kinds of flaws will take your infrastructure to the next level. It won’t just seem like it’s working, you’ll have confidence that it’s working.

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 boto3 Logging

Hello!

If you’re writing a lambda function, check out this article instead.

The best way to log output from boto3 is with Python’s logging library. The core docs have a nice tutorial.

If you use print() statements for output, all you’ll get from boto is what you capture and print yourself. But, boto does a lot of internal logging that we can capture for free.

Good libraries, like boto, use Python’s logging library internally. If you set up a logger using the same library, it will automatically capture boto’s logs along with your own.

Here’s how I set up logging. This is a demo script, in the real world you’d parameterize the inputs, etc.

import logging
import boto3
 
if __name__ == '__main__':
    logging.basicConfig(
        level=logging.INFO,
        format=f'%(asctime)s %(levelname)s %(message)s'
    )
    logger = logging.getLogger()
    logger.debug('The script is starting.')
    logger.info('Connecting to EC2...')
    ec2 = boto3.client('ec2')

That’s it! The basicConfig() function sets up the root logger for you. We’ve told it what amount of output to show (the level) and to show the event time and level on each output line. The logging library docs have more info on what levels and formatting are available.

If you set the level to INFO, it’ll output anything logged with .info() (or higher) by your code and boto’s internal code. You won’t see our 'The script is starting.' line because anything logged at the DEBUG level will be excluded.

2019-08-18 07:59:20,123 INFO Connecting to EC2...
Traceback (most recent call last):
  File "demo.py", line 11, in <module>
    ec2 = boto3.client('ec2')
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/boto3/__init__.py", line 91, in client
    return _get_default_session().client(*args, **kwargs)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/boto3/session.py", line 263, in client
    aws_session_token=aws_session_token, config=config)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/session.py", line 838, in create_client
    client_config=config, api_version=api_version)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 86, in create_client
    verify, credentials, scoped_config, client_config, endpoint_bridge)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 328, in _get_client_args
    verify, credentials, scoped_config, client_config, endpoint_bridge)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/args.py", line 47, in get_client_args
    endpoint_url, is_secure, scoped_config)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/args.py", line 117, in compute_client_args
    service_name, region_name, endpoint_url, is_secure)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 402, in resolve
    service_name, region_name)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/regions.py", line 122, in construct_endpoint
    partition, service_name, region_name)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/regions.py", line 135, in _endpoint_for_partition
    raise NoRegionError()
botocore.exceptions.NoRegionError: You must specify a region.

If you change the level to DEBUG, you’ll get everything:

2019-08-18 08:28:06,189 DEBUG The script is starting.
2019-08-18 08:28:06,190 INFO Connecting to EC2...
2019-08-18 08:28:06,190 DEBUG Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
2019-08-18 08:28:06,193 DEBUG Changing event name from before-call.apigateway to before-call.api-gateway
2019-08-18 08:28:06,193 DEBUG Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
2019-08-18 08:28:06,194 DEBUG Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
2019-08-18 08:28:06,195 DEBUG Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
2019-08-18 08:28:06,195 DEBUG Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
2019-08-18 08:28:06,195 DEBUG Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
2019-08-18 08:28:06,197 DEBUG Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
2019-08-18 08:28:06,197 DEBUG Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
2019-08-18 08:28:06,197 DEBUG Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
2019-08-18 08:28:06,197 DEBUG Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
2019-08-18 08:28:06,211 DEBUG Looking for credentials via: env
2019-08-18 08:28:06,211 DEBUG Looking for credentials via: assume-role
2019-08-18 08:28:06,211 DEBUG Looking for credentials via: shared-credentials-file
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: custom-process
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: config-file
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: ec2-credentials-file
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: boto-config
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: container-role
2019-08-18 08:28:06,212 DEBUG Looking for credentials via: iam-role
2019-08-18 08:28:06,213 DEBUG Converted retries value: False -> Retry(total=False, connect=None, read=None, redirect=0, status=None)
2019-08-18 08:28:06,213 DEBUG Starting new HTTP connection (1): 169.254.169.254:80
2019-08-18 08:28:07,215 DEBUG Caught retryable HTTP exception while making metadata service request to http://169.254.169.254/latest/meta-data/iam/security-credentials/: Connect timeout on endpoint URL: "http://169.254.169.254/latest/meta-data/iam/security-credentials/"
Traceback (most recent call last):
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connection.py", line 159, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/util/connection.py", line 80, in create_connection
    raise err
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/util/connection.py", line 70, in create_connection
    sock.connect(sa)
socket.timeout: timed out
 
During handling of the above exception, another exception occurred:
 
Traceback (most recent call last):
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/httpsession.py", line 258, in send
    decode_content=False,
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connectionpool.py", line 638, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/util/retry.py", line 343, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connectionpool.py", line 600, in urlopen
    chunked=chunked)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connectionpool.py", line 354, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/Users/adam/.pyenv/versions/3.7.2/lib/python3.7/http/client.py", line 1229, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/awsrequest.py", line 125, in _send_request
    method, url, body, headers, *args, **kwargs)
  File "/Users/adam/.pyenv/versions/3.7.2/lib/python3.7/http/client.py", line 1275, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/Users/adam/.pyenv/versions/3.7.2/lib/python3.7/http/client.py", line 1224, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/awsrequest.py", line 152, in _send_output
    self.send(msg)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/awsrequest.py", line 236, in send
    return super(AWSConnection, self).send(str)
  File "/Users/adam/.pyenv/versions/3.7.2/lib/python3.7/http/client.py", line 956, in send
    self.connect()
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connection.py", line 181, in connect
    conn = self._new_conn()
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/urllib3/connection.py", line 164, in _new_conn
    (self.host, self.timeout))
urllib3.exceptions.ConnectTimeoutError: (<botocore.awsrequest.AWSHTTPConnection object at 0x1045a1f98>, 'Connection to 169.254.169.254 timed out. (connect timeout=1)')
 
During handling of the above exception, another exception occurred:
 
Traceback (most recent call last):
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/utils.py", line 303, in _get_request
    response = self._session.send(request.prepare())
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/httpsession.py", line 282, in send
    raise ConnectTimeoutError(endpoint_url=request.url, error=e)
botocore.exceptions.ConnectTimeoutError: Connect timeout on endpoint URL: "http://169.254.169.254/latest/meta-data/iam/security-credentials/"
2019-08-18 08:28:07,219 DEBUG Max number of attempts exceeded (1) when attempting to retrieve data from metadata service.
2019-08-18 08:28:07,219 DEBUG Loading JSON file: /Users/adam/opt/env3/lib/python3.7/site-packages/botocore/data/endpoints.json
2019-08-18 08:28:07,224 DEBUG Event choose-service-name: calling handler <function handle_service_name_alias at 0x1044b29d8>
2019-08-18 08:28:07,235 DEBUG Loading JSON file: /Users/adam/opt/env3/lib/python3.7/site-packages/botocore/data/ec2/2016-11-15/service-2.json
2019-08-18 08:28:07,258 DEBUG Event creating-client-class.ec2: calling handler <function add_generate_presigned_url at 0x104474510>
Traceback (most recent call last):
  File "demo.py", line 12, in <module>
    ec2 = boto3.client('ec2')
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/boto3/__init__.py", line 91, in client
    return _get_default_session().client(*args, **kwargs)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/boto3/session.py", line 263, in client
    aws_session_token=aws_session_token, config=config)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/session.py", line 838, in create_client
    client_config=config, api_version=api_version)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 86, in create_client
    verify, credentials, scoped_config, client_config, endpoint_bridge)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 328, in _get_client_args
    verify, credentials, scoped_config, client_config, endpoint_bridge)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/args.py", line 47, in get_client_args
    endpoint_url, is_secure, scoped_config)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/args.py", line 117, in compute_client_args
    service_name, region_name, endpoint_url, is_secure)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/client.py", line 402, in resolve
    service_name, region_name)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/regions.py", line 122, in construct_endpoint
    partition, service_name, region_name)
  File "/Users/adam/opt/env3/lib/python3.7/site-packages/botocore/regions.py", line 135, in _endpoint_for_partition
    raise NoRegionError()
botocore.exceptions.NoRegionError: You must specify a region.

See how it started saying where it found AWS credentials? Imagine you’re trying to figure out why your script worked locally but didn’t work on an EC2 instance; knowing where it found keys is huge. Maybe there are some hardcoded ones you didn’t know about that it’s picking up instead of the IAM role you attached to the instance. In DEBUG mode that’s easy to figure out. With print you’d have to hack out these details yourself.

This is great for simple scripts, but for something you’re going to run in production I recommend this pattern.

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: boto3 CloudWatch Logs

Good morning!

If you’re writing a regular script (i.e. not a lambda function), check out this article.

This pattern outputs traditional delimited strings. If you want to upgrade that into output structured as JSON objects, check out this article.

For those custom cases that don’t fit into Terraform or CloudFormation, a little bit of Python and some boto3 in a lambda function can save you. Lambda captures the output of both print() and logging.Logger calls into CloudWatch so it’s easy to log information about what your code is doing. When things go wrong, though, I often find that just the output I wrote doesn’t give me enough to diagnose the problem. In those cases, it’s helpful to see the log output both for your code and boto3. Here’s how you do that.

Use the logging library. It’s a Python core library that provides standard features like timestamped prefixes and support for levels (e.g. INFO or DEBUG). For simple deployment helpers this is usually all you need:

logger = logging.getLogger(logging.INFO)
logger.info('Message at the INFO level.')
logger.debug('Message at the DEBUG level.')

This sets the root logger (which sees all log messages) to the INFO level. Normally you’d have to configure the root logger, but lambda does that automatically (which is actually annoying if you need to change your formatter, but that’s for another post). Now, logger.info() calls will show up in the logs and logger.debug() calls won’t. If you increase the level to DEBUG you’ll see both.

Because logging is the standard Python way to handle log output, maintainers of libraries like boto3 use it throughout their code to show what the library is doing (and they’re usually smart about choosing what to log at each level). By setting a level on the root logger, you’re choosing which of your output to capture and which of boto3’s output to capture. Powerful when you’re diagnosing a failure.

Here’s a demo function to show how the output looks. You might notice that it puts the logger setup calls inside the handler even though the AWS docs tell you to put them under the import. Function calls made directly in modules (e.g. not inside functions declared within the module) are import-side effects and import side-effects are an anti-pattern. I put the calls in the handler so they only run when the handler is called. This isn’t likely to matter much in a lambda function, but I like to stick to good patterns.

import logging
 
import boto3
 
def lambda_handler(event, context):
    logger = logging.getLogger()
    logger.setLevel(logging.INFO)
 
    client = boto3.client('sts')
    account_id = client.get_caller_identity()['Account']
 
    logger.info('Getting account ID...')
    logger.debug('Account ID: {}'.format(account_id))
    return account_id

This is the full output when run at the INFO level:

START RequestId: a61471fe-c3fd-11e8-9f43-bdb22e22a203 Version: $LATEST
[INFO]  2018-09-29T15:38:01.882Z    a61471fe-c3fd-11e8-9f43-bdb22e22a203    Found credentials in environment variables.
[INFO]  2018-09-29T15:38:02.83Z a61471fe-c3fd-11e8-9f43-bdb22e22a203    Starting new HTTPS connection (1): sts.amazonaws.com
[INFO]  2018-09-29T15:38:02.531Z    a61471fe-c3fd-11e8-9f43-bdb22e22a203    Getting account ID...
END RequestId: a61471fe-c3fd-11e8-9f43-bdb22e22a203
REPORT RequestId: a61471fe-c3fd-11e8-9f43-bdb22e22a203  Duration: 734.96 ms Billed Duration: 800 ms Memory Size: 128 MB Max Memory Used: 29 MB

When run at the DEBUG level it produces a ton of lines:

START RequestId: 9ea3bbef-c3fe-11e8-8eb1-730a799b5405 Version: $LATEST
[DEBUG] 2018-09-29T15:44:58.850Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.880Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable config_file from defaults.
[DEBUG] 2018-09-29T15:44:58.881Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable credentials_file from defaults.
[DEBUG] 2018-09-29T15:44:58.881Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable data_path from defaults.
[DEBUG] 2018-09-29T15:44:58.881Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable region from environment with value 'us-west-2'.
[DEBUG] 2018-09-29T15:44:58.900Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.900Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable ca_bundle from defaults.
[DEBUG] 2018-09-29T15:44:58.900Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.900Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable api_versions from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable credentials_file from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable config_file from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable metadata_service_timeout from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.901Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable metadata_service_num_attempts from defaults.
[DEBUG] 2018-09-29T15:44:58.942Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:58.960Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Looking for credentials via: env
[INFO]  2018-09-29T15:44:58.960Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Found credentials in environment variables.
[DEBUG] 2018-09-29T15:44:58.961Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading JSON file: /var/runtime/botocore/data/endpoints.json
[DEBUG] 2018-09-29T15:44:59.1Z  9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading variable profile from defaults.
[DEBUG] 2018-09-29T15:44:59.20Z 9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event choose-service-name: calling handler
[DEBUG] 2018-09-29T15:44:59.60Z 9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading JSON file: /var/runtime/botocore/data/sts/2011-06-15/service-2.json
[DEBUG] 2018-09-29T15:44:59.82Z 9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event creating-client-class.sts: calling handler
[DEBUG] 2018-09-29T15:44:59.100Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    The s3 config key is not a dictionary type, ignoring its value of: None
[DEBUG] 2018-09-29T15:44:59.103Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Setting sts timeout as (60, 60)
[DEBUG] 2018-09-29T15:44:59.141Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Loading JSON file: /var/runtime/botocore/data/_retry.json
[DEBUG] 2018-09-29T15:44:59.141Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Registering retry handlers for service: sts
[DEBUG] 2018-09-29T15:44:59.160Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event before-parameter-build.sts.GetCallerIdentity: calling handler
[DEBUG] 2018-09-29T15:44:59.161Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Making request for OperationModel(name=GetCallerIdentity) (verify_ssl=True) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8', 'User-Agent': 'Boto3/1.7.74 Python/3.6.1 Linux/4.14.62-65.117.amzn1.x86_64 exec-env/AWS_Lambda_python3.6 Botocore/1.10.74'}, 'body': {'Action': 'GetCallerIdentity', 'Version': '2011-06-15'}, 'url': 'https://sts.amazonaws.com/', 'context': {'client_region': 'us-west-2', 'client_config': , 'has_streaming_input': False, 'auth_type': None}}
[DEBUG] 2018-09-29T15:44:59.161Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event request-created.sts.GetCallerIdentity: calling handler
[DEBUG] 2018-09-29T15:44:59.161Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event choose-signer.sts.GetCallerIdentity: calling handler
[DEBUG] 2018-09-29T15:44:59.162Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Calculating signature using v4 auth.
[DEBUG] 2018-09-29T15:44:59.180Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    CanonicalRequest:
POST
/
 
content-type:application/x-www-form-urlencoded; charset=utf-8
host:sts.amazonaws.com
x-amz-date:20180929T154459Z
x-amz-security-token:FQoGZXIvYXdzEKn//////////wEaDOOlIItIhtRakeAyfCLrAWPZXQJFkNrDZNa4Bny102eGKJ5KWD0F+ixFqZaW+A9mgadICpLRxBG4JGUzMtPTDeqxPoLT1qnS6bI/jVmXXUxjVPPMRiXdIlP+li0eFyB/xOK+PN/DOiByee0eu6bjQmkjoC3P5MREvxeanPY7hpgXNO52jSBPo8LMIdAcjCJxyRF7GHZjtZGAMARQWng6DJa9RAiIbxOmXpSbNGpABBVg/TUt8XMUT+p9Lm2Txi10P0ueu1n5rcuxJdBV8Jr/PUF3nZY+/k7MzOPCnzZNqVgpDAQbwby+AVIQcvVwaKsXePqubCqBTHxoh/Mo0ay+3QU=
 
content-type;host;x-amz-date;x-amz-security-token
ab821ae955788b0e33ebd34c208442ccfc2d406e2edc5e7a39bd6458fbb4f843
[DEBUG] 2018-09-29T15:44:59.181Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    StringToSign:
AWS4-HMAC-SHA256
20180929T154459Z
20180929/us-east-1/sts/aws4_request
7cf0af0e8f55fb1b9c0009104aa8f141097f00fea428ddf1654321e7054a920d
[DEBUG] 2018-09-29T15:44:59.181Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Signature:
c00de0a12c9ee0fce348df452f2833749b854915db58f8d106e3166545a70c43
[DEBUG] 2018-09-29T15:44:59.183Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Sending http request:
[INFO]  2018-09-29T15:44:59.201Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Starting new HTTPS connection (1): sts.amazonaws.com
[DEBUG] 2018-09-29T15:44:59.628Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    "POST / HTTP/1.1" 200 461
[DEBUG] 2018-09-29T15:44:59.628Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Response headers: {'x-amzn-requestid': '9f421e56-c3fe-11e8-b622-2d5da14a8dc9', 'content-type': 'text/xml', 'content-length': '461', 'date': 'Sat, 29 Sep 2018 15:44:58 GMT'}
[DEBUG] 2018-09-29T15:44:59.640Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Response body:
b'\n \n arn:aws:sts::268133297303:assumed-role/demo-boto3-logging/demo-boto3-logging\n AROAITTVSA67NGZPH2QZI:demo-boto3-logging\n 268133297303\n \n \n 9f421e56-c3fe-11e8-b622-2d5da14a8dc9\n \n\n'
[DEBUG] 2018-09-29T15:44:59.640Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Event needs-retry.sts.GetCallerIdentity: calling handler
[DEBUG] 2018-09-29T15:44:59.641Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    No retry needed.
[INFO]  2018-09-29T15:44:59.641Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Getting account ID...
[DEBUG] 2018-09-29T15:44:59.641Z    9ea3bbef-c3fe-11e8-8eb1-730a799b5405    Account ID: 268133297303
END RequestId: 9ea3bbef-c3fe-11e8-8eb1-730a799b5405
REPORT RequestId: 9ea3bbef-c3fe-11e8-8eb1-730a799b5405  Duration: 813.73 ms Billed Duration: 900 ms Memory Size: 128 MB Max Memory Used: 29 MB

boto3 can be very verbose in DEBUG so I recommend staying at INFO unless you’re actively troubleshooting.

Happy debugging!

Adam

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

You might also want to check out these related articles: