refactor: improve error readability (#1265)

## Rationale
Currently when there are errors, sql is in the middle of err message,
the most important message is in the last, when sql is too long, it's
hard to find real root cause.

## Detailed Changes
- Put sql in the last part of error message
- Remove failed log, use slow_log instead.
## Test Plan
Integration tests.

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`;