Skip to content

Commit adaba77

Browse files
sanityclaude
andcommitted
feat: improve operation lifecycle logging for CI debugging
Add real-time visibility into network operations to help debug flaky CI test failures: - Add --nocapture to CI test command for unbuffered output - Enhance timeout logs with elapsed time and TTL info - Add elapsed_ms to PUT and Connect completion logs - Make Transaction::elapsed() public for logging access This will show operation timing directly in CI logs: [INFO] Connect operation started tx=... gateway=... [INFO] Transaction timed out tx=... elapsed_ms=60012 ttl_ms=60000 [INFO] PUT operation completed tx=... elapsed_ms=1234 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
1 parent 5cac4e1 commit adaba77

File tree

5 files changed

+26
-4
lines changed

5 files changed

+26
-4
lines changed

.github/workflows/ci.yml

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -129,7 +129,8 @@ jobs:
129129
- name: Test
130130
# Limit test threads to reduce resource contention on high-core-count runners
131131
# Without this, 64+ parallel tests cause timing-sensitive network tests to fail
132-
run: cargo test --workspace --no-default-features --features trace,websocket,redb -- --test-threads=8
132+
# --nocapture shows logs in real-time instead of buffering until test completion
133+
run: cargo test --workspace --no-default-features --features trace,websocket,redb -- --test-threads=8 --nocapture
133134

134135
six_peer_regression:
135136
name: six-peer-regression

crates/core/src/message.rs

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,8 @@ impl Transaction {
9898
self.id.0.to_le_bytes()
9999
}
100100

101-
fn elapsed(&self) -> Duration {
101+
/// Returns the elapsed time since this transaction was created.
102+
pub fn elapsed(&self) -> Duration {
102103
let current_unix_epoch_ts = SystemTime::now()
103104
.duration_since(SystemTime::UNIX_EPOCH)
104105
.expect("now should be always be later than unix epoch")

crates/core/src/node/op_state_manager.rs

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -812,7 +812,13 @@ async fn garbage_cleanup_task<ER: NetEventRegister>(
812812
} else {
813813
ops.under_progress.remove(&tx);
814814
ops.completed.remove(&tx);
815-
tracing::debug!("Transaction timed out: {tx}");
815+
tracing::info!(
816+
tx = %tx,
817+
tx_type = ?tx.transaction_type(),
818+
elapsed_ms = tx.elapsed().as_millis(),
819+
ttl_ms = crate::config::OPERATION_TTL.as_millis(),
820+
"Transaction timed out"
821+
);
816822

817823
// Check if this is a child operation and propagate timeout to parent
818824
if let Some(parent_tx) = sub_op_tracker.get_parent(tx) {
@@ -857,7 +863,13 @@ async fn garbage_cleanup_task<ER: NetEventRegister>(
857863
TransactionType::Update => ops.update.remove(&tx).is_some(),
858864
};
859865
if removed {
860-
tracing::debug!("Transaction timed out: {tx}");
866+
tracing::info!(
867+
tx = %tx,
868+
tx_type = ?tx.transaction_type(),
869+
elapsed_ms = tx.elapsed().as_millis(),
870+
ttl_ms = crate::config::OPERATION_TTL.as_millis(),
871+
"Transaction timed out"
872+
);
861873

862874
// Check if this is a child operation and propagate timeout to parent
863875
if let Some(parent_tx) = sub_op_tracker.get_parent(tx) {

crates/core/src/operations/connect.rs

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -678,6 +678,11 @@ impl ConnectOp {
678678
self.recency.remove(&new_acceptor.peer);
679679
}
680680
if result.satisfied {
681+
tracing::info!(
682+
tx = %self.id,
683+
elapsed_ms = self.id.elapsed().as_millis(),
684+
"Connect operation completed"
685+
);
681686
self.state = Some(ConnectState::Completed);
682687
}
683688
Some(result)
@@ -975,11 +980,13 @@ impl Operation for ConnectOp {
975980
tracing::info!(
976981
%peer_id,
977982
tx=%self.id,
983+
elapsed_ms = self.id.elapsed().as_millis(),
978984
"connect joined peer"
979985
);
980986
} else {
981987
tracing::warn!(
982988
tx=%self.id,
989+
elapsed_ms = self.id.elapsed().as_millis(),
983990
"connect ConnectPeer failed"
984991
);
985992
}

crates/core/src/operations/put.rs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -341,6 +341,7 @@ impl Operation for PutOp {
341341
tracing::info!(
342342
tx = %id,
343343
%key,
344+
elapsed_ms = id.elapsed().as_millis(),
344345
"PUT operation completed successfully"
345346
);
346347

0 commit comments

Comments
 (0)