refactor: improve error readability

components/logger/src/lib.rs

@@ -37,7 +37,6 @@ use slog_term::{Decorator, PlainDecorator, RecordDecorator, TermDecorator};
 const ASYNC_CHAN_SIZE: usize = 102400;
 const TIMESTAMP_FORMAT: &str = "%Y-%m-%d %H:%M:%S%.3f";
 pub const SLOW_QUERY_TAG: &str = "slow";
-pub const FAILED_QUERY_TAG: &str = "failed";
 pub const DEFAULT_TAG: &str = "";
 
 // Thanks to tikv
@@ -97,27 +96,21 @@ pub fn file_drainer(path: &Option<String>) -> Option<CeresFormat<PlainDecorator<
 }
 
 /// Dispatcher for logs
-pub struct LogDispatcher<N, S, F> {
+pub struct LogDispatcher<N, S> {
     normal: N,
     slow: Option<S>,
-    failed: Option<F>,
 }
 
-impl<N: Drain, S: Drain, F: Drain> LogDispatcher<N, S, F> {
-    pub fn new(normal: N, slow: Option<S>, failed: Option<F>) -> Self {
-        Self {
-            normal,
-            slow,
-            failed,
-        }
+impl<N: Drain, S: Drain> LogDispatcher<N, S> {
+    pub fn new(normal: N, slow: Option<S>) -> Self {
+        Self { normal, slow }
     }
 }
 
-impl<N, S, F> Drain for LogDispatcher<N, S, F>
+impl<N, S> Drain for LogDispatcher<N, S>
 where
     N: Drain<Ok = (), Err = io::Error>,
     S: Drain<Ok = (), Err = io::Error>,
-    F: Drain<Ok = (), Err = io::Error>,
 {
     type Err = io::Error;
     type Ok = ();
@@ -128,8 +121,6 @@ where
             self.normal.log(record, values)
         } else if self.slow.is_some() && tag == SLOW_QUERY_TAG {
             self.slow.as_ref().unwrap().log(record, values)
-        } else if self.failed.is_some() && tag == FAILED_QUERY_TAG {
-            self.failed.as_ref().unwrap().log(record, values)
         } else {
             Ok(())
         }
@@ -173,8 +164,7 @@ pub fn init_log(config: &Config) -> Result<RuntimeLevel, SetLoggerError> {
 
     let normal_drain = term_drainer();
     let slow_drain = file_drainer(&config.slow_query_path);
-    let failed_drain = file_drainer(&config.failed_query_path);
-    let drain = LogDispatcher::new(normal_drain, slow_drain, failed_drain);
+    let drain = LogDispatcher::new(normal_drain, slow_drain);
 
     // Use async and init stdlog
     init_log_from_drain(
@@ -467,7 +457,6 @@ pub fn init_test_logger() {
     let drain = LogDispatcher::new(
         term_drain,
         Option::<CeresFormat<PlainDecorator<File>>>::None,
-        Option::<CeresFormat<PlainDecorator<File>>>::None,
     );
 
     // Use async and init stdlog
@@ -476,29 +465,46 @@ pub fn init_test_logger() {
 
 /// Timer for collecting slow query
 #[derive(Debug)]
-pub struct SlowTimer {
+pub struct SlowTimer<'a> {
+    request_id: u64,
+    sql: &'a str,
     slow_threshold: Duration,
-    timer: Instant,
+    start_time: Instant,
+}
+
+impl<'a> Drop for SlowTimer<'a> {
+    fn drop(&mut self) {
+        let cost = self.elapsed();
+        maybe_slow_query!(
+            self,
+            "RequestId:{}, elapsed:{:?}, sql:{}",
+            self.request_id,
+            cost,
+            self.sql,
+        );
+    }
 }
 
-impl SlowTimer {
-    pub fn new(threshold: Duration) -> SlowTimer {
+impl<'a> SlowTimer<'a> {
+    pub fn new(request_id: u64, sql: &'a str, threshold: Duration) -> SlowTimer {
         SlowTimer {
+            request_id,
+            sql,
             slow_threshold: threshold,
-            timer: Instant::now(),
+            start_time: Instant::now(),
         }
     }
 
     pub fn elapsed(&self) -> Duration {
-        self.timer.elapsed()
+        self.start_time.elapsed()
     }
 
     pub fn is_slow(&self) -> bool {
         self.elapsed() >= self.slow_threshold
     }
 
-    pub fn now(&self) -> Instant {
-        self.timer
+    pub fn start_time(&self) -> Instant {
+        self.start_time
     }
 }
 
@@ -561,18 +567,11 @@ macro_rules! trace {
 macro_rules! maybe_slow_query {
     ($t:expr, $($args:tt)*) => {{
         if $t.is_slow() {
-            info!(target: logger::SLOW_QUERY_TAG, $($args)*);
+            info!(target: $crate::SLOW_QUERY_TAG, $($args)*);
         }
     }}
 }
 
-#[macro_export(local_inner_macros)]
-macro_rules! failed_query {
-    ($($args:tt)*) => {{
-        info!(target: logger::FAILED_QUERY_TAG, $($args)*);
-    }}
-}
-
 #[cfg(test)]
 mod tests {
     use super::*;

integration_tests/cases/common/dml/case_sensitive.result

@@ -33,7 +33,7 @@ SELECT
 FROM
     CASE_SENSITIVE_TABLE1;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SELECT\n    *\nFROM\n    CASE_SENSITIVE_TABLE1;. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Execution error: Table is not found, \"table:CASE_SENSITIVE_TABLE1\"" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Execution error: Table is not found, \"table:CASE_SENSITIVE_TABLE1\" sql:SELECT\n    *\nFROM\n    CASE_SENSITIVE_TABLE1;" })
 
 SELECT
     *
@@ -51,7 +51,7 @@ SELECT
 FROM
     `CASE_SENSITIVE_TABLE1`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SELECT\n    *\nFROM\n    `CASE_SENSITIVE_TABLE1`;. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Execution error: Table is not found, \"table:CASE_SENSITIVE_TABLE1\"" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Execution error: Table is not found, \"table:CASE_SENSITIVE_TABLE1\" sql:SELECT\n    *\nFROM\n    `CASE_SENSITIVE_TABLE1`;" })
 
 SHOW CREATE TABLE case_SENSITIVE_table1;
 
@@ -61,7 +61,7 @@ String("case_SENSITIVE_table1"),String("CREATE TABLE `case_SENSITIVE_table1` (`t
 
 SHOW CREATE TABLE CASE_SENSITIVE_TABLE1;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SHOW CREATE TABLE CASE_SENSITIVE_TABLE1;. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1 sql:SHOW CREATE TABLE CASE_SENSITIVE_TABLE1;" })
 
 SHOW CREATE TABLE `case_SENSITIVE_table1`;
 
@@ -71,7 +71,7 @@ String("case_SENSITIVE_table1"),String("CREATE TABLE `case_SENSITIVE_table1` (`t
 
 SHOW CREATE TABLE `CASE_SENSITIVE_TABLE1`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SHOW CREATE TABLE `CASE_SENSITIVE_TABLE1`;. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1 sql:SHOW CREATE TABLE `CASE_SENSITIVE_TABLE1`;" })
 
 DESC case_SENSITIVE_table1;
 
@@ -83,7 +83,7 @@ String("VALUE1"),String("double"),Boolean(false),Boolean(true),Boolean(false),Bo
 
 DESC CASE_SENSITIVE_TABLE1;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:DESC CASE_SENSITIVE_TABLE1;. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1 sql:DESC CASE_SENSITIVE_TABLE1;" })
 
 DESC `case_SENSITIVE_table1`;
 
@@ -95,7 +95,7 @@ String("VALUE1"),String("double"),Boolean(false),Boolean(true),Boolean(false),Bo
 
 DESC `CASE_SENSITIVE_TABLE1`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:DESC `CASE_SENSITIVE_TABLE1`;. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:CASE_SENSITIVE_TABLE1 sql:DESC `CASE_SENSITIVE_TABLE1`;" })
 
 DROP TABLE IF EXISTS case_SENSITIVE_table1;
 

integration_tests/cases/common/dummy/select_1.result

@@ -6,7 +6,7 @@ Int64(1),
 
 SELECT x;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SELECT x;. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Schema error: No field named x." })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Schema error: No field named x. sql:SELECT x;" })
 
 SELECT 'a';
 
@@ -59,5 +59,5 @@ String("That is not good."),
 
 SELECT *;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:SELECT *;. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Error during planning: SELECT * with no tables specified is not valid" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Failed to generate datafusion plan, err:Error during planning: SELECT * with no tables specified is not valid sql:SELECT *;" })
 

integration_tests/cases/common/explain/explain.result

@@ -1,6 +1,6 @@
 DROP TABLE `04_explain_t`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:DROP TABLE `04_explain_t`;. Caused by: Failed to create plan, err:Table not found, table:04_explain_t" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:04_explain_t sql:DROP TABLE `04_explain_t`;" })
 
 CREATE TABLE `04_explain_t` (t timestamp NOT NULL, TIMESTAMP KEY(t)) ENGINE=Analytic;
 

integration_tests/cases/common/optimizer/optimizer.result

@@ -1,6 +1,6 @@
 DROP TABLE `07_optimizer_t`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:DROP TABLE `07_optimizer_t`;. Caused by: Failed to create plan, err:Table not found, table:07_optimizer_t" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Table not found, table:07_optimizer_t sql:DROP TABLE `07_optimizer_t`;" })
 
 CREATE TABLE `07_optimizer_t` (name string TAG, value double NOT NULL, t timestamp NOT NULL, TIMESTAMP KEY(t)) ENGINE=Analytic with (enable_ttl='false');
 

integration_tests/cases/env/cluster/ddl/alter_table.result

@@ -19,7 +19,7 @@ UInt64(0),Timestamp(1),Int32(1),String("d1"),
 -- doesn't support rename
 ALTER TABLE `05_alter_table_t0` RENAME TO `t1`;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:ALTER TABLE `05_alter_table_t0` RENAME TO `t1`;. Caused by: Failed to create plan, err:Unsupported SQL statement" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Unsupported SQL statement sql:ALTER TABLE `05_alter_table_t0` RENAME TO `t1`;" })
 
 ALTER TABLE `05_alter_table_t0` add COLUMN (b string);
 
@@ -49,7 +49,7 @@ UInt64(0),Timestamp(2),Int32(2),String("d2"),String("2"),
 -- doesn't support drop column
 ALTER TABLE `05_alter_table_t0` DROP COLUMN b;
 
-Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan, query:ALTER TABLE `05_alter_table_t0` DROP COLUMN b;. Caused by: Failed to create plan, err:Unsupported SQL statement" })
+Failed to execute query, err: Server(ServerError { code: 500, msg: "Failed to create plan. Caused by: Failed to create plan, err:Unsupported SQL statement sql:ALTER TABLE `05_alter_table_t0` DROP COLUMN b;" })
 
 DESCRIBE TABLE `05_alter_table_t0`;