At some point you’ll need to debug a function in production.
There are many ways to do this, including writing a couple of dbg! or println! macros but there are important drawbacks to logging out arbitrary strings at arbitrary locations.
The biggest of which is that as traffic goes up, multi-line strings of arbitrary data become harder and harder to comb through to figure out what’s wrong.
Ideally we want something structured that gives us context to what we’re logging out.
The Rust ecosystem’s standard for this is the tracing crate.
We’ll need two crates: tracing and tracing_subscriber.
❯ cargo add tracing tracing-subscriber -F tracing-subscriber/fmt
Updating crates.io index
Adding tracing v0.1.37 to dependencies.
Features:
+ attributes
+ std
+ tracing-attributes
- async-await
- log
- log-always
- max_level_debug
- max_level_error
- max_level_info
- max_level_off
- max_level_trace
- max_level_warn
- release_max_level_debug
- release_max_level_error
- release_max_level_info
- release_max_level_off
- release_max_level_trace
- release_max_level_warn
- valuable
Adding tracing-subscriber v0.3.17 to dependencies.
Features:
+ alloc
+ ansi
+ fmt
+ nu-ansi-term
+ registry
+ sharded-slab
+ smallvec
+ std
+ thread_local
+ tracing-log
- env-filter
- json
- local-time
- matchers
- once_cell
- parking_lot
- regex
- serde
- serde_json
- time
- tracing
- tracing-serde
- valuable
- valuable-serde
- valuable_crate
tracing allows us to produce trace data while tracing-subscriber is an implementation of collecting that data.
There are two major concepts related to the tracing crate: spans and events.
A Span represents a period of time with a beginning and an end, such as the duration of a function’s execution.
A span could collect the arguments to a function as well as the value it returns.
Events are a specific point in time and are analogous to “just logging something out” with println.
So while a function is a unit of work and would be wrapped in a span to track when we call and exit, an event would be something that happened inside of that function.
Setting up tracing-subscriber
We’ll start by using the default collector from tracing-subscriber. This will collect our trace data and output it to the terminal.
#[tokio::main]
async fn main() -> Result<(), Error> {
tracing_subscriber::fmt::init();
run(service_fn(function_handler)).await
}
Then let’s instrument our application.
The tracing crate provides an attribute macro named instrument that handles setting up a span around any given function.
This span automatically handles collecting the arguments to this function as part of the span.
#[instrument]
async fn function_handler(
...
Then below our who and message variables, we can use tracing's macros to pick a log level (info is a good default choice) and track an event.
let who = event
.query_string_parameters_ref()
.and_then(|params| params.first("name"))
.unwrap_or("world");
let message = format!(
"Hello {who}, this is an Netlify serverless request"
);
info!(who, message);
The event will retain who as a structured piece of data, and use our message as an arbitrary string that logs out alongside it.
Each event will log out with the context in which it was logged. In this case, we’re in the function_handler span, so we get our event with who and our message contextualized with the arguments to the function, which is the Request in this case.
2023-08-06T22:01:52.192672Z INFO Lambda runtime invoke {
requestId="4dedea1c-0e10-44bb-b645-7037318f96b4"
xrayTraceId="Root=1-64d0184f-3434c877b2f2e12632b9245e;Parent=9b0744bd4f4e4a8e;Sampled=1"
}:function_handler {
event=Request {
method: POST,
uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/hello/world?name=chris,
version: HTTP/1.1,
headers: {
"accept": "*/*",
"accept-encoding": "gzip, deflate",
"cache-control": "no-cache",
"cloudfront-forwarded-proto": "https",
"cloudfront-is-desktop-viewer": "true",
"cloudfront-is-mobile-viewer": "false",
"cloudfront-is-smarttv-viewer": "false",
"cloudfront-is-tablet-viewer": "false",
"cloudfront-viewer-country": "US",
"content-type": "application/json",
"headername": "headerValue",
"host": "gy415nuibc.execute-api.us-east-1.amazonaws.com",
"postman-token": "9f583ef0-ed83-4a38-aef3-eb9ce3f7a57f",
"user-agent": "PostmanRuntime/2.4.5",
"via": "1.1 d98420743a69852491bbdea73f7680bd.cloudfront.net (CloudFront)",
"x-amz-cf-id": "pn-PWIJc6thYnZm5P0NMgOUglL1DYtl0gdeJky8tqsg8iS_sgsKD1A==",
"x-forwarded-for": "54.240.196.186, 54.182.214.83",
"x-forwarded-port": "443",
"x-forwarded-proto": "https",
"x-amzn-trace-id": "Root=1-64d0184f-3434c877b2f2e12632b9245e;Parent=9b0744bd4f4e4a8e;Sampled=1"
},
body: Text("{\r\n\t\"a\": 1\r\n}")
}
}: serverless_intro_netlify: who="chris" Hello chris, this is an Netlify serverless request
The default formatter is meant to be human-readable, single-line logs for each event.
There are other formats for output as well, such as pretty, which can output multiple lines per event.
tracing_subscriber::fmt().pretty().init();
2023-08-06T22:12:25.569856Z INFO serverless_intro_netlify: who: "chris", Hello chris, this is an Netlify serverless request
at src/main.rs:25
in serverless_intro_netlify::function_handler with event: Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/hello/world?name=chris, version: HTTP/1.1, headers: {"accept": "*/*", "accept-encoding": "gzip, deflate", "cache-control": "no-cache", "cloudfront-forwarded-proto": "https", "cloudfront-is-desktop-viewer": "true", "cloudfront-is-mobile-viewer": "false", "cloudfront-is-smarttv-viewer": "false", "cloudfront-is-tablet-viewer": "false", "cloudfront-viewer-country": "US", "content-type": "application/json", "headername": "headerValue", "host": "gy415nuibc.execute-api.us-east-1.amazonaws.com", "postman-token": "9f583ef0-ed83-4a38-aef3-eb9ce3f7a57f", "user-agent": "PostmanRuntime/2.4.5", "via": "1.1 d98420743a69852491bbdea73f7680bd.cloudfront.net (CloudFront)", "x-amz-cf-id": "pn-PWIJc6thYnZm5P0NMgOUglL1DYtl0gdeJky8tqsg8iS_sgsKD1A==", "x-forwarded-for": "54.240.196.186, 54.182.214.83", "x-forwarded-port": "443", "x-forwarded-proto": "https", "x-amzn-trace-id": "Root=1-64d01ac8-56bd15367cba1ed2a9560927;Parent=508a0ed40efa1827;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }
in lambda_runtime::Lambda runtime invoke with requestId: "3f7a352c-04e0-4cd4-b20c-578a9f6ed9f9", xrayTraceId: "Root=1-64d01ac8-56bd15367cba1ed2a9560927;Parent=508a0ed40efa1827;Sampled=1"
or compact, which tries to optimize for shorter line lengths (which are still going to be quite long).
tracing_subscriber::fmt().compact().init();
2023-08-06T22:13:31.278399Z INFO Lambda runtime invoke:function_handler: serverless_intro_netlify: who="chris" Hello chris, this is an Netlify serverless request requestId="f5435133-4ca9-4370-8850-b1435d2db482" xrayTraceId="Root=1-64d01b0a-3293ad166e1b5dfd090c0aa2;Parent=0c61e69613a27e04;Sampled=1" event=Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/hello/world?name=chris, version: HTTP/1.1, headers: {"accept": "*/*", "accept-encoding": "gzip, deflate", "cache-control": "no-cache", "cloudfront-forwarded-proto": "https", "cloudfront-is-desktop-viewer": "true", "cloudfront-is-mobile-viewer": "false", "cloudfront-is-smarttv-viewer": "false", "cloudfront-is-tablet-viewer": "false", "cloudfront-viewer-country": "US", "content-type": "application/json", "headername": "headerValue", "host": "gy415nuibc.execute-api.us-east-1.amazonaws.com", "postman-token": "9f583ef0-ed83-4a38-aef3-eb9ce3f7a57f", "user-agent": "PostmanRuntime/2.4.5", "via": "1.1 d98420743a69852491bbdea73f7680bd.cloudfront.net (CloudFront)", "x-amz-cf-id": "pn-PWIJc6thYnZm5P0NMgOUglL1DYtl0gdeJky8tqsg8iS_sgsKD1A==", "x-forwarded-for": "54.240.196.186, 54.182.214.83", "x-forwarded-port": "443", "x-forwarded-proto": "https", "x-amzn-trace-id": "Root=1-64d01b0a-3293ad166e1b5dfd090c0aa2;Parent=0c61e69613a27e04;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }
Or in production, when you’re using services to collect and analyze your logs, you can turn the json feature on and use the json formatter.
# Cargo.toml
tracing-subscriber = { version = "0.3.17", features = ["fmt", "json"] }
// src/main.rs
tracing_subscriber::fmt().json().init();
The JSON formatter displays on a single line, but I’ve formatter it for easier reading here.
{
"timestamp": "2023-08-06T22:17:44.816215Z",
"level": "INFO",
"fields": {
"who": "chris",
"message": "Hello chris, this is an Netlify serverless request"
},
"target": "serverless_intro_netlify",
"span": {
"event": "Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/hello/world?name=chris, version: HTTP/1.1, headers: {\"accept\": \"*/*\", \"accept-encoding\": \"gzip, deflate\", \"cache-control\": \"no-cache\", \"cloudfront-forwarded-proto\": \"https\", \"cloudfront-is-desktop-viewer\": \"true\", \"cloudfront-is-mobile-viewer\": \"false\", \"cloudfront-is-smarttv-viewer\": \"false\", \"cloudfront-is-tablet-viewer\": \"false\", \"cloudfront-viewer-country\": \"US\", \"content-type\": \"application/json\", \"headername\": \"headerValue\", \"host\": \"gy415nuibc.execute-api.us-east-1.amazonaws.com\", \"postman-token\": \"9f583ef0-ed83-4a38-aef3-eb9ce3f7a57f\", \"user-agent\": \"PostmanRuntime/2.4.5\", \"via\": \"1.1 d98420743a69852491bbdea73f7680bd.cloudfront.net (CloudFront)\", \"x-amz-cf-id\": \"pn-PWIJc6thYnZm5P0NMgOUglL1DYtl0gdeJky8tqsg8iS_sgsKD1A==\", \"x-forwarded-for\": \"54.240.196.186, 54.182.214.83\", \"x-forwarded-port\": \"443\", \"x-forwarded-proto\": \"https\", \"x-amzn-trace-id\": \"Root=1-64d01c06-676ef1f6c7aaa55c5a0aef8d;Parent=da6ccf4ab6cd6904;Sampled=1\"}, body: Text(\"{\\r\\n\\t\\\"a\\\": 1\\r\\n}\") }",
"name": "function_handler"
},
"spans": [
{
"requestId": "c53196f0-1796-484b-8ea2-a2c35501e230",
"xrayTraceId": "Root=1-64d01c06-676ef1f6c7aaa55c5a0aef8d;Parent=da6ccf4ab6cd6904;Sampled=1",
"name": "Lambda runtime invoke"
},
{
"event": "Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/hello/world?name=chris, version: HTTP/1.1, headers: {\"accept\": \"*/*\", \"accept-encoding\": \"gzip, deflate\", \"cache-control\": \"no-cache\", \"cloudfront-forwarded-proto\": \"https\", \"cloudfront-is-desktop-viewer\": \"true\", \"cloudfront-is-mobile-viewer\": \"false\", \"cloudfront-is-smarttv-viewer\": \"false\", \"cloudfront-is-tablet-viewer\": \"false\", \"cloudfront-viewer-country\": \"US\", \"content-type\": \"application/json\", \"headername\": \"headerValue\", \"host\": \"gy415nuibc.execute-api.us-east-1.amazonaws.com\", \"postman-token\": \"9f583ef0-ed83-4a38-aef3-eb9ce3f7a57f\", \"user-agent\": \"PostmanRuntime/2.4.5\", \"via\": \"1.1 d98420743a69852491bbdea73f7680bd.cloudfront.net (CloudFront)\", \"x-amz-cf-id\": \"pn-PWIJc6thYnZm5P0NMgOUglL1DYtl0gdeJky8tqsg8iS_sgsKD1A==\", \"x-forwarded-for\": \"54.240.196.186, 54.182.214.83\", \"x-forwarded-port\": \"443\", \"x-forwarded-proto\": \"https\", \"x-amzn-trace-id\": \"Root=1-64d01c06-676ef1f6c7aaa55c5a0aef8d;Parent=da6ccf4ab6cd6904;Sampled=1\"}, body: Text(\"{\\r\\n\\t\\\"a\\\": 1\\r\\n}\") }",
"name": "function_handler"
}
]
}
In Production
I’ve chosen to stay with the “human-readable” default formatter since I’m going to be reading Netlify logs on Netlify and not somewhere else.
If you build, copy, and deploy your function now, you’ll get a log line in-between the cold start and metrics for the function.
Aug 6, 03:35:21 PM: INIT_START Runtime Version: provided:al2.v20 Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:e448fca582d6ef7f5f1faf3cae4b2bb6521010ebae50e60019812234a4c0d549
Aug 6, 03:35:21 PM: 2023-08-06T22:35:21.667174Z INFO Lambda runtime invoke{requestId="f2d55f16-b5d3-4b1b-a33c-bdd6e96c56fc" xrayTraceId="Root=1-64d02029-5ed0d5dc3542f9b70f387bfb;Parent=23a936e436836a1a;Sampled=0;Lineage=883b3179:0"}:function_handler{event=Request { method: GET, uri: https://64d01fe2a3461a0e0d47e980--sprightly-hamster-f6f5dd.netlify.app/.netlify/functions/hello?name=chris, version: HTTP/1.1, headers: {"accept": "*/*,image/webp", "accept-encoding": "gzip", "cdn-loop": "netlify", "user-agent": "nushell", "x-country": "US", "x-forwarded-for": "98.51.111.23", "x-forwarded-proto": "https", "x-nf-account-id": "59026505cf321c7359e99660", "x-nf-client-connection-ip": "98.51.111.23", "x-nf-deploy-id": "64d01fe2a3461a0e0d47e980", "x-nf-request-id": "01H76FV8A6ATDJK73616ZDPD9H", "x-nf-site-id": "1153eee6-cb2d-441b-acfe-fe7b4f946c3a", "host": "64d01fe2a3461a0e0d47e980--sprightly-hamster-f6f5dd.netlify.app", "x-amzn-trace-id": "Root=1-64d02029-5ed0d5dc3542f9b70f387bfb;Parent=23a936e436836a1a;Sampled=0;Lineage=883b3179:0"}, body: Text("") }}: serverless_intro_netlify: who="chris" Hello chris, this is an Netlify serverless request
Aug 6, 03:35:21 PM: f2d55f16 Duration: 8.38 ms Memory Usage: 21 MB Init Duration: 53.48 ms
This trace will contain different information than we had locally, because locally we were using a fixture to simulate a request.
For example, I use nushell as my default shell, so the user agent when I sent my http request shows up in the request as nushell.
"user-agent": "nushell"