Start moving from logging to tracing on collab server

Nathan Sobo and Antonio Scandurra created 

Install some spans. Probably more work to do here.

Co-Authored-By: Antonio Scandurra <me@as-cii.com>

Change summary

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(-)

Detailed changes

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",

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"] }

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)
+            }
+        }
     };
 }

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!(

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<Server>, Box<dyn AnyTypedEnvelope>) -> BoxFuture<'static, Result<()>>,
->;
+type MessageHandler =
+    Box<dyn Send + Sync + Fn(Arc<Server>, Box<dyn AnyTypedEnvelope>) -> BoxFuture<'static, ()>>;
 
 pub struct Server {
     peer: Arc<Peer>,
@@ -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<E: Executor>(
         self: &Arc<Self>,
         connection: Connection,
-        addr: String,
+        address: String,
         user_id: UserId,
         mut send_connection_id: Option<mpsc::Sender<ConnectionId>>,
         executor: E,
     ) -> impl Future<Output = ()> {
         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");
-                                    }
-                                    if let Some(mut notifications) = notifications {
-                                        let _ = notifications.send(()).await;
+                                        handle_message.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<Self>, 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<Self>,
         state: &Store,

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,