Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

adjust log levels and remove tracing::trace!() #879

Merged
merged 3 commits into from
Oct 9, 2024
Merged

adjust log levels and remove tracing::trace!() #879

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
48d92b7
adjust log levels and remove tracing::trace!()
ppca Oct 8, 2024
b5bb71d
address comments
ppca Oct 9, 2024
7891b19
comments
ppca Oct 9, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions chain-signatures/node/src/cli.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -216,7 +216,7 @@ pub fn run(cmd: Cli) -> anyhow::Result<()> {
client_headers.insert(http::header::REFERER, referer_param.parse().unwrap());
}

tracing::debug!(rpc_addr = rpc_client.rpc_addr(), "rpc client initialized");
tracing::info!(rpc_addr = rpc_client.rpc_addr(), "rpc client initialized");
let signer = InMemorySigner::from_secret_key(account_id.clone(), account_sk);
let (protocol, protocol_state) = MpcSignProtocol::init(
my_address,
Expand All @@ -238,18 +238,18 @@ pub fn run(cmd: Cli) -> anyhow::Result<()> {
);

rt.block_on(async {
tracing::debug!("protocol initialized");
tracing::info!("protocol initialized");
let protocol_handle = tokio::spawn(async move { protocol.run().await });
tracing::debug!("protocol thread spawned");
tracing::info!("protocol thread spawned");
let cipher_sk = hpke::SecretKey::try_from_bytes(&hex::decode(cipher_sk)?)?;
let web_handle = tokio::spawn(async move {
web::run(web_port, sender, cipher_sk, protocol_state, indexer).await
});
tracing::debug!("protocol http server spawned");
tracing::info!("protocol http server spawned");

protocol_handle.await??;
web_handle.await??;
tracing::debug!("spinning down");
tracing::info!("spinning down");

indexer_handle.join().unwrap()?;
anyhow::Ok(())
Expand Down
2 changes: 1 addition & 1 deletion chain-signatures/node/src/http_client.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -169,7 +169,7 @@ impl MessageQueue {
}

if uncompacted > 0 {
tracing::debug!(
tracing::info!(
uncompacted,
compacted,
"{from:?} sent messages in {:?};",
Comment on lines 171 to 175
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how come this is now info? Do you think it's important to surface this info? This is going to spam a lot

Copy link
Contributor Author

@ppca ppca Oct 9, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah this helps to know if messages were successfully sent, what spams is "sending encrypted", this one is much better

Expand Down
12 changes: 6 additions & 6 deletions chain-signatures/node/src/indexer.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -146,7 +146,7 @@ impl Indexer {
block_height: BlockHeight,
gcp: &GcpService,
) -> Result<(), DatastoreStorageError> {
tracing::trace!(block_height, "update_block_height");
tracing::debug!(block_height, "update_block_height");
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like this and many other logs do not have a span. Do we want to add it everywhere and in the indexer in particular?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's going to have a target in the log to filter on. We don't use span at all.

*self.last_updated_timestamp.write().await = Instant::now();
self.latest_block_height
.write()
Expand All @@ -170,11 +170,11 @@ async fn handle_block(
mut block: near_lake_primitives::block::Block,
ctx: &Context,
) -> anyhow::Result<()> {
tracing::trace!(block_height = block.block_height(), "handle_block");
tracing::debug!(block_height = block.block_height(), "handle_block");
let mut pending_requests = Vec::new();
for action in block.actions().cloned().collect::<Vec<_>>() {
if action.receiver_id() == ctx.mpc_contract_id {
tracing::trace!("got action targeting {}", ctx.mpc_contract_id);
tracing::debug!("got action targeting {}", ctx.mpc_contract_id);
let Some(receipt) = block.receipt_by_id(&action.receipt_id()) else {
let err = format!(
"indexer unable to find block for receipt_id={}",
Expand All @@ -190,7 +190,7 @@ async fn handle_block(
continue;
};
if function_call.method_name() == "sign" {
tracing::trace!("found `sign` function call");
tracing::debug!("found `sign` function call");
let arguments =
match serde_json::from_slice::<'_, SignArguments>(function_call.args()) {
Ok(arguments) => arguments,
Expand Down Expand Up @@ -369,7 +369,7 @@ pub fn run(
let outcome = rt.block_on(async {
if i > 0 {
// give it some time to catch up
tracing::trace!("giving indexer some time to catch up");
tracing::debug!("giving indexer some time to catch up");
backoff(i, 10, 300);
}
// while running, we will keep the task spinning, and check every so often if
Expand All @@ -383,7 +383,7 @@ pub fn run(

// Abort the indexer task if it's still running.
if !join_handle.is_finished() {
tracing::trace!("aborting indexer task");
tracing::debug!("aborting indexer task");
join_handle.abort();
}

Expand Down
12 changes: 6 additions & 6 deletions chain-signatures/node/src/protocol/consensus.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -255,7 +255,7 @@ impl ConsensusProtocol for GeneratingState {
) -> Result<NodeState, ConsensusError> {
match contract_state {
ProtocolState::Initializing(_) => {
tracing::debug!("generating(initializing): continuing generation, contract state has not been finalized yet");
tracing::info!("generating(initializing): continuing generation, contract state has not been finalized yet");
Ok(NodeState::Generating(self))
}
ProtocolState::Running(contract_state) => {
Expand Down Expand Up @@ -305,7 +305,7 @@ impl ConsensusProtocol for WaitingForConsensusState {
) -> Result<NodeState, ConsensusError> {
match contract_state {
ProtocolState::Initializing(contract_state) => {
tracing::debug!("waiting(initializing): waiting for consensus, contract state has not been finalized yet");
tracing::info!("waiting(initializing): waiting for consensus, contract state has not been finalized yet");
let public_key = self.public_key.into_near_public_key();
let has_voted = contract_state
.pk_votes
Expand Down Expand Up @@ -427,7 +427,7 @@ impl ConsensusProtocol for WaitingForConsensusState {
}
Ordering::Less => Err(ConsensusError::EpochRollback),
Ordering::Equal => {
tracing::debug!(
tracing::info!(
"waiting(resharing): waiting for resharing consensus, contract state has not been finalized yet"
);
let has_voted = contract_state.finished_votes.contains(ctx.my_account_id());
Expand Down Expand Up @@ -494,7 +494,7 @@ impl ConsensusProtocol for RunningState {
}
Ordering::Less => Err(ConsensusError::EpochRollback),
Ordering::Equal => {
tracing::trace!("running(running): continuing to run as normal");
tracing::debug!("running(running): continuing to run as normal");
if contract_state.participants != self.participants {
return Err(ConsensusError::MismatchedParticipants);
}
Expand Down Expand Up @@ -599,7 +599,7 @@ impl ConsensusProtocol for ResharingState {
}
Ordering::Less => Err(ConsensusError::EpochRollback),
Ordering::Equal => {
tracing::debug!("resharing(resharing): continue to reshare as normal");
tracing::info!("resharing(resharing): continue to reshare as normal");
if contract_state.old_participants != self.old_participants {
return Err(ConsensusError::MismatchedParticipants);
}
Expand Down Expand Up @@ -685,7 +685,7 @@ impl ConsensusProtocol for JoiningState {
tracing::info!("joining(resharing): joining as a new participant");
start_resharing(None, ctx, contract_state).await
} else {
tracing::debug!("joining(resharing): network is resharing without us, waiting for them to finish");
tracing::info!("joining(resharing): network is resharing without us, waiting for them to finish");
Ok(NodeState::Joining(self))
}
}
Expand Down
8 changes: 4 additions & 4 deletions chain-signatures/node/src/protocol/cryptography.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,7 @@ impl CryptographicProtocol for GeneratingState {
match action {
Action::Wait => {
drop(protocol);
tracing::trace!("generating: waiting");
tracing::debug!("generating: waiting");
let failures = self
.messages
.write()
Expand Down Expand Up @@ -246,7 +246,7 @@ impl CryptographicProtocol for ResharingState {
match action {
Action::Wait => {
drop(protocol);
tracing::trace!("resharing: waiting");
tracing::debug!("resharing: waiting");
let failures = self
.messages
.write()
Expand Down Expand Up @@ -359,7 +359,7 @@ impl CryptographicProtocol for RunningState {
let protocol_cfg = &ctx.cfg().protocol;
let active = ctx.mesh().active_participants();
if active.len() < self.threshold {
tracing::info!(
tracing::warn!(
active = ?active.keys_vec(),
"running: not enough participants to progress"
);
Expand Down Expand Up @@ -427,7 +427,7 @@ impl CryptographicProtocol for RunningState {
// block height is up to date, such that they too can process signature requests. If they cannot
// then they are considered unstable and should not be a part of signature generation this round.
let stable = ctx.mesh().stable_participants().await;
tracing::trace!(?stable, "stable participants");
tracing::debug!(?stable, "stable participants");

let mut sign_queue = self.sign_queue.write().await;
crate::metrics::SIGN_QUEUE_SIZE
Expand Down
4 changes: 2 additions & 2 deletions chain-signatures/node/src/protocol/message.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -333,7 +333,7 @@ impl MessageHandler for RunningState {
) => {
// This triple has already been generated or removed from the triple manager, so we will have to bin
// the entirety of the messages we received for this presignature id, and have the other nodes timeout
tracing::debug!(id, ?err, "presignature cannot be generated");
tracing::warn!(id, ?err, "presignature cannot be generated");
queue.clear();
continue;
}
Expand Down Expand Up @@ -437,7 +437,7 @@ impl MessageHandler for RunningState {
// and have the other nodes timeout in the following cases:
// - If a presignature is in GC, then it was used already or failed to be produced.
// - If a presignature is missing, that means our system cannot process this signature.
tracing::debug!(%receipt_id, ?err, "signature cannot be generated");
tracing::warn!(%receipt_id, ?err, "signature cannot be generated");
queue.clear();
continue;
}
Expand Down
10 changes: 5 additions & 5 deletions chain-signatures/node/src/protocol/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -226,20 +226,20 @@ impl MpcSignProtocol {

loop {
let protocol_time = Instant::now();
tracing::trace!("trying to advance chain signatures protocol");
tracing::debug!("trying to advance chain signatures protocol");
loop {
let msg_result = self.receiver.try_recv();
match msg_result {
Ok(msg) => {
tracing::trace!("received a new message");
tracing::debug!("received a new message");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I vote to get rid of this log actually. Does not add much value because we're supposed to always be receiving messages. And this is going to show per protocol message which can be in the millions

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nah. Actually when things get stuck, we start "no new message received". And it helps to know if it's the node not receiving anything or it not doing anything

queue.push(msg);
}
Err(TryRecvError::Empty) => {
tracing::trace!("no new messages received");
tracing::debug!("no new messages received");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same with this one. If anything we should have a message that shows how many messages we received in this loop

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same with above

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so this is for every triple/presignature/signature message, so it's better just to keep tally of how many messages we received instead of just printing the same message on every message. We'd still be able to understand that the node is receiving messages

break;
}
Err(TryRecvError::Disconnected) => {
tracing::debug!("communication was disconnected, no more messages will be received, spinning down");
tracing::warn!("communication was disconnected, no more messages will be received, spinning down");
return Ok(());
}
}
Expand Down Expand Up @@ -296,7 +296,7 @@ impl MpcSignProtocol {
let crypto_time = Instant::now();
let mut state = match state.progress(&mut self).await {
Ok(state) => {
tracing::trace!("progress ok: {state}");
tracing::debug!("progress ok: {state}");
state
}
Err(err) => {
Expand Down
20 changes: 10 additions & 10 deletions chain-signatures/node/src/protocol/presignature.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -234,7 +234,7 @@ impl PresignatureManager {
)));
}

tracing::debug!(id, "starting protocol to generate a new presignature");
tracing::info!(id, "starting protocol to generate a new presignature");
let generator = Self::generate_internal(
participants,
self.me,
Expand Down Expand Up @@ -279,15 +279,15 @@ impl PresignatureManager {
};

if not_enough_presignatures {
tracing::trace!("not enough presignatures, generating");
tracing::debug!("not enough presignatures, generating");
// To ensure there is no contention between different nodes we are only using triples
// that we proposed. This way in a non-BFT environment we are guaranteed to never try
// to use the same triple as any other node.
if let Some((triple0, triple1)) = triple_manager.take_two_mine().await {
let presig_participants = active
.intersection(&[&triple0.public.participants, &triple1.public.participants]);
if presig_participants.len() < self.threshold {
tracing::debug!(
tracing::warn!(
participants = ?presig_participants.keys_vec(),
"running: the intersection of participants is less than the threshold"
);
Expand All @@ -307,7 +307,7 @@ impl PresignatureManager {
)?;
}
} else {
tracing::debug!("running: we don't have enough triples to generate a presignature");
tracing::warn!("running: we don't have enough triples to generate a presignature");
}
}

Expand All @@ -333,10 +333,10 @@ impl PresignatureManager {
cfg: &ProtocolConfig,
) -> Result<&mut PresignatureProtocol, GenerationError> {
if self.presignatures.contains_key(&id) {
tracing::debug!(id, "presignature already generated");
tracing::warn!(id, "presignature already generated");
Err(GenerationError::AlreadyGenerated)
} else if self.gc.contains_key(&id) {
tracing::debug!(id, "presignature was garbage collected");
tracing::warn!(id, "presignature was garbage collected");
Err(GenerationError::PresignatureIsGarbageCollected(id))
} else {
match self.generators.entry(id) {
Expand Down Expand Up @@ -405,7 +405,7 @@ impl PresignatureManager {

pub fn take_mine(&mut self) -> Option<Presignature> {
let my_presignature_id = self.mine.pop_front()?;
tracing::debug!(my_presignature_id, "take presignature of mine");
tracing::info!(my_presignature_id, "take presignature of mine");
// SAFETY: This unwrap is safe because taking mine will always succeed since it is only
// present when generation completes where the determination of ownership is made.
Some(self.take(my_presignature_id).unwrap())
Expand All @@ -414,7 +414,7 @@ impl PresignatureManager {
pub fn take(&mut self, id: PresignatureId) -> Result<Presignature, GenerationError> {
if let Some(presignature) = self.presignatures.remove(&id) {
self.gc.insert(id, Instant::now());
tracing::trace!(id, "took presignature");
tracing::info!(id, "took presignature");
return Ok(presignature);
}

Expand All @@ -431,7 +431,7 @@ impl PresignatureManager {
}

pub fn insert_mine(&mut self, presig: Presignature) {
tracing::trace!(id = ?presig.id, "inserting presignature");
tracing::debug!(id = ?presig.id, "inserting presignature");
// Remove from taken list if it was there
self.gc.remove(&presig.id);
self.mine.push_back(presig.id);
Expand Down Expand Up @@ -461,7 +461,7 @@ impl PresignatureManager {
};
match action {
Action::Wait => {
tracing::trace!("waiting");
tracing::debug!("presignature: waiting");
// Retain protocol until we are finished
return true;
}
Expand Down
2 changes: 1 addition & 1 deletion chain-signatures/node/src/protocol/signature.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -539,7 +539,7 @@ impl SignatureManager {
};
match action {
Action::Wait => {
tracing::trace!("waiting");
tracing::debug!("signature: waiting");
// Retain protocol until we are finished
return true;
}
Expand Down
10 changes: 5 additions & 5 deletions chain-signatures/node/src/protocol/triple.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -226,7 +226,7 @@ impl TripleManager {
)));
}

tracing::debug!(id, "starting protocol to generate a new triple");
tracing::info!(id, "starting protocol to generate a new triple");
let participants: Vec<_> = participants.keys().cloned().collect();
let protocol: TripleProtocol = Box::new(cait_sith::triples::generate_triple::<Secp256k1>(
&participants,
Expand Down Expand Up @@ -267,7 +267,7 @@ impl TripleManager {
};

if not_enough_triples {
tracing::trace!("not enough triples, genertion");
tracing::debug!("not enough triples, generating");
self.generate(participants, cfg.triple.generation_timeout)?;
}
Ok(())
Expand Down Expand Up @@ -391,7 +391,7 @@ impl TripleManager {
}

pub async fn insert_mine(&mut self, triple: Triple) {
tracing::trace!(id = triple.id, "inserting mine triple");
tracing::debug!(id = triple.id, "inserting mine triple");
self.mine.push_back(triple.id);
self.triples.insert(triple.id, triple.clone());
self.gc.remove(&triple.id);
Expand Down Expand Up @@ -421,7 +421,7 @@ impl TripleManager {
return Ok(None);
}

tracing::debug!(id, "joining protocol to generate a new triple");
tracing::info!(id, "joining protocol to generate a new triple");
let participants = participants.keys_vec();
let protocol = Box::new(cait_sith::triples::generate_triple::<Secp256k1>(
&participants,
Expand Down Expand Up @@ -489,7 +489,7 @@ impl TripleManager {

match action {
Action::Wait => {
tracing::trace!("waiting");
tracing::debug!("triple: waiting");
// Retain protocol until we are finished
break true;
}
Expand Down
6 changes: 3 additions & 3 deletions chain-signatures/node/src/storage/secret_storage.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -95,7 +95,7 @@ impl DiskNodeStorage {
#[async_trait]
impl SecretNodeStorage for DiskNodeStorage {
async fn store(&mut self, data: &PersistentNodeData) -> SecretResult<()> {
tracing::debug!("storing PersistentNodeData using DiskNodeStorage");
tracing::info!("storing PersistentNodeData using DiskNodeStorage");
let mut file = File::create(self.path.as_os_str()).await?;
// Serialize the person object to JSON and convert directly to bytes
let json_bytes = serde_json::to_vec(data)?;
Expand All @@ -114,10 +114,10 @@ impl SecretNodeStorage for DiskNodeStorage {
Ok(mut file) => {
let mut contents = Vec::new();
// Read the contents of the file into the vector
tracing::debug!("loading PersistentNodeData using DiskNodeStorage: reading");
tracing::info!("loading PersistentNodeData using DiskNodeStorage: reading");
file.read_to_end(&mut contents).await?;

tracing::debug!("loading PersistentNodeData using DiskNodeStorage: read done");
tracing::info!("loading PersistentNodeData using DiskNodeStorage: read done");
// Deserialize the JSON content to a PersistentNodeData object
let data: PersistentNodeData = serde_json::from_slice(&contents)?;

Expand Down
Loading
Loading