Skip to content

Commit 327e480

Browse files
authored
Log server latency on failures also (#3711)
## Motivation We were not logging on failures before, but the proxy logs on failures, which makes the data confusing ## Proposal Log latency on failures ## Test Plan CI + will look at this while debugging the `babbage` performance issue ## Release Plan - Nothing to do / These changes follow the usual release cycle.
1 parent 3d49725 commit 327e480

File tree

1 file changed

+26
-67
lines changed

1 file changed

+26
-67
lines changed

linera-rpc/src/grpc/server.rs

Lines changed: 26 additions & 67 deletions
Original file line numberDiff line numberDiff line change
@@ -441,16 +441,20 @@ where
441441
.await;
442442
}
443443

444-
fn log_request_success_and_latency(start: Instant, method_name: &str) {
444+
fn log_request_outcome_and_latency(start: Instant, success: bool, method_name: &str) {
445445
#![allow(unused_variables)]
446446
#[cfg(with_metrics)]
447447
{
448448
SERVER_REQUEST_LATENCY_PER_REQUEST_TYPE
449449
.with_label_values(&[method_name])
450450
.observe(start.elapsed().as_secs_f64() * 1000.0);
451-
SERVER_REQUEST_SUCCESS
452-
.with_label_values(&[method_name])
453-
.inc();
451+
if success {
452+
SERVER_REQUEST_SUCCESS
453+
.with_label_values(&[method_name])
454+
.inc();
455+
} else {
456+
SERVER_REQUEST_ERROR.with_label_values(&[method_name]).inc();
457+
}
454458
}
455459
}
456460
}
@@ -479,17 +483,12 @@ where
479483
Ok(Response::new(
480484
match self.state.clone().handle_block_proposal(proposal).await {
481485
Ok((info, actions)) => {
482-
Self::log_request_success_and_latency(start, "handle_block_proposal");
486+
Self::log_request_outcome_and_latency(start, true, "handle_block_proposal");
483487
self.handle_network_actions(actions);
484488
info.try_into()?
485489
}
486490
Err(error) => {
487-
#[cfg(with_metrics)]
488-
{
489-
SERVER_REQUEST_ERROR
490-
.with_label_values(&["handle_block_proposal"])
491-
.inc();
492-
}
491+
Self::log_request_outcome_and_latency(start, false, "handle_block_proposal");
493492
let nickname = self.state.nickname();
494493
warn!(nickname, %error, "Failed to handle block proposal");
495494
NodeError::from(error).try_into()?
@@ -526,7 +525,7 @@ where
526525
.await
527526
{
528527
Ok((info, actions)) => {
529-
Self::log_request_success_and_latency(start, "handle_lite_certificate");
528+
Self::log_request_outcome_and_latency(start, true, "handle_lite_certificate");
530529
self.handle_network_actions(actions);
531530
if let Some(receiver) = receiver {
532531
if let Err(e) = receiver.await {
@@ -536,12 +535,7 @@ where
536535
Ok(Response::new(info.try_into()?))
537536
}
538537
Err(error) => {
539-
#[cfg(with_metrics)]
540-
{
541-
SERVER_REQUEST_ERROR
542-
.with_label_values(&["handle_lite_certificate"])
543-
.inc();
544-
}
538+
Self::log_request_outcome_and_latency(start, false, "handle_lite_certificate");
545539
let nickname = self.state.nickname();
546540
if let WorkerError::MissingCertificateValue = &error {
547541
debug!(nickname, %error, "Failed to handle lite certificate");
@@ -580,7 +574,7 @@ where
580574
.await
581575
{
582576
Ok((info, actions)) => {
583-
Self::log_request_success_and_latency(start, "handle_confirmed_certificate");
577+
Self::log_request_outcome_and_latency(start, true, "handle_confirmed_certificate");
584578
self.handle_network_actions(actions);
585579
if let Some(receiver) = receiver {
586580
if let Err(e) = receiver.await {
@@ -590,12 +584,7 @@ where
590584
Ok(Response::new(info.try_into()?))
591585
}
592586
Err(error) => {
593-
#[cfg(with_metrics)]
594-
{
595-
SERVER_REQUEST_ERROR
596-
.with_label_values(&["handle_confirmed_certificate"])
597-
.inc();
598-
}
587+
Self::log_request_outcome_and_latency(start, false, "handle_confirmed_certificate");
599588
let nickname = self.state.nickname();
600589
error!(nickname, %error, "Failed to handle confirmed certificate");
601590
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -626,17 +615,12 @@ where
626615
.await
627616
{
628617
Ok((info, actions)) => {
629-
Self::log_request_success_and_latency(start, "handle_validated_certificate");
618+
Self::log_request_outcome_and_latency(start, true, "handle_validated_certificate");
630619
self.handle_network_actions(actions);
631620
Ok(Response::new(info.try_into()?))
632621
}
633622
Err(error) => {
634-
#[cfg(with_metrics)]
635-
{
636-
SERVER_REQUEST_ERROR
637-
.with_label_values(&["handle_validated_certificate"])
638-
.inc();
639-
}
623+
Self::log_request_outcome_and_latency(start, false, "handle_validated_certificate");
640624
let nickname = self.state.nickname();
641625
error!(nickname, %error, "Failed to handle validated certificate");
642626
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -667,16 +651,11 @@ where
667651
.await
668652
{
669653
Ok((info, _actions)) => {
670-
Self::log_request_success_and_latency(start, "handle_timeout_certificate");
654+
Self::log_request_outcome_and_latency(start, true, "handle_timeout_certificate");
671655
Ok(Response::new(info.try_into()?))
672656
}
673657
Err(error) => {
674-
#[cfg(with_metrics)]
675-
{
676-
SERVER_REQUEST_ERROR
677-
.with_label_values(&["handle_timeout_certificate"])
678-
.inc();
679-
}
658+
Self::log_request_outcome_and_latency(start, false, "handle_timeout_certificate");
680659
let nickname = self.state.nickname();
681660
error!(nickname, %error, "Failed to handle timeout certificate");
682661
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -702,17 +681,12 @@ where
702681
trace!(?query, "Handling chain info query");
703682
match self.state.clone().handle_chain_info_query(query).await {
704683
Ok((info, actions)) => {
705-
Self::log_request_success_and_latency(start, "handle_chain_info_query");
684+
Self::log_request_outcome_and_latency(start, true, "handle_chain_info_query");
706685
self.handle_network_actions(actions);
707686
Ok(Response::new(info.try_into()?))
708687
}
709688
Err(error) => {
710-
#[cfg(with_metrics)]
711-
{
712-
SERVER_REQUEST_ERROR
713-
.with_label_values(&["handle_chain_info_query"])
714-
.inc();
715-
}
689+
Self::log_request_outcome_and_latency(start, false, "handle_chain_info_query");
716690
let nickname = self.state.nickname();
717691
error!(nickname, %error, "Failed to handle chain info query");
718692
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -743,16 +717,11 @@ where
743717
.await
744718
{
745719
Ok(blob) => {
746-
Self::log_request_success_and_latency(start, "download_pending_blob");
720+
Self::log_request_outcome_and_latency(start, true, "download_pending_blob");
747721
Ok(Response::new(blob.into_content().try_into()?))
748722
}
749723
Err(error) => {
750-
#[cfg(with_metrics)]
751-
{
752-
SERVER_REQUEST_ERROR
753-
.with_label_values(&["download_pending_blob"])
754-
.inc();
755-
}
724+
Self::log_request_outcome_and_latency(start, false, "download_pending_blob");
756725
let nickname = self.state.nickname();
757726
error!(nickname, %error, "Failed to download pending blob");
758727
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -780,16 +749,11 @@ where
780749
trace!(?chain_id, ?blob_id, "Handle pending blob");
781750
match self.state.clone().handle_pending_blob(chain_id, blob).await {
782751
Ok(info) => {
783-
Self::log_request_success_and_latency(start, "handle_pending_blob");
752+
Self::log_request_outcome_and_latency(start, true, "handle_pending_blob");
784753
Ok(Response::new(info.try_into()?))
785754
}
786755
Err(error) => {
787-
#[cfg(with_metrics)]
788-
{
789-
SERVER_REQUEST_ERROR
790-
.with_label_values(&["handle_pending_blob"])
791-
.inc();
792-
}
756+
Self::log_request_outcome_and_latency(start, false, "handle_pending_blob");
793757
let nickname = self.state.nickname();
794758
error!(nickname, %error, "Failed to handle pending blob");
795759
Ok(Response::new(NodeError::from(error).try_into()?))
@@ -815,16 +779,11 @@ where
815779
trace!(?request, "Handling cross-chain request");
816780
match self.state.clone().handle_cross_chain_request(request).await {
817781
Ok(actions) => {
818-
Self::log_request_success_and_latency(start, "handle_cross_chain_request");
782+
Self::log_request_outcome_and_latency(start, true, "handle_cross_chain_request");
819783
self.handle_network_actions(actions)
820784
}
821785
Err(error) => {
822-
#[cfg(with_metrics)]
823-
{
824-
SERVER_REQUEST_ERROR
825-
.with_label_values(&["handle_cross_chain_request"])
826-
.inc();
827-
}
786+
Self::log_request_outcome_and_latency(start, false, "handle_cross_chain_request");
828787
let nickname = self.state.nickname();
829788
error!(nickname, %error, "Failed to handle cross-chain request");
830789
}

0 commit comments

Comments
 (0)