From b298b35b3bd7d06379030bdb773dcb3f9a26d7f6 Mon Sep 17 00:00:00 2001 From: Ning Sun Date: Mon, 29 Jul 2024 11:59:42 +0800 Subject: [PATCH] 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 --- src/common/error/src/ext.rs | 14 ++++++++++++ src/servers/src/grpc/greptime_handler.rs | 3 ++- src/servers/src/http.rs | 2 +- src/servers/src/mysql/handler.rs | 4 ++-- src/servers/src/mysql/writer.rs | 25 ++++++++++++++-------- src/servers/src/postgres/handler.rs | 27 ++++++++++++++++++------ 6 files changed, 56 insertions(+), 19 deletions(-) diff --git a/src/common/error/src/ext.rs b/src/common/error/src/ext.rs index 271310e80f96..3b4d15a8350d 100644 --- 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 index 726e8dd3304c..042680d15932 100644 --- 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 index d4180f5478e7..a5796285dd9d 100644 --- 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 { - 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 index 48d8e72c8121..d7b5173bd9c3 100644 --- a/src/servers/src/mysql/handler.rs +++ b/src/servers/src/mysql/handler.rs @@ -332,7 +332,7 @@ impl AsyncMysqlShim for MysqlInstanceShi let plan = match replace_params_with_values(&plan, param_types, ¶ms) { 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 AsyncMysqlShim 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 index fac8b7381086..bf4d967aa5a6 100644 --- a/src/servers/src/mysql/writer.rs +++ b/src/servers/src/mysql/writer.rs @@ -53,16 +53,19 @@ pub async fn write_output( } /// 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 index 4be95374eacd..0d221e935749 100644 --- 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(), + )))) + } } }