Refactor tests #400

willcl-ark · 2024-07-08T12:04:35Z

This has been bothering me for a long while... Fix it by refactoring all the tests (but not WarnetTestFramework, yet) to give them more homogenous structure.

There are a few "tidy-ups" in here too, sorry, but it's but mainly just breaking things down into a function-per-test, much like the bitcoin core functional test suite.

Makes it easier to add new tests, and re-use parts of other tests.

Also improve test logging using logging module where possible.

willcl-ark · 2024-07-08T12:11:36Z

fpush to re-add some erroneously-dropped comments,

pinheadmz

fuck yeah bravo, muchas gracias this is great.

some suggestions below

test/test_base.py

test/rpc_test.py

pinheadmz · 2024-07-08T19:01:44Z

test/scenarios_test.py

+    def run_and_check_scenario_from_file(self, scenario_file):
+        self.log.info(f"Running scenario from file: {scenario_file}")
+        self.warcli(f"scenarios run-file {scenario_file} --allnodes --interval=1")
+        self.wait_for_predicate(lambda: self.check_blocks(32))


e36df8e

This isnt great because there might still be a race from the last test not stopping in time. Maybe you can start the updated tx_scenario here instead, and wait for predicate can check for getchaintxstats["tx_count"] > getblockcount (or ensure there are 50 more txs than blocks i.e. coinbase txs). Although I guess if you do that youll need to keep miner_std running as well so the txs confirm and get counted

Nice catch, tried to fixup with 61e3331#diff-3c6951d855400160cce6184d9af9c0e5a663af6ae1f55a232fd53c53d6971188R51

mmmm ok Id still prefer loading a different scenario file entirely, maybe even a fragment we can keep in test/data or test/framework_tests

pinheadmz · 2024-07-08T19:03:26Z

test/scenarios_test.py

+    def test_scenarios(self):
+        self.check_available_scenarios()
+        self.run_and_check_scenario("miner_std")
+        self.run_and_check_scenario_from_file("src/scenarios/miner_std.py")
+


e36df8e

heh oh kay, OR you could just put these lines in run_test ?

Might add more files in the future though? (probably not, lol!)

Gunna leave though I think

test/v25_net_test.py

test/ln_test.py

pinheadmz · 2024-07-08T19:17:54Z

test/test_base.py

+        fh.setLevel(logging.DEBUG)
+        ch = logging.StreamHandler()
+        ch.setLevel(logging.DEBUG)
+        formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")


something is a bit funky here, im seeing double timestamps in some but not all log messages:

2024-07-08 15:18:43,320 - TestFramework - DEBUG - Node 2 has 1 settled invoices 2024-07-08 15:18:48,326 - TestFramework - DEBUG - Executing warcli command: lncli 2 listinvoices 2024-07-08 15:18:48,711 - TestFramework - DEBUG - 2024-07-08T19:18:48+0000 - DEBUG - {'jsonrpc': '2.0', 'method': 'tank_lncli', 'params': {'network': 'warnet-test-wspv4wt2', 'node': 2, 'command': ['listinvoices']}, 'id': 1} 2024-07-08 15:18:48,714 - TestFramework - DEBUG - 2024-07-08T19:18:48+0000 - DEBUG - Running lncli cmd=lncli --network=regtest listinvoices on tank.index=2 2024-07-08 15:18:48,714 - TestFramework - DEBUG - 2024-07-08T19:18:48+0000 - DEBUG - Running exec_cmd=['/bin/sh', '-c', 'lncli --network=regtest listinvoices'] on tank_index=2

Yeah, i need to update this to use our logging.config too: #384 (comment)

fixed in e1373a9 and 7872277 and 34e3331

pinheadmz · 2024-07-08T19:20:26Z

test/test_base.py

+                for service in ["bitcoin", "lightning", "circuitbreaker"]:
+                    status = tank.get(f"{service}_status")
+                    if status:
+                        stats[status] = stats.get(status, 0) + 1
+            self.log.info(f"Waiting for all tanks to reach '{target}': {stats}")


something else funky here, total shouldn't be the smallest number!

examples from local tests

Waiting for all tanks to reach 'stopped': {'total': 4, 'stopped': 3, 'pending': 4, 'running': 2}

Waiting for all tanks to reach 'stopped': {'total': 4, 'stopped': 9}

This test still stopped eventually because of

ERROR - Error bringing network down: Timed out waiting for predicate Truth

damn wth. I was so happy with that too. Is that happening every time? What test did you see that on?

It doesn't seem to for me:

Will investigate more tests in a bit.

try the ln_test because it has 4 tanks but a bunch of other pods for ln and cb

Fixed in e1373a9

willcl-ark

Thanks @pinheadmz

Taken almost everything in 5e361f9f60580c9e12046670e9843ed44d556ce2

test/ln_test.py

test/rpc_test.py

willcl-ark · 2024-07-08T19:33:23Z

test/scenarios_test.py

+    def test_scenarios(self):
+        self.check_available_scenarios()
+        self.run_and_check_scenario("miner_std")
+        self.run_and_check_scenario_from_file("src/scenarios/miner_std.py")
+


Might add more files in the future though? (probably not, lol!)

Gunna leave though I think

willcl-ark · 2024-07-08T19:33:32Z

test/scenarios_test.py

+    def run_and_check_scenario_from_file(self, scenario_file):
+        self.log.info(f"Running scenario from file: {scenario_file}")
+        self.warcli(f"scenarios run-file {scenario_file} --allnodes --interval=1")
+        self.wait_for_predicate(lambda: self.check_blocks(32))


Nice catch, tried to fixup with 61e3331#diff-3c6951d855400160cce6184d9af9c0e5a663af6ae1f55a232fd53c53d6971188R51

test/test_base.py

willcl-ark · 2024-07-08T19:36:36Z

test/test_base.py

+                for service in ["bitcoin", "lightning", "circuitbreaker"]:
+                    status = tank.get(f"{service}_status")
+                    if status:
+                        stats[status] = stats.get(status, 0) + 1
+            self.log.info(f"Waiting for all tanks to reach '{target}': {stats}")


damn wth. I was so happy with that too. Is that happening every time? What test did you see that on?

It doesn't seem to for me:

Will investigate more tests in a bit.

test/v25_net_test.py

mplsgrant · 2024-07-08T23:11:04Z

test/test_base.py


        self.server_thread = threading.Thread(
-            target=self.output_reader, args=(self.server.stdout, self.log.debug)
+            target=self.output_reader, args=(self.server.stdout, print)


Why bring print back from earlier in the PR? ca382c7#diff-1a293b58d544ac5f9d384afd0652dc7e9e17ae7564df252dd5a8fc39543ee0e6L99

In #384, the route I took was to create an instance method that takes one argument and does a call to logger: https://github.com/mplsgrant/warnet/blob/3e2d110d3bfbf73518a0af492832c57ae04372bd/test/test_base.py#L48

def passthrough_logger(self, message): self.logger.info(f"{self.pod_name} - {message}")

But maybe we can just leave this as is and change it in #384.

Why bring print back from earlier in the PR? ca382c7#diff-1a293b58d544ac5f9d384afd0652dc7e9e17ae7564df252dd5a8fc39543ee0e6L99

The reason is this is being logged from outside already (well, here in test_base), and we are using the output_reader to capture all output from stdout and log it. So if we log, it prepends all the log info (time data etc.). We then capture this entire line via stdout and prepend a second layer of log info in output_reader, so we end up with double log details.

But maybe we can just leave this as is and change it in #384.

Hopefully this :P

The passtrhough logger does feel quite nice though... it would probably be nicer to get an actual (sub) logger sharing the same logfile/stdout stream though

m3dwards · 2024-07-09T09:56:05Z

test/scenarios_test.py

+        self.warcli(f"scenarios run-file {scenario_file} --allnodes --interval=1")
+        start = int(self.warcli("rpc 0 getblockcount"))
+        self.wait_for_predicate(lambda: self.check_blocks(2, start=start))
+


Should there also be a stop_scenario() here?

Yes, thanks. I think it does get cleaned up ok, but better to have it in :)

m3dwards · 2024-07-09T09:59:18Z

A problem I had with the ln_test was that as part of it's setup it called a scenario (ln_init) but there's no way to check if the scenario failed or not. Perhaps the list of running scenarios should keep a list of failed ones?

willcl-ark · 2024-07-09T10:20:27Z

A problem I had with the ln_test was that as part of it's setup it called a scenario (ln_init) but there's no way to check if the scenario failed or not. Perhaps the list of running scenarios should keep a list of failed ones?

They are marked as active with a bool, no? Can we check that?

Not entirely sure why this changed, but some changes in a previous commit caused the (correct) issue that these services were unavailable, to surface as a proper error, causing the graph test to fail.

This is currently a little confusing in the code that it's a global enum, and has cause me some mild debugging issues.

m3dwards · 2024-07-09T10:37:14Z

They are marked as active with a bool, no? Can we check that?

Oh maybe, I didn't understand what not active meant.

m3dwards · 2024-07-09T10:41:20Z

LGTM. Ship it!

pinheadmz · 2024-07-09T13:58:12Z

src/warnet/test_framework_bridge.py

    def setup(self):
        signal.signal(signal.SIGTERM, self.handle_sigterm)
+
+        # Must setuup warnet first to avoid double formatting


setuuuuuuup!

pinheadmz · 2024-07-09T14:01:27Z

src/logging_config/config.json

    "simple": {
-      "format": " %(asctime)s - %(levelname)s - %(message)s",
-      "datefmt": "%Y-%m-%dT%H:%M:%S%z"
+      "format": "%(asctime)s │ %(levelname)-7s │ %(name)-17s │ %(message)s",


would prefer to leave out | to save a bit more space, and limit (name) as well, i bet we can cap it at 8 chars and come up with short little nicknames for each module

willcl-ark force-pushed the tidy-tests branch from 388d73e to 3b224ab Compare July 8, 2024 12:11

pinheadmz reviewed Jul 8, 2024

View reviewed changes

willcl-ark force-pushed the tidy-tests branch from 3b224ab to 5e361f9 Compare July 8, 2024 19:39

willcl-ark commented Jul 8, 2024

View reviewed changes

willcl-ark force-pushed the tidy-tests branch from f5658f6 to 8fc9498 Compare July 8, 2024 20:54

mplsgrant reviewed Jul 8, 2024

View reviewed changes

mplsgrant mentioned this pull request Jul 8, 2024

Allow asserting againt TestBase log file #384

Merged

willcl-ark added 2 commits July 9, 2024 08:40

test: refactor test_base

e1373a9

test: refactor rpc_test

2243454

willcl-ark force-pushed the tidy-tests branch 3 times, most recently from a1ad3ea to 5700227 Compare July 9, 2024 09:03

m3dwards reviewed Jul 9, 2024

View reviewed changes

willcl-ark added 11 commits July 9, 2024 11:28

test: refactor scenarios_test

d9f63af

test: refactor v25_net_test

27d8929

test: refactor ln_test

e7668cc

test: refactor build_branch_test

d3d8960

test: refactor dag_connection_test

360e4f2

test: use debug log level in stream

bf9227c

test: rename v25_net_test to onion_test

9c74e19

test: use logging.config in test_base

6dab9f0

fixup logging

7a9b687

test: remove unavailable services

bb2b11d

Not entirely sure why this changed, but some changes in a previous commit caused the (correct) issue that these services were unavailable, to surface as a proper error, causing the graph test to fail.

fixup services enum

57dfc9a

This is currently a little confusing in the code that it's a global enum, and has cause me some mild debugging issues.

willcl-ark force-pushed the tidy-tests branch from 5700227 to 57dfc9a Compare July 9, 2024 10:30

m3dwards merged commit e30f29e into bitcoin-dev-project:main Jul 9, 2024

pinheadmz reviewed Jul 9, 2024

View reviewed changes

Refactor tests #400

Refactor tests #400

Uh oh!

Conversation

willcl-ark commented Jul 8, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

willcl-ark commented Jul 8, 2024

Uh oh!

pinheadmz left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

willcl-ark Jul 8, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

willcl-ark Jul 9, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

willcl-ark left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

willcl-ark Jul 8, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

m3dwards commented Jul 9, 2024

Uh oh!

willcl-ark commented Jul 9, 2024

Uh oh!

m3dwards commented Jul 9, 2024

Uh oh!

m3dwards commented Jul 9, 2024

Uh oh!

pinheadmz Jul 9, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

willcl-ark commented Jul 8, 2024 •

edited

Loading

willcl-ark Jul 8, 2024 •

edited

Loading

willcl-ark Jul 9, 2024 •

edited

Loading

willcl-ark Jul 8, 2024 •

edited

Loading

pinheadmz Jul 9, 2024 •

edited

Loading