turn off error logging unless test fails (was unwrap_err() in a bunch of test cases)

[mcr]

While looking at some issues relating to the PropertyTag changes I have proposed, I see ~70 errors from various tests.
But, only they aren't being logged as errors. I'm seeing:

running 1 test
WARNING:esys:src/tss2-esys/api/Esys_Sign.c:311:Esys_Sign_Finish() Received TPM Error 
ERROR:esys:src/tss2-esys/api/Esys_Sign.c:105:Esys_Sign() Esys Finish ErrorCode (0x000001d5) 
[2025-12-21T22:22:36Z ERROR tss_esapi::context::tpm_commands::signing_and_signature_verification] Error when signing: 0x000001D5
test context_tests::tpm_commands::signing_and_signature_verification_tests::test_sign::test_sign_large_digest ... ok

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

this test, just one that I picked, does not seem to be expecting an error based upon what I read.
Yet, it's using .unwrap_err(), which as I understand it, panics if an Ok() value is returned.
Perhaps I'm wrong here, maybe it is supposed to fail, but in that case, it's failing for the wrong reason.
Maybe the test case name should say it is a failure in the name.

[mcr]

The above error seems to be the correct error, yet I have failures that I can not reproduce individually.

[mcr]

---- abstraction_tests::ak_tests::test_create_custom_ak stdout ----

thread 'abstraction_tests::ak_tests::test_create_custom_ak' (5239) panicked at tss-esapi/tests/integration_tests/abstraction_tests/ak_tests.rs:286:6:
called `Result::unwrap()` on an `Err` value: TssError(Tpm(FormatZero(Warning(TpmFormatZeroWarningResponseCode { error_number: SessionMemory }))))
stack backtrace:
   0: __rustc::rust_begin_unwind
             at /rustc/f5209000832c9d3bc29c91f4daef4ca9f28dc797/library/std/src/panicking.rs:689:5
   1: core::panicking::panic_fmt
             at /rustc/f5209000832c9d3bc29c91f4daef4ca9f28dc797/library/core/src/panicking.rs:80:14
   2: core::result::unwrap_failed
             at /rustc/f5209000832c9d3bc29c91f4daef4ca9f28dc797/library/core/src/result.rs:1867:5
   3: <core::result::Result<tss_esapi::structures::result::CreateKeyResult, tss_esapi::error::Error>>::unwrap
             at /cache/mcr/rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/result.rs:1233:23
   4: integration_tests::abstraction_tests::ak_tests::test_create_custom_ak
             at ./tests/integration_tests/abstraction_tests/ak_tests.rs:286:6
   5: integration_tests::abstraction_tests::ak_tests::test_create_custom_ak::{closure#0}
             at ./tests/integration_tests/abstraction_tests/ak_tests.rs:253:27
   6: <integration_tests::abstraction_tests::ak_tests::test_create_custom_ak::{closure#0} as core::ops::function::FnOnce<()>>::call_once
             at /cache/mcr/rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
   7: <fn() -> core::result::Result<(), alloc::string::String> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/f5209000832c9d3bc29c91f4daef4ca9f28dc797/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
```

```
failures:
    abstraction_tests::ak_tests::test_create_ak_ecc
    abstraction_tests::ak_tests::test_create_ak_ecdaa
    abstraction_tests::ak_tests::test_create_ak_rsa_rsa_3072
    abstraction_tests::ak_tests::test_create_custom_ak
    abstraction_tests::ek_tests::test_create_ek_rsa
...
```

yet:

```
% cargo test context_tests::tpm_commands::hierarchy_commands_tests::test_clear_control::test_clear_control
    Finished `test` profile [unoptimized + debuginfo] target(s) in 0.41s
     Running unittests src/lib.rs (/ssw/projects/bangkok/rust-tss-esapi/target/debug/deps/tss_esapi-75c0e1d0724113a2)

running 0 tests

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

     Running tests/integration_tests/main.rs (/ssw/projects/bangkok/rust-tss-esapi/target/debug/deps/integration_tests-fdd929454ab1bfd6)

running 1 test
WARNING:esys:src/tss2-esys/api/Esys_Clear.c:291:Esys_Clear_Finish() Received TPM Error 
ERROR:esys:src/tss2-esys/api/Esys_Clear.c:97:Esys_Clear() Esys Finish ErrorCode (0x00000120) 
[2025-12-21T23:23:16Z ERROR tss_esapi::context::tpm_commands::hierarchy_commands] Error in clearing TPM hierarchy: 0x00000120
test context_tests::tpm_commands::hierarchy_commands_tests::test_clear_control::test_clear_control ... ok

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

[mcr]

What I'd like to do is change the logger(s) so that they say nothing unless the test case fails.
RUST_LOG=off cargo test
isn't really the right choice... but at least it is less noisy. I still see, for instance:

test context_tests::tpm_commands::attestation_commands_tests::test_quote::time ... ok
WARNING:esys:src/tss2-esys/api/Esys_StartAuthSession.c:391:Esys_StartAuthSession_Finish() Received TPM Error 
ERROR:esys:src/tss2-esys/api/Esys_StartAuthSession.c:136:Esys_StartAuthSession() Esys Finish ErrorCode (0x00000903) 
test context_tests::tpm_commands::context_management_tests::test_ctx_save::test_ctx_save_leaf ... FAILED

yet:

obiwan-[bangkok/rust-tss-esapi/tss-esapi](3.3.8) mcr 11198 %cargo test context_tests::tpm_commands::context_management_tests::test_ctx_save::test_ctx_save_leaf
    Finished `test` profile [unoptimized + debuginfo] target(s) in 0.39s
     Running unittests src/lib.rs (/ssw/projects/bangkok/rust-tss-esapi/target/debug/deps/tss_esapi-75c0e1d0724113a2)

running 0 tests

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

     Running tests/integration_tests/main.rs (/ssw/projects/bangkok/rust-tss-esapi/target/debug/deps/integration_tests-fdd929454ab1bfd6)

running 1 test
test context_tests::tpm_commands::context_management_tests::test_ctx_save::test_ctx_save_leaf ... ok

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

it looks like it is working.  Maybe this is about parallel test running vs swtpm?   
with --test-threads=1, the count is down to 15... is there someway to force this in the integration test code (only)?

Not being able to reproduce errors when test case runs alone is annoying, if it is really failing...
so, I guess the 15 tests that still fail actually are failing individually.

[Superhepper]

I am not sure if I understood your problem properly. But there are two things that produce messages. One is the crate that can be controlled with env variable you pointed out. The second thing we see here are the messages produced by the tss2 libraries and if I am not mistaken that can be controlled by another TSS2_LOG=NONE.

[mcr]

1. The error messages coming out for tests which are passing obscures which tests are actually failing.
2. Some tests expect an error, but the error that they are getting isn't the correct one, so they should fail, but they don't.
3. It turns out that the swtpm can run into other issues relating to memory and lockouts that will cause streams of test failures, when it is all systematic.

--test-threads=1 is given by the ./run-foobar.sh (docker-focused) scripts, but not everyone sees/remembers that.
I'm working on a patch to clean this all up.
There are also dozens of conversion tests in the integration_tests directories which have no side effects, and do not depend upon a running swtpm; and I wonder if they should just be regular tests.

[Superhepper]

In the example test_sign_empty_digest and test_sign_large_digest are both expected to fail with an error. Though I am not really happy with the unwrap_err I would much rather see expect_err instead but maybe that was not available when the tests were written or I had not learned yet how bad unwrap with a comment could be who knows?

And they will produce an error in the TSS and also possibly in our crate when it occurs. I wonder if it could be a good solution to introduce a kind of scoped object which could set RUST_LOG and TSS_LOG when created and then restore them on drop? In order to try to turn of logging when we expect errors. It is just an idea I have not tried yet.

Too me integration tests are tests that tests the API of the crate it has little to do with if the need an actual TPM or not. So I guess that is why there are a lot of conversion tests inside the integration test folder.

[mcr]

In the example test_sign_empty_digest and test_sign_large_digest are both expected to fail with an error. Though I am not really happy with the unwrap_err I would much rather see expect_err instead but maybe that was not available when the tests were written or I had not learned yet how bad unwrap with a comment could be who knows?

Yes, there are quite a few of these.

And they will produce an error in the TSS and also possibly in our crate when it occurs. I wonder if it could be a good solution to introduce a kind of scoped object which could set RUST_LOG and TSS_LOG when created and then restore them on drop? In order to try to turn of logging when we expect errors. It is just an idea I have not tried yet.

That would cool if it works, I don't know if the environment variable gets inspected often enough for that, but let's try it, and maybe this points to the need for an additional control.

Too me integration tests are tests that tests the API of the crate it has little to do with if the need an actual TPM or not. So I guess that is why there are a lot of conversion tests inside the integration test folder.

Yes, I can buy that. We can have more than one category of integration tests; some with conversions and some with TPM access. "cargo test" should run as many as possible, toggling the TPM ones on/off based upon whether TCTI* is set.
Alternatively, or perhaps additionally, I'd like a main() test driver that spawned off the swtpm and then killed it at the end.
In theory, one can use the chardev version of swtpm to feed a socketpair(2) at the swtpm/etc. which eliminates port-conflicts, or file system names. What's blocking me is that I don't know how to form the list of tests to run in this main; which normally is created by ??? not sure.