forest/rpc/
log_layer.rs

1// Copyright 2019-2025 ChainSafe Systems
2// SPDX-License-Identifier: Apache-2.0, MIT
3
4//! Middleware layer for logging RPC calls.
5
6use std::{
7    borrow::Cow,
8    fmt::Display,
9    hash::{DefaultHasher, Hash as _, Hasher},
10};
11
12use futures::future::Either;
13use jsonrpsee::MethodResponse;
14use jsonrpsee::core::middleware::{Batch, Notification};
15use jsonrpsee::{server::middleware::rpc::RpcServiceT, types::Id};
16use tower::Layer;
17
18// State-less jsonrpcsee layer for logging information about RPC calls
19#[derive(Clone, Default)]
20pub(super) struct LogLayer {}
21
22impl<S> Layer<S> for LogLayer {
23    type Service = Logging<S>;
24
25    fn layer(&self, service: S) -> Self::Service {
26        Logging { service }
27    }
28}
29
30#[derive(Clone)]
31pub(super) struct Logging<S> {
32    service: S,
33}
34
35impl<S> Logging<S> {
36    fn log_enabled() -> bool {
37        tracing::enabled!(tracing::Level::DEBUG)
38    }
39
40    async fn log<F>(
41        id: Id<'_>,
42        method_name: impl Display,
43        params: impl Display,
44        future: F,
45    ) -> MethodResponse
46    where
47        F: Future<Output = MethodResponse>,
48    {
49        // Avoid performance overhead if DEBUG level is not enabled.
50        if !tracing::enabled!(tracing::Level::DEBUG) {
51            return future.await;
52        }
53
54        let start_time = std::time::Instant::now();
55        let id = create_unique_id(id, start_time);
56        tracing::trace!("RPC#{id}: {method_name}. Params: {params}");
57        let resp = future.await;
58        let elapsed = start_time.elapsed();
59        let result = resp.as_error_code().map_or(Cow::Borrowed("OK"), |code| {
60            Cow::Owned(format!("ERR({code})"))
61        });
62        tracing::debug!(
63            "RPC#{id} {result}: {method_name}. Took {}",
64            humantime::format_duration(elapsed)
65        );
66        resp
67    }
68}
69
70impl<S> RpcServiceT for Logging<S>
71where
72    S: RpcServiceT<MethodResponse = MethodResponse, NotificationResponse = MethodResponse>
73        + Send
74        + Sync
75        + Clone
76        + 'static,
77{
78    type MethodResponse = S::MethodResponse;
79    type NotificationResponse = S::NotificationResponse;
80    type BatchResponse = S::BatchResponse;
81
82    fn call<'a>(
83        &self,
84        req: jsonrpsee::types::Request<'a>,
85    ) -> impl Future<Output = Self::MethodResponse> + Send + 'a {
86        // Avoid performance overhead if DEBUG level is not enabled.
87        if !Self::log_enabled() {
88            Either::Left(self.service.call(req))
89        } else {
90            Either::Right(Self::log(
91                req.id(),
92                req.method_name().to_owned(),
93                req.params().as_str().unwrap_or("[]").to_owned(),
94                self.service.call(req),
95            ))
96        }
97    }
98
99    fn batch<'a>(&self, batch: Batch<'a>) -> impl Future<Output = Self::BatchResponse> + Send + 'a {
100        self.service.batch(batch)
101    }
102
103    fn notification<'a>(
104        &self,
105        n: Notification<'a>,
106    ) -> impl Future<Output = Self::NotificationResponse> + Send + 'a {
107        // Avoid performance overhead if DEBUG level is not enabled.
108        if !Self::log_enabled() {
109            Either::Left(self.service.notification(n))
110        } else {
111            Either::Right(Self::log(
112                Id::Null,
113                n.method_name().to_owned(),
114                "",
115                self.service.notification(n),
116            ))
117        }
118    }
119}
120
121/// Creates a unique ID for the RPC call, so it can be easily tracked in logs.
122fn create_unique_id(id: Id, start_time: std::time::Instant) -> String {
123    const ID_LEN: usize = 6;
124    let mut hasher = DefaultHasher::new();
125    id.hash(&mut hasher);
126    start_time.hash(&mut hasher);
127    let mut id = format!("{:x}", hasher.finish());
128    id.truncate(ID_LEN);
129    id
130}
131
132#[cfg(test)]
133mod tests {
134    use std::time::Duration;
135
136    use super::*;
137
138    #[test]
139    fn test_create_unique_id_same() {
140        let id = Id::Number(1);
141        let start_time = std::time::Instant::now();
142        let id1 = create_unique_id(id.clone(), start_time);
143        let id2 = create_unique_id(id, start_time);
144        assert_eq!(id1, id2);
145    }
146
147    #[test]
148    fn test_create_unique_id_different_ids() {
149        let id1 = Id::Number(1);
150        let id2 = Id::Number(2);
151        let start_time = std::time::Instant::now();
152        let id1 = create_unique_id(id1, start_time);
153        let id2 = create_unique_id(id2, start_time);
154        assert_ne!(id1, id2);
155    }
156
157    #[test]
158    fn test_create_unique_id_different_times() {
159        let id = Id::Number(1);
160        let start_time1 = std::time::Instant::now();
161        let start_time2 = std::time::Instant::now() + Duration::from_nanos(1);
162        let id1 = create_unique_id(id.clone(), start_time1);
163        let id2 = create_unique_id(id, start_time2);
164        assert_ne!(id1, id2);
165    }
166}
forest/rpc/log_layer.rs

forest/rpc/
log_layer.rs
