From 1fe964ac16feace7d518064ad76d374ff5df0a46 Mon Sep 17 00:00:00 2001 From: Nathan Sobo Date: Thu, 28 Apr 2022 09:45:59 -0600 Subject: [PATCH] Start moving from logging to tracing on collab server Install some spans. Probably more work to do here. Co-Authored-By: Antonio Scandurra --- Cargo.lock | 55 ++++-------------- crates/collab/Cargo.toml | 1 - crates/collab/k8s/manifest.template.yml | 2 - crates/collab/src/db.rs | 6 ++ crates/collab/src/main.rs | 6 +- crates/collab/src/rpc.rs | 74 +++++++++++++------------ crates/collab/src/rpc/store.rs | 3 + crates/util/src/lib.rs | 1 + 8 files changed, 63 insertions(+), 85 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 05a70f6230..71eda5f640 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -474,7 +474,7 @@ dependencies = [ "cexpr", "clang-sys", "clap 2.33.3", - "env_logger 0.8.3", + "env_logger", "lazy_static", "lazycell", "log", @@ -845,11 +845,10 @@ dependencies = [ "collections", "ctor", "editor", - "env_logger 0.8.3", + "env_logger", "envy", "futures", "gpui", - "json_env_logger", "language", "lazy_static", "lipsum", @@ -900,7 +899,7 @@ version = "0.1.0" dependencies = [ "ctor", "editor", - "env_logger 0.8.3", + "env_logger", "fuzzy", "gpui", "picker", @@ -1349,7 +1348,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger 0.8.3", + "env_logger", "futures", "fuzzy", "gpui", @@ -1395,15 +1394,6 @@ dependencies = [ "cfg-if 1.0.0", ] -[[package]] -name = "env_logger" -version = "0.7.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" -dependencies = [ - "log", -] - [[package]] name = "env_logger" version = "0.8.3" @@ -1485,7 +1475,7 @@ version = "0.1.0" dependencies = [ "ctor", "editor", - "env_logger 0.8.3", + "env_logger", "fuzzy", "gpui", "picker", @@ -1889,7 +1879,7 @@ dependencies = [ "core-text", "ctor", "dhat", - "env_logger 0.8.3", + "env_logger", "etagere", "font-kit", "foreign-types", @@ -2341,18 +2331,6 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "41ee439ee368ba4a77ac70d04f14015415af8600d6c894dc1f11bd79758c57d5" -[[package]] -name = "json_env_logger" -version = "0.1.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4e2ec540ea0448b187d3a8b4a9f13e75527d06ef76b3a2baa1cd982aecb62ce2" -dependencies = [ - "env_logger 0.7.1", - "kv-log-macro", - "log", - "serde_json", -] - [[package]] name = "kernel32-sys" version = "0.2.2" @@ -2372,15 +2350,6 @@ dependencies = [ "arrayvec 0.5.2", ] -[[package]] -name = "kv-log-macro" -version = "1.0.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0de8b303297635ad57c9f5059fd9cee7a47f8e8daa09df0fcd07dd39fb22977f" -dependencies = [ - "log", -] - [[package]] name = "language" version = "0.1.0" @@ -2392,7 +2361,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger 0.8.3", + "env_logger", "futures", "fuzzy", "gpui", @@ -2559,7 +2528,7 @@ dependencies = [ "async-pipe", "collections", "ctor", - "env_logger 0.8.3", + "env_logger", "futures", "gpui", "log", @@ -3162,7 +3131,7 @@ version = "0.1.0" dependencies = [ "ctor", "editor", - "env_logger 0.8.3", + "env_logger", "gpui", "serde_json", "settings", @@ -4632,7 +4601,7 @@ version = "0.1.0" dependencies = [ "arrayvec 0.7.1", "ctor", - "env_logger 0.8.3", + "env_logger", "log", "rand 0.8.3", ] @@ -4749,7 +4718,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger 0.8.3", + "env_logger", "gpui", "lazy_static", "log", @@ -5903,7 +5872,7 @@ dependencies = [ "dirs 3.0.1", "easy-parallel", "editor", - "env_logger 0.8.3", + "env_logger", "file_finder", "fsevent", "futures", diff --git a/crates/collab/Cargo.toml b/crates/collab/Cargo.toml index 741bc72b6c..feeed1ba6c 100644 --- a/crates/collab/Cargo.toml +++ b/crates/collab/Cargo.toml @@ -25,7 +25,6 @@ base64 = "0.13" envy = "0.4.2" env_logger = "0.8" futures = "0.3" -json_env_logger = "0.1" lazy_static = "1.4" lipsum = { version = "0.8", optional = true } log = { version = "0.4.16", features = ["kv_unstable_serde"] } diff --git a/crates/collab/k8s/manifest.template.yml b/crates/collab/k8s/manifest.template.yml index d3f398c473..2e9f0ae298 100644 --- a/crates/collab/k8s/manifest.template.yml +++ b/crates/collab/k8s/manifest.template.yml @@ -81,8 +81,6 @@ spec: secretKeyRef: name: api key: token - - name: LOG_JSON - value: "1" - name: RUST_LOG value: ${RUST_LOG} - name: TRACE_LEVEL diff --git a/crates/collab/src/db.rs b/crates/collab/src/db.rs index 737929db4d..28375b6685 100644 --- a/crates/collab/src/db.rs +++ b/crates/collab/src/db.rs @@ -431,6 +431,12 @@ macro_rules! id_type { self.0 as u64 } } + + impl std::fmt::Display for $name { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + self.0.fmt(f) + } + } }; } diff --git a/crates/collab/src/main.rs b/crates/collab/src/main.rs index 82176a53ca..d7f8905a9a 100644 --- a/crates/collab/src/main.rs +++ b/crates/collab/src/main.rs @@ -41,11 +41,7 @@ impl AppState { #[tokio::main] async fn main() -> Result<()> { - if std::env::var("LOG_JSON").is_ok() { - json_env_logger::init(); - } else { - env_logger::init(); - } + env_logger::init(); if let Err(error) = env::load_dotenv() { log::error!( diff --git a/crates/collab/src/rpc.rs b/crates/collab/src/rpc.rs index 60df2b8447..9c00c930c9 100644 --- a/crates/collab/src/rpc.rs +++ b/crates/collab/src/rpc.rs @@ -25,7 +25,6 @@ use axum::{ use collections::{HashMap, HashSet}; use futures::{channel::mpsc, future::BoxFuture, FutureExt, SinkExt, StreamExt, TryStreamExt}; use lazy_static::lazy_static; -use log::{as_debug, as_display}; use rpc::{ proto::{self, AnyTypedEnvelope, EntityMessage, EnvelopedMessage, RequestMessage}, Connection, ConnectionId, Peer, TypedEnvelope, @@ -38,7 +37,7 @@ use std::{ ops::{Deref, DerefMut}, rc::Rc, sync::Arc, - time::{Duration, Instant}, + time::Duration, }; use store::{Store, Worktree}; use time::OffsetDateTime; @@ -47,12 +46,11 @@ use tokio::{ time::Sleep, }; use tower::ServiceBuilder; -use tracing::{info_span, Instrument}; +use tracing::{info_span, instrument, Instrument}; use util::ResultExt; -type MessageHandler = Box< - dyn Send + Sync + Fn(Arc, Box) -> BoxFuture<'static, Result<()>>, ->; +type MessageHandler = + Box, Box) -> BoxFuture<'static, ()>>; pub struct Server { peer: Arc, @@ -161,7 +159,14 @@ impl Server { "handle message", payload_type = envelope.payload_type_name() ); - (handler)(server, *envelope).instrument(span).boxed() + let future = (handler)(server, *envelope); + async move { + if let Err(error) = future.await { + tracing::error!(%error, "error handling message"); + } + } + .instrument(span) + .boxed() }), ); if prev_handler.is_some() { @@ -238,12 +243,13 @@ impl Server { pub fn handle_connection( self: &Arc, connection: Connection, - addr: String, + address: String, user_id: UserId, mut send_connection_id: Option>, executor: E, ) -> impl Future { let mut this = self.clone(); + let span = info_span!("handle connection", %user_id, %address); async move { let (connection_id, handle_io, mut incoming_rx) = this .peer @@ -258,6 +264,8 @@ impl Server { }) .await; + tracing::info!(%user_id, %connection_id, %address, "connection opened"); + if let Some(send_connection_id) = send_connection_id.as_mut() { let _ = send_connection_id.send(connection_id).await; } @@ -275,50 +283,47 @@ impl Server { futures::pin_mut!(next_message); futures::select_biased! { result = handle_io => { - if let Err(err) = result { - log::error!("error handling rpc connection {:?} - {:?}", addr, err); + if let Err(error) = result { + tracing::error!(%error, "error handling I/O"); } break; } message = next_message => { if let Some(message) = message { - let start_time = Instant::now(); let type_name = message.payload_type_name(); - log::info!(connection_id = connection_id.0, type_name = type_name; "rpc message received"); - if let Some(handler) = this.handlers.get(&message.payload_type_id()) { - let notifications = this.notifications.clone(); - let is_background = message.is_background(); - let handle_message = (handler)(this.clone(), message); - let handle_message = async move { - if let Err(err) = handle_message.await { - log::error!(connection_id = connection_id.0, type = type_name, error = as_display!(err); "rpc message error"); + let span = tracing::info_span!("receive message", %user_id, %connection_id, %address, type_name); + async { + if let Some(handler) = this.handlers.get(&message.payload_type_id()) { + let notifications = this.notifications.clone(); + let is_background = message.is_background(); + let handle_message = (handler)(this.clone(), message); + let handle_message = async move { + handle_message.await; + if let Some(mut notifications) = notifications { + let _ = notifications.send(()).await; + } + }; + if is_background { + executor.spawn_detached(handle_message); } else { - log::info!(connection_id = connection_id.0, type = type_name, duration = as_debug!(start_time.elapsed()); "rpc message handled"); + handle_message.await; } - if let Some(mut notifications) = notifications { - let _ = notifications.send(()).await; - } - }; - if is_background { - executor.spawn_detached(handle_message); } else { - handle_message.await; + tracing::error!("no message handler"); } - } else { - log::warn!("unhandled message: {}", type_name); - } + }.instrument(span).await; } else { - log::info!(address = as_debug!(addr); "rpc connection closed"); + tracing::info!(%user_id, %connection_id, %address, "connection closed"); break; } } } } - if let Err(err) = this.sign_out(connection_id).await { - log::error!("error signing out connection {:?} - {:?}", addr, err); + if let Err(error) = this.sign_out(connection_id).await { + tracing::error!(%error, "error signing out"); } - } + }.instrument(span) } async fn sign_out(self: &mut Arc, connection_id: ConnectionId) -> Result<()> { @@ -854,6 +859,7 @@ impl Server { Ok(proto::GetUsersResponse { users }) } + #[instrument(skip(self, state, user_ids))] fn update_contacts_for_users<'a>( self: &Arc, state: &Store, diff --git a/crates/collab/src/rpc/store.rs b/crates/collab/src/rpc/store.rs index 7a123ee484..aaaea50263 100644 --- a/crates/collab/src/rpc/store.rs +++ b/crates/collab/src/rpc/store.rs @@ -3,6 +3,7 @@ use anyhow::{anyhow, Result}; use collections::{BTreeMap, HashMap, HashSet}; use rpc::{proto, ConnectionId}; use std::{collections::hash_map, path::PathBuf}; +use tracing::instrument; #[derive(Default)] pub struct Store { @@ -81,6 +82,7 @@ pub struct LeftProject { } impl Store { + #[instrument(skip(self))] pub fn add_connection(&mut self, connection_id: ConnectionId, user_id: UserId) { self.connections.insert( connection_id, @@ -96,6 +98,7 @@ impl Store { .insert(connection_id); } + #[instrument(skip(self))] pub fn remove_connection( &mut self, connection_id: ConnectionId, diff --git a/crates/util/src/lib.rs b/crates/util/src/lib.rs index 5870390285..e5a98fd675 100644 --- a/crates/util/src/lib.rs +++ b/crates/util/src/lib.rs @@ -37,6 +37,7 @@ where } } } + pub trait ResultExt { type Ok;