From 3a2831be598fa0ca13f3d4059462f056583c4356 Mon Sep 17 00:00:00 2001 From: Niklas Adolfsson Date: Fri, 15 Oct 2021 11:22:37 +0200 Subject: [PATCH] switch to the tracing crate --- examples/Cargo.toml | 3 +- examples/http.rs | 6 ++- examples/proc_macro.rs | 4 +- examples/ws.rs | 7 +++- examples/ws_sub_with_params.rs | 9 ++-- examples/ws_subscription.rs | 10 +++-- http-client/Cargo.toml | 2 +- http-client/src/transport.rs | 2 +- http-server/Cargo.toml | 2 +- http-server/src/access_control/matcher.rs | 2 +- http-server/src/server.rs | 4 +- proc-macros/Cargo.toml | 2 +- proc-macros/src/render_server.rs | 4 +- test-utils/Cargo.toml | 2 +- test-utils/src/mocks.rs | 10 ++--- tests/Cargo.toml | 2 +- types/Cargo.toml | 2 +- types/src/v2/params.rs | 8 ++-- utils/Cargo.toml | 4 +- utils/src/server/helpers.rs | 8 ++-- utils/src/server/rpc_module.rs | 18 ++++---- ws-client/Cargo.toml | 2 +- ws-client/src/client.rs | 50 +++++++++++------------ ws-client/src/helpers.rs | 12 +++--- ws-client/src/transport.rs | 14 +++---- ws-server/Cargo.toml | 2 +- ws-server/src/server.rs | 18 ++++---- ws-server/src/tests.rs | 4 +- 28 files changed, 114 insertions(+), 99 deletions(-) diff --git a/examples/Cargo.toml b/examples/Cargo.toml index fafa500d85..7eb987a911 100644 --- a/examples/Cargo.toml +++ b/examples/Cargo.toml @@ -10,7 +10,8 @@ publish = false anyhow = "1" env_logger = "0.9" jsonrpsee = { path = "../jsonrpsee", features = ["full"] } -log = "0.4" +tracing = "0.1" +tracing-subscriber = "0.2" tokio = { version = "1", features = ["full"] } [[example]] diff --git a/examples/http.rs b/examples/http.rs index 926da1b330..7bc735cf49 100644 --- a/examples/http.rs +++ b/examples/http.rs @@ -34,7 +34,9 @@ use std::net::SocketAddr; #[tokio::main] async fn main() -> anyhow::Result<()> { - env_logger::init(); + // init tracing `FmtSubscriber`. + let subscriber = tracing_subscriber::FmtSubscriber::new(); + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); let (server_addr, _handle) = run_server().await?; let url = format!("http://{}", server_addr); @@ -42,7 +44,7 @@ async fn main() -> anyhow::Result<()> { let client = HttpClientBuilder::default().build(url)?; let params = rpc_params!(1_u64, 2, 3); let response: Result = client.request("say_hello", params).await; - println!("r: {:?}", response); + tracing::info!("r: {:?}", response); Ok(()) } diff --git a/examples/proc_macro.rs b/examples/proc_macro.rs index fd7ca64624..ee12c89016 100644 --- a/examples/proc_macro.rs +++ b/examples/proc_macro.rs @@ -72,7 +72,9 @@ impl RpcServer for RpcServerImpl { #[tokio::main] async fn main() -> anyhow::Result<()> { - env_logger::init(); + // init tracing `FmtSubscriber`. + let subscriber = tracing_subscriber::FmtSubscriber::builder().finish(); + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); let (server_addr, _handle) = run_server().await?; let url = format!("ws://{}", server_addr); diff --git a/examples/ws.rs b/examples/ws.rs index 259afaf02d..6768c52b83 100644 --- a/examples/ws.rs +++ b/examples/ws.rs @@ -33,13 +33,16 @@ use std::net::SocketAddr; #[tokio::main] async fn main() -> anyhow::Result<()> { - env_logger::init(); + // init tracing `FmtSubscriber`. + let subscriber = tracing_subscriber::FmtSubscriber::builder().finish(); + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); + let addr = run_server().await?; let url = format!("ws://{}", addr); let client = WsClientBuilder::default().build(&url).await?; let response: String = client.request("say_hello", None).await?; - println!("r: {:?}", response); + tracing::info!("response: {:?}", response); Ok(()) } diff --git a/examples/ws_sub_with_params.rs b/examples/ws_sub_with_params.rs index 703461d5d2..d6720204ed 100644 --- a/examples/ws_sub_with_params.rs +++ b/examples/ws_sub_with_params.rs @@ -34,7 +34,10 @@ use std::net::SocketAddr; #[tokio::main] async fn main() -> anyhow::Result<()> { - env_logger::init(); + // init tracing `FmtSubscriber`. + let subscriber = tracing_subscriber::FmtSubscriber::builder().finish(); + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); + let addr = run_server().await?; let url = format!("ws://{}", addr); @@ -43,12 +46,12 @@ async fn main() -> anyhow::Result<()> { // Subscription with a single parameter let mut sub_params_one = client.subscribe::>("sub_one_param", rpc_params![3], "unsub_one_param").await?; - println!("subscription with one param: {:?}", sub_params_one.next().await); + tracing::info!("subscription with one param: {:?}", sub_params_one.next().await); // Subscription with multiple parameters let mut sub_params_two = client.subscribe::("sub_params_two", rpc_params![2, 5], "unsub_params_two").await?; - println!("subscription with two params: {:?}", sub_params_two.next().await); + tracing::info!("subscription with two params: {:?}", sub_params_two.next().await); Ok(()) } diff --git a/examples/ws_subscription.rs b/examples/ws_subscription.rs index 57b6feabf2..02308a7004 100644 --- a/examples/ws_subscription.rs +++ b/examples/ws_subscription.rs @@ -32,10 +32,14 @@ use jsonrpsee::{ }; use std::net::SocketAddr; +const NUM_SUBSCRIPTION_RESPONSES: usize = 5; + #[tokio::main] async fn main() -> anyhow::Result<()> { - const NUM_SUBSCRIPTION_RESPONSES: usize = 5; - env_logger::init(); + // init tracing `FmtSubscriber`. + let subscriber = tracing_subscriber::FmtSubscriber::builder().finish(); + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); + let addr = run_server().await?; let url = format!("ws://{}", addr); @@ -46,7 +50,7 @@ async fn main() -> anyhow::Result<()> { let mut i = 0; while i <= NUM_SUBSCRIPTION_RESPONSES { let r = subscribe_hello.next().await; - println!("received {:?}", r); + tracing::info!("received {:?}", r); i += 1; } diff --git a/http-client/Cargo.toml b/http-client/Cargo.toml index 8b78436d4c..5f29bcf01d 100644 --- a/http-client/Cargo.toml +++ b/http-client/Cargo.toml @@ -15,7 +15,7 @@ hyper-rustls = "0.22" hyper = { version = "0.14.10", features = ["client", "http1", "http2", "tcp"] } jsonrpsee-types = { path = "../types", version = "0.4.1" } jsonrpsee-utils = { path = "../utils", version = "0.4.1", features = ["http-helpers"] } -log = "0.4" +tracing = "0.1" serde = { version = "1.0", default-features = false, features = ["derive"] } serde_json = "1.0" tokio = { version = "1", features = ["time"] } diff --git a/http-client/src/transport.rs b/http-client/src/transport.rs index 80cb8ded9b..1fecdd0f18 100644 --- a/http-client/src/transport.rs +++ b/http-client/src/transport.rs @@ -39,7 +39,7 @@ impl HttpTransportClient { } async fn inner_send(&self, body: String) -> Result, Error> { - log::debug!("send: {}", body); + tracing::debug!("send: {}", body); if body.len() > self.max_request_body_size as usize { return Err(Error::RequestTooLarge); diff --git a/http-server/Cargo.toml b/http-server/Cargo.toml index 35280c0c15..b2bf840b77 100644 --- a/http-server/Cargo.toml +++ b/http-server/Cargo.toml @@ -17,7 +17,7 @@ jsonrpsee-types = { path = "../types", version = "0.4.1" } jsonrpsee-utils = { path = "../utils", version = "0.4.1", features = ["server", "http-helpers"] } globset = "0.4" lazy_static = "1.4" -log = "0.4" +tracing = "0.1" serde_json = "1" socket2 = "0.4" tokio = { version = "1", features = ["rt-multi-thread", "macros"] } diff --git a/http-server/src/access_control/matcher.rs b/http-server/src/access_control/matcher.rs index 0a0d0163f2..c20ed1d654 100644 --- a/http-server/src/access_control/matcher.rs +++ b/http-server/src/access_control/matcher.rs @@ -25,8 +25,8 @@ // DEALINGS IN THE SOFTWARE. use globset::{GlobBuilder, GlobMatcher}; -use log::warn; use std::{fmt, hash}; +use tracing::warn; /// Pattern that can be matched to string. pub(crate) trait Pattern { diff --git a/http-server/src/server.rs b/http-server/src/server.rs index 8521c3f780..276d075ee9 100644 --- a/http-server/src/server.rs +++ b/http-server/src/server.rs @@ -222,7 +222,7 @@ impl Server { Err(GenericTransportError::TooLarge) => return Ok::<_, HyperError>(response::too_large()), Err(GenericTransportError::Malformed) => return Ok::<_, HyperError>(response::malformed()), Err(GenericTransportError::Inner(e)) => { - log::error!("Internal error reading request body: {}", e); + tracing::error!("Internal error reading request body: {}", e); return Ok::<_, HyperError>(response::internal_error()); } }; @@ -281,7 +281,7 @@ impl Server { } else { collect_batch_response(rx).await }; - log::debug!("[service_fn] sending back: {:?}", &response[..cmp::min(response.len(), 1024)]); + tracing::debug!("[service_fn] sending back: {:?}", &response[..cmp::min(response.len(), 1024)]); Ok::<_, HyperError>(response::ok_response(response)) } })) diff --git a/proc-macros/Cargo.toml b/proc-macros/Cargo.toml index 95eee70d53..6e209c7108 100644 --- a/proc-macros/Cargo.toml +++ b/proc-macros/Cargo.toml @@ -17,7 +17,7 @@ proc-macro2 = "1.0" quote = "1.0" syn = { version = "1.0", default-features = false, features = ["extra-traits", "full", "visit", "parsing"] } proc-macro-crate = "1" -log = "0.4" +tracing = "0.1" [dev-dependencies] jsonrpsee = { path = "../jsonrpsee", features = ["full"] } diff --git a/proc-macros/src/render_server.rs b/proc-macros/src/render_server.rs index 0204befc38..37b728412b 100644 --- a/proc-macros/src/render_server.rs +++ b/proc-macros/src/render_server.rs @@ -292,7 +292,7 @@ impl RpcDescription { let #name: #ty = match seq.optional_next() { Ok(v) => v, Err(e) => { - log::error!(concat!("Error parsing optional \"", stringify!(#name), "\" as \"", stringify!(#ty), "\": {:?}"), e); + tracing::error!(concat!("Error parsing optional \"", stringify!(#name), "\" as \"", stringify!(#ty), "\": {:?}"), e); return Err(e.into()) } }; @@ -302,7 +302,7 @@ impl RpcDescription { let #name: #ty = match seq.next() { Ok(v) => v, Err(e) => { - log::error!(concat!("Error parsing \"", stringify!(#name), "\" as \"", stringify!(#ty), "\": {:?}"), e); + tracing::error!(concat!("Error parsing \"", stringify!(#name), "\" as \"", stringify!(#ty), "\": {:?}"), e); return Err(e.into()) } }; diff --git a/test-utils/Cargo.toml b/test-utils/Cargo.toml index 73062dec59..74ceae0d51 100644 --- a/test-utils/Cargo.toml +++ b/test-utils/Cargo.toml @@ -12,7 +12,7 @@ anyhow = "1" futures-channel = "0.3.14" futures-util = "0.3.14" hyper = { version = "0.14.10", features = ["full"] } -log = "0.4" +tracing = "0.1" serde = { version = "1", default-features = false, features = ["derive"] } serde_json = "1" soketto = { version = "0.7", features = ["http"] } diff --git a/test-utils/src/mocks.rs b/test-utils/src/mocks.rs index c3bb183ba0..faa89f0ffe 100644 --- a/test-utils/src/mocks.rs +++ b/test-utils/src/mocks.rs @@ -278,12 +278,12 @@ async fn connection_task(socket: tokio::net::TcpStream, mode: ServerMode, mut ex match &mode { ServerMode::Subscription { subscription_response, .. } => { if let Err(e) = sender.send_text(&subscription_response).await { - log::warn!("send response to subscription: {:?}", e); + tracing::warn!("send response to subscription: {:?}", e); } }, ServerMode::Notification(n) => { if let Err(e) = sender.send_text(&n).await { - log::warn!("send notification: {:?}", e); + tracing::warn!("send notification: {:?}", e); } }, _ => {} @@ -296,12 +296,12 @@ async fn connection_task(socket: tokio::net::TcpStream, mode: ServerMode, mut ex match &mode { ServerMode::Response(r) => { if let Err(e) = sender.send_text(&r).await { - log::warn!("send response to request error: {:?}", e); + tracing::warn!("send response to request error: {:?}", e); } }, ServerMode::Subscription { subscription_id, .. } => { if let Err(e) = sender.send_text(&subscription_id).await { - log::warn!("send subscription id error: {:?}", e); + tracing::warn!("send subscription id error: {:?}", e); } }, _ => {} @@ -340,7 +340,7 @@ async fn handler( other_server: String, ) -> Result, soketto::BoxedError> { if is_upgrade_request(&req) { - log::debug!("{:?}", req); + tracing::debug!("{:?}", req); match req.uri().path() { "/myblock/two" => { diff --git a/tests/Cargo.toml b/tests/Cargo.toml index ea469d721e..e3f7682901 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -13,4 +13,4 @@ futures = { version = "0.3.14", default-features = false, features = ["std"] } jsonrpsee = { path = "../jsonrpsee", features = ["full"] } tokio = { version = "1", features = ["full"] } serde_json = "1" -log = "0.4" +tracing = "0.1" diff --git a/types/Cargo.toml b/types/Cargo.toml index 9b4e70e7ec..cc488e43e9 100644 --- a/types/Cargo.toml +++ b/types/Cargo.toml @@ -15,7 +15,7 @@ anyhow = "1" beef = { version = "0.5.1", features = ["impl_serde"] } futures-channel = { version = "0.3.14", features = ["sink"] } futures-util = { version = "0.3.14", default-features = false, features = ["std", "sink", "channel"] } -log = { version = "0.4", default-features = false } +tracing = { version = "0.1", default-features = false } serde = { version = "1", default-features = false, features = ["derive"] } serde_json = { version = "1", default-features = false, features = ["alloc", "raw_value", "std"] } thiserror = "1.0" diff --git a/types/src/v2/params.rs b/types/src/v2/params.rs index a49949286d..b3a8fd799f 100644 --- a/types/src/v2/params.rs +++ b/types/src/v2/params.rs @@ -158,18 +158,18 @@ impl<'a> ParamsSequence<'a> { T: Deserialize<'a>, { let mut json = self.0; - log::trace!("[next_inner] Params JSON: {:?}", json); + tracing::trace!("[next_inner] Params JSON: {:?}", json); match json.as_bytes().get(0)? { b']' => { self.0 = ""; - log::trace!("[next_inner] Reached end of sequence."); + tracing::trace!("[next_inner] Reached end of sequence."); return None; } b'[' | b',' => json = &json[1..], _ => { let errmsg = format!("Invalid params. Expected one of '[', ']' or ',' but found {:?}", json); - log::error!("[next_inner] {}", errmsg); + tracing::error!("[next_inner] {}", errmsg); return Some(Err(CallError::InvalidParams(anyhow!(errmsg)))); } } @@ -183,7 +183,7 @@ impl<'a> ParamsSequence<'a> { Some(Ok(value)) } Err(e) => { - log::error!( + tracing::error!( "[next_inner] Deserialization to {:?} failed. Error: {:?}, input JSON: {:?}", std::any::type_name::(), e, diff --git a/utils/Cargo.toml b/utils/Cargo.toml index b566ce4518..8bad8f61a5 100644 --- a/utils/Cargo.toml +++ b/utils/Cargo.toml @@ -14,7 +14,7 @@ futures-channel = { version = "0.3.14", default-features = false, optional = tru futures-util = { version = "0.3.14", default-features = false, optional = true } hyper = { version = "0.14.10", default-features = false, features = ["stream"], optional = true } jsonrpsee-types = { path = "../types", version = "0.4.1", optional = true } -log = { version = "0.4", optional = true } +tracing = { version = "0.1", optional = true } rustc-hash = { version = "1", optional = true } rand = { version = "0.8", optional = true } serde = { version = "1.0", default-features = false, features = ["derive"], optional = true } @@ -32,7 +32,7 @@ server = [ "rustc-hash", "serde", "serde_json", - "log", + "tracing", "parking_lot", "rand", ] diff --git a/utils/src/server/helpers.rs b/utils/src/server/helpers.rs index 00614eb256..82924245dc 100644 --- a/utils/src/server/helpers.rs +++ b/utils/src/server/helpers.rs @@ -39,14 +39,14 @@ pub fn send_response(id: Id, tx: &MethodSink, result: impl Serialize) { let json = match serde_json::to_string(&Response { jsonrpc: TwoPointZero, id: id.clone(), result }) { Ok(json) => json, Err(err) => { - log::error!("Error serializing response: {:?}", err); + tracing::error!("Error serializing response: {:?}", err); return send_error(id, tx, ErrorCode::InternalError.into()); } }; if let Err(err) = tx.unbounded_send(json) { - log::error!("Error sending response to the client: {:?}", err) + tracing::error!("Error sending response to the client: {:?}", err) } } @@ -55,14 +55,14 @@ pub fn send_error(id: Id, tx: &MethodSink, error: ErrorObject) { let json = match serde_json::to_string(&RpcError { jsonrpc: TwoPointZero, error, id }) { Ok(json) => json, Err(err) => { - log::error!("Error serializing error message: {:?}", err); + tracing::error!("Error serializing error message: {:?}", err); return; } }; if let Err(err) = tx.unbounded_send(json) { - log::error!("Could not send error response to the client: {:?}", err) + tracing::error!("Could not send error response to the client: {:?}", err) } } diff --git a/utils/src/server/rpc_module.rs b/utils/src/server/rpc_module.rs index 89e261ac10..fd7acdf587 100644 --- a/utils/src/server/rpc_module.rs +++ b/utils/src/server/rpc_module.rs @@ -152,7 +152,7 @@ impl MethodCallback { match &self.callback { MethodKind::Sync(callback) => { - log::trace!( + tracing::trace!( "[MethodCallback::execute] Executing sync callback, params={:?}, req.id={:?}, conn_id={:?}", params, id, @@ -169,7 +169,7 @@ impl MethodCallback { let tx = tx.clone(); let params = params.into_owned(); let id = id.into_owned(); - log::trace!( + tracing::trace!( "[MethodCallback::execute] Executing async callback, params={:?}, req.id={:?}, conn_id={:?}", params, id, @@ -284,7 +284,7 @@ impl Methods { /// Attempt to execute a callback, sending the resulting JSON (success or error) to the specified sink. pub fn execute(&self, tx: &MethodSink, req: Request, conn_id: ConnectionId) -> Option> { - log::trace!("[Methods::execute] Executing request: {:?}", req); + tracing::trace!("[Methods::execute] Executing request: {:?}", req); match self.callbacks.get(&*req.method) { Some(callback) => callback.execute(tx, req, conn_id, None), None => { @@ -302,12 +302,12 @@ impl Methods { conn_id: ConnectionId, resources: &Resources, ) -> Option> { - log::trace!("[Methods::execute_with_resources] Executing request: {:?}", req); + tracing::trace!("[Methods::execute_with_resources] Executing request: {:?}", req); match self.callbacks.get(&*req.method) { Some(callback) => match callback.claim(&req.method, resources) { Ok(guard) => callback.execute(tx, req, conn_id, Some(guard)), Err(err) => { - log::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err); + tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err); send_error(req.id, tx, ErrorCode::ServerIsBusy.into()); None } @@ -350,7 +350,7 @@ impl Methods { /// [`SubscriptionId`] and a channel on which subscription JSON payloads can be received. pub async fn test_subscription(&self, method: &str, params: impl ToRpcParams) -> TestSubscription { let params = params.to_rpc_params().expect("valid JSON-RPC params"); - log::trace!("[Methods::test_subscription] Calling subscription method: {:?}, params: {:?}", method, params); + tracing::trace!("[Methods::test_subscription] Calling subscription method: {:?}, params: {:?}", method, params); let req = Request { jsonrpc: TwoPointZero, id: Id::Number(0), method: Cow::borrowed(method), params: Some(¶ms) }; @@ -534,7 +534,7 @@ impl RpcModule { is_connected: Some(conn_tx), }; if let Err(err) = callback(params, sink, ctx.clone()) { - log::error!( + tracing::error!( "subscribe call '{}' failed: {:?}, request id={:?}", subscribe_method_name, err, @@ -553,7 +553,7 @@ impl RpcModule { let sub_id = match params.one() { Ok(sub_id) => sub_id, Err(_) => { - log::error!( + tracing::error!( "unsubscribe call '{}' failed: couldn't parse subscription id, request id={:?}", unsubscribe_method_name, id @@ -865,7 +865,7 @@ mod tests { .register_subscription("my_sub", "my_unsub", |_, mut sink, _| { let mut stream_data = vec!['0', '1', '2']; std::thread::spawn(move || loop { - log::debug!("This is your friendly subscription sending data."); + tracing::debug!("This is your friendly subscription sending data."); if let Some(letter) = stream_data.pop() { if let Err(Error::SubscriptionClosed(_)) = sink.send(&letter) { return; diff --git a/ws-client/Cargo.toml b/ws-client/Cargo.toml index 6f9464ab36..328f0cda93 100644 --- a/ws-client/Cargo.toml +++ b/ws-client/Cargo.toml @@ -20,7 +20,7 @@ fnv = "1" futures = { version = "0.3.14", default-features = false, features = ["std"] } http = "0.2" jsonrpsee-types = { path = "../types", version = "0.4.1" } -log = "0.4" +tracing = "0.1" pin-project = "1" rustls-native-certs = "0.5.0" serde = "1" diff --git a/ws-client/src/client.rs b/ws-client/src/client.rs index e9dbcf1cea..cf16a8f44e 100644 --- a/ws-client/src/client.rs +++ b/ws-client/src/client.rs @@ -258,7 +258,7 @@ impl Client for WsClient { self.id_guard.reclaim_request_id(); Error::ParseError(e) })?; - log::trace!("[frontend]: send notification: {:?}", raw); + tracing::trace!("[frontend]: send notification: {:?}", raw); let mut sender = self.to_back.clone(); let fut = sender.send(FrontToBack::Notification(raw)); @@ -287,7 +287,7 @@ impl Client for WsClient { self.id_guard.reclaim_request_id(); Error::ParseError(e) })?; - log::trace!("[frontend]: send request: {:?}", raw); + tracing::trace!("[frontend]: send request: {:?}", raw); if self .to_back @@ -328,7 +328,7 @@ impl Client for WsClient { self.id_guard.reclaim_request_id(); Error::ParseError(e) })?; - log::trace!("[frontend]: send batch request: {:?}", raw); + tracing::trace!("[frontend]: send batch request: {:?}", raw); if self .to_back .clone() @@ -370,7 +370,7 @@ impl SubscriptionClient for WsClient { where N: DeserializeOwned, { - log::trace!("[frontend]: subscribe: {:?}, unsubscribe: {:?}", subscribe_method, unsubscribe_method); + tracing::trace!("[frontend]: subscribe: {:?}, unsubscribe: {:?}", subscribe_method, unsubscribe_method); if subscribe_method == unsubscribe_method { return Err(Error::SubscriptionNameConflict(unsubscribe_method.to_owned())); @@ -417,7 +417,7 @@ impl SubscriptionClient for WsClient { where N: DeserializeOwned, { - log::trace!("[frontend]: register_notification: {:?}", method); + tracing::trace!("[frontend]: register_notification: {:?}", method); let (send_back_tx, send_back_rx) = oneshot::channel(); if self @@ -471,41 +471,41 @@ async fn background_task( // User dropped the sender side of the channel. // There is nothing to do just terminate. Either::Left((None, _)) => { - log::trace!("[backend]: frontend dropped; terminate client"); + tracing::trace!("[backend]: frontend dropped; terminate client"); break; } Either::Left((Some(FrontToBack::Batch(batch)), _)) => { - log::trace!("[backend]: client prepares to send batch request: {:?}", batch.raw); + tracing::trace!("[backend]: client prepares to send batch request: {:?}", batch.raw); // NOTE(niklasad1): annoying allocation. if let Err(send_back) = manager.insert_pending_batch(batch.ids.clone(), batch.send_back) { - log::warn!("[backend]: batch request: {:?} already pending", batch.ids); + tracing::warn!("[backend]: batch request: {:?} already pending", batch.ids); let _ = send_back.send(Err(Error::InvalidRequestId)); continue; } if let Err(e) = sender.send(batch.raw).await { - log::warn!("[backend]: client batch request failed: {:?}", e); + tracing::warn!("[backend]: client batch request failed: {:?}", e); manager.complete_pending_batch(batch.ids); } } // User called `notification` on the front-end Either::Left((Some(FrontToBack::Notification(notif)), _)) => { - log::trace!("[backend]: client prepares to send notification: {:?}", notif); + tracing::trace!("[backend]: client prepares to send notification: {:?}", notif); if let Err(e) = sender.send(notif).await { - log::warn!("[backend]: client notif failed: {:?}", e); + tracing::warn!("[backend]: client notif failed: {:?}", e); } } // User called `request` on the front-end Either::Left((Some(FrontToBack::Request(request)), _)) => { - log::trace!("[backend]: client prepares to send request={:?}", request); + tracing::trace!("[backend]: client prepares to send request={:?}", request); match sender.send(request.raw).await { Ok(_) => manager .insert_pending_call(request.id, request.send_back) .expect("ID unused checked above; qed"), Err(e) => { - log::warn!("[backend]: client request failed: {:?}", e); + tracing::warn!("[backend]: client request failed: {:?}", e); let _ = request.send_back.map(|s| s.send(Err(Error::Transport(e.into())))); } } @@ -522,13 +522,13 @@ async fn background_task( ) .expect("Request ID unused checked above; qed"), Err(e) => { - log::warn!("[backend]: client subscription failed: {:?}", e); + tracing::warn!("[backend]: client subscription failed: {:?}", e); let _ = sub.send_back.send(Err(Error::Transport(e.into()))); } }, // User dropped a subscription. Either::Left((Some(FrontToBack::SubscriptionClosed(sub_id)), _)) => { - log::trace!("Closing subscription: {:?}", sub_id); + tracing::trace!("Closing subscription: {:?}", sub_id); // NOTE: The subscription may have been closed earlier if // the channel was full or disconnected. if let Some(unsub) = manager @@ -541,7 +541,7 @@ async fn background_task( // User called `register_notification` on the front-end. Either::Left((Some(FrontToBack::RegisterNotification(reg)), _)) => { - log::trace!("[backend] registering notification handler: {:?}", reg.method); + tracing::trace!("[backend] registering notification handler: {:?}", reg.method); let (subscribe_tx, subscribe_rx) = mpsc::channel(max_notifs_per_subscription); if manager.insert_notification_handler(®.method, subscribe_tx).is_ok() { @@ -553,13 +553,13 @@ async fn background_task( // User dropped the notificationHandler for this method Either::Left((Some(FrontToBack::UnregisterNotification(method)), _)) => { - log::trace!("[backend] unregistering notification handler: {:?}", method); + tracing::trace!("[backend] unregistering notification handler: {:?}", method); let _ = manager.remove_notification_handler(method); } Either::Right((Some(Ok(raw)), _)) => { // Single response to a request. if let Ok(single) = serde_json::from_slice::>(&raw) { - log::debug!("[backend]: recv method_call {:?}", single); + tracing::debug!("[backend]: recv method_call {:?}", single); match process_single_response(&mut manager, single, max_notifs_per_subscription) { Ok(Some(unsub)) => { stop_subscription(&mut sender, &mut manager, unsub).await; @@ -573,19 +573,19 @@ async fn background_task( } // Subscription response. else if let Ok(response) = serde_json::from_slice::>(&raw) { - log::debug!("[backend]: recv subscription {:?}", response); + tracing::debug!("[backend]: recv subscription {:?}", response); if let Err(Some(unsub)) = process_subscription_response(&mut manager, response) { let _ = stop_subscription(&mut sender, &mut manager, unsub).await; } } // Incoming Notification else if let Ok(notif) = serde_json::from_slice::>(&raw) { - log::debug!("[backend]: recv notification {:?}", notif); + tracing::debug!("[backend]: recv notification {:?}", notif); let _ = process_notification(&mut manager, notif); } // Batch response. else if let Ok(batch) = serde_json::from_slice::>>(&raw) { - log::debug!("[backend]: recv batch {:?}", batch); + tracing::debug!("[backend]: recv batch {:?}", batch); if let Err(e) = process_batch_response(&mut manager, batch) { let _ = front_error.send(e); break; @@ -593,7 +593,7 @@ async fn background_task( } // Error response else if let Ok(err) = serde_json::from_slice::(&raw) { - log::debug!("[backend]: recv error response {:?}", err); + tracing::debug!("[backend]: recv error response {:?}", err); if let Err(e) = process_error_response(&mut manager, err) { let _ = front_error.send(e); break; @@ -601,7 +601,7 @@ async fn background_task( } // Unparsable response else { - log::debug!( + tracing::debug!( "[backend]: recv unparseable message: {:?}", serde_json::from_slice::(&raw) ); @@ -610,12 +610,12 @@ async fn background_task( } } Either::Right((Some(Err(e)), _)) => { - log::error!("Error: {:?} terminating client", e); + tracing::error!("Error: {:?} terminating client", e); let _ = front_error.send(Error::Transport(e.into())); break; } Either::Right((None, _)) => { - log::error!("[backend]: WebSocket receiver dropped; terminate client"); + tracing::error!("[backend]: WebSocket receiver dropped; terminate client"); let _ = front_error.send(Error::Custom("WebSocket receiver dropped".into())); break; } diff --git a/ws-client/src/helpers.rs b/ws-client/src/helpers.rs index b0e1147944..9a7c711beb 100644 --- a/ws-client/src/helpers.rs +++ b/ws-client/src/helpers.rs @@ -52,7 +52,7 @@ pub fn process_batch_response(manager: &mut RequestManager, rps: Vec state, None => { - log::warn!("Received unknown batch response"); + tracing::warn!("Received unknown batch response"); return Err(Error::InvalidRequestId); } }; @@ -85,14 +85,14 @@ pub fn process_subscription_response( Some(send_back_sink) => match send_back_sink.try_send(response.params.result) { Ok(()) => Ok(()), Err(err) => { - log::error!("Dropping subscription {:?} error: {:?}", sub_id, err); + tracing::error!("Dropping subscription {:?} error: {:?}", sub_id, err); let msg = build_unsubscribe_message(manager, request_id, sub_id) .expect("request ID and subscription ID valid checked above; qed"); Err(Some(msg)) } }, None => { - log::error!("Subscription ID: {:?} is not an active subscription", sub_id); + tracing::error!("Subscription ID: {:?} is not an active subscription", sub_id); Err(None) } } @@ -107,13 +107,13 @@ pub fn process_notification(manager: &mut RequestManager, notif: Notification match send_back_sink.try_send(notif.params) { Ok(()) => Ok(()), Err(err) => { - log::error!("Error sending notification, dropping handler for {:?} error: {:?}", notif.method, err); + tracing::error!("Error sending notification, dropping handler for {:?} error: {:?}", notif.method, err); let _ = manager.remove_notification_handler(notif.method.to_owned()); Err(Error::Internal(err.into_send_error())) } }, None => { - log::error!("Notification: {:?} not a registered method", notif.method); + tracing::error!("Notification: {:?} not a registered method", notif.method); Err(Error::UnregisteredNotification(notif.method.to_owned())) } } @@ -176,7 +176,7 @@ pub fn process_single_response( // NOTE: we don't count this a concurrent request as it's part of a subscription. pub async fn stop_subscription(sender: &mut WsSender, manager: &mut RequestManager, unsub: RequestMessage) { if let Err(e) = sender.send(unsub.raw).await { - log::error!("Send unsubscribe request failed: {:?}", e); + tracing::error!("Send unsubscribe request failed: {:?}", e); let _ = manager.complete_pending_call(unsub.id); } } diff --git a/ws-client/src/transport.rs b/ws-client/src/transport.rs index fec9cbfdf4..aab6a9620f 100644 --- a/ws-client/src/transport.rs +++ b/ws-client/src/transport.rs @@ -161,7 +161,7 @@ impl Sender { /// Sends out a request. Returns a `Future` that finishes when the request has been /// successfully sent. pub async fn send(&mut self, body: String) -> Result<(), WsError> { - log::debug!("send: {}", body); + tracing::debug!("send: {}", body); self.inner.send_text(body).await?; self.inner.flush().await?; Ok(()) @@ -213,7 +213,7 @@ impl<'a> WsTransportClientBuilder<'a> { } for _ in 0..self.max_redirections { - log::debug!("Connecting to target: {:?}", target); + tracing::debug!("Connecting to target: {:?}", target); // The sockaddrs might get reused if the server replies with a relative URI. let sockaddrs = std::mem::take(&mut target.sockaddrs); @@ -221,7 +221,7 @@ impl<'a> WsTransportClientBuilder<'a> { let tcp_stream = match connect(*sockaddr, self.timeout, &target.host, &tls_connector).await { Ok(stream) => stream, Err(e) => { - log::debug!("Failed to connect to sockaddr: {:?}", sockaddr); + tracing::debug!("Failed to connect to sockaddr: {:?}", sockaddr); err = Some(Err(e)); continue; } @@ -237,7 +237,7 @@ impl<'a> WsTransportClientBuilder<'a> { // Perform the initial handshake. match client.handshake().await { Ok(ServerResponse::Accepted { .. }) => { - log::info!("Connection established to target: {:?}", target); + tracing::info!("Connection established to target: {:?}", target); let mut builder = client.into_builder(); builder.set_max_message_size(self.max_request_body_size as usize); let (sender, receiver) = builder.finish(); @@ -245,11 +245,11 @@ impl<'a> WsTransportClientBuilder<'a> { } Ok(ServerResponse::Rejected { status_code }) => { - log::debug!("Connection rejected: {:?}", status_code); + tracing::debug!("Connection rejected: {:?}", status_code); err = Some(Err(WsHandshakeError::Rejected { status_code })); } Ok(ServerResponse::Redirect { status_code, location }) => { - log::debug!("Redirection: status_code: {}, location: {}", status_code, location); + tracing::debug!("Redirection: status_code: {}, location: {}", status_code, location); match location.parse::() { // redirection with absolute path => need to lookup. Ok(uri) => { @@ -321,7 +321,7 @@ async fn connect( socket = socket => { let socket = socket?; if let Err(err) = socket.set_nodelay(true) { - log::warn!("set nodelay failed: {:?}", err); + tracing::warn!("set nodelay failed: {:?}", err); } match tls_connector { None => Ok(TlsOrPlain::Plain(socket)), diff --git a/ws-server/Cargo.toml b/ws-server/Cargo.toml index ff8adfda1c..68652d1437 100644 --- a/ws-server/Cargo.toml +++ b/ws-server/Cargo.toml @@ -14,7 +14,7 @@ futures-channel = "0.3.14" futures-util = { version = "0.3.14", default-features = false, features = ["io", "async-await-macro"] } jsonrpsee-types = { path = "../types", version = "0.4.1" } jsonrpsee-utils = { path = "../utils", version = "0.4.1", features = ["server"] } -log = "0.4" +tracing = "0.1" serde_json = { version = "1", features = ["raw_value"] } soketto = "0.7" tokio = { version = "1", features = ["net", "rt-multi-thread", "macros"] } diff --git a/ws-server/src/server.rs b/ws-server/src/server.rs index 8002533d7f..6a0abf25af 100644 --- a/ws-server/src/server.rs +++ b/ws-server/src/server.rs @@ -94,12 +94,12 @@ impl Server { match connections.select_with(&mut incoming).await { Ok((socket, _addr)) => { if let Err(e) = socket.set_nodelay(true) { - log::error!("Could not set NODELAY on socket: {:?}", e); + tracing::error!("Could not set NODELAY on socket: {:?}", e); continue; } if connections.count() >= self.cfg.max_connections as usize { - log::warn!("Too many connections. Try again in a while."); + tracing::warn!("Too many connections. Try again in a while."); connections.add(Box::pin(handshake(socket, HandshakeResponse::Reject { status_code: 429 }))); continue; } @@ -121,7 +121,7 @@ impl Server { id = id.wrapping_add(1); } Err(IncomingError::Io(err)) => { - log::error!("Error while awaiting a new connection: {:?}", err); + tracing::error!("Error while awaiting a new connection: {:?}", err); } Err(IncomingError::Shutdown) => break, } @@ -251,7 +251,7 @@ async fn background_task( while !stop_server2.shutdown_requested() { match rx.next().await { Some(response) => { - log::debug!("send: {}", response); + tracing::debug!("send: {}", response); let _ = sender.send_text(response).await; let _ = sender.flush().await; } @@ -272,13 +272,13 @@ async fn background_task( data.clear(); if let Err(e) = method_executors.select_with(receiver.receive_data(&mut data)).await { - log::error!("Could not receive WS data: {:?}; closing connection", e); + tracing::error!("Could not receive WS data: {:?}; closing connection", e); tx.close_channel(); return Err(e.into()); } if data.len() > max_request_body_size as usize { - log::warn!("Request is too big ({} bytes, max is {})", data.len(), max_request_body_size); + tracing::warn!("Request is too big ({} bytes, max is {})", data.len(), max_request_body_size); send_error(Id::Null, &tx, ErrorCode::OversizedRequest.into()); continue; } @@ -286,7 +286,7 @@ async fn background_task( match data.get(0) { Some(b'{') => { if let Ok(req) = serde_json::from_slice::(&data) { - log::debug!("recv: {:?}", req); + tracing::debug!("recv: {:?}", req); if let Some(fut) = methods.execute_with_resources(&tx, req, conn_id, &resources) { method_executors.add(fut); } @@ -315,7 +315,7 @@ async fn background_task( rx_batch.close(); let results = collect_batch_response(rx_batch).await; if let Err(err) = tx.unbounded_send(results) { - log::error!("Error sending batch response to the client: {:?}", err) + tracing::error!("Error sending batch response to the client: {:?}", err) } } else { send_error(Id::Null, &tx, ErrorCode::InvalidRequest.into()); @@ -346,7 +346,7 @@ impl AllowedValue { if let (AllowedValue::OneOf(list), Some(value)) = (self, value) { if !list.iter().any(|o| o.as_bytes() == value) { let error = format!("{} denied: {}", header, String::from_utf8_lossy(value)); - log::warn!("{}", error); + tracing::warn!("{}", error); return Err(Error::Request(error)); } } diff --git a/ws-server/src/tests.rs b/ws-server/src/tests.rs index 9055720851..020ae7b61a 100644 --- a/ws-server/src/tests.rs +++ b/ws-server/src/tests.rs @@ -63,7 +63,7 @@ async fn server_with_handles() -> (SocketAddr, StopHandle) { let mut module = RpcModule::new(()); module .register_method("say_hello", |_, _| { - log::debug!("server respond to hello"); + tracing::debug!("server respond to hello"); Ok("hello") }) .unwrap(); @@ -77,7 +77,7 @@ async fn server_with_handles() -> (SocketAddr, StopHandle) { module .register_async_method("say_hello_async", |_, _| { async move { - log::debug!("server respond to hello"); + tracing::debug!("server respond to hello"); // Call some async function inside. futures_util::future::ready(()).await; Ok("hello")