feat: 📈 intensive tracing log

Author: Eason0729

backend/Cargo.toml

@@ -30,6 +30,7 @@ hickory-resolver = "0.24.0"
 crossbeam-queue = "0.3.8"
 dashmap = "5.5.3"
 tracing-opentelemetry = "0.22.0"
+# a lot of opentelemetry dependencies
 opentelemetry_sdk = { version = "0.21.1", features = ["rt-tokio"] }
 opentelemetry = "0.21.0"
 opentelemetry-stdout = { version = "0.2.0", features = ["metrics"] }
@@ -46,7 +47,7 @@ features = ["json"]
 
 [dependencies.tracing]
 version = "0.1.40"
-features = ["async-await", "log"]
+features = ["async-await", "log", "release_max_level_debug"]
 
 [dependencies.tokio]
 version = "1.34.0"

backend/src/controller/crypto.rs

@@ -3,6 +3,7 @@ use ring::{
     signature::{self, KeyPair},
 };
 use serde::{de::DeserializeOwned, Serialize};
+use tracing::Span;
 
 use crate::{init::config::GlobalConfig, report_internal};
 
@@ -46,8 +47,8 @@ impl From<HashValue> for Vec<u8> {
 }
 
 impl CryptoController {
-    #[tracing::instrument(level = "info")]
-    pub fn new(config: &GlobalConfig) -> Self {
+    #[tracing::instrument(parent=span,name="crypto_construct",level = "info",skip_all)]
+    pub fn new(config: &GlobalConfig, span: &Span) -> Self {
         let rng = rand::SystemRandom::new();
         let pkcs8_bytes = signature::Ed25519KeyPair::generate_pkcs8(&rng).unwrap();
         let signer = signature::Ed25519KeyPair::from_pkcs8(pkcs8_bytes.as_ref()).unwrap();

backend/src/controller/duplicate.rs

@@ -1,22 +1,20 @@
 use quick_cache::sync::Cache;
+use tracing::Span;
 use uuid::Uuid;
 
 pub struct DupController {
     #[cfg(feature = "single-instance")]
     dups: Cache<(i32, Uuid), i32>,
 }
 
-impl Default for DupController {
-    fn default() -> Self {
-        log::debug!("Setup DupController");
+impl DupController {
+    #[tracing::instrument(parent=span, name="duplicate_construct",level = "info",skip_all)]
+    pub fn new(span: &Span) -> Self {
         Self {
             #[cfg(feature = "single-instance")]
             dups: Cache::new(300),
         }
     }
-}
-
-impl DupController {
     pub fn store(&self, user_id: i32, uuid: Uuid, result: i32) {
         #[cfg(feature = "single-instance")]
         self.dups.insert((user_id, uuid), result);

backend/src/controller/judger/mod.rs

@@ -9,6 +9,7 @@ use sea_orm::{ActiveModelTrait, ActiveValue, EntityTrait, QueryOrder};
 use thiserror::Error;
 use tokio_stream::StreamExt;
 use tonic::Status;
+use tracing::{instrument, span, Instrument, Level, Span};
 use uuid::Uuid;
 
 use crate::{
@@ -113,16 +114,18 @@ impl From<JudgeResult> for SubmitStatus {
     }
 }
 
-pub struct SubmitController {
+pub struct JudgerController {
     router: Arc<Router>,
     pubsub: Arc<PubSub<Result<SubmitStatus, Status>, i32>>,
     limiter: Arc<RateLimiter>,
 }
 
-impl SubmitController {
-    pub async fn new(config: &GlobalConfig) -> Result<Self, Error> {
-        Ok(SubmitController {
-            router: Router::new(config.judger.clone()).await?,
+impl JudgerController {
+    #[tracing::instrument(parent=span, name="judger_construct",level = "info",skip_all)]
+    pub async fn new(config: &GlobalConfig, span: &Span) -> Result<Self, Error> {
+        let router = Router::new(config.judger.clone(), span).await?;
+        Ok(JudgerController {
+            router,
             pubsub: Arc::new(PubSub::default()),
             limiter: Arc::new(
                 RateLimiter::builder()
@@ -134,11 +137,13 @@ impl SubmitController {
             ),
         })
     }
+    #[instrument(skip(ps_guard, stream, model, scores))]
     async fn stream(
         ps_guard: PubGuard<Result<SubmitStatus, Status>, i32>,
         mut stream: tonic::Streaming<JudgeResponse>,
         mut model: submit::ActiveModel,
         mut scores: Vec<u32>,
+        submit_id: i32,
     ) {
         let mut result = 0;
         let mut running_case = 0;
@@ -252,7 +257,13 @@ impl SubmitController {
 
         conn.report_success();
 
-        tokio::spawn(Self::stream(tx, res.into_inner(), submit_model, scores));
+        tokio::spawn(Self::stream(
+            tx,
+            res.into_inner(),
+            submit_model,
+            scores,
+            submit_id,
+        ));
 
         Ok(submit_id)
     }

backend/src/controller/judger/route/mod.rs

@@ -14,6 +14,7 @@ use std::{
 use crossbeam_queue::SegQueue;
 use dashmap::{DashMap, DashSet};
 use tonic::{service::Interceptor, *};
+use tracing::{instrument, span, Instrument, Level, Span};
 use uuid::Uuid;
 
 use crate::{
@@ -106,21 +107,23 @@ async fn discover<I: Routable + Send>(
     config: JudgerConfig,
     router: Weak<Router>,
 ) -> Result<(), Error> {
-    let span = tracing::span!(
-        tracing::Level::DEBUG,
-        "service discover",
-        name = config.name
-    );
-    let mut instance = I::new(config)?;
+    let mut instance = I::new(config.clone())?;
+    let span = span!(Level::INFO, "service_discover", config_name = config.name);
     loop {
-        match instance.discover().await {
+        match instance
+            .discover()
+            .instrument(span!(parent:span.clone(),Level::DEBUG, "try advance"))
+            .in_current_span()
+            .await
+        {
             RouteStatus::NewConnection(detail) => {
-                log::info!("new upstream found: {}", detail.uri);
+                let span =
+                    span!(parent:span.clone(),Level::DEBUG,"upstream_connect",uri=detail.uri);
                 let router = match router.upgrade() {
                     Some(x) => x,
                     None => break,
                 };
-                let (upstream, langs) = Upstream::new(detail).await?;
+                let (upstream, langs) = Upstream::new(detail).in_current_span().await?;
                 for (uuid, lang) in langs.into_iter() {
                     router.langs.insert(lang);
                     loop {
@@ -136,14 +139,10 @@ async fn discover<I: Routable + Send>(
                     }
                 }
             }
-            RouteStatus::Wait(dur) => {
-                log::trace!("Service Discovery halt for {} seconds", dur.as_secs());
-                tokio::time::sleep(dur).await
-            }
+            RouteStatus::Wait(dur) => tokio::time::sleep(dur).in_current_span().await,
             _ => break,
         }
     }
-    drop(span);
     Ok(())
 }
 
@@ -154,8 +153,8 @@ pub struct Router {
 
 impl Router {
     // skip because config contain basic auth secret
-    #[tracing::instrument(level = "debug", skip_all)]
-    pub async fn new(config: Vec<JudgerConfig>) -> Result<Arc<Self>, Error> {
+    #[instrument(name="router_construct",level = "info",skip_all, follows_from = [span])]
+    pub async fn new(config: Vec<JudgerConfig>, span: &Span) -> Result<Arc<Self>, Error> {
         let self_ = Arc::new(Self {
             routing_table: DashMap::default(),
             langs: DashSet::default(),
@@ -206,7 +205,7 @@ pub struct Upstream {
     healthy: AtomicIsize,
     clients: SegQueue<JudgerIntercept>,
     connection: ConnectionDetail,
-    _live_span: tracing::Span,
+    // live_span: tracing::span::EnteredSpan,
 }
 
 impl Upstream {
@@ -227,8 +226,6 @@ impl Upstream {
             result.push((uuid, lang));
         }
 
-        let live_span = tracing::span!(tracing::Level::INFO, "judger livetime", uri = detail.uri);
-
         let clients = SegQueue::default();
         clients.push(client);
 
@@ -237,7 +234,6 @@ impl Upstream {
                 healthy: AtomicIsize::new(HEALTHY_THRESHOLD),
                 clients,
                 connection: detail,
-                _live_span: live_span,
             }),
             result,
         ))

backend/src/controller/token.rs

@@ -7,7 +7,7 @@ use sea_orm::{
 };
 use std::sync::Arc;
 use tokio::time;
-use tracing::instrument;
+use tracing::{instrument, Span};
 
 use crate::{init::db::DB, report_internal};
 
@@ -65,7 +65,8 @@ pub struct TokenController {
 }
 
 impl TokenController {
-    pub fn new() -> Arc<Self> {
+    #[tracing::instrument(parent = span,name="token_construct",level = "info",skip_all)]
+    pub fn new(span: &Span) -> Arc<Self> {
         log::debug!("Setup TokenController");
         #[cfg(feature = "single-instance")]
         let cache = Cache::new(300);

backend/src/endpoint/education.rs

@@ -8,12 +8,10 @@ use entity::{education::*, *};
 
 impl Filter for Entity {
     fn read_filter<S: QueryFilter + Send>(query: S, auth: &Auth) -> Result<S, Error> {
-        let (user_id, perm) = auth.ok_or_default()?;
-        if perm.can_root() {
-            return Ok(query);
-        }
-        if perm.can_manage_education() {
-            return Ok(query.filter(education::Column::UserId.eq(user_id)));
+        if let Some(perm) = auth.user_perm() {
+            if perm.can_root() || perm.can_manage_education() {
+                return Ok(query);
+            }
         }
         Err(Error::Unauthenticated)
     }

backend/src/endpoint/util/pagination.rs

@@ -3,6 +3,7 @@ use std::marker::PhantomData;
 use ::entity::*;
 use sea_orm::*;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 use crate::{grpc::backend::SortBy, init::db::DB};
 
@@ -361,13 +362,15 @@ where
 }
 
 impl<E: PagerTrait> Pager<E> {
+    #[instrument(level = "debug")]
     pub fn sort_search(sort: SortBy, reverse: bool) -> Self {
         Self {
             ppk: None,
             sort: SearchDep::Column(sort, reverse),
             _entity: PhantomData,
         }
     }
+    #[instrument(level = "debug")]
     pub fn text_search(sort: String) -> Self {
         Self {
             ppk: None,

backend/src/init/logger.rs

@@ -107,6 +107,19 @@ fn init_tracing_subscriber(level: Level) -> OtelGuard {
         .with(MetricsLayer::new(meter_provider.clone()))
         .with(OpenTelemetryLayer::new(init_tracer()))
         .init();
+    
+    std::panic::set_hook(Box::new(|panic| {
+        if let Some(location) = panic.location() {
+            tracing::error!(
+                message = %panic,
+                panic.file = location.file(),
+                panic.line = location.line(),
+                panic.column = location.column(),
+            );
+        } else {
+            tracing::error!(message = %panic);
+        }
+    }));
 
     OtelGuard { meter_provider }
 }

backend/src/server.rs

@@ -2,6 +2,7 @@ use std::sync::Arc;
 
 use tokio::fs;
 use tonic::transport;
+use tracing::{instrument, span, Instrument, Level};
 
 use crate::{
     controller::*,
@@ -22,7 +23,7 @@ const MAX_FRAME_SIZE: u32 = 1024 * 1024 * 8;
 
 pub struct Server {
     pub token: Arc<token::TokenController>,
-    pub submit: judger::SubmitController,
+    pub submit: judger::JudgerController,
     pub dup: duplicate::DupController,
     pub crypto: crypto::CryptoController,
     config: GlobalConfig,
@@ -34,25 +35,35 @@ impl Server {
     pub async fn new() -> Arc<Self> {
         let config = config::init().await;
 
-        init::db::init(&config).await;
         let otp_guard = logger::init(&config);
 
-        log::info!("Loading TLS certificate...");
+        let span = span!(Level::INFO, "construct_server");
+
+        init::db::init(&config)
+            .instrument(span!(parent:span.clone(),Level::INFO,"construct_database"))
+            .await;
+
+        tracing::info!("Loading TLS certificate...");
         let cert = fs::read_to_string(&config.grpc.public_pem)
+            .instrument(span!(parent:span.clone(),Level::INFO,"load_tls"))
             .await
             .expect("public key.pem not found");
         let key = fs::read_to_string(&config.grpc.private_pem)
+            .instrument(span!(parent:span.clone(),Level::INFO,"load_tls"))
             .await
             .expect("privite key.pem not found");
+
         let identity = transport::Identity::from_pem(cert, key);
 
-        log::info!("Constructing server...");
+        tracing::info!("Constructing server...");
+
+        let submit = judger::JudgerController::new(&config, &span).await.unwrap();
 
         Arc::new(Server {
-            token: token::TokenController::new(),
-            submit: judger::SubmitController::new(&config).await.unwrap(),
-            dup: duplicate::DupController::default(),
-            crypto: crypto::CryptoController::new(&config),
+            token: token::TokenController::new(&span),
+            submit: submit,
+            dup: duplicate::DupController::new(&span),
+            crypto: crypto::CryptoController::new(&config, &span),
             config,
             identity,
             _otp_guard: otp_guard,

judger/src/init/logger.rs

@@ -14,5 +14,5 @@ pub fn init() {
         _ => Level::Info,
     };
 
-    simple_logger::init_with_level(level).unwrap();
+    simple_logger::init_with_level(level).ok();
 }