ecp_tracing.md

Using tracing-tree for Instrumenting Compute@Edge Apps

This gist shows how to instrument a C@E app using the tracing-tree crate.

This is an example of what the output will look like. It works in a local environment as well.

tracing-tree works out-of-the-box on Compute@Edge. However, to enhance the format of the output shown in the image above, I used a modified, forked version.

Preparations

Step 1: Add Dependencies to Cargo.toml

tracing = "0.1.37"
tracing-subscriber = "0.3.17"
tracing-tree = { version = "0.2.4", git = "https://github.com/hrmsk66/tracing-tree", branch = "hrmsk66/print-span-duration-on-close" }

Step 2. Create Layer and Initialize Subscriber

use tracing::instrument;
use tracing_subscriber::prelude::*;
use tracing_subscriber::Registry;
use tracing_tree::HierarchicalLayer;

( snip )

// Place the following code in the main() function or somewhere at the beginning of your program.
let tree_layer = HierarchicalLayer::default()
    .with_ansi(true)
    .with_indent_amount(2)
    .with_indent_lines(true)
    .with_targets(false)
    .with_bracketed_fields(true)
    .with_higher_precision(true);

Registry::default()
    .with(tree_layer)
    .init();

Examples

In the following examples, the tracing::instrument macro is used to instrument each function. This generates a Span when the function is called, and closes the Span when the function exits. Additionally, macros like tracing::info! are used inside the functions to generate Events.

For more information on how to instrument your code, please refer to the tracing crate documentation

Now we are ready to add instrumenting code. Here is an example:

Example1:

use fastly::http::StatusCode;
use fastly::{Error, Request, Response};
use tracing::instrument;
use tracing_subscriber::prelude::*;
use tracing_subscriber::Registry;
use tracing_tree::HierarchicalLayer;

#[fastly::main]
fn main(_req: Request) -> Result<Response, Error> {
    
    // Create and register a new HierarchicalLayer
    let tree_layer = HierarchicalLayer::default()
        .with_ansi(true)
        .with_indent_amount(2)
        .with_indent_lines(true)
        .with_targets(false)
        .with_bracketed_fields(true)
        .with_higher_precision(true);
        
    Registry::default()
        .with(tree_layer)
        .init();

    Ok(Response::from_status(StatusCode::OK))
}

#[instrument]
fn one() {
    two();
}

#[instrument]
fn two() {
    three();
}

#[instrument]
fn three() {
    tracing::debug!("done!");
}

Example 2:

Here is a more practical example with fastly.toml and main.rs:

authors = ["foo@example.com"]
description = ""
language = "rust"
manifest_version = 3
name = "tracing-tree-demo"
service_id = ""

[local_server]
  kv_stores.subscriptions = [
    {key = "foo@example.com", data = "{ \"timestamp\" : \"2023-08-03T01:59:26.0Z\", \"email\": \"foo@example.com\", \"name\" : \"foo\" }"}
  ]

  [local_server.backends]
    [local_server.backends.example]
      override_host = "example.com"
      url = "https://example.com/"
    [local_server.backends.httpbin]
      override_host = "httpbin.org"
      url = "https://httpbin.org/"

use fastly::KVStore;
use fastly::{Error, Request, Response};
use tracing::instrument;
use tracing_subscriber::prelude::*;
use tracing_subscriber::Registry;
use tracing_tree::HierarchicalLayer;

const HTTPBIN: &str = "httpbin";
const EXAMPLE: &str = "example";
const KVSTORE: &str = "subscriptions";
const KEY: &str = "foo@example.com";

#[fastly::main]
fn main(req: Request) -> Result<Response, Error> {
    let tree_layer = HierarchicalLayer::default()
        .with_ansi(true)
        .with_indent_amount(2)
        .with_indent_lines(true)
        .with_targets(false)
        .with_bracketed_fields(true)
        .with_higher_precision(true);

    Registry::default()
        .with(tree_layer)
        .init();

    let hostname = std::env::var("FASTLY_HOSTNAME").unwrap_or_else(|_| String::new());
    run(req, &hostname)
}

#[instrument(skip(req))]
fn run(req: Request, hostname: &str) -> Result<Response, Error> {
    tracing::trace!("Request received");

    fetch_httpbin(req)?;

    let bereq = Request::get("https://example.com/");
    let resp = fetch_example(bereq)?;

    tracing::trace!(status = %resp.get_status(), "Returning response");
    Ok(resp)
}

#[instrument(level = "warn", skip(req), fields(method = %req.get_method(), path = req.get_path()))]
fn fetch_httpbin(req: Request) -> Result<(), Error> {
    let beresp = req.send(HTTPBIN)?;
    let cache_status = beresp.get_header_str("x-cache").unwrap_or("MISS");
    tracing::debug!(backend = %HTTPBIN, status = %beresp.get_status(), %cache_status, "Response received");
    Ok(())
}

#[instrument(skip(req), fields(method = %req.get_method(), path = req.get_path()))]
fn fetch_example(req: Request) -> Result<Response, Error> {
    let beresp = req.send(EXAMPLE)?;
    let cache_status = beresp.get_header_str("x-cache").unwrap_or("MISS");
    tracing::debug!(backend = %EXAMPLE, status = %beresp.get_status(), %cache_status, "Response received from example");

    if let Some(kvs) = open_kv_store(KVSTORE)? {
        read_from_kv_store(kvs, KEY)?
    }

    Ok(beresp)
}

#[instrument]
fn open_kv_store(name: &str) -> Result<Option<KVStore>, Error> {
    Ok(KVStore::open(name)?)
}

#[instrument(skip(kvs))]
fn read_from_kv_store(kvs: KVStore, key: &str) -> Result<(), Error> {
    if kvs.lookup(key)?.is_some() {
        tracing::warn!(%key, "Item found");
    } else {
        tracing::error!(%key, "Item not found");
    }

    Ok(())
}