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: