From 68e287400b489001e76348674c64d152eba7eac1 Mon Sep 17 00:00:00 2001 From: Jordan Doyle Date: Sat, 09 Oct 2021 01:59:42 +0100 Subject: [PATCH] Log using tracing --- Cargo.lock | 236 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++------------------- chartered-db/Cargo.toml | 6 +++--- chartered-git/Cargo.toml | 5 ++--- chartered-web/Cargo.toml | 4 ++-- chartered-db/src/lib.rs | 7 +++---- chartered-git/src/main.rs | 209 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-------------- chartered-web/src/main.rs | 2 +- chartered-git/src/command_handlers/ls_refs.rs | 2 +- chartered-web/src/middleware/logging.rs | 63 ++++++++++++++++++++++++++++++++++++++++++++------------------- chartered-web/src/endpoints/web_api/ssh_key.rs | 2 +- 10 files changed, 270 insertions(+), 266 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6afd0d8..c900bc0 100644 --- a/Cargo.lock +++ a/Cargo.lock @@ -41,6 +41,15 @@ ] [[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi", +] + +[[package]] name = "anyhow" version = "1.0.44" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -261,7 +270,7 @@ "chartered-types", "chrono", "diesel", - "diesel_logger", + "diesel-tracing", "diesel_migrations", "displaydoc", "dotenv", @@ -317,13 +326,12 @@ "serde_json", "sha-1", "shlex", - "slog", - "slog-async", - "slog-term", "thrussh", "thrussh-keys", "tokio", "tokio-util", + "tracing", + "tracing-subscriber", "url", ] @@ -347,11 +355,9 @@ "chartered-types", "chrono", "clap", - "env_logger", "futures", "headers", "hex", - "log", "nom", "once_cell", "openid", @@ -366,6 +372,8 @@ "toml", "tower", "tower-http 0.1.1 (git+https://github.com/tower-rs/tower-http?branch=cors)", + "tracing", + "tracing-subscriber", ] [[package]] @@ -473,28 +481,8 @@ version = "1.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "81156fece84ab6a9f2afdb109ce3ae577e42b1228441eded99bd77f627953b1a" -dependencies = [ - "cfg-if", -] - -[[package]] -name = "crossbeam-channel" -version = "0.5.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "06ed27e177f16d65f0f0c22a213e17c696ace5dd64b14258b52f9417ccb52db4" -dependencies = [ - "cfg-if", - "crossbeam-utils", -] - -[[package]] -name = "crossbeam-utils" -version = "0.8.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d82cfc11ce7f2c3faef78d8a684447b40d503d9681acebed6cb728d45940c4db" dependencies = [ "cfg-if", - "lazy_static", ] [[package]] @@ -542,9 +530,22 @@ "byteorder", "chrono", "diesel_derives", + "ipnetwork", + "libc", "libsqlite3-sys", "pq-sys", "r2d2", +] + +[[package]] +name = "diesel-tracing" +version = "0.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1c039d591e23293c9d9682139758ea499e2a56b27c2ef38704c8f1dc5e2044ad" +dependencies = [ + "diesel", + "ipnetwork", + "tracing", ] [[package]] @@ -556,16 +557,6 @@ "proc-macro2", "quote", "syn", -] - -[[package]] -name = "diesel_logger" -version = "0.1.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1793935ad14586bf2aa51574a7157932640c345205ccfb2db431846d846e3db7" -dependencies = [ - "diesel", - "log", ] [[package]] @@ -597,31 +588,10 @@ ] [[package]] -name = "dirs-next" -version = "2.0.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b98cf8ebf19c3d1b223e151f99a4f9f0690dca41414773390fc824184ac833e1" -dependencies = [ - "cfg-if", - "dirs-sys-next", -] - -[[package]] name = "dirs-sys" version = "0.3.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "03d86534ed367a67548dc68113a0f5db55432fdfbb6e6f9d77704397d95d5780" -dependencies = [ - "libc", - "redox_users", - "winapi", -] - -[[package]] -name = "dirs-sys-next" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4ebda144c4fe02d1f7ea1a7d9641b6fc6b580adcfa024ae48797ecdeb6825b4d" dependencies = [ "libc", "redox_users", @@ -658,19 +628,6 @@ checksum = "80df024fbc5ac80f87dfef0d9f5209a252f2a497f7f42944cff24d8253cac065" dependencies = [ "cfg-if", -] - -[[package]] -name = "env_logger" -version = "0.9.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0b2cf0344971ee6c64c31be0d530793fba457d322dfec2810c453d0ef228f9c3" -dependencies = [ - "atty", - "humantime", - "log", - "regex", - "termcolor", ] [[package]] @@ -970,12 +927,6 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6456b8a6c8f33fee7d958fcd1b60d55b11940a79e63ae87013e6d22e26034440" - -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" [[package]] name = "hyper" @@ -1064,6 +1015,15 @@ version = "2.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "68f2d64f2edebec4ce84ad108148e67e1064789bee435edc5b60ad398714a3a9" + +[[package]] +name = "ipnetwork" +version = "0.18.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4088d739b183546b239688ddbc79891831df421773df95e236daf7867866d355" +dependencies = [ + "serde", +] [[package]] name = "itertools" @@ -1140,6 +1100,15 @@ checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710" dependencies = [ "cfg-if", +] + +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", ] [[package]] @@ -1690,6 +1659,15 @@ dependencies = [ "aho-corasick", "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ "regex-syntax", ] @@ -1757,12 +1735,6 @@ "web-sys", "winapi", ] - -[[package]] -name = "rustversion" -version = "1.0.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "61b3909d758bb75c79f23d4736fac9433868679d3ad2ea7a61e3c25cfda9a088" [[package]] name = "ryu" @@ -1895,6 +1867,15 @@ "cpufeatures", "digest", "opaque-debug", +] + +[[package]] +name = "sharded-slab" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "740223c51853f3145fe7c90360d2d4232f2b62e3449489c207eccde818979982" +dependencies = [ + "lazy_static", ] [[package]] @@ -1919,37 +1900,6 @@ checksum = "c307a32c1c5c437f38c7fd45d753050587732ba8628319fbdf12a7e289ccc590" [[package]] -name = "slog" -version = "2.7.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8347046d4ebd943127157b94d63abb990fcf729dc4e9978927fdf4ac3c998d06" - -[[package]] -name = "slog-async" -version = "2.7.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "766c59b252e62a34651412870ff55d8c4e6d04df19b43eecb2703e417b097ffe" -dependencies = [ - "crossbeam-channel", - "slog", - "take_mut", - "thread_local", -] - -[[package]] -name = "slog-term" -version = "2.8.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "95c1e7e5aab61ced6006149ea772770b84a0d16ce0f7885def313e4829946d76" -dependencies = [ - "atty", - "chrono", - "slog", - "term", - "thread_local", -] - -[[package]] name = "smallvec" version = "1.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" @@ -1999,12 +1949,6 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "20518fe4a4c9acf048008599e464deb21beeae3d3578418951a189c235a7a9a8" - -[[package]] -name = "take_mut" -version = "0.2.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f764005d11ee5f36500a149ace24e00e3da98b0158b3e2d53a7495660d3f4d60" [[package]] name = "tempfile" @@ -2017,17 +1961,6 @@ "rand", "redox_syscall", "remove_dir_all", - "winapi", -] - -[[package]] -name = "term" -version = "0.7.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c59df8ac95d96ff9bede18eb7300b0fda5e5d8d90960e76f8e14ae765eedbf1f" -dependencies = [ - "dirs-next", - "rustversion", "winapi", ] @@ -2334,8 +2267,51 @@ version = "0.1.20" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "46125608c26121c81b0c6d693eab5a420e416da7e43c426d2e8f7df8da8a3acf" +dependencies = [ + "lazy_static", +] + +[[package]] +name = "tracing-log" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.25" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0e0d2eaa99c3c2e41547cfa109e910a68ea03823cccad4a0525dcbc9b01e8c71" dependencies = [ + "ansi_term", + "chrono", "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] diff --git a/chartered-db/Cargo.toml b/chartered-db/Cargo.toml index d4583a6..aa8f3fb 100644 --- a/chartered-db/Cargo.toml +++ a/chartered-db/Cargo.toml @@ -13,8 +13,8 @@ bitflags = "1" chrono = "0.4" diesel = { version = "1", features = ["r2d2", "chrono"] } -diesel_logger = "0.1" diesel_migrations = "1.4" +diesel-tracing = "0.1" displaydoc = "0.2" hex = "0.4" http = "0.2" @@ -32,6 +32,6 @@ thrussh-keys = "0.21" [features] -sqlite = ["libsqlite3-sys", "diesel/sqlite"] -postgres = ["diesel/postgres"] +sqlite = ["libsqlite3-sys", "diesel/sqlite", "diesel-tracing/sqlite"] +postgres = ["diesel/postgres", "diesel-tracing/postgres"] diff --git a/chartered-git/Cargo.toml b/chartered-git/Cargo.toml index 72cd5f5..6c9bfff 100644 --- a/chartered-git/Cargo.toml +++ a/chartered-git/Cargo.toml @@ -24,9 +24,6 @@ indexmap = "1" indoc = "1.0" itoa = "0.4" -slog = { version = "2.7", features = ["max_level_trace", "release_max_level_info"] } -slog-async = "2.7" -slog-term = "2.8" serde = { version = "1", features = ["derive"] } serde_json = "1" shlex = "1" @@ -35,4 +32,6 @@ thrussh-keys = "0.21" tokio = { version = "1", features = ["full"] } tokio-util = { version = "0.6", features = ["codec"] } +tracing = "0.1" +tracing-subscriber = "0.2" url = "2" diff --git a/chartered-web/Cargo.toml b/chartered-web/Cargo.toml index 623d7f5..9988378 100644 --- a/chartered-web/Cargo.toml +++ a/chartered-web/Cargo.toml @@ -17,11 +17,9 @@ chacha20poly1305 = { version = "0.9", features = ["std"] } chrono = { version = "0.4", features = ["serde"] } clap = { version = "3.0.0-beta.4", features = ["std", "suggestions", "color"] } -env_logger = "0.9" futures = "0.3" headers = "0.3" hex = "0.4" -log = "0.4" nom = "7" once_cell = "1.8" openid = "0.9" @@ -37,3 +35,5 @@ # tower-http = { version = "0.1", features = ["trace", "set-header"] } tower-http = { git = "https://github.com/tower-rs/tower-http", branch = "cors", features = ["trace", "set-header", "cors"] } toml = "0.5" +tracing = "0.1" +tracing-subscriber = "0.2" diff --git a/chartered-db/src/lib.rs b/chartered-db/src/lib.rs index 02fe455..b3f9549 100644 --- a/chartered-db/src/lib.rs +++ a/chartered-db/src/lib.rs @@ -48,16 +48,15 @@ r2d2::{ConnectionManager, Pool}, sql_types::{Integer, Nullable}, }; -use diesel_logger::LoggingConnection; use displaydoc::Display; use std::sync::Arc; use thiserror::Error; #[cfg(feature = "sqlite")] -pub type Connection = diesel::SqliteConnection; +pub type Connection = diesel_tracing::sqlite::InstrumentedSqliteConnection; #[cfg(feature = "postgres")] -pub type Connection = diesel::PostgresConnection; +pub type Connection = diesel_tracing::postgres::InstrumentedPostgresConnection; #[cfg(not(any(feature = "sqlite", feature = "postgres")))] compile_error!( @@ -66,7 +65,7 @@ #[cfg(not(any(feature = "sqlite", feature = "postgres")))] pub type Connection = unimplemented!(); -pub type ConnectionPool = Arc>>>; +pub type ConnectionPool = Arc>>; pub type Result = std::result::Result; embed_migrations!(); diff --git a/chartered-git/src/main.rs b/chartered-git/src/main.rs index e7581ff..62afdf1 100644 --- a/chartered-git/src/main.rs +++ a/chartered-git/src/main.rs @@ -19,7 +19,6 @@ use arrayvec::ArrayVec; use bytes::BytesMut; use futures::future::Future; -use slog::{debug, error, info, o, warn, Drain, Logger}; use std::{fmt::Write, pin::Pin, sync::Arc}; use thrussh::{ server::{self, Auth, Session}, @@ -27,15 +26,13 @@ }; use thrussh_keys::{key, PublicKeyBase64}; use tokio_util::codec::{Decoder, Encoder as TokioEncoder}; +use tracing::{debug, error, event, info, warn, Instrument}; use url::Url; #[tokio::main] #[allow(clippy::semicolon_if_nothing_returned)] // broken clippy lint async fn main() { - let decorator = slog_term::TermDecorator::new().build(); - let drain = slog_term::FullFormat::new(decorator).build().fuse(); - let drain = slog_async::Async::new(drain).build().fuse(); - let log = slog::Logger::root(drain, o!()); + tracing_subscriber::fmt::init(); let config = Arc::new(thrussh::server::Config { methods: thrussh::MethodSet::PUBLICKEY, @@ -45,7 +42,6 @@ let server = Server { db: chartered_db::init().unwrap(), - log, }; thrussh::server::run(config, "127.0.0.1:2233", server) @@ -56,19 +52,20 @@ #[derive(Clone)] struct Server { db: chartered_db::ConnectionPool, - log: Logger, } impl server::Server for Server { type Handler = Handler; fn new(&mut self, ip: Option) -> Self::Handler { - let log = self.log.new(o!("ip" => ip)); - info!(log, "Connection received"); + let connection_id = chartered_db::uuid::Uuid::new_v4(); + let span = tracing::info_span!("ssh", "connection_id" = connection_id.to_string().as_str()); + span.in_scope(|| info!("Connection accepted from {:?}", ip)); + Handler { ip, - log, + span, codec: GitCodec::default(), input_bytes: BytesMut::default(), output_bytes: BytesMut::default(), @@ -82,7 +79,7 @@ struct Handler { ip: Option, - log: Logger, + span: tracing::Span, codec: GitCodec, input_bytes: BytesMut, output_bytes: BytesMut, @@ -152,7 +149,7 @@ value: &str, session: Session, ) -> Self::FutureUnit { - debug!(&self.log, "env set {}={}", name, value); + self.span.in_scope(|| debug!("env set {}={}", name, value)); match (name, value) { ("GIT_PROTOCOL", "version=2") => self.is_git_protocol_v2 = true, @@ -163,15 +160,17 @@ } fn shell_request(mut self, channel: ChannelId, mut session: Session) -> Self::FutureUnit { + let span = self.span.clone(); + Box::pin(async move { - error!(&self.log, "Attempted to open a shell, rejecting connection"); + error!("Client attempted to open a shell, closing connection"); let username = self.authed()?.user.username.clone(); // todo write!(&mut self.output_bytes, "Hi there, {}! You've successfully authenticated, but chartered does not provide shell access.\r\n", username)?; self.flush(&mut session, channel); session.close(channel); Ok((self, session)) - }) + }.instrument(tracing::info_span!(parent: span, "shell request"))) } fn exec_request( @@ -180,15 +179,17 @@ data: &[u8], mut session: Session, ) -> Self::FutureUnit { + let span = self.span.clone(); + let data = match std::str::from_utf8(data) { Ok(data) => data, Err(e) => return Box::pin(futures::future::err(e.into())), }; let args = shlex::split(data); - debug!(&self.log, "exec {}", data); - Box::pin(async move { + debug!("exec {:?}", args); + if !self.is_git_protocol_v2 { anyhow::bail!("not git protocol v2"); } @@ -224,7 +225,7 @@ self.flush(&mut session, channel); Ok((self, session)) - }) + }.instrument(tracing::info_span!(parent: span, "exec"))) } fn subsystem_request( @@ -237,32 +238,36 @@ } fn auth_publickey(mut self, _username: &str, key: &key::PublicKey) -> Self::FutureAuth { + let span = self.span.clone(); let public_key = key.public_key_bytes(); - Box::pin(async move { - let (ssh_key, user) = - match chartered_db::users::User::find_by_ssh_key(self.db.clone(), public_key) - .await? - { - Some(user) => user, - None => return self.finished_auth(server::Auth::Reject).await, - }; - let ssh_key = Arc::new(ssh_key); - - if let Err(e) = ssh_key.clone().update_last_used(self.db.clone()).await { - warn!(&self.log, "Failed to update last used key: {:?}", e); - } + Box::pin( + async move { + let (ssh_key, user) = + match chartered_db::users::User::find_by_ssh_key(self.db.clone(), public_key) + .await? + { + Some(user) => user, + None => return self.finished_auth(server::Auth::Reject).await, + }; + let ssh_key = Arc::new(ssh_key); + + if let Err(e) = ssh_key.clone().update_last_used(self.db.clone()).await { + warn!("Failed to update last used key: {:?}", e); + } - let auth_key = ssh_key - .clone() - .get_or_insert_session(self.db.clone(), self.ip.map(|v| v.to_string())) - .await? - .session_key; + let auth_key = ssh_key + .clone() + .get_or_insert_session(self.db.clone(), self.ip.map(|v| v.to_string())) + .await? + .session_key; - self.authed = Some(Authed { user, auth_key }); + self.authed = Some(Authed { user, auth_key }); - self.finished_auth(server::Auth::Accept).await - }) + self.finished_auth(server::Auth::Accept).await + } + .instrument(tracing::info_span!(parent: span, "auth pubkey")), + ) } fn auth_keyboard_interactive( @@ -283,71 +288,79 @@ } fn data(mut self, channel: ChannelId, data: &[u8], mut session: Session) -> Self::FutureUnit { + let span = self.span.clone(); self.input_bytes.extend_from_slice(data); - - Box::pin(async move { - while let Some(frame) = self.codec.decode(&mut self.input_bytes)? { - debug!( - &self.log, - "decoded frame command={:?} metadata={:?}", frame.command, frame.metadata - ); - - // if the client flushed without giving us a command, we're expected to close - // the connection or else the client will just hang - if frame.command.is_empty() { - session.exit_status_request(channel, 0); - session.eof(channel); - session.close(channel); - return Ok((self, session)); - } - let authed = self.authed()?; - let org_name = self.org_name()?; - - let mut packfile = GitRepository::default(); - let config = CargoConfig::new( - Url::parse("http://127.0.0.1:8888/")?, - &authed.auth_key, - org_name, - ); - let config = serde_json::to_vec(&config)?; - packfile.insert(ArrayVec::<_, 0>::new(), "config.json", &config); - // todo: the whole tree needs caching and then we can filter in code rather than at - // the database - let tree = Tree::build(self.db.clone(), authed.user.id, org_name.to_string()).await; - tree.write_to_packfile(&mut packfile); - - let (commit_hash, packfile_entries) = - packfile.commit("computer", "john@computer.no", "Update crates"); - - match frame.command.as_ref() { - b"command=ls-refs" => { - command_handlers::ls_refs::handle( - &mut self, - &mut session, - channel, - frame.metadata, - &commit_hash, - ) - .await? + Box::pin( + async move { + while let Some(frame) = self.codec.decode(&mut self.input_bytes)? { + debug!( + "decoded frame command={:?} metadata={:?}", + frame.command, frame.metadata + ); + + // if the client flushed without giving us a command, we're expected to close + // the connection or else the client will just hang + if frame.command.is_empty() { + session.exit_status_request(channel, 0); + session.eof(channel); + session.close(channel); + return Ok((self, session)); } - b"command=fetch" => { - command_handlers::fetch::handle( - &mut self, - &mut session, - channel, - frame.metadata, - packfile_entries, - ) - .await? - } - v => { - error!(&self.log, "Client sent unknown command, ignoring"; "command" => std::str::from_utf8(v).unwrap_or("invalid utf8")) + + let authed = self.authed()?; + let org_name = self.org_name()?; + + let mut packfile = GitRepository::default(); + let config = CargoConfig::new( + Url::parse("http://127.0.0.1:8888/")?, + &authed.auth_key, + org_name, + ); + let config = serde_json::to_vec(&config)?; + packfile.insert(ArrayVec::<_, 0>::new(), "config.json", &config); + // todo: the whole tree needs caching and then we can filter in code rather than at + // the database + let tree = + Tree::build(self.db.clone(), authed.user.id, org_name.to_string()).await; + tree.write_to_packfile(&mut packfile); + + let (commit_hash, packfile_entries) = + packfile.commit("computer", "john@computer.no", "Update crates"); + + match frame.command.as_ref() { + b"command=ls-refs" => { + command_handlers::ls_refs::handle( + &mut self, + &mut session, + channel, + frame.metadata, + &commit_hash, + ) + .await? + } + b"command=fetch" => { + command_handlers::fetch::handle( + &mut self, + &mut session, + channel, + frame.metadata, + packfile_entries, + ) + .await? + } + v => { + error!( + "Client sent unknown command, ignoring command {}", + std::str::from_utf8(v).unwrap_or("invalid utf8") + ); + } } } - } - Ok((self, session)) - }) + Ok((self, session)) + } + .instrument(tracing::info_span!(parent: span, "data")), + ) } } diff --git a/chartered-web/src/main.rs b/chartered-web/src/main.rs index 7e9b95d..836095e 100644 --- a/chartered-web/src/main.rs +++ a/chartered-web/src/main.rs @@ -60,7 +60,7 @@ let opts: Opts = Opts::parse(); let config: config::Config = toml::from_slice(&std::fs::read(&opts.config).unwrap()).unwrap(); - env_logger::init(); + tracing_subscriber::fmt::init(); let pool = chartered_db::init().unwrap(); diff --git a/chartered-git/src/command_handlers/ls_refs.rs b/chartered-git/src/command_handlers/ls_refs.rs index 9fe41a0..78da003 100644 --- a/chartered-git/src/command_handlers/ls_refs.rs +++ a/chartered-git/src/command_handlers/ls_refs.rs @@ -1,8 +1,8 @@ //! [ls-refs][lsr] is sent from the client when they want to see what refs we have //! on the server, we're generating our commits on the fly though so we'll just tell //! them we have a master branch with whatever the generated commit hash is. //! -//! [ls-ref]: https://git-scm.com/docs/protocol-v2/2.19.0#_ls_refs +//! [lsr]: https://git-scm.com/docs/protocol-v2/2.19.0#_ls_refs use bytes::Bytes; use thrussh::{server::Session, ChannelId}; diff --git a/chartered-web/src/middleware/logging.rs b/chartered-web/src/middleware/logging.rs index 7ccd855..c92d36d 100644 --- a/chartered-web/src/middleware/logging.rs +++ a/chartered-web/src/middleware/logging.rs @@ -1,9 +1,8 @@ use axum::{ extract::{self, FromRequest, RequestParts}, http::{Request, Response}, }; use futures::future::BoxFuture; -use log::log; use once_cell::sync::Lazy; use regex::Regex; use std::{ @@ -11,6 +10,7 @@ task::{Context, Poll}, }; use tower::Service; +use tracing::{error, info, Instrument}; pub trait GenericError: std::error::Error + Debug + Send + Sync {} @@ -42,6 +42,9 @@ let clone = self.0.clone(); let mut inner = std::mem::replace(&mut self.0, clone); + let request_id = chartered_db::uuid::Uuid::new_v4(); + let span = tracing::info_span!("web", "request_id" = request_id.to_string().as_str()); + Box::pin(async move { let start = std::time::Instant::now(); let user_agent = req.headers_mut().remove(axum::http::header::USER_AGENT); @@ -56,30 +59,44 @@ // this is infallible because of the type of S::Error let response = inner.call(req.try_into_request().unwrap()).await?; - log!( - if response.status().is_server_error() { - log::Level::Error - } else { - log::Level::Info - }, - "{ip} - \"{method} {uri}\" {status} {duration:?} \"{user_agent}\" \"{error:?}\"", - ip = socket_addr, - method = method, - uri = uri, - status = response.status().as_u16(), - duration = start.elapsed(), - user_agent = user_agent - .as_ref() - .and_then(|v| v.to_str().ok()) - .unwrap_or("unknown"), - error = match response.extensions().get::>() { - Some(e) => Err(e), - None => Ok(()), - } - ); + if response.status().is_server_error() { + error!( + "{ip} - \"{method} {uri}\" {status} {duration:?} \"{user_agent}\" \"{error:?}\"", + ip = socket_addr, + method = method, + uri = uri, + status = response.status().as_u16(), + duration = start.elapsed(), + user_agent = user_agent + .as_ref() + .and_then(|v| v.to_str().ok()) + .unwrap_or("unknown"), + error = match response.extensions().get::>() { + Some(e) => Err(e), + None => Ok(()), + } + ); + } else { + info!( + "{ip} - \"{method} {uri}\" {status} {duration:?} \"{user_agent}\" \"{error:?}\"", + ip = socket_addr, + method = method, + uri = uri, + status = response.status().as_u16(), + duration = start.elapsed(), + user_agent = user_agent + .as_ref() + .and_then(|v| v.to_str().ok()) + .unwrap_or("unknown"), + error = match response.extensions().get::>() { + Some(e) => Err(e), + None => Ok(()), + } + ); + } Ok(response) - }) + }.instrument(span)) } } diff --git a/chartered-web/src/endpoints/web_api/ssh_key.rs b/chartered-web/src/endpoints/web_api/ssh_key.rs index b71d96e..5eb3855 100644 --- a/chartered-web/src/endpoints/web_api/ssh_key.rs +++ a/chartered-web/src/endpoints/web_api/ssh_key.rs @@ -1,12 +1,12 @@ use chartered_db::{users::User, ConnectionPool}; use axum::{extract, Json}; use chartered_db::uuid::Uuid; use chrono::{DateTime, TimeZone, Utc}; -use log::warn; use serde::{Deserialize, Serialize}; use std::sync::Arc; use thiserror::Error; +use tracing::warn; use crate::endpoints::ErrorResponse; -- rgit 0.1.3