feat: rework logs (#2988)

This commit is contained in:
Bjerg
2023-06-05 19:43:14 +02:00
committed by GitHub
parent 643b3811c2
commit d2c68edf23
24 changed files with 74 additions and 70 deletions

View File

@ -277,19 +277,19 @@ impl RpcServerArgs {
let server_config = self.rpc_server_config();
let launch_rpc = rpc_modules.start_server(server_config).map_ok(|handle| {
if let Some(url) = handle.ipc_endpoint() {
info!(target: "reth::cli", url=%url, "IPC server started");
info!(target: "reth::cli", url=%url, "RPC IPC server started");
}
if let Some(addr) = handle.http_local_addr() {
info!(target: "reth::cli", url=%addr, "HTTP server started");
info!(target: "reth::cli", url=%addr, "RPC HTTP server started");
}
if let Some(addr) = handle.ws_local_addr() {
info!(target: "reth::cli", url=%addr, "WS server started");
info!(target: "reth::cli", url=%addr, "RPC WS server started");
}
handle
});
let launch_auth = auth_module.start_server(auth_config).inspect(|_| {
info!(target: "reth::cli", "Started Auth server");
info!(target: "reth::cli", "RPC auth server started");
});
// launch servers concurrently

View File

@ -108,7 +108,7 @@ pub struct Logs {
journald: bool,
/// The filter to use for logs written to the log file.
#[arg(long = "log.filter", value_name = "FILTER", global = true, default_value = "debug")]
#[arg(long = "log.filter", value_name = "FILTER", global = true, default_value = "error")]
filter: String,
}
@ -166,7 +166,7 @@ impl Verbosity {
_ => Level::TRACE,
};
format!("reth::cli={level}").parse().unwrap()
format!("{level}").parse().unwrap()
}
}
}

View File

@ -95,7 +95,7 @@ impl<'a, DB: Database> DbTool<'a, DB> {
/// Drops the database at the given path.
pub fn drop(&mut self, path: impl AsRef<Path>) -> Result<()> {
let path = path.as_ref();
info!(target: "reth::cli", "Dropping db at {:?}", path);
info!(target: "reth::cli", "Dropping database at {:?}", path);
std::fs::remove_dir_all(path).wrap_err("Dropping the database failed")?;
Ok(())
}

View File

@ -621,20 +621,20 @@ impl<DB: Database, C: Consensus, EF: ExecutorFactory> BlockchainTree<DB, C, EF>
if let Err(e) =
self.externals.consensus.validate_header_with_total_difficulty(block, U256::MAX)
{
info!(
"Failed to validate header for TD related check with error: {e:?}, block:{:?}",
block
error!(
?block,
"Failed to validate total difficulty for block {}: {e:?}", block.header.hash
);
return Err(e)
}
if let Err(e) = self.externals.consensus.validate_header(block) {
info!("Failed to validate header with error: {e:?}, block:{:?}", block);
error!(?block, "Failed to validate header {}: {e:?}", block.header.hash);
return Err(e)
}
if let Err(e) = self.externals.consensus.validate_block(block) {
info!("Failed to validate blocks with error: {e:?}, block:{:?}", block);
error!(?block, "Failed to validate block {}: {e:?}", block.header.hash);
return Err(e)
}
@ -868,7 +868,7 @@ impl<DB: Database, C: Consensus, EF: ExecutorFactory> BlockchainTree<DB, C, EF>
// If block is already canonical don't return error.
if let Some(header) = self.find_canonical_header(block_hash)? {
info!(target: "blockchain_tree", ?block_hash, "Block is already canonical");
info!(target: "blockchain_tree", ?block_hash, "Block is already canonical, ignoring.");
let td = self
.externals
.database()
@ -882,7 +882,7 @@ impl<DB: Database, C: Consensus, EF: ExecutorFactory> BlockchainTree<DB, C, EF>
}
let Some(chain_id) = self.block_indices.get_blocks_chain_id(block_hash) else {
info!(target: "blockchain_tree", ?block_hash, "Block hash not found in block indices");
error!(target: "blockchain_tree", ?block_hash, "Block hash not found in block indices");
// TODO: better error
return Err(BlockExecutionError::BlockHashNotFoundInChain { block_hash: *block_hash }.into())
};
@ -1032,7 +1032,7 @@ impl<DB: Database, C: Consensus, EF: ExecutorFactory> BlockchainTree<DB, C, EF>
let tip = tx.tip_number()?;
let revert_range = (revert_until + 1)..=tip;
info!(target: "blockchain_tree", "Revert canonical chain range: {:?}", revert_range);
info!(target: "blockchain_tree", "Unwinding canonical chain blocks: {:?}", revert_range);
// read block and execution result from database. and remove traces of block from tables.
let blocks_and_execution = tx
.take_block_and_execution_range(self.externals.chain_spec.as_ref(), revert_range)

View File

@ -1100,7 +1100,7 @@ where
None => {
// This is only possible if the node was run with `debug.tip`
// argument and without CL.
warn!(target: "consensus::engine", "No forkchoice state available");
warn!(target: "consensus::engine", "No fork choice state available");
return None
}
};
@ -1132,7 +1132,7 @@ where
match self.restore_tree_if_possible(sync_target_state) {
Ok(_) => self.sync_state_updater.update_sync_state(SyncState::Idle),
Err(error) => {
error!(target: "consensus::engine", ?error, "Error restoring blockchain tree");
error!(target: "consensus::engine", ?error, "Error restoring blockchain tree state");
return Some(Err(error.into()))
}
};

View File

@ -54,7 +54,7 @@ use tokio::{
time::Interval,
};
use tokio_stream::{wrappers::ReceiverStream, Stream, StreamExt};
use tracing::{debug, info, trace, warn};
use tracing::{debug, trace, warn};
pub mod error;
mod proto;
@ -322,10 +322,10 @@ impl Discv4 {
fn send_to_service(&self, cmd: Discv4Command) {
let _ = self.to_service.try_send(cmd).map_err(|err| {
warn!(
debug!(
target : "discv4",
%err,
"dropping command",
"channel capacity reached, dropping command",
)
});
}
@ -503,10 +503,10 @@ impl Discv4Service {
/// discovery
pub fn set_external_ip_addr(&mut self, external_ip: IpAddr) {
if self.local_node_record.address != external_ip {
info!(target : "discv4", ?external_ip, "Updating external ip");
debug!(target : "discv4", ?external_ip, "Updating external ip");
self.local_node_record.address = external_ip;
let _ = self.local_eip_868_enr.set_ip(external_ip, &self.secret_key);
info!(target : "discv4", enr=?self.local_eip_868_enr, "Updated local ENR");
debug!(target : "discv4", enr=?self.local_eip_868_enr, "Updated local ENR");
}
}
@ -857,10 +857,10 @@ impl Discv4Service {
let (payload, hash) = msg.encode(&self.secret_key);
trace!(target : "discv4", r#type=?msg.msg_type(), ?to, ?hash, "sending packet");
let _ = self.egress.try_send((payload, to)).map_err(|err| {
warn!(
debug!(
target : "discv4",
%err,
"drop outgoing packet",
"dropped outgoing packet",
);
});
hash
@ -1589,7 +1589,7 @@ pub(crate) async fn send_loop(udp: Arc<UdpSocket>, rx: EgressReceiver) {
pub(crate) async fn receive_loop(udp: Arc<UdpSocket>, tx: IngressSender, local_id: PeerId) {
let send = |event: IngressEvent| async {
let _ = tx.send(event).await.map_err(|err| {
warn!(
debug!(
target : "discv4",
%err,
"failed send incoming packet",

View File

@ -26,7 +26,7 @@ use tokio::{
task::{JoinHandle, JoinSet},
};
use tokio_stream::{Stream, StreamExt};
use tracing::error;
use tracing::{debug, error};
/// Mock discovery node
pub struct MockDiscovery {
@ -145,7 +145,7 @@ impl Stream for MockDiscovery {
match event {
IngressEvent::RecvError(_) => {}
IngressEvent::BadPacket(from, err, data) => {
error!( target : "discv4", ?from, ?err, packet=?hex::encode(&data), "bad packet");
debug!( target : "discv4", ?from, ?err, packet=?hex::encode(&data), "bad packet");
}
IngressEvent::Packet(remote_addr, Packet { msg, node_id, hash }) => match msg {
Message::Ping(ping) => {

View File

@ -24,6 +24,7 @@ use std::{
sync::Arc,
task::{Context, Poll},
};
use tracing::info;
/// The scope for headers downloader metrics.
pub const BODIES_DOWNLOADER_SCOPE: &str = "downloaders.bodies";
@ -312,7 +313,7 @@ where
fn set_download_range(&mut self, range: RangeInclusive<BlockNumber>) -> DownloadResult<()> {
// Check if the range is valid.
if range.is_empty() {
tracing::error!(target: "downloaders::bodies", ?range, "Range is invalid");
tracing::error!(target: "downloaders::bodies", ?range, "Bodies download range is invalid (empty)");
return Err(DownloadError::InvalidBodyRange { range })
}
@ -330,6 +331,7 @@ where
if is_next_consecutive_range {
// New range received.
tracing::trace!(target: "downloaders::bodies", ?range, "New download range set");
info!(target: "downloaders::bodies", "Downloading bodies {range:?}");
self.download_range = range;
return Ok(())
}
@ -337,6 +339,7 @@ where
// The block range is reset. This can happen either after unwind or after the bodies were
// written by external services (e.g. BlockchainTree).
tracing::trace!(target: "downloaders::bodies", ?range, prev_range = ?self.download_range, "Download range reset");
info!(target: "downloaders::bodies", "Downloading bodies {range:?}");
self.clear();
self.download_range = range;
Ok(())

View File

@ -125,7 +125,7 @@ impl<T: BodyDownloader> Future for SpawnedDownloader<T> {
}
Poll::Ready(Some(range)) => {
if let Err(err) = this.downloader.set_download_range(range) {
tracing::error!(target: "downloaders::bodies", ?err, "Failed to set download range");
tracing::error!(target: "downloaders::bodies", ?err, "Failed to set bodies download range");
match ready!(this.bodies_tx.poll_reserve(cx)) {
Ok(()) => {

View File

@ -228,14 +228,14 @@ async fn resolve_external_ip_upnp() -> Option<IpAddr> {
search_gateway(Default::default())
.await
.map_err(|err| {
warn!(target: "net::nat", ?err, "failed to find upnp gateway");
warn!(target: "net::nat", ?err, "Failed to resolve external IP via UPnP: failed to find gateway");
err
})
.ok()?
.get_external_ip()
.await
.map_err(|err| {
warn!(target: "net::nat", ?err, "failed to resolve external ip via upnp gateway");
warn!(target: "net::nat", ?err, "Failed to resolve external IP via UPnP");
err
})
.ok()

View File

@ -54,7 +54,7 @@ use std::{
};
use tokio::sync::mpsc::{self, error::TrySendError};
use tokio_stream::wrappers::UnboundedReceiverStream;
use tracing::{debug, error, info, trace};
use tracing::{debug, error, info, trace, warn};
/// Manages the _entire_ state of the network.
///
/// This is an endless [`Future`] that consistently drives the state of the entire network forward.
@ -501,7 +501,7 @@ where
unreachable!("Not emitted by session")
}
PeerMessage::Other(other) => {
error!(target : "net", message_id=%other.id, "Ignoring unsupported message");
debug!(target : "net", message_id=%other.id, "Ignoring unsupported message");
}
}
}
@ -514,7 +514,8 @@ where
}
NetworkHandleMessage::AnnounceBlock(block, hash) => {
if self.handle.mode().is_stake() {
error!(target : "net", "Block propagation is not supported in POS - [EIP-3675](https://eips.ethereum.org/EIPS/eip-3675#devp2p)");
// See [EIP-3675](https://eips.ethereum.org/EIPS/eip-3675#devp2p)
warn!(target : "net", "Peer performed block propagation, but it is not supported in proof of stake (EIP-3675)");
return
}
let msg = NewBlockMessage { hash, block: Arc::new(block) };
@ -601,7 +602,7 @@ where
Poll::Ready(None) => {
// This is only possible if the channel was deliberately closed since we always
// have an instance of `NetworkHandle`
error!("network message channel closed.");
error!("Network message channel closed.");
return Poll::Ready(())
}
Poll::Ready(Some(msg)) => this.on_handle_message(msg),

View File

@ -1143,7 +1143,7 @@ impl PeersConfig {
return Ok(self)
};
let reader = match std::fs::File::open(file_path.as_ref()) {
Ok(file) => std::io::BufReader::new(file),
Ok(file) => io::BufReader::new(file),
Err(e) if e.kind() == ErrorKind::NotFound => return Ok(self),
Err(e) => Err(e)?,
};

View File

@ -37,7 +37,7 @@ use tokio::{
time::Interval,
};
use tokio_stream::wrappers::ReceiverStream;
use tracing::{debug, error, info, trace};
use tracing::{debug, info, trace};
/// Constants for timeout updating
@ -265,7 +265,7 @@ impl ActiveSession {
unreachable!("Not emitted by network")
}
PeerMessage::Other(other) => {
error!(target : "net::session", message_id=%other.id, "Ignoring unsupported message");
debug!(target : "net::session", message_id=%other.id, "Ignoring unsupported message");
}
}
}
@ -283,7 +283,7 @@ impl ActiveSession {
self.queued_outgoing.push_back(msg.into());
}
Err(err) => {
error!(target : "net", ?err, "Failed to respond to received request");
debug!(target : "net", ?err, "Failed to respond to received request");
}
}
}
@ -395,7 +395,7 @@ impl ActiveSession {
self.poll_disconnect(cx)
}
Err(err) => {
error!(target: "net::session", ?err, remote_peer_id=?self.remote_peer_id, "could not send disconnect");
debug!(target: "net::session", ?err, remote_peer_id=?self.remote_peer_id, "could not send disconnect");
self.close_on_error(err);
Poll::Ready(())
}
@ -474,7 +474,7 @@ impl Future for ActiveSession {
progress = true;
match cmd {
SessionCommand::Disconnect { reason } => {
info!(target: "net::session", ?reason, remote_peer_id=?this.remote_peer_id, "session received disconnect command");
info!(target: "net::session", ?reason, remote_peer_id=?this.remote_peer_id, "Received disconnect command for session");
let reason =
reason.unwrap_or(DisconnectReason::DisconnectRequested);
@ -519,7 +519,7 @@ impl Future for ActiveSession {
OutgoingMessage::Broadcast(msg) => this.conn.start_send_broadcast(msg),
};
if let Err(err) = res {
error!(target: "net::session", ?err, remote_peer_id=?this.remote_peer_id, "failed to send message");
debug!(target: "net::session", ?err, remote_peer_id=?this.remote_peer_id, "failed to send message");
// notify the manager
this.close_on_error(err);
return Poll::Ready(())
@ -573,7 +573,7 @@ impl Future for ActiveSession {
progress = true;
}
OnIncomingMessageOutcome::BadMessage { error, message } => {
error!(target: "net::session", ?error, msg=?message, remote_peer_id=?this.remote_peer_id, "received invalid protocol message");
debug!(target: "net::session", ?error, msg=?message, remote_peer_id=?this.remote_peer_id, "received invalid protocol message");
this.close_on_error(error);
return Poll::Ready(())
}

View File

@ -20,7 +20,7 @@ use std::{
sync::Arc,
task::{Context, Poll},
};
use tracing::{trace, warn};
use tracing::{debug, trace};
/// Contains the connectivity related state of the network.
///
@ -225,7 +225,7 @@ where
return Some(SwarmEvent::IncomingTcpConnection { session_id, remote_addr })
}
Err(err) => {
warn!(target: "net", ?err, "Incoming connection rejected");
debug!(target: "net", ?err, "Incoming connection rejected, capacity already reached.");
self.state_mut()
.peers_mut()
.on_incoming_pending_session_rejected_internally();

View File

@ -217,7 +217,7 @@ where
trace!(%id, "payload job finished");
}
Poll::Ready(Err(err)) => {
warn!(?err, ?id, "payload job failed; resolving payload");
warn!(?err, ?id, "Payload builder job failed; resolving payload");
this.metrics.inc_failed_jobs();
this.metrics.set_active_jobs(this.payload_jobs.len());
}
@ -240,7 +240,7 @@ where
let mut res = Ok(id);
if this.contains_payload(id) {
warn!(%id, parent = ?attr.parent, "payload job already in progress");
warn!(%id, parent = ?attr.parent, "Payload job already in progress, ignoring.");
} else {
// no job for this payload yet, create one
match this.generator.new_payload_job(attr) {
@ -251,7 +251,7 @@ where
}
Err(err) => {
this.metrics.inc_failed_jobs();
warn!(?err, %id, "failed to create payload job");
warn!(?err, %id, "Failed to create payload builder job");
res = Err(err);
}
}

View File

@ -22,7 +22,7 @@ use tokio::{
sync::{oneshot, watch, OwnedSemaphorePermit},
};
use tower::{layer::util::Identity, Service};
use tracing::{trace, warn};
use tracing::{debug, trace, warn};
// re-export so can be used during builder setup
pub use parity_tokio_ipc::Endpoint;
@ -97,12 +97,12 @@ impl IpcServer {
stop_handle: StopHandle,
on_ready: oneshot::Sender<Result<(), String>>,
) -> io::Result<()> {
trace!( endpoint=?self.endpoint.path(), "starting ipc server" );
trace!( endpoint = ?self.endpoint.path(), "starting ipc server");
if cfg!(unix) {
// ensure the file does not exist
if std::fs::remove_file(self.endpoint.path()).is_ok() {
warn!( endpoint=?self.endpoint.path(), "removed existing file");
debug!(endpoint = ?self.endpoint.path(), "removed existing IPC endpoint file");
}
}
@ -142,7 +142,7 @@ impl IpcServer {
let conn = match connection_guard.try_acquire() {
Some(conn) => conn,
None => {
warn!("Too many connections. Please try again later.");
warn!("Too many IPC connections. Please try again later.");
connections.add(ipc.reject_connection().boxed());
continue
}
@ -181,7 +181,7 @@ impl IpcServer {
id = id.wrapping_add(1);
}
Err(MonitoredError::Selector(err)) => {
tracing::error!("Error while awaiting a new connection: {:?}", err);
tracing::error!("Error while awaiting a new IPC connection: {:?}", err);
}
Err(MonitoredError::Shutdown) => break,
}
@ -315,7 +315,7 @@ async fn spawn_connection<S, T>(
}
},
Some(Err(e)) => {
tracing::warn!("Request failed: {:?}", e);
tracing::warn!("IPC request failed: {:?}", e);
break
}
None => {
@ -338,7 +338,7 @@ async fn spawn_connection<S, T>(
// send item over ipc
if let Err(err) = conn.send(item).await {
warn!("Failed to send response: {:?}", err);
warn!("Failed to send IPC response: {:?}", err);
break
}
}

View File

@ -104,7 +104,7 @@ where
) -> Self {
// sanitize the percentile to be less than 100
if oracle_config.percentile > 100 {
warn!(prev_percentile=?oracle_config.percentile, "Invalid configured gas price percentile, using 100 instead");
warn!(prev_percentile = ?oracle_config.percentile, "Invalid configured gas price percentile, assuming 100.");
oracle_config.percentile = 100;
}

View File

@ -29,14 +29,14 @@ impl AuthValidator for JwtAuthValidator {
Some(jwt) => match self.secret.validate(jwt) {
Ok(_) => Ok(()),
Err(e) => {
error!(target = "engine::jwt-validator", "{e}");
error!(target = "engine::jwt-validator", "Invalid JWT: {e}");
let response = err_response(e);
Err(response)
}
},
None => {
let e = JwtError::MissingOrInvalidAuthorizationHeader;
error!(target = "engine::jwt-validator", "{e}");
error!(target = "engine::jwt-validator", "Invalid JWT: {e}");
let response = err_response(e);
Err(response)
}

View File

@ -124,7 +124,7 @@ where
#[track_caller]
pub fn set_tip(&self, tip: H256) {
let _ = self.tip_tx.as_ref().expect("tip sender is set").send(tip).map_err(|_| {
warn!(target: "sync::pipeline", "tip channel closed");
warn!(target: "sync::pipeline", "Chain tip channel closed");
});
}
@ -318,7 +318,7 @@ where
stage = %stage_id,
max_block = self.max_block,
prev_block = prev_checkpoint.map(|progress| progress.block_number),
"Stage reached maximum block, skipping."
"Stage reached target block, skipping."
);
self.listeners.notify(PipelineEvent::Skipped { stage_id });
@ -348,7 +348,7 @@ where
progress = checkpoint.block_number,
%checkpoint,
%done,
"Stage made progress"
"Stage committed progress"
);
self.metrics.stage_checkpoint(
stage_id,
@ -407,7 +407,7 @@ where
warn!(
target: "sync::pipeline",
stage = %stage_id,
"Stage encountered a non-fatal error: {err}. Retrying"
"Stage encountered a non-fatal error: {err}. Retrying..."
);
continue
};

View File

@ -72,7 +72,7 @@ impl<DB: Database, D: BodyDownloader> Stage<DB> for BodyStage<D> {
let range = input.next_block_range();
if range.is_empty() {
let (from, to) = range.into_inner();
info!(target: "sync::stages::bodies", from, "Target block already reached");
info!(target: "sync::stages::bodies", from, "Target block already downloaded, skipping.");
return Ok(ExecOutput::done(StageCheckpoint::new(to)))
}

View File

@ -79,7 +79,7 @@ impl MerkleStage {
if got == expected.state_root {
Ok(())
} else {
warn!(target: "sync::stages::merkle", ?target_block, ?got, ?expected, "Block's root state failed verification");
warn!(target: "sync::stages::merkle", ?target_block, ?got, ?expected, "Failed to verify block state root");
Err(StageError::Validation {
block: expected.clone(),
error: consensus::ConsensusError::BodyStateRootDiff {

View File

@ -44,7 +44,7 @@ where
{
// TODO: Auto-detect
let with_ansi = std::env::var("RUST_LOG_STYLE").map(|val| val != "never").unwrap_or(true);
let with_target = std::env::var("RUST_LOG_TARGET").map(|val| val != "0").unwrap_or(false);
let with_target = std::env::var("RUST_LOG_TARGET").map(|val| val != "0").unwrap_or(true);
let filter =
EnvFilter::builder().with_default_directive(default_directive.into()).from_env_lossy();

View File

@ -12,7 +12,7 @@ use std::{
collections::HashSet,
hash::{Hash, Hasher},
};
use tracing::{debug, warn};
use tracing::debug;
/// Maximum (reorg) depth we handle when updating the transaction pool: `new.number -
/// last_seen.number`
@ -98,7 +98,7 @@ pub async fn maintain_transaction_pool<Client, V, T, St>(
}
Err(err) => {
let (addresses, err) = *err;
warn!(
debug!(
?err,
"failed to load missing changed accounts at new tip: {:?}",
new_tip.hash

View File

@ -91,7 +91,7 @@ use std::{
time::Instant,
};
use tokio::sync::mpsc;
use tracing::warn;
use tracing::debug;
mod best;
mod events;
@ -343,7 +343,7 @@ where
Ok(()) => true,
Err(err) => {
if matches!(err, mpsc::error::TrySendError::Full(_)) {
warn!(
debug!(
target: "txpool",
"[{:?}] failed to send pending tx; channel full",
ready,
@ -364,7 +364,7 @@ where
Ok(()) => true,
Err(err) => {
if matches!(err, mpsc::error::TrySendError::Full(_)) {
warn!(
debug!(
target: "txpool",
"skipping transaction on full transaction listener",
);