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" using println!("coldstart") when our function is booting up, or "handler" using println!("handler") when our handler function is running.
These strings show us only what we've explicitly written out in the println or dbg macros. 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.
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_subscriber::fmt::init() at the top of our main function.
async fn main() -> Result<(), Error> {
tracing_subscriber::fmt::init();
...
}
The smallest next step we can take is to use the tracing::instrument macro on our function_handler function.
#[instrument]
async fn function_handler(
event: Request,
) -> Result<Response<Body>, Error> {
...
}
We'll need to bring tracing::instrument into scope as well.
use tracing::instrument;
We need one final piece before we can see any output. Let's output the requested_pokemon when we parse it from the URL.
let requested_pokemon = path.split("/").last();
info!(requested_pokemon, "requested a pokemon");
The info macro is a convenience macro. The tracing crate helps us record two types of data: spans and events.
Spans are handled for us by the tracing::instrument macro and represent a unit of work, such as one event being processed. These usually wrap functions but can be used for other blocks of work as well.
Events are usually supplied by us and represent some instantaneous value, like the pokemon a user requested. You can use the event macro to build an event with a log level of INFO like this, or you can use the info macro which does the same thing.
event!(Level::INFO, "something happened");
Viewing events
The subscriber we set up using tracing_subscriber::fmt::init allows us to specify log levels using an environment variable. There are a number of log levels, including trace, debug, info, warn, and error.
Most of the time in production, you'll want info, while debug can be useful for well, debugging if you need it.
After running cargo lambda watch with RUST_LOG=info, we see quite a few more logs than we might expect. That's because a lot of the Rust ecosystem uses tracing, or tracing-compatible, logging approaches. This includes the logs from cargo lambda itself!
❯ RUST_LOG=info DATABASE_URL=mysql://127.0.0.1:3306 cargo lambda watch
INFO invoke server listening on [::]:9000
INFO starting lambda function function="pokemon-api" manifest="Cargo.toml"
INFO action constructed action=Action { events: [Event { tags: [], metadata: {} }], outcome: OnceCell(Uninit) }
INFO outcome resolved outcome=Start
INFO spawning command command=Command { std: AWS_LAMBDA_FUNCTION_MEMORY_SIZE="4096" AWS_LAMBDA_FUNCTION_NAME="pokemon-api" AWS_LAMBDA_FUNCTION_VERSION="1" AWS_LAMBDA_RUNTIME_API="http://[::]:9000/.rt/pokemon-api" "cargo" "run" "--bin" "pokemon-api", kill_on_drop: false }
INFO process group spawned pgid=83019
Finished dev [unoptimized + debuginfo] target(s) in 0.27s
Running `target/debug/pokemon-api`
2023-09-24T06:17:32.371849Z INFO Lambda runtime invoke{requestId="cb9cd75e-3767-4e26-9e04-cc95b6852463" xrayTraceId="Root=1-650fd47a-45283be0af442c0f630ce0c5;Parent=a522bdc0ad022b0d;Sampled=1"}:function_handler{event=Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/bulbasaur?name=me, 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-650fd47a-45283be0af442c0f630ce0c5;Parent=a522bdc0ad022b0d;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }}: pokemon_api: requested a pokemon requested_pokemon="bulbasaur"
To only see the logs from pokemon_api, our crate, use RUST_LOG=pokemon_api=info. Note the underscore in pokemon_api.
❯ RUST_LOG=pokemon_api=info DATABASE_URL=mysql://127.0.0.1:3306 cargo lambda watch
Finished dev [unoptimized + debuginfo] target(s) in 0.08s
Running `target/debug/pokemon-api`
2023-09-24T06:28:27.622875Z INFO function_handler{event=Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/bulbasaur?name=me, 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-650fd70a-1de973ec62b1a2d8631f6668;Parent=6c0ba87d523dcfa5;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }}: pokemon_api: requested a pokemon requested_pokemon="bulbasaur"
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.
It includes the context from the spans surrounding the event, as well as the structured data from the event itself. In this case, the context is the whole Request and the event is our info!.
In our event we can see the string requested a pokemon and the structured data requested_pokemon=bulbasaur.
More Events
We'll use error in our 400 response handler, only passing in a string to log out.
Some("") => {
error!("searched for empty pokemon");
...
}
The error macro will add the ERROR level to the log as well as the message we passed in. Since we're filtering at the info level for logs from the pokemon_api target, we still see ERROR level events.
ERROR function_handler{...}: pokemon_api: searched for empty pokemon
We now have spans and events logging our from our own crate. What about the crates we're using like sqlx?
Enabling sqlx logs
sqlx includes tracing support for queries under the debug level. In products like PlanetScale there is often already database monitoring for slow queries and other aspects so this can make sense but really IMO they exist under debug because sqlx just switched over to using tracing in the most recent version. Let's enable the sqlx logs though.
RUST_LOG=pokemon_api=info,sqlx=debug
❯ RUST_LOG=pokemon_api=info,sqlx=debug DATABASE_URL=mysql://127.0.0.1:3306 cargo lambda watch
Finished dev [unoptimized + debuginfo] target(s) in 0.08s
Running `target/debug/pokemon-api`
2023-09-24T06:37:45.517734Z DEBUG sqlx_mysql::connection::tls: not performing TLS upgrade: unsupported by server
2023-09-24T06:37:45.778360Z DEBUG sqlx::query: summary="SET sql_mode=(SELECT CONCAT(@@sql_mode, ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION')),time_zone='+00:00',NAMES …" db.statement="\n\nSET\n sql_mode =(\n SELECT\n CONCAT(\n @ @sql_mode,\n ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION'\n )\n ),\n time_zone = '+00:00',\n NAMES utf8mb4 COLLATE utf8mb4_unicode_ci;\n" rows_affected=0 rows_returned=0 elapsed=89.595958ms
2023-09-24T06:37:45.792166Z INFO function_handler{event=Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/bulbasaur?name=me, 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-650fd939-3100b88069c32fc1a2368824;Parent=5c236803bbeba633;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }}: pokemon_api: requested a pokemon requested_pokemon="bulbasaur"
2023-09-24T06:37:46.028329Z DEBUG function_handler{event=Request { method: POST, uri: https://gy415nuibc.execute-api.us-east-1.amazonaws.com/testStage/bulbasaur?name=me, 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-650fd939-3100b88069c32fc1a2368824;Parent=5c236803bbeba633;Sampled=1"}, body: Text("{\r\n\t\"a\": 1\r\n}") }}: sqlx::query: summary="SELECT name, hp from …" db.statement="\n\nSELECT\n name,\n hp\nfrom\n pokemon\nwhere\n slug = ?\n" rows_affected=0 rows_returned=1 elapsed=160.079042ms
There are still some "extra" logs in here, so lets further refine sqlx to sqlx::query. You can see how we can start to specify exactly what we want, even though we'd often prefer to set the output to info and be done.
RUST_LOG=pokemon_api=info,sqlx::query=debug
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.17/tracing_subscriber/fmt/index.html).
Finally, lets get this show into production. Make sure you set RUST_LOG in your Netlify environment variables.
RUST_LOG=info,sqlx::query=debug
and re-deploy the function.
DATABASE_URL=mysql://127.0.0.1:3306 cargo lambda build -p pokemon-api
cp target/lambda/pokemon-api/bootstrap functions/pokemon-api
netlify deploy --prod
Sep 23, 11:51:56 PM: INIT_START Runtime Version: provided:al2.v22 Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:6c21009b8813291ce404aa6dd6aef448ced6660fa4965c4efec3a53801823417
Sep 23, 11:51:56 PM: 2023-09-24T06:51:56.786890Z DEBUG sqlx::query: summary="SET sql_mode=(SELECT CONCAT(@@sql_mode, ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION')),time_zone='+00:00',NAMES …" db.statement="\n\nSET\n sql_mode =(\n SELECT\n CONCAT(\n @ @sql_mode,\n ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION'\n )\n ),\n time_zone = '+00:00',\n NAMES utf8mb4 COLLATE utf8mb4_unicode_ci;\n" rows_affected=0 rows_returned=0 elapsed=9.183965ms
Sep 23, 11:51:56 PM: 2023-09-24T06:51:56.798610Z INFO Lambda runtime invoke{requestId="b0c68695-d6b6-4380-a576-b98b15c18b97" xrayTraceId="Root=1-650fdc8c-484365d34cc768045eaa17ae;Parent=50db587c5381a247;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/charizard, version: HTTP/1.1, headers: {"accept": "*/*,image/webp", "cdn-loop": "netlify", "user-agent": "curl/7.86.0", "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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZB0T7SBCJRB9A714VB63C", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdc8c-484365d34cc768045eaa17ae;Parent=50db587c5381a247;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: pokemon_api: requested a pokemon requested_pokemon="charizard"
Sep 23, 11:51:56 PM: 2023-09-24T06:51:56.809094Z DEBUG Lambda runtime invoke{requestId="b0c68695-d6b6-4380-a576-b98b15c18b97" xrayTraceId="Root=1-650fdc8c-484365d34cc768045eaa17ae;Parent=50db587c5381a247;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/charizard, version: HTTP/1.1, headers: {"accept": "*/*,image/webp", "cdn-loop": "netlify", "user-agent": "curl/7.86.0", "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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZB0T7SBCJRB9A714VB63C", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdc8c-484365d34cc768045eaa17ae;Parent=50db587c5381a247;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: sqlx::query: summary="SELECT name, hp from …" db.statement="\n\nSELECT\n name,\n hp\nfrom\n pokemon\nwhere\n slug = ?\n" rows_affected=0 rows_returned=1 elapsed=8.739644ms
Sep 23, 11:51:56 PM: b0c68695 Duration: 16.73 ms Memory Usage: 29 MB Init Duration: 165.81 ms
Sep 23, 11:52:08 PM: 2023-09-24T06:52:08.554559Z INFO Lambda runtime invoke{requestId="12872724-7511-43cf-aa80-8a4cd15616b6" xrayTraceId="Root=1-650fdc98-2ff416c928ac4cbf7991e31c;Parent=0d1deda814f2b75e;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/bulbasaur, 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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZBCVSE9BYTKT8HV11Z2Z8", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdc98-2ff416c928ac4cbf7991e31c;Parent=0d1deda814f2b75e;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: pokemon_api: requested a pokemon requested_pokemon="bulbasaur"
Sep 23, 11:52:08 PM: 2023-09-24T06:52:08.560439Z DEBUG Lambda runtime invoke{requestId="12872724-7511-43cf-aa80-8a4cd15616b6" xrayTraceId="Root=1-650fdc98-2ff416c928ac4cbf7991e31c;Parent=0d1deda814f2b75e;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/bulbasaur, 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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZBCVSE9BYTKT8HV11Z2Z8", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdc98-2ff416c928ac4cbf7991e31c;Parent=0d1deda814f2b75e;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: sqlx::query: summary="SELECT name, hp from …" db.statement="\n\nSELECT\n name,\n hp\nfrom\n pokemon\nwhere\n slug = ?\n" rows_affected=0 rows_returned=1 elapsed=4.206792ms
Sep 23, 11:52:08 PM: 12872724 Duration: 8.23 ms Memory Usage: 30 MB
Sep 23, 11:52:19 PM: 2023-09-24T06:52:19.698220Z INFO Lambda runtime invoke{requestId="fbf4a39b-6834-49f0-952b-c0b14247477c" xrayTraceId="Root=1-650fdca3-4a30efbf72d8a6ec097dcc41;Parent=0b9f48eb16875b90;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/charmander, 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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZBQQN7VA9YBNNSM5718MP", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdca3-4a30efbf72d8a6ec097dcc41;Parent=0b9f48eb16875b90;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: pokemon_api: requested a pokemon requested_pokemon="charmander"
Sep 23, 11:52:19 PM: 2023-09-24T06:52:19.704427Z DEBUG Lambda runtime invoke{requestId="fbf4a39b-6834-49f0-952b-c0b14247477c" xrayTraceId="Root=1-650fdca3-4a30efbf72d8a6ec097dcc41;Parent=0b9f48eb16875b90;Sampled=0;Lineage=7e82f2ac:0"}:function_handler{event=Request { method: GET, uri: https://<site-name>.netlify.app/api/pokemon/charmander, 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": "650fdc41a1f7c130f3b56dee", "x-nf-geo": "eyJjaXR5IjoiU2FuIEZyYW5jaXNjbyIsImNvdW50cnkiOnsiY29kZSI6IlVTIiwibmFtZSI6IlVuaXRlZCBTdGF0ZXMifSwic3ViZGl2aXNpb24iOnsiY29kZSI6IkNBIiwibmFtZSI6IkNhbGlmb3JuaWEifSwidGltZXpvbmUiOiJBbWVyaWNhL0xvc19BbmdlbGVzIiwibGF0aXR1ZGUiOjM3LjgwMjEsImxvbmdpdHVkZSI6LTEyMi40MzN9", "x-nf-request-id": "01HB2ZBQQN7VA9YBNNSM5718MP", "x-nf-site-id": "269df08c-d19f-4dcc-968b-2097a09df6ef", "host": "<site-name>.netlify.app", "x-amzn-trace-id": "Root=1-650fdca3-4a30efbf72d8a6ec097dcc41;Parent=0b9f48eb16875b90;Sampled=0;Lineage=7e82f2ac:0"}, body: Binary([]) }}: sqlx::query: summary="SELECT name, hp from …" db.statement="\n\nSELECT\n name,\n hp\nfrom\n pokemon\nwhere\n slug = ?\n" rows_affected=0 rows_returned=1 elapsed=4.461514ms
Sep 23, 11:52:19 PM: fbf4a39b Duration: 8.86 ms Memory Usage: 30 MB
The production logs are thick and have a lot of context, but now we can see how long each sqlx query took:
elapsed=8.739644ms
elapsed=4.206792ms
elapsed=4.461514ms
and which pokemon was requested.
requested a pokemon requested_pokemon="charizard"
requested a pokemon requested_pokemon="bulbasaur"
requested a pokemon requested_pokemon="charmander"
There's a lot you can do and learn when it comes to tracing but that's where we'll leave it for today.