Merge pull request #1731 from tursodatabase/logging-qol

Improve logging QOL

Author: MarinPostma

libsql-server/src/connection/mod.rs

@@ -10,6 +10,7 @@ use tonic::metadata::BinaryMetadataValue;
 
 use crate::auth::Authenticated;
 use crate::error::Error;
+use crate::http::user::timing::sample_time;
 use crate::metrics::{
     CONCURRENT_CONNECTIONS_COUNT, CONNECTION_ALIVE_DURATION, CONNECTION_CREATE_TIME,
 };
@@ -398,6 +399,7 @@ pub struct TrackedConnection<DB> {
 
 impl<T> Drop for TrackedConnection<T> {
     fn drop(&mut self) {
+        sample_time("connection-duration", self.created_at.elapsed());
         CONCURRENT_CONNECTIONS_COUNT.decrement(1.0);
         CONNECTION_ALIVE_DURATION.record(self.created_at.elapsed());
     }

libsql-server/src/http/admin/mod.rs

@@ -48,6 +48,7 @@ struct AppState<C> {
     user_http_server: Arc<hrana::http::Server>,
     connector: C,
     metrics: Metrics,
+    set_env_filter: Option<Box<dyn Fn(&str) -> anyhow::Result<()> + Sync + Send + 'static>>,
 }
 
 impl<C> FromRef<Arc<AppState<C>>> for Metrics {
@@ -66,6 +67,7 @@ pub async fn run<A, C>(
     disable_metrics: bool,
     shutdown: Arc<Notify>,
     auth: Option<Arc<str>>,
+    set_env_filter: Option<Box<dyn Fn(&str) -> anyhow::Result<()> + Sync + Send + 'static>>,
 ) -> anyhow::Result<()>
 where
     A: crate::net::Accept,
@@ -167,11 +169,13 @@ where
         .route("/profile/heap/enable", post(enable_profile_heap))
         .route("/profile/heap/disable/:id", post(disable_profile_heap))
         .route("/profile/heap/:id", delete(delete_profile_heap))
+        .route("/log-filter", post(handle_set_log_filter))
         .with_state(Arc::new(AppState {
             namespaces: namespaces.clone(),
             connector,
             user_http_server,
             metrics,
+            set_env_filter,
         }))
         .layer(
             tower_http::trace::TraceLayer::new_for_http()
@@ -512,6 +516,16 @@ async fn handle_delete_namespace<C>(
     Ok(())
 }
 
+async fn handle_set_log_filter<C>(
+    State(app_state): State<Arc<AppState<C>>>,
+    body: String,
+) -> crate::Result<()> {
+    if let Some(ref cb) = app_state.set_env_filter {
+        cb(&body)?;
+    }
+    Ok(())
+}
+
 async fn handle_checkpoint<C>(
     State(app_state): State<Arc<AppState<C>>>,
     Path(namespace): Path<NamespaceName>,

libsql-server/src/http/user/timing.rs

@@ -40,13 +40,22 @@ macro_rules! record_time {
             let __ret__ = {
                 $($rest)*
             };
-            let _ = $crate::http::user::timing::TIMINGS.try_with(|t| t.record($k, __before__.elapsed()));
+            let __elapsed__ = __before__.elapsed();
+            tracing::debug!(target: "timings", name = $k, elapsed = tracing::field::debug(__elapsed__));
+            let _ = $crate::http::user::timing::TIMINGS.try_with(|t| t.record($k, __elapsed__));
             __ret__
         }
     };
 }
 
+pub fn sample_time(name: &'static str, duration: Duration) {
+    tracing::debug!(target: "timings", name = name, elapsed = tracing::field::debug(duration));
+    let _ = TIMINGS.try_with(|t| t.record(name, duration));
+}
+
+#[tracing::instrument(skip_all, fields(req_id = tracing::field::debug(uuid::Uuid::new_v4())))]
 pub(crate) async fn timings_middleware<B>(request: Request<B>, next: Next<B>) -> Response {
+    // tracing::error!("hello");
     TIMINGS
         .scope(Default::default(), async move {
             let mut response = record_time! {

libsql-server/src/lib.rs

@@ -181,6 +181,7 @@ pub struct Server<C = HttpConnector, A = AddrIncoming, D = HttpsConnector<HttpCo
     pub should_sync_from_storage: bool,
     pub force_load_wals: bool,
     pub sync_conccurency: usize,
+    pub set_log_level: Option<Box<dyn Fn(&str) -> anyhow::Result<()> + Send + Sync + 'static>>,
 }
 
 impl<C, A, D> Default for Server<C, A, D> {
@@ -210,6 +211,7 @@ impl<C, A, D> Default for Server<C, A, D> {
             should_sync_from_storage: false,
             force_load_wals: false,
             sync_conccurency: 8,
+            set_log_level: None,
         }
     }
 }
@@ -225,6 +227,7 @@ struct Services<A, P, S, C> {
     disable_default_namespace: bool,
     db_config: DbConfig,
     user_auth_strategy: Auth,
+    pub set_log_level: Option<Box<dyn Fn(&str) -> anyhow::Result<()> + Send + Sync + 'static>>,
 }
 
 struct TaskManager {
@@ -304,7 +307,7 @@ where
     S: ReplicationLog,
     C: Connector,
 {
-    fn configure(self, task_manager: &mut TaskManager) {
+    fn configure(mut self, task_manager: &mut TaskManager) {
         let user_http = UserApi {
             http_acceptor: self.user_api_config.http_acceptor,
             hrana_ws_acceptor: self.user_api_config.hrana_ws_acceptor,
@@ -339,6 +342,7 @@ where
                     disable_metrics,
                     shutdown,
                     auth_key.map(Into::into),
+                    self.set_log_level.take(),
                 )
             });
         }
@@ -538,7 +542,7 @@ where
     }
 
     fn make_services<P: Proxy, L: ReplicationLog>(
-        self,
+        mut self,
         namespace_store: NamespaceStore,
         idle_shutdown_kicker: Option<IdleShutdownKicker>,
         proxy_service: P,
@@ -556,6 +560,7 @@ where
             disable_default_namespace: self.disable_default_namespace,
             db_config: self.db_config,
             user_auth_strategy,
+            set_log_level: self.set_log_level.take(),
         }
     }
 

libsql-server/src/main.rs

@@ -1,6 +1,7 @@
 use std::env;
 use std::net::SocketAddr;
 use std::path::PathBuf;
+use std::str::FromStr;
 use std::sync::Arc;
 
 use anyhow::{bail, Context as _, Result};
@@ -10,9 +11,9 @@ use hyper::client::HttpConnector;
 use libsql_server::auth::{parse_http_basic_auth_arg, parse_jwt_keys, user_auth_strategies, Auth};
 use tokio::sync::Notify;
 use tokio::time::Duration;
-use tracing_subscriber::prelude::*;
 use tracing_subscriber::util::SubscriberInitExt;
 use tracing_subscriber::Layer;
+use tracing_subscriber::{prelude::*, EnvFilter};
 
 use libsql_server::config::{
     AdminApiConfig, BottomlessConfig, DbConfig, HeartbeatConfig, MetaStoreConfig, RpcClientConfig,
@@ -641,7 +642,10 @@ fn make_meta_store_config(config: &Cli) -> anyhow::Result<MetaStoreConfig> {
     })
 }
 
-async fn build_server(config: &Cli) -> anyhow::Result<Server> {
+async fn build_server(
+    config: &Cli,
+    set_log_level: impl Fn(&str) -> anyhow::Result<()> + Send + Sync + 'static,
+) -> anyhow::Result<Server> {
     let db_config = make_db_config(config)?;
     let user_api_config = make_user_api_config(config).await?;
     let admin_api_config = make_admin_api_config(config).await?;
@@ -709,6 +713,7 @@ async fn build_server(config: &Cli) -> anyhow::Result<Server> {
         should_sync_from_storage: config.sync_from_storage,
         force_load_wals: config.force_load_wals,
         sync_conccurency: config.sync_conccurency,
+        set_log_level: Some(Box::new(set_log_level)),
     })
 }
 
@@ -748,16 +753,24 @@ async fn main() -> Result<()> {
     #[cfg(feature = "debug-tools")]
     enable_libsql_logging();
 
+    let (filter, reload_handle) =
+        tracing_subscriber::reload::Layer::new(tracing_subscriber::EnvFilter::from_default_env());
+    let set_log_level = move |s: &str| -> anyhow::Result<()> {
+        let filter = EnvFilter::from_str(s.trim())?;
+        reload_handle.reload(filter)?;
+        Ok(())
+    };
+
     registry
         .with(
             tracing_subscriber::fmt::layer()
                 .with_ansi(false)
-                .with_filter(tracing_subscriber::EnvFilter::from_default_env()),
+                .with_filter(filter),
         )
         .init();
 
     args.print_welcome_message();
-    let server = build_server(&args).await?;
+    let server = build_server(&args, set_log_level).await?;
     server.start().await?;
 
     Ok(())