Allow asserting againt TestBase log file

[mplsgrant]

Issue

I want to use an assert_log function against the output of rpc-0. Specifically, I want to assert the existence of some text that is produced by a scenario and logged by rpc-0. I don't believe that is possible today.

Also, when scenarios fail today, that failure does not bubble up to the test framework.

Cause

• The server_thread in TestBase prints the log output of rpc-0, but it does not store that information anywhere in a way that allows tests to access it.
• The current server in TestBase reads the entire history of kubectl log -f pod/rpc-0 which causes assert statements in test cases to incorrectly check old/stale log entries.

Solution

Allow TestBase to examine the output of the kubectl process log and create assertions against it. Limit that log output to the current run by preventing kubectl from logging old messages by using the --since flag.

[pinheadmz]

Warnet RPC server itself logs to ~/.warnet/warnet.log inside the rpc-0 pod during tests and that includes all scenario output. So I think if you want to assert a log message in a test, that would be the file to search. You mine as well include a log assertion in some existing test for this PR as well so we can see it working.

However, I see what you mean about reading old log messages. For that reason, it might make sense for us to move the warnet server log into the network-specific subfolder (there will be a new one for each test run e.g. ~/.warnet/warnet/warnet-test-rhyjpwjn/ etc). So like, we wouldn't even write any log file at all until network start, and then we start logging right after the folder is created in server.py generate_deployment().

And finally yes the addition of --since=1s is smart, I don't think I realized each new test run printed the entire container's life history every time!

[pinheadmz]

@mplsgrant I think #385 is ready for merge, if youre done with it lets merge that then rebase this one

[mplsgrant]

This has been rebased.

[willcl-ark]

Concept ACK from me.

Just left a few comments/questions on first pass over

[mplsgrant]

Assuming we go with this logging approach, I want to go in an replace the existing print statements with calls to logger.

[mplsgrant]

I switched the logger config to warnet's established config json file.

Also, converted all the existing print statements into logger.info.

[willcl-ark]

Great! I'd like to re-review and try to merge this before my giant refactor, I think... (also you reminded me that I should use our loggingconfig in my pr, probably)

[willcl-ark]

I think in addition to the conflict with (newly reformatted) dag_connection_test.py, this may now conflict with the two final commits in https://github.com/bitcoin-dev-project/warnet/pull/400/commits which fixup the logging in test_base.py, I think in the same way (roughly) being done here.

I also slightly changed the entire log output format: https://github.com/bitcoin-dev-project/warnet/actions/runs/9846784937/job/27185339346#step:8:133 but I think that will actually not be an issue for your regex?

Perhaps you can drop your first three commits here, if that one gets merged first (or visa versa)? Not checked thoroughly yet...

[mplsgrant]

This is rebased/refactored and ready to go.

[pinheadmz]

I'm not convinced this is working... 🤔

[mplsgrant]

I also re-added "since" to clear the messages.

[pinheadmz]

Does this flag need to get reset ever? What if a test uses assert_log a few times with the same test_base instance?

[mplsgrant]

I imagined users setting self.log_expected_msgs and self.log_unexpected_msgs once per TestBase instance.

[mplsgrant]

We could reset the assertions status after checking. I updated with that concept. Need to test it.

[pinheadmz]

ACK 96c7978

I think this is good to go. I have 2 suggestions below you can take or leave, or apply to follow-ups...

Show Signature

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

ACK 96c7978c1e978abb3e2bd79bc7209a7cdf587350
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEE5hdzzW4BBA4vG9eM5+KYS2KJyToFAmaVLLwACgkQ5+KYS2KJ
yTr1BhAArvSVNdvm92D/yStxqtkgy05PeQJVxI7X/oeleb/W2BjHq966TckyXKmA
XtnlYi0NirHqAZtldODwjPkXhDI/fYOjt0lr+nfkOtHXM6Oy0T7M7M/2fxNkxtBa
N/mCutSIH07H0s99W/RvdVPL20VINJESzxViR4VIo6LwUu7JuY2v6kNqebpyIJQ5
7XlbFCMNn/tPayqwiFhh09KoTaL7NNtpx+GeKBajGwYVFVNGkaVaahCTR8h2dKCf
SpWzR8PWWe1HhUd5SuslsLs/creHDIJv9NpGWyBq4Ne39meNQiffZe8w/HqIKF3w
RexTbSIfaNwc3HR8t2UhI1kHVXUY9IIPjXpQ71evDxlla4sgUdbSt6ohsFSPZ4oh
W4Xl6QXOz0Xe90lnoIbX2q76OEaEqNjF3d++OYtGpKfh0h2gLPjYZmaxNJZMNHFK
jFEi1gv6faW97c2ErwEiBkW2DpNFSppZeIUkcVAsAP51S2E2Ntq50zj66vkSb3IM
coWPhLuIAZ0lgEpEzyTn5SEQYcNqFuyxgKrY5AxhpMkMa5ul5nCshfPIY1DpLzC3
Jm+ZPbUniHEhQQAJ0GPku58pbKSpzynhf46cdjbLk2NdYT6+rQ113mT5KmDmaQLb
KcRNfbwInpdXFobzlDlySejCZ2QmBFaXi2U2Unnsm26/EtUVNmw=
=1aXP
-----END PGP SIGNATURE-----

pinheadmz's public key is on keybase

[pinheadmz]

I ran a test with an unexpected message which aborted early, as expected. Funny thing though, because it exited early the test never got to the part where it prints the expected message. So even though its true the expected message was not found in the log, the more relevant error is the unexpected message which occurred first. I'm not sure if there's anything we really need to change about this, unless you have an idea:

2024-07-15 13:55:25 | INFO    | scenario | ConnectDag PRNG seed is: 131260415370612
Exception in thread Thread-1 (output_reader):
Traceback (most recent call last):
  File "/opt/homebrew/Cellar/[email protected]/3.12.3/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/[email protected]/3.12.3/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1010, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/matthewzipkin/Desktop/work/warnet/test/test_base.py", line 103, in output_reader
    func(line)
  File "/Users/matthewzipkin/Desktop/work/warnet/test/test_base.py", line 67, in _print_and_assert_msgs
    if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log(
                                                                ^^^^^^^^^^^
  File "/Users/matthewzipkin/Desktop/work/warnet/test/test_base.py", line 214, in assert_log
    raise AssertionError(f"Unexpected message found in log: {unexpected_msg}")
AssertionError: Unexpected message found in log: Tank
2024-07-15 09:55:29 | DEBUG   | test     | Executing RPC method: scenarios_list_running
2024-07-15 09:55:29 | INFO    | test     | Stopping network
2024-07-15 09:55:29 | DEBUG   | test     | Executing warcli command: network down
2024-07-15 09:55:30 | DEBUG   | test     | Waiting for predicate with timeout 60s and interval 1s
2024-07-15 09:55:30 | DEBUG   | test     | Executing RPC method: network_status
2024-07-15 09:55:30 | INFO    | test     | Waiting for all tanks to reach 'stopped': {'total': 10, 'stopped': 9, 'running': 1}
2024-07-15 09:55:31 | DEBUG   | test     | Executing RPC method: network_status
2024-07-15 09:55:32 | INFO    | test     | Waiting for all tanks to reach 'stopped': {'total': 10, 'stopped': 10}
Traceback (most recent call last):
  File "/Users/matthewzipkin/Desktop/work/warnet/test/dag_connection_test.py", line 52, in <module>
    test.run_test()
  File "/Users/matthewzipkin/Desktop/work/warnet/test/dag_connection_test.py", line 20, in run_test
    self.run_connect_dag_scenario()
  File "/Users/matthewzipkin/Desktop/work/warnet/test/dag_connection_test.py", line 39, in run_connect_dag_scenario
    self.assert_log_msgs()
  File "/Users/matthewzipkin/Desktop/work/warnet/test/test_base.py", line 75, in assert_log_msgs
    self.log_msg_assertions_passed
AssertionError: Log assertion failed. Expected message not found: ['Successfully ran the connect_dag.py scenario using a temporary file']

[mplsgrant]

It looks like the unexpected message AssertionError gets buried in the log, and the less meaningful message not found AssertionError gets highlighted by virtue of being the last message.

To fix this, I would probably use an enum named "Found": Nothing, Expected, Unexpected, and UnexpectedExpected. Then lift the assertion call out of the assert_log helper function and plug it into the TestBase's asset_log_msgs function. Then I would have the helper assert_log functions return the enum.

[pinheadmz]

re-ACK 4098f6e

thanks Grant nice work