Skip to content

Commit 2d9e579

Browse files
BohuTANGBohuTANG
authored
chore: improve the http handler log and error message (#17958)
* chore: improve the error message * improve more http handler error/log message * fix the logic tests * fix http_query_handlers.rs tests * fix the http handler logic test * continue fix the 09_0007_token.result * Update 09_0007_token.result
1 parent f237cbd commit 2d9e579

28 files changed

+270
-166
lines changed

‎src/query/service/src/auth.rs

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -123,11 +123,11 @@ impl AuthMgr {
123123
let jwt_auth = self
124124
.jwt_auth
125125
.as_ref()
126-
.ok_or_else(|| ErrorCode::AuthenticateFailure("jwt auth not configured."))?;
126+
.ok_or_else(|| ErrorCode::AuthenticateFailure("[AUTH] JWT authentication failed: JWT auth is not configured on this server"))?;
127127
let jwt = jwt_auth.parse_jwt_claims(t.as_str()).await?;
128128
let user_name = jwt.subject.ok_or_else(|| {
129129
ErrorCode::AuthenticateFailure(
130-
"jwt auth not configured correctly, user name is missing.",
130+
"[AUTH] JWT authentication failed: subject claim (user name) is missing in the token",
131131
)
132132
})?;
133133

@@ -147,20 +147,20 @@ impl AuthMgr {
147147
{
148148
Ok(user_info) => match user_info.auth_info {
149149
AuthInfo::JWT => user_info,
150-
_ => return Err(ErrorCode::AuthenticateFailure("wrong auth type")),
150+
_ => return Err(ErrorCode::AuthenticateFailure("[AUTH] Authentication failed: user exists but is not configured for JWT authentication")),
151151
},
152152
Err(e) => {
153153
match e.code() {
154154
ErrorCode::UNKNOWN_USER => {}
155155
ErrorCode::META_SERVICE_ERROR => {
156156
return Err(e);
157157
}
158-
_ => return Err(ErrorCode::AuthenticateFailure(e.message())),
158+
_ => return Err(ErrorCode::AuthenticateFailure(format!("[AUTH] Authentication failed: {}", e.message()))),
159159
}
160160
let ensure_user = jwt
161161
.custom
162162
.ensure_user
163-
.ok_or_else(|| ErrorCode::AuthenticateFailure(e.message()))?;
163+
.ok_or_else(|| ErrorCode::AuthenticateFailure(format!("[AUTH] JWT authentication failed: ensure_user claim is missing and user does not exist: {}", e.message())))?;
164164
// create a new user if not exists
165165
let mut user_info = UserInfo::new(&user_name, "%", AuthInfo::JWT);
166166
if let Some(ref roles) = ensure_user.roles {
@@ -226,16 +226,16 @@ impl AuthMgr {
226226
hash_method: t,
227227
..
228228
} => match p {
229-
None => Err(ErrorCode::AuthenticateFailure("password required")),
229+
None => Err(ErrorCode::AuthenticateFailure("[AUTH] Authentication failed: password is required but was not provided")),
230230
Some(p) => {
231231
if *h == t.hash(p) {
232232
Ok(())
233233
} else {
234-
Err(ErrorCode::AuthenticateFailure("wrong password"))
234+
Err(ErrorCode::AuthenticateFailure("[AUTH] Authentication failed: incorrect password"))
235235
}
236236
}
237237
},
238-
_ => Err(ErrorCode::AuthenticateFailure("wrong auth type")),
238+
_ => Err(ErrorCode::AuthenticateFailure("[AUTH] Authentication failed: user exists but is not configured for password authentication")),
239239
};
240240
UserApiProvider::instance()
241241
.update_user_login_result(tenant, identity, authed.is_ok(), &user)

‎src/query/service/src/servers/http/middleware/panic_handler.rs

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,9 @@ impl poem::middleware::PanicHandler for PanicHandler {
3131

3232
fn get_response(&self, _err: Box<dyn Any + Send + 'static>) -> Self::Response {
3333
metrics_incr_http_response_panics_count();
34-
(StatusCode::INTERNAL_SERVER_ERROR, "internal server error")
34+
(
35+
StatusCode::INTERNAL_SERVER_ERROR,
36+
"[HTTP-PANIC] Internal server error: request handler panicked",
37+
)
3538
}
3639
}

‎src/query/service/src/servers/http/middleware/session.rs

Lines changed: 32 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -134,7 +134,7 @@ impl EndpointKind {
134134
}
135135
}
136136
EndpointKind::Login | EndpointKind::Clickhouse => Err(ErrorCode::AuthenticateFailure(
137-
format!("should not use databend token for {self:?}",),
137+
format!("[HTTP-SESSION] Invalid token usage: databend token cannot be used for {self:?}",),
138138
)),
139139
}
140140
}
@@ -198,7 +198,10 @@ fn get_credential(
198198
}
199199
let std_auth_headers: Vec<_> = req.headers().get_all(AUTHORIZATION).iter().collect();
200200
if std_auth_headers.len() > 1 {
201-
let msg = &format!("Multiple {} headers detected", AUTHORIZATION);
201+
let msg = &format!(
202+
"[HTTP-SESSION] Authentication error: multiple {} headers detected",
203+
AUTHORIZATION
204+
);
202205
return Err(ErrorCode::AuthenticateFailure(msg));
203206
}
204207
let client_ip = get_client_ip(req);
@@ -207,7 +210,7 @@ fn get_credential(
207210
get_clickhouse_name_password(req, client_ip)
208211
} else {
209212
Err(ErrorCode::AuthenticateFailure(
210-
"No authorization header detected",
213+
"[HTTP-SESSION] Authentication error: no authorization header provided",
211214
))
212215
}
213216
} else {
@@ -261,7 +264,9 @@ fn get_credential_from_header(
261264
};
262265
Ok(c)
263266
}
264-
None => Err(ErrorCode::AuthenticateFailure("bad Basic auth header")),
267+
None => Err(ErrorCode::AuthenticateFailure(
268+
"[HTTP-SESSION] Authentication error: invalid Basic auth header format",
269+
)),
265270
}
266271
} else if value.as_bytes().starts_with(b"Bearer ") {
267272
match Bearer::decode(value) {
@@ -270,18 +275,22 @@ fn get_credential_from_header(
270275
if SessionClaim::is_databend_token(&token) {
271276
if let Some(t) = endpoint_kind.require_databend_token_type()? {
272277
if t != SessionClaim::get_type(&token)? {
273-
return Err(ErrorCode::AuthenticateFailure("wrong data token type"));
278+
return Err(ErrorCode::AuthenticateFailure("[HTTP-SESSION] Authentication error: incorrect token type for this endpoint"));
274279
}
275280
}
276281
Ok(Credential::DatabendToken { token })
277282
} else {
278283
Ok(Credential::Jwt { token, client_ip })
279284
}
280285
}
281-
None => Err(ErrorCode::AuthenticateFailure("bad Bearer auth header")),
286+
None => Err(ErrorCode::AuthenticateFailure(
287+
"[HTTP-SESSION] Authentication error: invalid Bearer auth header format",
288+
)),
282289
}
283290
} else {
284-
Err(ErrorCode::AuthenticateFailure("bad auth header"))
291+
Err(ErrorCode::AuthenticateFailure(
292+
"[HTTP-SESSION] Authentication error: unsupported authorization header format",
293+
))
285294
}
286295
}
287296

@@ -300,7 +309,12 @@ fn get_clickhouse_name_password(req: &Request, client_ip: Option<String>) -> Res
300309
} else {
301310
let query_str = req.uri().query().unwrap_or_default();
302311
let query_params = serde_urlencoded::from_str::<HashMap<String, String>>(query_str)
303-
.map_err(|e| ErrorCode::BadArguments(format!("{}", e)))?;
312+
.map_err(|e| {
313+
ErrorCode::BadArguments(format!(
314+
"[HTTP-SESSION] Failed to parse query parameters: {}",
315+
e
316+
))
317+
})?;
304318
let (user, key) = (query_params.get("user"), query_params.get("password"));
305319
if let (Some(name), Some(password)) = (user, key) {
306320
Ok(Credential::Password {
@@ -310,7 +324,7 @@ fn get_clickhouse_name_password(req: &Request, client_ip: Option<String>) -> Res
310324
})
311325
} else {
312326
Err(ErrorCode::AuthenticateFailure(
313-
"No header or query parameters for authorization detected",
327+
"[HTTP-SESSION] Authentication error: no credentials found in headers or query parameters",
314328
))
315329
}
316330
}
@@ -376,7 +390,7 @@ impl<E> HTTPSessionEndpoint<E> {
376390
(Some(id1), Some(id2)) => {
377391
if id1 != id2 {
378392
return Err(ErrorCode::AuthenticateFailure(format!(
379-
"session id in token ({}) != session id in cookie({}) ",
393+
"[HTTP-SESSION] Session ID mismatch: token session ID '{}' does not match cookie session ID '{}'",
380394
id1, id2
381395
)));
382396
}
@@ -390,7 +404,7 @@ impl<E> HTTPSessionEndpoint<E> {
390404
(None, None) => {
391405
if cookie_enabled {
392406
let id = Uuid::new_v4().to_string();
393-
info!("new session id: {}", id);
407+
info!("[HTTP-SESSION] Created new session with ID: {}", id);
394408
req.cookie().add(make_cookie(COOKIE_SESSION_ID, &id));
395409
Some(id)
396410
} else {
@@ -405,13 +419,16 @@ impl<E> HTTPSessionEndpoint<E> {
405419
.get(COOKIE_LAST_ACCESS_TIME)
406420
.map(|s| s.value_str().to_string());
407421
if let Some(ts) = &last_access_time {
408-
let ts = ts
409-
.parse::<u64>()
410-
.map_err(|_| ErrorCode::BadArguments(format!("bad last_access_time {ts}")))?;
422+
let ts = ts.parse::<u64>().map_err(|_| {
423+
ErrorCode::BadArguments(format!(
424+
"[HTTP-SESSION] Invalid last_access_time value: {}",
425+
ts
426+
))
427+
})?;
411428
let ts = SystemTime::UNIX_EPOCH + Duration::from_secs(ts);
412429
if let Err(err) = ts.elapsed() {
413430
log::error!(
414-
"last_access_time is incorrect or has clock drift, difference: {:?}",
431+
"[HTTP-SESSION] Invalid last_access_time: detected clock drift or incorrect timestamp, difference: {:?}",
415432
err.duration()
416433
);
417434
};

‎src/query/service/src/servers/http/v1/catalog/get_database_table.rs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ async fn handle(
6969
db.get_db_info().database_id.db_id,
7070
) {
7171
return Err(ErrorCode::UnknownDatabase(format!(
72-
"Unknown database '{}'",
72+
"[HTTP-CATALOG] Unknown database: '{}'",
7373
database
7474
)));
7575
}
@@ -83,7 +83,7 @@ async fn handle(
8383
tbl.get_table_info().ident.table_id,
8484
) {
8585
return Err(ErrorCode::UnknownTable(format!(
86-
"Unknown table '{}'",
86+
"[HTTP-CATALOG] Unknown table: '{}'",
8787
table
8888
)));
8989
}
@@ -106,7 +106,7 @@ async fn handle(
106106
.await
107107
.unwrap_or_else(|e| {
108108
let msg = format!(
109-
"show create query of {}.{}.{} failed(ignored): {}",
109+
"[HTTP-CATALOG] Failed to generate CREATE query for table {}.{}.{}: {}",
110110
catalog.name(),
111111
database,
112112
table,

‎src/query/service/src/servers/http/v1/catalog/list_database_table_fields.rs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -57,7 +57,7 @@ async fn handle(
5757
db.get_db_info().database_id.db_id,
5858
) {
5959
return Err(ErrorCode::UnknownDatabase(format!(
60-
"Unknown database '{}'",
60+
"[HTTP-CATALOG] Unknown database: '{}'",
6161
database
6262
)));
6363
}
@@ -71,7 +71,7 @@ async fn handle(
7171
tbl.get_table_info().ident.table_id,
7272
) {
7373
return Err(ErrorCode::UnknownTable(format!(
74-
"Unknown table '{}'",
74+
"[HTTP-CATALOG] Unknown table: '{}'",
7575
table
7676
)));
7777
}

‎src/query/service/src/servers/http/v1/catalog/list_database_tables.rs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,7 @@ async fn handle(ctx: &HttpQueryContext, database: String) -> Result<ListDatabase
6161
db.get_db_info().database_id.db_id,
6262
) {
6363
return Err(ErrorCode::UnknownDatabase(format!(
64-
"Unknown database '{}'",
64+
"[HTTP-CATALOG] Unknown database: '{}'",
6565
database
6666
)));
6767
}

‎src/query/service/src/servers/http/v1/http_query_handlers.rs

Lines changed: 21 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -260,7 +260,7 @@ async fn query_final_handler(
260260
let _t = SlowRequestLogTracker::new(ctx);
261261
async {
262262
info!(
263-
"{}: got {} request, this query is going to be finally completed.",
263+
"[HTTP-QUERY] Query {} received final request at {}, completing query execution",
264264
query_id,
265265
make_final_uri(&query_id)
266266
);
@@ -301,7 +301,7 @@ async fn query_cancel_handler(
301301
let _t = SlowRequestLogTracker::new(ctx);
302302
async {
303303
info!(
304-
"{}: got {} request, cancel the query",
304+
"[HTTP-QUERY] Query {} received cancel request at {}, terminating execution",
305305
query_id,
306306
make_kill_uri(&query_id)
307307
);
@@ -374,7 +374,7 @@ async fn query_page_handler(
374374
if query.user_name != ctx.user_name {
375375
return Err(poem::error::Error::from_string(
376376
format!(
377-
"wrong user, query {} expect {}, got {}",
377+
"[HTTP-QUERY] Authentication error: query {} expected user {}, but got {}",
378378
query_id, query.user_name, ctx.user_name
379379
),
380380
StatusCode::UNAUTHORIZED,
@@ -387,7 +387,10 @@ async fn query_page_handler(
387387
} else {
388388
query.update_expire_time(true).await;
389389
let resp = query.get_response_page(page_no).await.map_err(|err| {
390-
poem::Error::from_string(err.message(), StatusCode::NOT_FOUND)
390+
poem::Error::from_string(
391+
format!("[HTTP-QUERY] {}", err.message()),
392+
StatusCode::NOT_FOUND,
393+
)
391394
})?;
392395
query.update_expire_time(false).await;
393396
Ok(QueryResponse::from_internal(query_id, resp, false))
@@ -431,7 +434,7 @@ pub(crate) async fn query_handler(
431434
.map(|s| format!("(client_session_id={s})"))
432435
.unwrap_or("".to_string());
433436
info!(
434-
"http query new request{}{}: {}",
437+
"[HTTP-QUERY] New query request{}{}: {}",
435438
agent_info,
436439
client_session_id_info,
437440
mask_connection_info(&format!("{:?}", req))
@@ -441,14 +444,14 @@ pub(crate) async fn query_handler(
441444
match HttpQuery::try_create(ctx, req.clone()).await {
442445
Err(err) => {
443446
let err = err.display_with_sql(&sql);
444-
error!("http query fail to start sql, error: {:?}", err);
447+
error!("[HTTP-QUERY] Failed to start SQL query, error: {:?}", err);
445448
ctx.set_fail();
446449
Ok(req.fail_to_start_sql(err).into_response())
447450
}
448451
Ok(mut query) => {
449452
if let Err(err) = query.start_query(sql.clone()).await {
450453
let err = err.display_with_sql(&sql);
451-
error!("http query fail to start sql, error: {:?}", err);
454+
error!("[HTTP-QUERY] Failed to start SQL query, error: {:?}", err);
452455
ctx.set_fail();
453456
return Ok(req.fail_to_start_sql(err).into_response());
454457
}
@@ -463,7 +466,10 @@ pub(crate) async fn query_handler(
463466
.await
464467
.map_err(|err| err.display_with_sql(&sql))
465468
.map_err(|err| {
466-
poem::Error::from_string(err.message(), StatusCode::NOT_FOUND)
469+
poem::Error::from_string(
470+
format!("[HTTP-QUERY] {}", err.message()),
471+
StatusCode::NOT_FOUND,
472+
)
467473
})?;
468474

469475
if matches!(resp.state.state, ExecuteStateKind::Failed) {
@@ -474,7 +480,7 @@ pub(crate) async fn query_handler(
474480
None => (0, None),
475481
Some(p) => (p.page.data.num_rows(), p.next_page_no),
476482
};
477-
info!( "http query initial response to http query_id={}, state={:?}, rows={}, next_page={:?}, sql='{}'",
483+
info!("[HTTP-QUERY] Initial response for query_id={}, state={:?}, rows={}, next_page={:?}, sql='{}'",
478484
&query.id, &resp.state, rows, next_page, mask_connection_info(&sql)
479485
);
480486
query.update_expire_time(false).await;
@@ -580,12 +586,12 @@ pub async fn heartbeat_handler(
580586
.unwrap(),
581587
)
582588
} else {
583-
warn!("heartbeat forward fail: {:?}", resp);
589+
warn!("[HTTP-QUERY] Heartbeat forward failed: {:?}", resp);
584590
None
585591
}
586592
}
587593
Err(e) => {
588-
warn!("heartbeat forward error: {:?}", e);
594+
warn!("[HTTP-QUERY] Heartbeat forward error: {:?}", e);
589595
None
590596
}
591597
}
@@ -728,14 +734,14 @@ pub fn query_route() -> Route {
728734

729735
fn query_id_removed(query_id: &str, remove_reason: RemoveReason) -> PoemError {
730736
PoemError::from_string(
731-
format!("query id {query_id} {}", remove_reason),
737+
format!("[HTTP-QUERY] Query ID {query_id} {}", remove_reason),
732738
StatusCode::BAD_REQUEST,
733739
)
734740
}
735741

736742
fn query_id_not_found(query_id: &str, node_id: &str) -> PoemError {
737743
PoemError::from_string(
738-
format!("query id {query_id} not found on {node_id}"),
744+
format!("[HTTP-QUERY] Query ID {query_id} not found on node {node_id}"),
739745
StatusCode::NOT_FOUND,
740746
)
741747
}
@@ -770,7 +776,7 @@ impl Drop for SlowRequestLogTracker {
770776
let elapsed = self.started_at.elapsed();
771777
if elapsed.as_secs_f64() > 60.0 {
772778
warn!(
773-
"slow http query request on {} {}, elapsed: {:.2}s",
779+
"[HTTP-QUERY] Slow request detected on {} {}, elapsed time: {:.2}s",
774780
self.method,
775781
self.uri,
776782
elapsed.as_secs_f64()
@@ -795,7 +801,7 @@ pub(crate) fn get_http_tracing_span(
795801
.with_properties(|| ctx.to_fastrace_properties());
796802
}
797803
None => {
798-
warn!("failed to decode trace parent: {}", trace);
804+
warn!("[HTTP-QUERY] Failed to decode trace parent: {}", trace);
799805
}
800806
}
801807
}

0 commit comments

Comments
 (0)