Cosmos-sdk: Limit amount of logs in tests

[robert-zaremba]

Summary

When running tests ideally we should see only a very short summary when tests are passing (eg: number of tests, number of tested packages / out of total packages).
Moreover we shouldn't see any info / logs from tests which are passing.

Problem Definition

We running a tests we see both debug logs, example:

D[2020-09-08|14:19:34.415] Commit synced                                module=sdk/app commit=436F6D6D697449447B5B5D3A317D

As well as list of tested packages:

ok      github.com/cosmos/cosmos-sdk/x/crisis   0.114s
ok      github.com/cosmos/cosmos-sdk/x/crisis/client/cli    13.905s
ok      github.com/cosmos/cosmos-sdk/x/crisis/keeper    0.069s
?       github.com/cosmos/cosmos-sdk/x/crisis/types [no test files]

Finally, after a long list of tested packages we see a summary:

....
ok      github.com/cosmos/cosmos-sdk/x/upgrade/types    0.039s
FAIL
make: *** [Makefile:188: test-unit-proto] Error 1

So we don't see the useful information without scrolling and grepping using eyes.

Proposal

1. Use testing.T.Log* functions as a handler / backend for the logger in tests.
2. [optinal] - grep successful tests
3. Use some library to print out the summary.

---

For Admin Use

• [ ] Not duplicate issue
• [ ] Appropriate labels applied
• [ ] Appropriate contributors tagged
• [ ] Contributor assigned/self-assigned

[alexanderbez]

The tendermint logger used in tests just needs to be a no-op logger. Note, I would keep the logs emitted from the integration test network framework.

[robert-zaremba]

@alexanderbez - then we can have no-op logger in none integration tests, and some other logger (which will pass logs output to wherever it's needed) in integration tests.

[alexanderbez]

Sounds good to me. We just need to find and update the unit tests that use a stdout/stderr logger and update it to a no-op logger. I know for sure BaseApp tests needs to be updated. That would be the bulk of it.

[alessio]

When running tests ideally we should see only a very short summary when tests are passing

CI or local runs?

Use testing.T.Log* functions as a handler / backend for the logger in tests.

Excellent idea. Though that should never be used by test cases to print unnecessary information.

Use some library to print out the summary.

No need for an extra library to just print a summary IMHO. We should just remove the -v flag from all go test calls.

[robert-zaremba]

CI or local runs?

All of them.

[robert-zaremba]

Use testing.T.Log* functions as a handler / backend for the logger in tests.

Excellent idea. Though that should never be used by test cases to print unnecessary information.

It's OK to log something in tests. The good thing about T.Log is that it will print the logs only when the test is not passing. So, this way if everything is OK, we won't see logs. If some tests are failing, then we will see only logs from that tests.

[alessio]

I'm currently trying this out: https://github.com/mfridman/tparse. It could work, yet it prints a pretty breakdown of all packages:

alessio@phoenix:~/work/cosmos-sdk$ tparse out.json 

+--------+----------+--------------------------------------------------------+-------+------+------+------+
| STATUS | ELAPSED  |                        PACKAGE                         | COVER | PASS | FAIL | SKIP |
+--------+----------+--------------------------------------------------------+-------+------+------+------+
| PASS   | 0.04s    | github.com/cosmos/cosmos-sdk/x/auth/simulation         | 0.0%  |    6 |    0 |    0 |
| PASS   | 11.13s   | github.com/cosmos/cosmos-sdk/x/auth/types              | 0.0%  |   54 |    0 |    0 |
| PASS   | 0.12s    | github.com/cosmos/cosmos-sdk/x/auth/tx                 | 0.0%  |   28 |    0 |    0 |
| PASS   | 0.05s    | github.com/cosmos/cosmos-sdk/x/auth/client             | 0.0%  |    8 |    0 |    0 |
| PASS   | 0.06s    | github.com/cosmos/cosmos-sdk/x/auth/keeper             | 0.0%  |   14 |    0 |    0 |
| PASS   | 0.04s    | github.com/cosmos/cosmos-sdk/x/auth/signing            | 0.0%  |    4 |    0 |    0 |
| PASS   | (cached) | github.com/cosmos/cosmos-sdk/x/auth                    | 0.0%  |    1 |    0 |    0 |
| PASS   | 0.09s    | github.com/cosmos/cosmos-sdk/x/auth/legacy/v0_36       | 0.0%  |    1 |    0 |    0 |
| PASS   | 0.10s    | github.com/cosmos/cosmos-sdk/x/auth/legacy/v0_38       | 0.0%  |    7 |    0 |    0 |
| PASS   | 11.12s   | github.com/cosmos/cosmos-sdk/x/auth/client/rest        | 0.0%  |    3 |    0 |    0 |
| PASS   | 0.03s    | github.com/cosmos/cosmos-sdk/x/auth/vesting/types      | 0.0%  |   28 |    0 |    0 |
| PASS   | 14.19s   | github.com/cosmos/cosmos-sdk/x/auth/vesting/client/cli | 0.0%  |    7 |    0 |    0 |
| PASS   | 0.07s    | github.com/cosmos/cosmos-sdk/x/auth/legacy/v0_40       | 0.0%  |    1 |    0 |    0 |
| PASS   | 0.14s    | github.com/cosmos/cosmos-sdk/x/auth/ante               | 0.0%  |  145 |    0 |    0 |
| PASS   | 0.04s    | github.com/cosmos/cosmos-sdk/x/auth/vesting            | 0.0%  |    5 |    0 |    0 |
| PASS   | 41.63s   | github.com/cosmos/cosmos-sdk/x/auth/client/cli         | 0.0%  |   22 |    0 |    0 |
+--------+----------+--------------------------------------------------------+-------+------+------+------+

Would that make you happier? Would you suggest to try print an even shorter summary?

[robert-zaremba]

This is awesome.

[alessio]

FTR upstream's just accepted my patch to introduce a -noborders flag and made a new release.