replace println with tracing #13736

yuunlimm · 2024-06-17T23:47:56Z

Description

Type of Change

remove println! and replace with tracing.

Which Components or Systems Does This Change Impact?

How Has This Been Tested?

Key Areas to Review

Checklist

I have read and followed the CONTRIBUTING doc
I have performed a self-review of my own code
I have commented my code, particularly in hard-to-understand areas
I identified and added all stakeholders and component owners affected by this change as reviewers
I tested both happy and unhappy path of the functionality
I have made corresponding changes to the documentation

trunk-io · 2024-06-17T23:48:01Z

⏱️ 17h 59m total CI duration on this PR

Job	Cumulative Duration	Recent Runs
test-fuzzers	5h 19m	🟩 🟩 🟩 🟩 🟩 (+4 more)
execution-performance / single-node-performance	2h 26m	🟩 🟥 🟩 🟩 🟩 (+1 more)
rust-targeted-unit-tests	1h 19m	⬜ 🟥 🟥 🟥
forge-framework-upgrade-test / forge	1h 8m	🟩 🟩 🟩 🟩
rust-smoke-tests	1h 7m	🟩 🟩
forge-e2e-test / forge	1h	🟩 🟩 🟩 🟩
forge-compat-test / forge	59m	🟩 🟩 🟩 🟩
rust-move-tests	52m	⬜ ⬜ 🟩 🟩 🟩
rust-images / rust-all	52m	⬜ 🟩 🟩 🟩 🟩
run-tests-main-branch	25m	🟩 🟩 🟩 🟩 🟩
rust-lints	23m	🟥 🟩 🟩 🟩
check	16m	⬜ 🟩 🟩 🟩 🟩
execution-performance / test-target-determinator	15m	🟩 🟩 🟩 🟩 🟩
test-target-determinator	14m	⬜ 🟩 🟩 🟩 🟩
general-lints	14m	🟩 🟩 🟩 🟩 🟩 (+3 more)
cli-e2e-tests / run-cli-tests	12m	🟩 🟩
check-dynamic-deps	12m	🟩 🟩 🟩 🟩 🟩 (+4 more)
rust-move-tests	9m	🟩
rust-move-tests	9m	🟩
rust-move-tests	9m	🟩
rust-build-cached-packages	8m	🟩 🟩
semgrep/ci	3m	🟩 🟩 🟩 🟩 🟩 (+4 more)
node-api-compatibility-tests / node-api-compatibility-tests	2m	🟩 🟩
file_change_determinator	1m	🟩 🟩 🟩 🟩 🟩 (+4 more)
file_change_determinator	1m	🟩 🟩 🟩 🟩 🟩 (+4 more)
file_change_determinator	1m	🟩 🟩 🟩 🟩 🟩
permission-check	30s	🟩 🟩 🟩 🟩 🟩 (+4 more)
permission-check	28s	🟩 🟩 🟩 🟩 🟩 (+4 more)
permission-check	28s	🟩 🟩 🟩 🟩 🟩 (+4 more)
permission-check	25s	🟩 🟩 🟩 🟩 🟩 (+4 more)
determine-docker-build-metadata	16s	🟩 🟩 🟩 🟩 🟩
permission-check	14s	🟩 🟩 🟩 🟩 🟩
rust-move-tests	13s	⬜

🚨 4 jobs on the last run were significantly faster/slower than expected

Job	Duration	vs 7d avg
rust-targeted-unit-tests	23m	14m
forge-framework-upgrade-test / forge	17m	13m
rust-build-cached-packages	4m	5m
execution-performance / test-target-determinator	3m	5m

_{settings ⋅ feedback ⋅ docs ⋅ learn more about trunk.io}

github-actions · 2024-07-31T20:44:55Z

❌ Forge suite `framework_upgrade` failure on `1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5` ==> `7ac70d64f543104e3257d87e7695a05830f6f214`

Compatibility test results for 1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5 ==> 7ac70d64f543104e3257d87e7695a05830f6f214 (PR)
Upgrade the nodes to version: 7ac70d64f543104e3257d87e7695a05830f6f214
Test Failed: Retry due to pod aptos-node-1-validator-0 status PodStatus { conditions: Some([PodCondition { last_probe_time: None, last_transition_time: Some(Time(2024-07-31T20:39:49Z)), message: Some("0/51 nodes are available: 1 node(s) had untolerated taint {ToBeDeletedByClusterAutoscaler: 1722458615}, 49 Insufficient cpu, 50 Insufficient memory. preemption: 0/51 nodes are available: 1 Preemption is not helpful for scheduling, 50 No preemption victims found for incoming pod.."), reason: Some("Unschedulable"), status: "False", type_: "PodScheduled" }]), container_statuses: None, ephemeral_container_statuses: None, host_ip: None, init_container_statuses: None, message: None, nominated_node_name: None, phase: Some("Pending"), pod_ip: None, pod_ips: None, qos_class: Some("Burstable"), reason: None, start_time: None }

Stack backtrace:
   0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.79/src/error.rs:565:25
   1: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/result.rs:1964:27
   2: aptos_forge::backend::k8s::stateful_set::wait_stateful_set::{{closure}}
             at ./testsuite/forge/src/backend/k8s/stateful_set.rs:69:5
   3: aptos_forge::backend::k8s::stateful_set::scale_stateful_set_replicas::{{closure}}
             at ./testsuite/forge/src/backend/k8s/stateful_set.rs:243:6
   4: <aptos_forge::backend::k8s::node::K8sNode as aptos_forge::interface::node::Node>::start::{{closure}}
             at ./testsuite/forge/src/backend/k8s/node.rs:138:84
   5: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/future/future.rs:123:9
   6: <aptos_forge::backend::k8s::swarm::K8sSwarm as aptos_forge::interface::swarm::Swarm>::upgrade_validator::{{closure}}
             at ./testsuite/forge/src/backend/k8s/swarm.rs:256:27
   7: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/future/future.rs:123:9
   8: aptos_testcases::batch_update::{{closure}}
             at ./testsuite/testcases/src/lib.rs:62:14
   9: <aptos_testcases::framework_upgrade::FrameworkUpgrade as aptos_forge::interface::network::NetworkTest>::run::{{closure}}
             at ./testsuite/testcases/src/framework_upgrade.rs:82:53
  10: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/future/future.rs:123:9
  11: tokio::runtime::park::CachedParkThread::block_on::{{closure}}
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/park.rs:282:63
  12: tokio::runtime::coop::with_budget
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/coop.rs:107:5
  13: tokio::runtime::coop::budget
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/coop.rs:73:5
  14: tokio::runtime::park::CachedParkThread::block_on
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/park.rs:282:31
  15: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/context/blocking.rs:66:9
  16: tokio::runtime::handle::Handle::block_on::{{closure}}
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/handle.rs:310:22
  17: tokio::runtime::context::runtime::enter_runtime
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/context/runtime.rs:65:16
  18: tokio::runtime::handle::Handle::block_on
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.35.1/src/runtime/handle.rs:309:9
  19: aptos_forge::runner::Forge<F>::run::{{closure}}
             at ./testsuite/forge/src/runner.rs:611:49
  20: aptos_forge::runner::run_test
             at ./testsuite/forge/src/runner.rs:684:11
  21: aptos_forge::runner::Forge<F>::run
             at ./testsuite/forge/src/runner.rs:611:30
  22: forge::run_forge
             at ./testsuite/forge-cli/src/main.rs:429:11
  23: forge::main
             at ./testsuite/forge-cli/src/main.rs:355:21
  24: core::ops::function::FnOnce::call_once
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:250:5
  25: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/sys_common/backtrace.rs:155:18
  26: std::rt::lang_start::{{closure}}
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:166:18
  27: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:284:13
  28: std::panicking::try::do_call
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40
  29: std::panicking::try
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19
  30: std::panic::catch_unwind
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14
  31: std::rt::lang_start_internal::{{closure}}
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:148:48
  32: std::panicking::try::do_call
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40
  33: std::panicking::try
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19
  34: std::panic::catch_unwind
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14
  35: std::rt::lang_start_internal
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:148:20
  36: main
  37: __libc_start_main
  38: _start
Trailing Log Lines:
  33: std::panicking::try
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19
  34: std::panic::catch_unwind
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14
  35: std::rt::lang_start_internal
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:148:20
  36: main
  37: __libc_start_main
  38: _start


Swarm logs can be found here: See fgi output for more information.
{"level":"INFO","source":{"package":"aptos_forge","file":"testsuite/forge/src/backend/k8s/cluster_helper.rs:292"},"thread_name":"main","hostname":"forge-framework-upgrade-pr-13736-1722458124-1c2ee7082d6eff8c811","timestamp":"2024-07-31T20:44:51.154001Z","message":"Deleting namespace forge-framework-upgrade-pr-13736: Some(NamespaceStatus { conditions: None, phase: Some(\"Terminating\") })"}
{"level":"INFO","source":{"package":"aptos_forge","file":"testsuite/forge/src/backend/k8s/cluster_helper.rs:400"},"thread_name":"main","hostname":"forge-framework-upgrade-pr-13736-1722458124-1c2ee7082d6eff8c811","timestamp":"2024-07-31T20:44:51.154059Z","message":"aptos-node resources for Forge removed in namespace: forge-framework-upgrade-pr-13736"}

Failed to run tests:
Tests Failed
failures:
    framework_upgrade::framework-upgrade

test result: FAILED. 0 passed; 1 failed; 0 filtered out

Error: Tests Failed

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
             at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.79/src/error.rs:83:36
   1: aptos_forge::runner::Forge<F>::run
             at ./testsuite/forge/src/runner.rs:636:13
   2: forge::run_forge
             at ./testsuite/forge-cli/src/main.rs:429:11
   3: forge::main
             at ./testsuite/forge-cli/src/main.rs:355:21
   4: core::ops::function::FnOnce::call_once
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:250:5
   5: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/sys_common/backtrace.rs:155:18
   6: std::rt::lang_start::{{closure}}
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:166:18
   7: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:284:13
   8: std::panicking::try::do_call
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40
   9: std::panicking::try
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19
  10: std::panic::catch_unwind
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14
  11: std::rt::lang_start_internal::{{closure}}
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:148:48
  12: std::panicking::try::do_call
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40
  13: std::panicking::try
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19
  14: std::panic::catch_unwind
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14
  15: std::rt::lang_start_internal
             at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/rt.rs:148:20
  16: main
  17: __libc_start_main
  18: _start
Debugging output:
NAME                                    READY   STATUS      RESTARTS   AGE
aptos-node-0-validator-0                1/1     Running     0          6m6s
aptos-node-1-validator-0                0/1     Pending     0          5m4s
aptos-node-2-validator-0                1/1     Running     0          8m47s
aptos-node-3-validator-0                1/1     Running     0          8m47s
genesis-aptos-genesis-eforge157-k2sfm   0/1     Completed   0          9m9s

github-actions · 2024-07-31T20:48:54Z

✅ Forge suite `realistic_env_max_load` success on `7ac70d64f543104e3257d87e7695a05830f6f214`

two traffics test: inner traffic : committed: 11909.428712282017 txn/s, latency: 3347.941243954685 ms, (p50: 3000 ms, p90: 3900 ms, p99: 9900 ms), latency samples: 4528300
two traffics test : committed: 99.89388224336005 txn/s, latency: 3109.6827586206896 ms, (p50: 2800 ms, p90: 3900 ms, p99: 11000 ms), latency samples: 1740
Latency breakdown for phase 0: ["QsBatchToPos: max: 0.237, avg: 0.226", "QsPosToProposal: max: 0.239, avg: 0.186", "ConsensusProposalToOrdered: max: 0.338, avg: 0.310", "ConsensusOrderedToCommit: max: 0.754, avg: 0.668", "ConsensusProposalToCommit: max: 1.064, avg: 0.978"]
Max round gap was 1 [limit 4] at version 2608064. Max no progress secs was 7.74364 [limit 15] at version 2608064.
Test Ok

github-actions · 2024-07-31T20:50:55Z

✅ Forge suite `compat` success on `1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5` ==> `7ac70d64f543104e3257d87e7695a05830f6f214`

Compatibility test results for 1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5 ==> 7ac70d64f543104e3257d87e7695a05830f6f214 (PR)
1. Check liveness of validators at old version: 1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5
compatibility::simple-validator-upgrade::liveness-check : committed: 7555.866270989992 txn/s, latency: 4078.665229471085 ms, (p50: 3600 ms, p90: 6000 ms, p99: 16600 ms), latency samples: 291540
2. Upgrading first Validator to new version: 7ac70d64f543104e3257d87e7695a05830f6f214
compatibility::simple-validator-upgrade::single-validator-upgrading : committed: 7605.997974307771 txn/s, latency: 3589.6867657367166 ms, (p50: 4000 ms, p90: 4300 ms, p99: 4500 ms), latency samples: 142660
compatibility::simple-validator-upgrade::single-validator-upgrade : committed: 7769.332585063657 txn/s, latency: 4043.6630042951374 ms, (p50: 4100 ms, p90: 4900 ms, p99: 5500 ms), latency samples: 260760
3. Upgrading rest of first batch to new version: 7ac70d64f543104e3257d87e7695a05830f6f214
compatibility::simple-validator-upgrade::half-validator-upgrading : committed: 6730.210011359253 txn/s, latency: 4012.2082616179 ms, (p50: 4300 ms, p90: 5100 ms, p99: 5400 ms), latency samples: 127820
compatibility::simple-validator-upgrade::half-validator-upgrade : committed: 7040.085735424696 txn/s, latency: 4432.677680451445 ms, (p50: 4400 ms, p90: 6800 ms, p99: 7100 ms), latency samples: 237460
4. upgrading second batch to new version: 7ac70d64f543104e3257d87e7695a05830f6f214
compatibility::simple-validator-upgrade::rest-validator-upgrading : committed: 11069.32427132923 txn/s, latency: 2575.438169196964 ms, (p50: 2800 ms, p90: 3100 ms, p99: 3200 ms), latency samples: 200240
compatibility::simple-validator-upgrade::rest-validator-upgrade : committed: 10412.139741042552 txn/s, latency: 3226.1881620669405 ms, (p50: 3000 ms, p90: 4800 ms, p99: 5800 ms), latency samples: 340600
5. check swarm health
Compatibility test for 1c2ee7082d6eff8c811ee25d6f5a7d00860a75d5 ==> 7ac70d64f543104e3257d87e7695a05830f6f214 passed
Test Ok

github-actions · 2024-09-15T02:04:22Z

This issue is stale because it has been open 45 days with no activity. Remove the stale label, comment or push a commit - otherwise this will be closed in 15 days.

yuunlimm force-pushed the yuunlimm/misc branch 2 times, most recently from 5b79f31 to 56be922 Compare June 17, 2024 23:57

larry-aptos approved these changes Jun 18, 2024

View reviewed changes

jillxuu approved these changes Jun 18, 2024

View reviewed changes

yuunlimm enabled auto-merge (squash) June 18, 2024 17:40

yuunlimm force-pushed the yuunlimm/misc branch from 56be922 to 1fae061 Compare June 18, 2024 17:42