feat: show root cause and db name on the error line (#4442)

* feat: show root cause on the error line * feat: show root error for grpc * feat: add error information for http error * feat: add db information on error mysql/postgres logs
GreptimeTeam · Jul 29, 2024 · b298b35 · b298b35
1 parent 164232e
commit b298b35
Show file tree

Hide file tree

Showing 6 changed files with 56 additions and 19 deletions.
diff --git a/src/common/error/src/ext.rs b/src/common/error/src/ext.rs
@@ -53,6 +53,20 @@ pub trait ErrorExt: StackError {
             }
         }
     }
+
+    /// Find out root level error for nested error
+    fn root_cause(&self) -> Option<&dyn std::error::Error>
+    where
+        Self: Sized,
+    {
+        let error = self.last();
+        if let Some(external_error) = error.source() {
+            let external_root = external_error.sources().last().unwrap();
+            Some(external_root)
+        } else {
+            None
+        }
+    }
 }
 
 pub trait StackError: std::error::Error {

diff --git a/src/servers/src/grpc/greptime_handler.rs b/src/servers/src/grpc/greptime_handler.rs
@@ -84,7 +84,8 @@ impl GreptimeRequestHandler {
                 .await
                 .map_err(|e| {
                     if e.status_code().should_log_error() {
-                        error!(e; "Failed to handle request");
+                        let root_error = e.root_cause().unwrap_or(&e);
+                        error!(e; "Failed to handle request, error: {}", root_error.to_string());
                     } else {
                         // Currently, we still print a debug log.
                         debug!("Failed to handle request, err: {:?}", e);

diff --git a/src/servers/src/http.rs b/src/servers/src/http.rs
@@ -932,7 +932,7 @@ impl Server for HttpServer {
 
 /// handle error middleware
 async fn handle_error(err: BoxError) -> Json<HttpResponse> {
-    error!(err; "Unhandled internal error");
+    error!(err; "Unhandled internal error: {}", err.to_string());
     Json(HttpResponse::Error(ErrorResponse::from_error_message(
         StatusCode::Unexpected,
         format!("Unhandled internal error: {err}"),

diff --git a/src/servers/src/mysql/handler.rs b/src/servers/src/mysql/handler.rs
@@ -332,7 +332,7 @@ impl<W: AsyncWrite + Send + Sync + Unpin> AsyncMysqlShim<W> for MysqlInstanceShi
                 let plan = match replace_params_with_values(&plan, param_types, &params) {
                     Ok(plan) => plan,
                     Err(e) => {
-                        let (kind, err) = handle_err(e);
+                        let (kind, err) = handle_err(e, query_ctx);
                         debug!(
                             "Failed to replace params on execute, kind: {:?}, err: {}",
                             kind, err
@@ -449,7 +449,7 @@ impl<W: AsyncWrite + Send + Sync + Unpin> AsyncMysqlShim<W> for MysqlInstanceShi
                             {
                                 Ok(plan) => plan,
                                 Err(e) => {
-                                    let (kind, err) = handle_err(e);
+                                    let (kind, err) = handle_err(e, query_ctx);
                                     debug!(
                                         "Failed to replace params on query, kind: {:?}, err: {}",
                                         kind, err

diff --git a/src/servers/src/mysql/writer.rs b/src/servers/src/mysql/writer.rs
@@ -53,16 +53,19 @@ pub async fn write_output<W: AsyncWrite + Send + Sync + Unpin>(
 }
 
 /// Handle GreptimeDB error, convert it to MySQL error
-pub fn handle_err(e: impl ErrorExt) -> (ErrorKind, String) {
+pub fn handle_err(e: impl ErrorExt, query_ctx: QueryContextRef) -> (ErrorKind, String) {
     let status_code = e.status_code();
     let kind = mysql_error_kind(&status_code);
 
     if status_code.should_log_error() {
-        error!(e; "Failed to handle mysql query, code: {}, kind: {:?}", status_code, kind);
+        let root_error = e.root_cause().unwrap_or(&e);
+        error!(e; "Failed to handle mysql query, code: {}, error: {}, db: {}", status_code, root_error.to_string(), query_ctx.get_db_string());
     } else {
         debug!(
-            "Failed to handle mysql query, code: {}, kind: {:?}, error: {:?}",
-            status_code, kind, e
+            "Failed to handle mysql query, code: {}, db: {}, error: {:?}",
+            status_code,
+            query_ctx.get_db_string(),
+            e
         );
     };
     let msg = e.output_msg();
@@ -124,7 +127,7 @@ impl<'a, W: AsyncWrite + Unpin> MysqlResultWriter<'a, W> {
                     )));
                 }
             },
-            Err(error) => Self::write_query_error(error, self.writer).await?,
+            Err(error) => Self::write_query_error(error, self.writer, self.query_context).await?,
         }
         Ok(None)
     }
@@ -169,7 +172,7 @@ impl<'a, W: AsyncWrite + Unpin> MysqlResultWriter<'a, W> {
                             .await?
                         }
                         Err(e) => {
-                            let (kind, err) = handle_err(e);
+                            let (kind, err) = handle_err(e, query_context);
                             debug!("Failed to get result, kind: {:?}, err: {}", kind, err);
                             row_writer.finish_error(kind, &err.as_bytes()).await?;
 
@@ -180,7 +183,7 @@ impl<'a, W: AsyncWrite + Unpin> MysqlResultWriter<'a, W> {
                 row_writer.finish().await?;
                 Ok(())
             }
-            Err(error) => Self::write_query_error(error, writer).await,
+            Err(error) => Self::write_query_error(error, writer, query_context).await,
         }
     }
 
@@ -234,12 +237,16 @@ impl<'a, W: AsyncWrite + Unpin> MysqlResultWriter<'a, W> {
         Ok(())
     }
 
-    async fn write_query_error(error: impl ErrorExt, w: QueryResultWriter<'a, W>) -> Result<()> {
+    async fn write_query_error(
+        error: impl ErrorExt,
+        w: QueryResultWriter<'a, W>,
+        query_context: QueryContextRef,
+    ) -> Result<()> {
         METRIC_ERROR_COUNTER
             .with_label_values(&[METRIC_ERROR_COUNTER_LABEL_MYSQL])
             .inc();
 
-        let (kind, err) = handle_err(error);
+        let (kind, err) = handle_err(error, query_context);
         debug!("Write query error, kind: {:?}, err: {}", kind, err);
         w.error(kind, err.as_bytes()).await?;
         Ok(())

diff --git a/src/servers/src/postgres/handler.rs b/src/servers/src/postgres/handler.rs
@@ -19,7 +19,7 @@ use common_error::ext::ErrorExt;
 use common_query::{Output, OutputData};
 use common_recordbatch::error::Result as RecordBatchResult;
 use common_recordbatch::RecordBatch;
-use common_telemetry::tracing;
+use common_telemetry::{debug, error, tracing};
 use datatypes::schema::SchemaRef;
 use futures::{future, stream, Stream, StreamExt};
 use pgwire::api::portal::{Format, Portal};
@@ -95,11 +95,26 @@ fn output_to_query_response<'a>(
                 )
             }
         },
-        Err(e) => Ok(Response::Error(Box::new(ErrorInfo::new(
-            "ERROR".to_string(),
-            "XX000".to_string(),
-            e.output_msg(),
-        )))),
+        Err(e) => {
+            let status_code = e.status_code();
+
+            if status_code.should_log_error() {
+                let root_error = e.root_cause().unwrap_or(&e);
+                error!(e; "Failed to handle postgres query, code: {}, db: {}, error: {}", status_code, query_ctx.get_db_string(), root_error.to_string());
+            } else {
+                debug!(
+                    "Failed to handle postgres query, code: {}, db: {}, error: {:?}",
+                    status_code,
+                    query_ctx.get_db_string(),
+                    e
+                );
+            };
+            Ok(Response::Error(Box::new(ErrorInfo::new(
+                "ERROR".to_string(),
+                "XX000".to_string(),
+                e.output_msg(),
+            ))))
+        }
     }
 }