From 7e5a3f9f6b8f457235a44be0eb2589bc71947ff5 Mon Sep 17 00:00:00 2001 From: Nathan Sobo Date: Fri, 8 Apr 2022 10:06:51 -0600 Subject: [PATCH] Introduce structured logging We're enabling the log crate feature everywhere, but only using it on the server for now. Co-Authored-By: Antonio Scandurra --- Cargo.lock | 76 +++++++++++++++++---- crates/client/Cargo.toml | 2 +- crates/editor/Cargo.toml | 2 +- crates/gpui/Cargo.toml | 4 +- crates/journal/Cargo.toml | 2 +- crates/language/Cargo.toml | 2 +- crates/lsp/Cargo.toml | 2 +- crates/project/Cargo.toml | 2 +- crates/rpc/Cargo.toml | 2 +- crates/search/Cargo.toml | 2 +- crates/server/Cargo.toml | 2 + crates/server/src/home.rs | 9 +-- crates/server/src/main.rs | 8 ++- crates/server/src/rpc.rs | 10 +-- crates/sum_tree/Cargo.toml | 2 +- crates/text/Cargo.toml | 2 +- crates/theme_selector/Cargo.toml | 2 +- crates/theme_selector/src/theme_selector.rs | 2 +- crates/util/Cargo.toml | 2 +- crates/vim/Cargo.toml | 2 +- crates/workspace/Cargo.toml | 2 +- crates/zed/Cargo.toml | 2 +- 22 files changed, 98 insertions(+), 43 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index e4b99c656691def6257363a1dfe14c2f9bbc7cd8..8a026ee11bc527b5c2a067cbd60fce84a5b73544 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -614,7 +614,7 @@ dependencies = [ "cexpr", "clang-sys", "clap 2.33.3", - "env_logger", + "env_logger 0.8.3", "lazy_static", "lazycell", "log", @@ -1634,7 +1634,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger", + "env_logger 0.8.3", "futures", "fuzzy", "gpui", @@ -1702,6 +1702,15 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b5320ae4c3782150d900b79807611a59a99fc9a1d61d686faafc24b93fc8d7ca" +[[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" @@ -1724,6 +1733,15 @@ dependencies = [ "serde", ] +[[package]] +name = "erased-serde" +version = "0.3.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad132dd8d0d0b546348d7d86cb3191aad14b34e5f979781fc005c80d4ac67ffd" +dependencies = [ + "serde", +] + [[package]] name = "etagere" version = "0.2.4" @@ -1806,7 +1824,7 @@ version = "0.1.0" dependencies = [ "ctor", "editor", - "env_logger", + "env_logger 0.8.3", "fuzzy", "gpui", "postage", @@ -2235,7 +2253,7 @@ dependencies = [ "core-text", "ctor", "dhat", - "env_logger", + "env_logger 0.8.3", "etagere", "font-kit", "foreign-types", @@ -2652,6 +2670,18 @@ dependencies = [ "wasm-bindgen", ] +[[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 = "jwt-simple" version = "0.10.1" @@ -2715,7 +2745,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger", + "env_logger 0.8.3", "futures", "fuzzy", "gpui", @@ -2834,11 +2864,12 @@ dependencies = [ [[package]] name = "log" -version = "0.4.14" +version = "0.4.16" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710" +checksum = "6389c490849ff5bc16be905ae24bc913a9c8892e19b2341dbc175e14c341c2b8" dependencies = [ "cfg-if 1.0.0", + "serde", "value-bag", ] @@ -2871,7 +2902,7 @@ dependencies = [ "async-pipe", "collections", "ctor", - "env_logger", + "env_logger 0.8.3", "futures", "gpui", "log", @@ -4342,6 +4373,15 @@ dependencies = [ "syn", ] +[[package]] +name = "serde_fmt" +version = "1.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2963a69a2b3918c1dc75a45a18bd3fcd1120e31d3f59deb1b2f9b5d5ffb8baa4" +dependencies = [ + "serde", +] + [[package]] name = "serde_json" version = "1.0.64" @@ -4986,7 +5026,7 @@ version = "0.1.0" dependencies = [ "arrayvec 0.7.1", "ctor", - "env_logger", + "env_logger 0.8.3", "log", "rand 0.8.3", ] @@ -5018,6 +5058,9 @@ name = "sval" version = "1.0.0-alpha.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "45f6ee7c7b87caf59549e9fe45d6a69c75c8019e79e212a835c5da0e92f0ba08" +dependencies = [ + "serde", +] [[package]] name = "svg_fmt" @@ -5116,7 +5159,7 @@ dependencies = [ "clock", "collections", "ctor", - "env_logger", + "env_logger 0.8.3", "gpui", "lazy_static", "log", @@ -5704,11 +5747,14 @@ checksum = "bc5cf98d8186244414c848017f0e2676b3fcb46807f6668a97dfe67359a3c4b7" [[package]] name = "value-bag" -version = "1.0.0-alpha.7" +version = "1.0.0-alpha.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "dd320e1520f94261153e96f7534476ad869c14022aee1e59af7c778075d840ae" +checksum = "79923f7731dc61ebfba3633098bf3ac533bbd35ccd8c57e7088d9a5eebe0263f" dependencies = [ "ctor", + "erased-serde", + "serde", + "serde_fmt", "sval", "version_check", ] @@ -6030,7 +6076,7 @@ dependencies = [ "dirs 3.0.1", "easy-parallel", "editor", - "env_logger", + "env_logger 0.8.3", "file_finder", "fsevent", "futures", @@ -6108,16 +6154,18 @@ dependencies = [ "ctor", "editor", "either", - "env_logger", + "env_logger 0.8.3", "envy", "futures", "gpui", "handlebars", "http-auth-basic", + "json_env_logger", "jwt-simple", "language", "lazy_static", "lipsum", + "log", "lsp", "oauth2", "oauth2-surf", diff --git a/crates/client/Cargo.toml b/crates/client/Cargo.toml index c60b82f1f8e9dfd762d24d802962b3d7bec103a7..211dc7a04b4c67e87e1d009ea7d35019fe597f74 100644 --- a/crates/client/Cargo.toml +++ b/crates/client/Cargo.toml @@ -21,7 +21,7 @@ async-tungstenite = { version = "0.16", features = ["async-tls"] } futures = "0.3" image = "0.23" lazy_static = "1.4.0" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } rand = "0.8.3" diff --git a/crates/editor/Cargo.toml b/crates/editor/Cargo.toml index 076fecbfcbb58385e859b97b793b3bb0a41e8302..a1c1409d06558f47b593c8265516a3e4038b71ae 100644 --- a/crates/editor/Cargo.toml +++ b/crates/editor/Cargo.toml @@ -40,7 +40,7 @@ futures = "0.3" indoc = "1.0.4" itertools = "0.10" lazy_static = "1.4" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } ordered-float = "2.1.1" parking_lot = "0.11" postage = { version = "0.4", features = ["futures-traits"] } diff --git a/crates/gpui/Cargo.toml b/crates/gpui/Cargo.toml index 9973ac6549c6d77e81cc2e5cc48db7612f4cff6d..442a2b5b2f312cc63da62851b8a0faa52b25e8a4 100644 --- a/crates/gpui/Cargo.toml +++ b/crates/gpui/Cargo.toml @@ -25,7 +25,7 @@ etagere = "0.2" futures = "0.3" image = "0.23" lazy_static = "1.4.0" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } num_cpus = "1.13" ordered-float = "2.1.1" parking = "2.0.0" @@ -67,6 +67,6 @@ core-graphics = "0.22.2" core-text = "19.2" font-kit = { git = "https://github.com/zed-industries/font-kit", rev = "8eaf7a918eafa28b0a37dc759e2e0e7683fa24f1" } foreign-types = "0.3" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } metal = "0.21.0" objc = "0.2" diff --git a/crates/journal/Cargo.toml b/crates/journal/Cargo.toml index 8ccd9dc27f081cc87495a3a828e4f17a345daef9..94dcf8e407411a266ea9ab3752ffa8d66ad8097b 100644 --- a/crates/journal/Cargo.toml +++ b/crates/journal/Cargo.toml @@ -14,4 +14,4 @@ util = { path = "../util" } workspace = { path = "../workspace" } chrono = "0.4" dirs = "4.0" -log = "0.4" \ No newline at end of file +log = { version = "0.4.16", features = ["kv_unstable_serde"] } diff --git a/crates/language/Cargo.toml b/crates/language/Cargo.toml index 0518261f847fa460bbb2d054e7fc65b9019c4686..275581f807dafa30f8a95421fc7d8990aff3511c 100644 --- a/crates/language/Cargo.toml +++ b/crates/language/Cargo.toml @@ -35,7 +35,7 @@ async-broadcast = "0.3.4" async-trait = "0.1" futures = "0.3" lazy_static = "1.4" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } rand = { version = "0.8.3", optional = true } diff --git a/crates/lsp/Cargo.toml b/crates/lsp/Cargo.toml index 199da8c24edc6ca1041b312a03f4e76d3e6b3b1b..c749261bf5a6eb9cbe092f2301cc6bca7a75a329 100644 --- a/crates/lsp/Cargo.toml +++ b/crates/lsp/Cargo.toml @@ -17,7 +17,7 @@ util = { path = "../util" } anyhow = "1.0" async-pipe = { git = "https://github.com/zed-industries/async-pipe-rs", rev = "82d00a04211cf4e1236029aa03e6b6ce2a74c553", optional = true } futures = "0.3" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } lsp-types = "0.91" parking_lot = "0.11" postage = { version = "0.4.1", features = ["futures-traits"] } diff --git a/crates/project/Cargo.toml b/crates/project/Cargo.toml index 8fda3aa0f32e9580c7a82a9ece6c3d3653a8a851..728dae312852480908315becf79e6c7ded7b9e99 100644 --- a/crates/project/Cargo.toml +++ b/crates/project/Cargo.toml @@ -35,7 +35,7 @@ futures = "0.3" ignore = "0.4" lazy_static = "1.4.0" libc = "0.2" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } rand = "0.8.3" diff --git a/crates/rpc/Cargo.toml b/crates/rpc/Cargo.toml index e773b3f0bada6d8adb65d925622fc09f69db42da..62fe9e5bda17962237ab5f7fcbc8e3240da7563c 100644 --- a/crates/rpc/Cargo.toml +++ b/crates/rpc/Cargo.toml @@ -17,7 +17,7 @@ async-lock = "2.4" async-tungstenite = "0.16" base64 = "0.13" futures = "0.3" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } prost = "0.8" diff --git a/crates/search/Cargo.toml b/crates/search/Cargo.toml index 77961de01f3efdee86603d01b99c259509d04c9e..295526939a2904aed209c4e4f397ebb4d9038030 100644 --- a/crates/search/Cargo.toml +++ b/crates/search/Cargo.toml @@ -18,7 +18,7 @@ theme = { path = "../theme" } util = { path = "../util" } workspace = { path = "../workspace" } anyhow = "1.0" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } postage = { version = "0.4.1", features = ["futures-traits"] } [dev-dependencies] diff --git a/crates/server/Cargo.toml b/crates/server/Cargo.toml index 6e27fa16c523cf0908f10fff8cdf772c54269b84..6c43b467acb3f93632bbf0ca0bd8e18813cb5cd2 100644 --- a/crates/server/Cargo.toml +++ b/crates/server/Cargo.toml @@ -29,8 +29,10 @@ envy = "0.4.2" futures = "0.3" handlebars = "3.5" http-auth-basic = "0.1.3" +json_env_logger = "0.1" jwt-simple = "0.10.0" lipsum = { version = "0.8", optional = true } +log = { version = "0.4.16", features = ["kv_unstable_serde"] } oauth2 = { version = "4.0.0", default_features = false } oauth2-surf = "0.1.1" parking_lot = "0.11.1" diff --git a/crates/server/src/home.rs b/crates/server/src/home.rs index 69bee449a8bc9aa56f699842950feaffc944733f..bddeadc35203e5f258cc7de70fad699d649d27c9 100644 --- a/crates/server/src/home.rs +++ b/crates/server/src/home.rs @@ -1,7 +1,8 @@ use crate::{AppState, Request, RequestExt as _}; -use serde::Deserialize; +use log::as_serde; +use serde::{Deserialize, Serialize}; use std::sync::Arc; -use tide::{http::mime, log, Server}; +use tide::{http::mime, Server}; pub fn add_routes(app: &mut Server>) { app.at("/").get(get_home); @@ -18,7 +19,7 @@ async fn get_home(mut request: Request) -> tide::Result { } async fn post_signup(mut request: Request) -> tide::Result { - #[derive(Debug, Deserialize)] + #[derive(Debug, Deserialize, Serialize)] struct Form { github_login: String, email_address: String, @@ -38,7 +39,7 @@ async fn post_signup(mut request: Request) -> tide::Result { .map(str::to_string) .unwrap_or(form.github_login); - log::info!("Signup submitted: {:?}", form); + log::info!(form = as_serde!(form); "signup submitted"); // Save signup in the database request diff --git a/crates/server/src/main.rs b/crates/server/src/main.rs index 47c8c82190bfbab775b981ebdfa39875a83f764f..97de59f36bdc51c734e516ac80ac16d4384d29ca 100644 --- a/crates/server/src/main.rs +++ b/crates/server/src/main.rs @@ -27,7 +27,7 @@ use rust_embed::RustEmbed; use serde::{Deserialize, Serialize}; use std::sync::Arc; use surf::http::cookies::SameSite; -use tide::{log, sessions::SessionMiddleware}; +use tide::sessions::SessionMiddleware; use tide_compress::CompressMiddleware; type Request = tide::Request>; @@ -138,7 +138,11 @@ struct LayoutData { #[async_std::main] async fn main() -> tide::Result<()> { - log::start(); + if std::env::var("LOG_JSON").is_ok() { + json_env_logger::init(); + } else { + tide::log::start(); + } if let Err(error) = env::load_dotenv() { log::error!( diff --git a/crates/server/src/rpc.rs b/crates/server/src/rpc.rs index 51c7807660708ea47209a5d133d2f7128e33b4f7..ace7080c8112139d97b5bc9bbf9f635808edfb7d 100644 --- a/crates/server/src/rpc.rs +++ b/crates/server/src/rpc.rs @@ -11,6 +11,7 @@ use async_std::task; use async_tungstenite::{tungstenite::protocol::Role, WebSocketStream}; use collections::{HashMap, HashSet}; use futures::{channel::mpsc, future::BoxFuture, FutureExt, SinkExt, StreamExt}; +use log::{as_debug, as_display}; use parking_lot::{RwLock, RwLockReadGuard, RwLockWriteGuard}; use rpc::{ proto::{self, AnyTypedEnvelope, EntityMessage, EnvelopedMessage, RequestMessage}, @@ -25,7 +26,6 @@ use std::{ }; use store::{Store, Worktree}; use surf::StatusCode; -use tide::log; use tide::{ http::headers::{HeaderName, CONNECTION, UPGRADE}, Request, Response, @@ -218,16 +218,16 @@ impl Server { if let Some(message) = message { let start_time = Instant::now(); let type_name = message.payload_type_name(); - log::info!("rpc message received. connection:{}, type:{}", connection_id, 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!("rpc message error. connection:{}, type:{}, error:{:?}", connection_id, type_name, err); + log::error!(connection_id = connection_id.0, type = type_name, error = as_display!(err); "rpc message error"); } else { - log::info!("rpc message handled. connection:{}, type:{}, duration:{:?}", connection_id, type_name, start_time.elapsed()); + 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; @@ -242,7 +242,7 @@ impl Server { log::warn!("unhandled message: {}", type_name); } } else { - log::info!("rpc connection closed {:?}", addr); + log::info!(address = as_debug!(addr); "rpc connection closed"); break; } } diff --git a/crates/sum_tree/Cargo.toml b/crates/sum_tree/Cargo.toml index f43cdd43d45ea4d9df206da9c6315dc5ac034827..b430f2e6b06703b591cf767b405e3b0272061779 100644 --- a/crates/sum_tree/Cargo.toml +++ b/crates/sum_tree/Cargo.toml @@ -9,7 +9,7 @@ doctest = false [dependencies] arrayvec = "0.7.1" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } [dev-dependencies] ctor = "0.1" diff --git a/crates/text/Cargo.toml b/crates/text/Cargo.toml index f6a887eb27fb8ced9a6628c80bfdc7ecff9b8780..a7209a750765587f7b48cc6ebf178abbb55f87b6 100644 --- a/crates/text/Cargo.toml +++ b/crates/text/Cargo.toml @@ -17,7 +17,7 @@ sum_tree = { path = "../sum_tree" } anyhow = "1.0.38" arrayvec = "0.7.1" lazy_static = "1.4" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11" postage = { version = "0.4.1", features = ["futures-traits"] } rand = { version = "0.8.3", optional = true } diff --git a/crates/theme_selector/Cargo.toml b/crates/theme_selector/Cargo.toml index 585d10d563c9919deb8a878576a14c9b09f35e72..9993287c8580b65870e20736c51ea66ca87f90c6 100644 --- a/crates/theme_selector/Cargo.toml +++ b/crates/theme_selector/Cargo.toml @@ -14,7 +14,7 @@ gpui = { path = "../gpui" } theme = { path = "../theme" } settings = { path = "../settings" } workspace = { path = "../workspace" } -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } smol = "1.2.5" diff --git a/crates/theme_selector/src/theme_selector.rs b/crates/theme_selector/src/theme_selector.rs index 5bcbd62e09578c1210d32a4be10b435c8f695a04..74ff49e7104632c02380c068a9993202a868d5a4 100644 --- a/crates/theme_selector/src/theme_selector.rs +++ b/crates/theme_selector/src/theme_selector.rs @@ -7,9 +7,9 @@ use gpui::{ AppContext, Axis, Element, ElementBox, Entity, MutableAppContext, RenderContext, View, ViewContext, ViewHandle, }; +use settings::Settings; use std::{cmp, sync::Arc}; use theme::{Theme, ThemeRegistry}; -use settings::Settings; use workspace::{ menu::{Confirm, SelectNext, SelectPrev}, Workspace, diff --git a/crates/util/Cargo.toml b/crates/util/Cargo.toml index 9d39fb04e2f9b5c8192d9792d30decd614030511..cfc68e0b1676bf44a834d3a5817d781b81309f82 100644 --- a/crates/util/Cargo.toml +++ b/crates/util/Cargo.toml @@ -12,7 +12,7 @@ test-support = ["rand", "serde_json", "tempdir"] [dependencies] anyhow = "1.0.38" futures = "0.3" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } rand = { version = "0.8", optional = true } surf = "2.2" tempdir = { version = "0.3.7", optional = true } diff --git a/crates/vim/Cargo.toml b/crates/vim/Cargo.toml index 4ffa6a4363c5e08e17899db49d20a46a568dcca9..6386141ffc2d53c44700f16220c87609282deabb 100644 --- a/crates/vim/Cargo.toml +++ b/crates/vim/Cargo.toml @@ -14,7 +14,7 @@ gpui = { path = "../gpui" } language = { path = "../language" } settings = { path = "../settings" } workspace = { path = "../workspace" } -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } [dev-dependencies] indoc = "1.0.4" diff --git a/crates/workspace/Cargo.toml b/crates/workspace/Cargo.toml index 75d1b1b8f2667ab111278d2efa6979c66e7d50bd..a2a6c74bac78e7edffffbf1cbdeb6fd8b199789f 100644 --- a/crates/workspace/Cargo.toml +++ b/crates/workspace/Cargo.toml @@ -22,7 +22,7 @@ theme = { path = "../theme" } util = { path = "../util" } anyhow = "1.0.38" futures = "0.3" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } parking_lot = "0.11.1" postage = { version = "0.4.1", features = ["futures-traits"] } serde = { version = "1", features = ["derive", "rc"] } diff --git a/crates/zed/Cargo.toml b/crates/zed/Cargo.toml index f87046b05ebc5479d6282efd30028500f7a49c53..1a5a214f035ce1b8738f743573ed0e02170df314 100644 --- a/crates/zed/Cargo.toml +++ b/crates/zed/Cargo.toml @@ -75,7 +75,7 @@ image = "0.23" indexmap = "1.6.2" lazy_static = "1.4.0" libc = "0.2" -log = "0.4" +log = { version = "0.4.16", features = ["kv_unstable_serde"] } log-panics = { version = "2.0", features = ["with-backtrace"] } num_cpus = "1.13.0" parking_lot = "0.11.1"