There are roughly three levels of logging to talk about today.
- Arbitrary strings
- Structured data
- Observability
I'm using logging as a loose term here. There is plenty of fighting on the internet about these words if you wish to go find it.
Arbitrary Strings
What we've been doing so far is what I'll refer to as "arbitrary strings". Basically it is logging out arbitrary strings at arbitrary times with no additional context. For example, the string "coldstart" when our function is booting up, or "handler" when our handler function is running.
These strings show us only what we've explicitly written out in the println or dbg macro. When debugging a problem with our function in production we will have had to already set up logging for the information we need to debug, before the problem happens.
It's... ok to do this and it's better than nothing. Also given that Netlify collects the logs from our functions for us and gives us a bit of a search bar it's ok for surfacing some information.
But Netlify already tells us when a cold start happened, and what the handler runtime of our function is. So both of these logs are kinda redundant and they don't give us any insight into what's happening inside of our function. For example, we don't get any information about our SQL query execution.
Remove the "cold start" and "handler" dbg logs.
Structured data
We can move from printing strings to printing structured information by using the tracing crate and specifically tracing_subscriber.
cargo add -p pokemon-api tracing tracing_subscriber
tracing_subscriber contains a few ways of printing structured logs to the console. These include single and multi-line human-readable output as well as JSON output.
To initialize the default output format, which is single-line logs for each event that occurs, we can call tracing_subscribe::fmt::init() to
async fn main() -> Result<(), Error> {
tracing_subscriber::fmt::init();
...
}
To see the output in the Netlify Functions logs, we need to set an environment variable in our deploy settings.
RUST_LOG=info
After adding the tracing subscriber fmt and without instrumenting anything, we can deploy the application and start getting information from sqlx immediately, including the rows returned and a quite large formatted sql printout of the query in question.
3:43:03 AM: Oct 28 10:43:03.774 INFO sqlx::query: SELECT name, hp FROM …; rows: 1, elapsed: 69.080ms
3:43:03 AM: SELECT
3:43:03 AM: name,
3:43:03 AM: hp
3:43:03 AM: FROM
3:43:03 AM: pokemon
3:43:03 AM: WHERE
3:43:03 AM: slug = ?
3:43:03 AM: e7fb532f Duration: 136.87 ms Memory Usage: 22 MB
We're mostly going to ignore the formatted sql for now, as while it's a bit verbose and such, sqlx has an issue open to redo their logging practices.
It's interesting to note though, that the tokio tracing implementation does pick up logs from other libraries. This makes it suitable for use both libraries and binaries.
The smallest next step we can take is to use the tracing::instrument macro on our handler function.
#[instrument]
async fn handler(
event: ApiGatewayProxyRequest,
_: Context,
) -> Result<ApiGatewayProxyResponse, Error> {
...
}
We'll need to bring tracing::instrument into scope as well.
use tracing::instrument;
After we instrument the handler function, we immediately gain additional context. All of the headers and other values from the request are included as structured data when logging out the SQL string.
11:35:19 PM: Oct 31 06:35:19.485 INFO handler{event=ApiGatewayProxyRequest { resource: None, path: Some("/.netlify/functions/pokemon-api/bulbasaur"), http_method: GET, headers: {"accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "accept-encoding": "br, gzip", "accept-language": "en-US,en;q=0.9", "cache-control": "max-age=0", "client-ip": "100.64.0.166", "forwarded": "for=67.180.63.210;proto=https", "host": "pokemon-rust.netlify.app", "sec-ch-ua": "\"Chromium\";v=\"94\", \"Google Chrome\";v=\"94\", \";Not A Brand\";v=\"99\"", "sec-ch-ua-mobile": "?0", "sec-ch-ua-platform": "\"macOS\"", "sec-fetch-dest": "document", "sec-fetch-mode": "navigate", "sec-fetch-site": "none", "sec-fetch-user": "?1", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36", "via": "http/1.1 Netlify[1ccb7b5b-cd68-42fd-bf65-2d312a7451bb] (Netlify Edge Server)", "x-bb-ab": "0.182537", "x-bb-client-request-uuid": "01FKAGYGCAHTVK0XM7TYPX27NB", "x-bb-ip": "67.180.63.210", "x-bb-loop": "1", "x-country": "US", "x-datadog-parent-id": "13288669469948633701", "x-datadog-sampling-priority": "1", "x-datadog-trace-id": "11392709661693501674", "x-forwarded-for": "67.180.63.210, 100.64.0.166", "x-forwarded-proto": "https", "x-language": "en,en;q=0.9", "x-nf-client-connection-ip": "67.180.63.210", "x-nf-connection-proto": "https", "x-nf-forwarded-proto": "https", "x-nf-request-id": "01FKAGYGCAHTVK0XM7TYPX27NB"}, multi_value_headers: {"accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", "accept-encoding": "br, gzip", "accept-language": "en-US,en;q=0.9", "cache-control": "max-age=0", "client-ip": "100.64.0.166", "forwarded": "for=67.180.63.210;proto=https", "sec-ch-ua": "\"Chromium\";v=\"94\", \"Google Chrome\";v=\"94\", \";Not A Brand\";v=\"99\"", "sec-ch-ua-mobile": "?0", "sec-ch-ua-platform": "\"macOS\"", "sec-fetch-dest": "document", "sec-fetch-mode": "navigate", "sec-fetch-site": "none", "sec-fetch-user": "?1", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36", "via": "http/1.1 Netlify[1ccb7b5b-cd68-42fd-bf65-2d312a7451bb] (Netlify Edge Server)", "x-bb-ab": "0.182537", "x-bb-client-request-uuid": "01FKAGYGCAHTVK0XM7TYPX27NB", "x-bb-ip": "67.180.63.210", "x-bb-loop": "1", "x-country": "US", "x-datadog-parent-id": "13288669469948633701", "x-datadog-sampling-priority": "1", "x-datadog-trace-id": "11392709661693501674", "x-forwarded-for": "67.180.63.210, 100.64.0.166", "x-forwarded-proto": "https", "x-language": "en,en;q=0.9", "x-nf-client-connection-ip": "67.180.63.210", "x-nf-connection-proto": "https", "x-nf-forwarded-proto": "https", "x-nf-request-id": "01FKAGYGCAHTVK0XM7TYPX27NB", "host": "pokemon-rust.netlify.app"}, query_string_parameters: {}, multi_value_query_string_parameters: {}, path_parameters: {}, stage_variables: {}, request_context: ApiGatewayProxyRequestContext { account_id: None, resource_id: None, operation_name: None, stage: None, domain_name: None, domain_prefix: None, request_id: None, protocol: None, identity: ApiGatewayRequestIdentity { cognito_identity_pool_id: None, account_id: None, cognito_identity_id: None, caller: None, api_key: None, api_key_id: None, access_key: None, source_ip: None, cognito_authentication_type: None, cognito_authentication_provider: None, user_arn: None, user_agent: None, user: None }, resource_path: None, authorizer: {}, http_method: GET, request_time: None, request_time_epoch: 0, apiid: None }, body: None, is_base64_encoded: Some(false) }}: sqlx::query: SELECT name, hp FROM …; rows: 1, elapsed: 71.286ms
11:35:19 PM: SELECT
11:35:19 PM: name,
11:35:19 PM: hp
11:35:19 PM: FROM
11:35:19 PM: pokemon
11:35:19 PM: WHERE
11:35:19 PM: slug = ?
11:35:19 PM: 0161726d Duration: 141.55 ms Memory Usage: 22 MB
The data is output in what's called "human readable" format, which looks similar to what Rust structs also looks like, but we could output this information as JSON too.
The output we're seeing here is usually referred to as "events", and it is what will lead us into more advanced techniques for debugging our production workloads. You may be familiar with the name for the technique we're on the road to: Observability.
For now, we'll focus on building up more events.
More Events
tracing offers the event! macro to record new events. It looks something like this
event!(Level::INFO, "something happened");
The event macro requires a Level and anything we want to log out. We'll be using specialized versions of the event macro that already include the logging level we want to use: error and info.
Bring error and info into scope.
use tracing::{error, info, instrument};
We'll use error in our 400 response handler, only passing in a string to log out.
match requested_pokemon {
Some("") => {
error!("searched for empty pokemon");
let error_message = serde_json::to_string(&json!({
"error": "searched for empty pokemon"
}))?;
...
}
and we'll use info in the branch that handles the pokemon request. To add additional structured data to our info event we can pass in the pokemon_name variable, which will result in a key name of pokemon_name and a value of the string inside the pokemon_name variable.
Some(pokemon_name) => {
info!(pokemon_name,"requested a pokemon");
...
}
The error macro will add the ERROR level to the log as well as the message we passed in.
ERROR handler{...}: pokemon_api: searched for empty pokemon
The info macro will add the INFO level to the log, as well as the pokemon_name and the message we passed in.
INFO handler{...}: pokemon_api: requested a pokemon pokemon_name="charmander"
Setting up either the fancier human output format or the json output format will require a bit of extra work. This I leave up to you. The instructions for getting this done can be found in the [tracing_subscriber docs, on the fmt page](https://docs.rs/tracing-subscriber/0.3.1/tracing_subscriber/fmt/index.html).
You will want to replace the tracing_subscriber::fmt::init() quickstart with an EnvFilter and a FmtSubscriber.