server: add tracing for graphql handling

server/Cargo.toml

@@ -15,7 +15,6 @@ async-trait = "0.1.81"
 build-info = "0.0.38"
 cacher = {git = "http://git-private.h.xinu.tv/wathiede/cacher.git"}
 css-inline = "0.13.0"
-glog = "0.1.0"
 html-escape = "0.2.13"
 linkify = "0.10.0"
 log = "0.4.17"
@@ -35,8 +34,11 @@ sqlx = { version = "0.7.4", features = ["postgres", "runtime-tokio", "time"] }
 tantivy = "0.22.0"
 thiserror = "1.0.37"
 tokio = "1.26.0"
+tracing = "0.1.41"
 url = "2.5.2"
 urlencoding = "2.1.3"
+#xtracing = { path = "../../xtracing" }
+xtracing = { git = "http://git-private.h.xinu.tv/wathiede/xtracing.git" }
 
 [build-dependencies]
 build-info-build = "0.0.38"

server/src/bin/server.rs

@@ -7,7 +7,6 @@ use std::{error::Error, io::Cursor, str::FromStr};
 
 use async_graphql::{http::GraphiQLSource, EmptySubscription, Schema};
 use async_graphql_rocket::{GraphQLQuery, GraphQLRequest, GraphQLResponse};
-use glog::Flags;
 use notmuch::{Notmuch, NotmuchError, ThreadSet};
 use rocket::{
     fairing::AdHoc,
@@ -176,14 +175,7 @@ async fn graphql_request(
 
 #[rocket::main]
 async fn main() -> Result<(), Box<dyn Error>> {
-    glog::new()
-        .init(Flags {
-            colorlogtostderr: true,
-            //alsologtostderr: true, // use logtostderr to only write to stderr and not to files
-            logtostderr: true,
-            ..Default::default()
-        })
-        .unwrap();
+    let _guard = xtracing::init(env!("CARGO_BIN_NAME"))?;
     build_info::build_info!(fn bi);
     info!("Build Info: {}", shared::build_version(bi));
     let allowed_origins = AllowedOrigins::all();

server/src/graphql.rs

@@ -9,6 +9,7 @@ use log::info;
 use notmuch::Notmuch;
 use serde::{Deserialize, Serialize};
 use sqlx::postgres::PgPool;
+use tracing::instrument;
 
 use crate::{config::Config, newsreader, nm, tantivy::TantivyConnection, Query};
 
@@ -269,6 +270,7 @@ impl QueryRoot {
         build_info::build_info!(fn bi);
         Ok(shared::build_version(bi))
     }
+    #[instrument(skip_all, fields(query=query))]
     async fn count<'ctx>(&self, ctx: &Context<'ctx>, query: String) -> Result<usize, Error> {
         let nm = ctx.data_unchecked::<Notmuch>();
         let pool = ctx.data_unchecked::<PgPool>();
@@ -284,6 +286,7 @@ impl QueryRoot {
         Ok(total)
     }
 
+    #[instrument(skip_all, fields(query=query))]
     async fn search<'ctx>(
         &self,
         ctx: &Context<'ctx>,
@@ -418,6 +421,7 @@ impl QueryRoot {
         .await?)
     }
 
+    #[instrument(skip_all)]
     async fn tags<'ctx>(&self, ctx: &Context<'ctx>) -> FieldResult<Vec<Tag>> {
         let nm = ctx.data_unchecked::<Notmuch>();
         let pool = ctx.data_unchecked::<PgPool>();
@@ -426,6 +430,7 @@ impl QueryRoot {
         tags.append(&mut nm::tags(nm, needs_unread)?);
         Ok(tags)
     }
+    #[instrument(skip_all, fields(thread_id=thread_id))]
     async fn thread<'ctx>(&self, ctx: &Context<'ctx>, thread_id: String) -> Result<Thread, Error> {
         let nm = ctx.data_unchecked::<Notmuch>();
         let pool = ctx.data_unchecked::<PgPool>();
@@ -500,6 +505,7 @@ async fn tantivy_search(
 pub struct Mutation;
 #[Object]
 impl Mutation {
+    #[instrument(skip_all, fields(query, bool))]
     async fn set_read_status<'ctx>(
         &self,
         ctx: &Context<'ctx>,
@@ -516,6 +522,7 @@ impl Mutation {
         nm::set_read_status(nm, &query, unread).await?;
         Ok(true)
     }
+    #[instrument(skip_all, fields(query, tag))]
     async fn tag_add<'ctx>(
         &self,
         ctx: &Context<'ctx>,
@@ -527,6 +534,7 @@ impl Mutation {
         nm.tag_add(&tag, &query)?;
         Ok(true)
     }
+    #[instrument(skip_all, fields(query, tag))]
     async fn tag_remove<'ctx>(
         &self,
         ctx: &Context<'ctx>,
@@ -548,6 +556,7 @@ impl Mutation {
 
         Ok(true)
     }
+    #[instrument(skip_all)]
     async fn refresh<'ctx>(&self, ctx: &Context<'ctx>) -> Result<bool, Error> {
         let nm = ctx.data_unchecked::<Notmuch>();
         let tantivy = ctx.data_unchecked::<TantivyConnection>();

server/src/nm.rs

@@ -9,6 +9,7 @@ use log::{error, info, warn};
 use mailparse::{parse_content_type, parse_mail, MailHeader, MailHeaderMap, ParsedMail};
 use memmap::MmapOptions;
 use notmuch::Notmuch;
+use tracing::instrument;
 
 use crate::{
     compute_offset_limit,
@@ -48,6 +49,7 @@ pub fn threadset_to_messages(thread_set: notmuch::ThreadSet) -> Result<Vec<Messa
     Ok(Vec::new())
 }
 
+#[instrument(name="nm::count", skip_all, fields(query=?query))]
 pub async fn count(nm: &Notmuch, query: &Query) -> Result<usize, ServerError> {
     if !is_notmuch_query(query) {
         return Ok(0);
@@ -56,6 +58,7 @@ pub async fn count(nm: &Notmuch, query: &Query) -> Result<usize, ServerError> {
     Ok(nm.count(&query)?)
 }
 
+#[instrument(name="nm::search", skip_all, fields(query=?query))]
 pub async fn search(
     nm: &Notmuch,
     after: Option<i32>,
@@ -99,6 +102,7 @@ pub async fn search(
         .collect())
 }
 
+#[instrument(name="nm::tags", skip_all, fields(needs_unread=needs_unread))]
 pub fn tags(nm: &Notmuch, needs_unread: bool) -> Result<Vec<Tag>, ServerError> {
     let now = Instant::now();
     let unread_msg_cnt: HashMap<String, usize> = if needs_unread {
@@ -140,6 +144,7 @@ pub fn tags(nm: &Notmuch, needs_unread: bool) -> Result<Vec<Tag>, ServerError> {
     Ok(tags)
 }
 
+#[instrument(name="nm::thread", skip_all, fields(thread_id=thread_id))]
 pub async fn thread(
     nm: &Notmuch,
     thread_id: String,
@@ -851,6 +856,7 @@ fn render_content_type_tree(m: &ParsedMail) -> String {
     )
 }
 
+#[instrument(name="nm::set_read_status", skip_all, fields(query=?query, unread=unread))]
 pub async fn set_read_status<'ctx>(
     nm: &Notmuch,
     query: &Query,

server/src/tantivy.rs

@@ -9,6 +9,7 @@ use tantivy::{
     schema::{Facet, IndexRecordOption, Value},
     DocAddress, Index, Searcher, TantivyDocument, TantivyError, Term,
 };
+use tracing::instrument;
 
 use crate::{
     compute_offset_limit,
@@ -42,6 +43,7 @@ impl TantivyConnection {
             db_path: tantivy_db_path.to_string(),
         })
     }
+    #[instrument(name = "tantivy::refresh", skip_all)]
     pub async fn refresh(&self, pool: &PgPool) -> Result<(), ServerError> {
         let start_time = std::time::Instant::now();
         let p_uids: Vec<_> = sqlx::query_file!("sql/all-uids.sql")
@@ -167,6 +169,7 @@ impl TantivyConnection {
         index_writer.commit()?;
         Ok(())
     }
+    #[instrument(name = "tantivy::reindex_thread", skip_all, fields(query=?query))]
     pub async fn reindex_thread(&self, pool: &PgPool, query: &Query) -> Result<(), ServerError> {
         let uids: Vec<_> = query
             .uids
@@ -176,6 +179,7 @@ impl TantivyConnection {
             .collect();
         Ok(self.reindex_uids(pool, &uids).await?)
     }
+    #[instrument(name = "tantivy::reindex_all", skip_all)]
     pub async fn reindex_all(&self, pool: &PgPool) -> Result<(), ServerError> {
         let rows = sqlx::query_file!("sql/all-posts.sql")
             .fetch_all(pool)
@@ -224,6 +228,7 @@ impl TantivyConnection {
         Ok((searcher, Box::new(search_query)))
     }
 
+    #[instrument(name="tantivy::count", skip_all, fields(query=?query))]
     pub async fn count(&self, query: &Query) -> Result<usize, ServerError> {
         if !is_tantivy_query(query) {
             return Ok(0);
@@ -233,6 +238,7 @@ impl TantivyConnection {
         let (searcher, query) = self.searcher_and_query(&query)?;
         Ok(searcher.search(&query, &Count)?)
     }
+    #[instrument(name="tantivy::search", skip_all, fields(query=?query))]
     pub async fn search(
         &self,
         pool: &PgPool,