RUST_TEST_TIME_INTEGRATION and RUST_TEST_TIME_UNIT ignored

[peter-lyons-kehl]

The below defected/unimplemented feature is NOT documented in Cargo book, but it's in the public & documented interface of library/test/src/time.rs and its submodule time_constants (even though it may be accessible from Rust tools only).

https://github.com/rust-lang/rust/blob/41bafc4ff3eb6a73aa40e60c3bd4494302c7ec57/library/test/src/time.rs#L31C38-L31C57 and https://github.com/rust-lang/rust/blob/41bafc4ff3eb6a73aa40e60c3bd4494302c7ec57/library/test/src/time.rs#L38C45-L38C71 suggest that unit tests use RUST_TEST_TIME_UNIT, and integration tests use RUST_TEST_TIME_INTEGRATION` (despite a 2x copy-and-paste mistake of mentioning "threshold for unit-tests" for integration and doc tests).

However, neither RUST_TEST_TIME_UNIT nor RUST_TEST_TIME_INTEGRATION seems to have any effect.

As per

rust/library/test/src/time.rs

Line 106 in 41bafc4

pub fn from_env_var(env_var_name: &str) -> Option<Self> {

from_env_var(&str):

With https://github.com/peter-kehl/test_timeout_rs:

export RUST_TEST_TIME_UNIT=3600000,3600000
export RUST_TEST_TIME_INTEGRATION=3600000,3600000
git clone https://github.com/peter-kehl/test_timeout_rs
cd test_timeout_rs
cargo test
   Compiling test_timeout_rs v0.1.0 (/share/pkehl/GIT/test_timeout_rs)
    Finished test [unoptimized + debuginfo] target(s) in 0.45s
     Running unittests src/lib.rs (target/debug/deps/test_timeout_rs-ccebbdfa21928176)

running 1 test

test unit_test::long_unit_test has been running for over 60 seconds
test unit_test::long_unit_test ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

     Running tests/integration.rs (target/debug/deps/integration-f2beccbd60895674)

running 1 test
test long_unit_test has been running for over 60 seconds
test long_unit_test ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

   Doc-tests test_timeout_rs

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

• cargo test still reports "test ... has been running for over 60 seconds" - for both unit tests and integration tests.

rustc --version --verbose
rustc 1.74.0-nightly (b4e54c6e3 2023-09-11)
binary: rustc
commit-hash: b4e54c6e39984840a04dcd02d14ec8c3574d30e5
commit-date: 2023-09-11
host: x86_64-unknown-linux-gnu
release: 1.74.0-nightly
LLVM version: 17.0.0

[ehuss]

The environment variables require extra CLI options in order to enable them. For example:

cargo test --tests -- -Zunstable-options --ensure-time

There's more information in the documentation at https://doc.rust-lang.org/nightly/unstable-book/compiler-flags/report-time.html.

[peter-lyons-kehl]

Thank you for looking it up Eric. Good to have met you at RustConf in Albuquerque.

Unfortunately, that doesn't make the "60 seconds" warning/notice go away:

cargo test --tests -- -Zunstable-options --ensure-time
   Compiling test_timeout_rs v0.1.0 (/share/pkehl/GIT/test_timeout_rs)
    Finished test [unoptimized + debuginfo] target(s) in 1.07s
     Running unittests src/lib.rs (target/debug/deps/test_timeout_rs-ccebbdfa21928176)

running 1 test
test unit_test::long_unit_test has been running for over 60 seconds
test unit_test::long_unit_test ... ok <62.000s>

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

     Running tests/integration.rs (target/debug/deps/integration-f2beccbd60895674)

running 1 test
test long_unit_test has been running for over 60 seconds
test long_unit_test ... ok <62.000s>

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

(With the same nightly as above, and also with the last night's nightly 1.74.0-nightly (bdb0fa3ee 2023-09-19)).

[peter-lyons-kehl]

The same problem with cargo test --tests -- -Zunstable-options --report-time, too - it still ignores

export RUST_TEST_TIME_UNIT=3600000,3600000
export RUST_TEST_TIME_INTEGRATION=3600000,3600000

and it reports if over 60 seconds.

Related to/for #64888.

[ehuss]

It was good to meet you too!

Can you make sure the environment variable is set in your second attempt? It seems to work for me:

> RUST_TEST_TIME_INTEGRATION=3600000,3600000 cargo test --tests -- -Zunstable-options --ensure-time
   Compiling test_timeout_rs v0.1.0 (/Users/eric/Temp/z64/test_timeout_rs)
    Finished test [unoptimized + debuginfo] target(s) in 3.35s
     Running unittests src/lib.rs (target/debug/deps/test_timeout_rs-cc8087b74c05184b)

running 1 test
test unit_test::long_unit_test has been running for over 60 seconds
test unit_test::long_unit_test ... FAILED (time limit exceeded) <62.005s>

failures (time limit exceeded):

failures (time limit exceeded):
    unit_test::long_unit_test

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.01s

error: test failed, to rerun pass `--lib`

Note that it is expected for it to print a warning after 60 seconds (that's what the first threshold defines), and then it should fail after it is done.

[peter-lyons-kehl]

Still the same. (Side note: I've renamed the integration test function to long_integration_test.)

RUST_TEST_TIME_INTEGRATION=3600000,3600000 cargo test --tests -- -Zunstable-options --ensure-time
    Finished test [unoptimized + debuginfo] target(s) in 0.01s
     Running unittests src/lib.rs (target/debug/deps/test_timeout_rs-ccebbdfa21928176)

running 1 test
test unit_test::long_unit_test has been running for over 60 seconds
test unit_test::long_unit_test ... ok <62.000s>

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

     Running tests/integration.rs (target/debug/deps/integration-f2beccbd60895674)

running 1 test
test long_integration_test has been running for over 60 seconds
test long_integration_test ... ok <62.000s>

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

I believe I have an ordinary bash on ordinary Manjaro (stable Arch Linux x64):

ps
    PID TTY          TIME CMD
 518178 pts/4    00:00:00 bash
 518422 pts/4    00:00:00 ps

bash --version
GNU bash, version 5.1.16(1)-release (x86_64-pc-linux-gnu)
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html

env | grep RUST
RUST_TEST_TIME_UNIT=3600000,3600000
RUST_TEST_TIME_INTEGRATION=3600000,3600000

uname -a
Linux spectre 6.6.0-1-MANJARO #3 SMP PREEMPT_DYNAMIC Mon Sep 11 12:25:45 CEST 2023 x86_64 GNU/Linux

What can be different?

[ehuss]

Oh, I see, I only set RUST_TEST_TIME_INTEGRATION, but not RUST_TEST_TIME_UNIT. Two things:

• The time values you have don't seem to be in the correct units. 3600000 is one hour. If you want 60 seconds, it should be 60000.
• When I only set RUST_TEST_TIME_INTEGRATION, it used the default for RUST_TEST_TIME_UNIT and that's what failed. The defaults are 50,100 for unit, and 500,1000 for integration.

[peter-lyons-kehl]

Still the same problem here ("has been running for over 60 seconds" reported), even if I set RUST_TEST_TIME_INTEGRATION only.

My goal: to suppress these warnings (for long tests). For example, from the following I'd expect a warning only if the test runs for over 1 hour, and an error/critical if it runs for over 10 hours.

RUST_TEST_TIME_INTEGRATION=3600000,36000000 cargo test
    Finished test [unoptimized + debuginfo] target(s) in 0.04s
     Running unittests src/lib.rs (target/debug/deps/test_timeout_rs-ccebbdfa21928176)

running 1 test
test unit_test::long_unit_test has been running for over 60 seconds
test unit_test::long_unit_test ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

     Running tests/integration.rs (target/debug/deps/integration-f2beccbd60895674)

running 1 test
test long_integration_test has been running for over 60 seconds
test long_integration_test ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 62.00s

   Doc-tests test_timeout_rs

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

[ehuss]

The "has been running for over 60 seconds" message is unrelated to the RUST_TEST_TIME environment settings. The warning threshold the env var sets is only for highlighting slow tests. I don't think it is possible to change the 60 second warning.

[peter-lyons-kehl]

Thank you Eric.