feat(telemtry): Moved from logs to tracing

- Updated docs
This commit is contained in:
minhtrannhat 2024-05-07 16:10:09 -04:00
parent ccf49ee214
commit 70a4eb23c6
Signed by: minhtrannhat
GPG Key ID: E13CFA85C53F8062
8 changed files with 213 additions and 84 deletions

213
Cargo.lock generated
View File

@ -285,17 +285,6 @@ dependencies = [
"num-traits",
]
[[package]]
name = "atty"
version = "0.2.14"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
dependencies = [
"hermit-abi 0.1.19",
"libc",
"winapi",
]
[[package]]
name = "autocfg"
version = "1.1.0"
@ -624,12 +613,14 @@ dependencies = [
"actix-web",
"chrono",
"config",
"env_logger",
"log",
"reqwest",
"serde",
"sqlx",
"tokio",
"tracing",
"tracing-bunyan-formatter",
"tracing-log 0.2.0",
"tracing-subscriber",
"uuid",
]
@ -642,19 +633,6 @@ dependencies = [
"cfg-if",
]
[[package]]
name = "env_logger"
version = "0.9.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a12e6657c4c97ebab115a42dcee77225f7f482cdd841cf7088c657a42e9e00e7"
dependencies = [
"atty",
"humantime",
"log",
"regex",
"termcolor",
]
[[package]]
name = "equivalent"
version = "1.0.1"
@ -833,6 +811,16 @@ dependencies = [
"version_check",
]
[[package]]
name = "gethostname"
version = "0.2.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c1ebd34e35c46e00bb73e81363248d627782724609fe1b6396f553f68fe3862e"
dependencies = [
"libc",
"winapi",
]
[[package]]
name = "getrandom"
version = "0.2.12"
@ -871,9 +859,9 @@ dependencies = [
[[package]]
name = "h2"
version = "0.4.3"
version = "0.4.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "51ee2dd2e4f378392eeff5d51618cd9a63166a2513846bbc55f21cfacd9199d4"
checksum = "816ec7294445779408f36fe57bc5b7fc1cf59664059096c65f905c1c61f58069"
dependencies = [
"bytes",
"fnv",
@ -925,15 +913,6 @@ dependencies = [
"unicode-segmentation",
]
[[package]]
name = "hermit-abi"
version = "0.1.19"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "62b467343b94ba476dcb2500d242dadbb39557df889310ac77c5d99100aaac33"
dependencies = [
"libc",
]
[[package]]
name = "hermit-abi"
version = "0.3.9"
@ -1030,12 +1009,6 @@ version = "1.0.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9"
[[package]]
name = "humantime"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
[[package]]
name = "hyper"
version = "1.2.0"
@ -1045,7 +1018,7 @@ dependencies = [
"bytes",
"futures-channel",
"futures-util",
"h2 0.4.3",
"h2 0.4.4",
"http 1.1.0",
"http-body",
"httparse",
@ -1268,6 +1241,15 @@ version = "0.4.21"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "90ed8c1e510134f979dbc4f070f87d4313098b704861a105fe34231c70a3901c"
[[package]]
name = "matchers"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
dependencies = [
"regex-automata 0.1.10",
]
[[package]]
name = "md-5"
version = "0.10.6"
@ -1345,6 +1327,16 @@ dependencies = [
"minimal-lexical",
]
[[package]]
name = "nu-ansi-term"
version = "0.46.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
dependencies = [
"overload",
"winapi",
]
[[package]]
name = "num-bigint-dig"
version = "0.8.4"
@ -1404,7 +1396,7 @@ version = "1.16.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4161fcb6d602d4d2081af7c3a45852d875a03dd337a6bfdd6e06407b61342a43"
dependencies = [
"hermit-abi 0.3.9",
"hermit-abi",
"libc",
]
@ -1477,6 +1469,12 @@ dependencies = [
"hashbrown 0.12.3",
]
[[package]]
name = "overload"
version = "0.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
[[package]]
name = "parking_lot"
version = "0.12.1"
@ -1708,8 +1706,17 @@ checksum = "c117dbdfde9c8308975b6a18d71f3f385c89461f7b3fb054288ecf2a2058ba4c"
dependencies = [
"aho-corasick",
"memchr",
"regex-automata",
"regex-syntax",
"regex-automata 0.4.6",
"regex-syntax 0.8.2",
]
[[package]]
name = "regex-automata"
version = "0.1.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
dependencies = [
"regex-syntax 0.6.29",
]
[[package]]
@ -1720,9 +1727,15 @@ checksum = "86b83b8b9847f9bf95ef68afb0b8e6cdb80f498442f5179a29fad448fcc1eaea"
dependencies = [
"aho-corasick",
"memchr",
"regex-syntax",
"regex-syntax 0.8.2",
]
[[package]]
name = "regex-syntax"
version = "0.6.29"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1"
[[package]]
name = "regex-syntax"
version = "0.8.2"
@ -1740,7 +1753,7 @@ dependencies = [
"encoding_rs",
"futures-core",
"futures-util",
"h2 0.4.3",
"h2 0.4.4",
"http 1.1.0",
"http-body",
"http-body-util",
@ -2010,6 +2023,15 @@ dependencies = [
"digest",
]
[[package]]
name = "sharded-slab"
version = "0.1.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
dependencies = [
"lazy_static",
]
[[package]]
name = "signal-hook-registry"
version = "1.4.1"
@ -2373,15 +2395,6 @@ dependencies = [
"windows-sys 0.52.0",
]
[[package]]
name = "termcolor"
version = "1.4.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "06794f8f6c5c898b3275aebefa6b8a1cb24cd2c6c79397ab15774837a0bc5755"
dependencies = [
"winapi-util",
]
[[package]]
name = "thiserror"
version = "1.0.59"
@ -2402,6 +2415,16 @@ dependencies = [
"syn 2.0.53",
]
[[package]]
name = "thread_local"
version = "1.1.8"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c"
dependencies = [
"cfg-if",
"once_cell",
]
[[package]]
name = "time"
version = "0.3.34"
@ -2573,6 +2596,24 @@ dependencies = [
"syn 2.0.53",
]
[[package]]
name = "tracing-bunyan-formatter"
version = "0.3.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b5c266b9ac83dedf0e0385ad78514949e6d89491269e7065bee51d2bb8ec7373"
dependencies = [
"ahash 0.8.11",
"gethostname",
"log",
"serde",
"serde_json",
"time",
"tracing",
"tracing-core",
"tracing-log 0.1.4",
"tracing-subscriber",
]
[[package]]
name = "tracing-core"
version = "0.1.32"
@ -2580,6 +2621,47 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
dependencies = [
"once_cell",
"valuable",
]
[[package]]
name = "tracing-log"
version = "0.1.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f751112709b4e791d8ce53e32c4ed2d353565a795ce84da2285393f41557bdf2"
dependencies = [
"log",
"once_cell",
"tracing-core",
]
[[package]]
name = "tracing-log"
version = "0.2.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
dependencies = [
"log",
"once_cell",
"tracing-core",
]
[[package]]
name = "tracing-subscriber"
version = "0.3.18"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
dependencies = [
"matchers",
"nu-ansi-term",
"once_cell",
"regex",
"sharded-slab",
"smallvec",
"thread_local",
"tracing",
"tracing-core",
"tracing-log 0.2.0",
]
[[package]]
@ -2665,6 +2747,12 @@ dependencies = [
"getrandom",
]
[[package]]
name = "valuable"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
[[package]]
name = "vcpkg"
version = "0.2.15"
@ -2806,15 +2894,6 @@ version = "0.4.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
[[package]]
name = "winapi-util"
version = "0.1.8"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4d4cc384e1e73b93bafa6fb4f1df8c41695c8a91cf9c4c64358067d15a7b6c6b"
dependencies = [
"windows-sys 0.52.0",
]
[[package]]
name = "winapi-x86_64-pc-windows-gnu"
version = "0.4.0"

View File

@ -17,13 +17,15 @@ edition = "2021"
[dependencies]
actix-web = "4.5.1"
reqwest = "0.12.2"
env_logger = "0.9"
log = "0.4"
serde = { version = "1.0.197", features = ["derive"] }
tokio = { version = "1.36.0", features = ["full"] }
config = "0.13"
uuid = { version = "1.8.0", features = ["v4"] }
chrono = { version = "0.4.38", default-features = false, features = ["clock"] }
tracing = { version = "0.1.40", features = ["log"] }
tracing-subscriber = { version = "0.3.18", features = ["registry", "env-filter"] }
tracing-bunyan-formatter = "0.3.9"
tracing-log = "0.2.0"
[dependencies.sqlx]
version = "0.7"

View File

@ -7,6 +7,7 @@
## Other topics
- [Tracing](./tracing.md)
- [Database (PostgreSQL)](./database.md)
- [Testing](./technical_write_up.md)
- [Actic-web](./actix_web.md)

24
docs/tracing.md Normal file
View File

@ -0,0 +1,24 @@
# Tracing
Logs only record events, but traces record all that plus the start and end events. This makes following traces much more logical.
## The flow
- Create a new span, attach some values to it. These values are key-value pairs.
- We explicitly step into the span with `.enter()`.
- `.enter()` returns an instance of Entered, a guard: as long the guard variable is not dropped all downstream spans and log events will be registered as children of the entered span. And then the compiler will drop these for us.
## Notations
- enter the span (->);
- We exit the span (<-);
- We finally close the span (--).
## Instrumenting
When we think about an async task, the async executor (in our case, the `tokio` async runtime) will have to poll the futures multiple times to drive that future to completion. And while that future is idle, we will do work on other futures.
We then need to think about how to not mix the spans of the futures. This is where instrument comes in. It is an extension trait for futures. `Instrument::instrument` does exactly what we want: enters the span we pass as argument every time self, the future, is polled; it exits the span every time the future is parked.
## Notes
- We can enter and exit the span multiple times. But can only close once. This is good for async tasks as we will enter and resume async tasks.

View File

@ -1,3 +1,4 @@
pub mod configuration;
pub mod routes;
pub mod startup;
pub mod telemetry;

View File

@ -1,14 +1,15 @@
use std::net::TcpListener;
use email_newsletter_api::telemetry::{get_subscriber, init_subscriber};
use email_newsletter_api::{configuration::get_configuration, startup};
use env_logger::Env;
use sqlx::PgPool;
#[tokio::main]
async fn main() -> Result<(), std::io::Error> {
let configuration = get_configuration().expect("Failed to read configuration");
env_logger::Builder::from_env(Env::default().default_filter_or("info")).init();
let subscriber = get_subscriber("email_newsletter_api".into(), "info".into());
init_subscriber(subscriber);
let db_conn = PgPool::connect(&configuration.database.connection_string())
.await

View File

@ -1,6 +1,7 @@
use actix_web::{web, HttpResponse};
use chrono::Utc;
use sqlx::PgPool;
use tracing::Instrument;
use uuid::Uuid;
#[derive(serde::Deserialize)]
@ -15,13 +16,17 @@ pub async fn subscribe_route(
) -> HttpResponse {
let request_id = Uuid::new_v4();
log::info!(
"request_id {} - Saving '{}' '{}' as a new subscriber in PostgreSQL",
request_id,
form.name,
form.email
let request_span = tracing::info_span!(
"Adding new subscriber",
%request_id,
subscriber_email = %form.email,
subscriber_name = %form.name
);
let _request_span_guard = request_span.enter();
let query_span = tracing::info_span!("Adding new subscriber in PostgreSQL");
match sqlx::query!(
r#"
INSERT INTO subscriptions (id, email, name, subscribed_at)
@ -33,17 +38,12 @@ pub async fn subscribe_route(
Utc::now()
)
.execute(db_conn_pool.get_ref())
.instrument(query_span)
.await
{
Ok(_) => {
log::info!(
"request_id {} - Saved new subscriber details in PostgreSQL",
request_id
);
HttpResponse::Ok().finish()
}
Ok(_) => HttpResponse::Ok().finish(),
Err(err) => {
log::info!(
tracing::error!(
"request_id {} - Failed to execute query: {:?}",
request_id,
err

21
src/telemetry.rs Normal file
View File

@ -0,0 +1,21 @@
use tracing::subscriber::set_global_default;
use tracing::Subscriber;
use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
use tracing_log::LogTracer;
use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry};
pub fn get_subscriber(name: String, env_filter: String) -> impl Subscriber + Send + Sync {
let env_filter =
EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(env_filter));
let formatting_layer = BunyanFormattingLayer::new(name, std::io::stdout);
Registry::default()
.with(env_filter)
.with(JsonStorageLayer)
.with(formatting_layer)
}
// init_subscriber should only be called once
pub fn init_subscriber(subscriber: impl Subscriber + Send + Sync) {
LogTracer::init().expect("Failed to set logger");
set_global_default(subscriber).expect("Failed to set subscriber");
}