search

bitcoin-dev-project / warnet

Monitor and analyze the emergent behaviors of Bitcoin networks
https://warnet.dev
MIT License
63 stars 28 forks source link

Failure in ln_init scenario #205

Closed carlaKC closed 6 months ago

carlaKC commented 6 months ago

Running warnet at 5535564 (Python 3.11.4):

Steps to Reproduce

Start network and check status: 

warcli network start test/data/ln.graphml --network="ln"
warcli network status --network=ln

Output: 

ln_tank_000000: running
ln_ln_000000: running
ln_tank_000001: running
ln_ln_000001: running
ln_tank_000002: running
ln_ln_000002: running
ln_tank_000003: running

Run scenario: 

warcli scenarios run ln_init

Logs

2023-11-21 14:00:41,941 - warnet - DEBUG - Running ['/Users/carla/Work/warnet/.venv/bin/python3.11', '/Users/carla/Work/warnet/src/scenarios/ln_init.py', '--network=warnet']
2023-11-21 14:00:41,953 - werkzeug - INFO - 127.0.0.1 - - [21/Nov/2023 14:00:41] "POST /api HTTP/1.1" 200 -
2023-11-21 14:00:42,322 - warnet - INFO - Adding TestNode 0 from warnet_tank_000000 with IP 100.195.41.163
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 1 from warnet_tank_000001 with IP 100.166.169.93
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 2 from warnet_tank_000002 with IP 100.227.231.204
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 3 from warnet_tank_000003 with IP 100.15.127.242
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 4 from warnet_tank_000004 with IP 100.216.46.29
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 5 from warnet_tank_000005 with IP 100.200.44.244
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 6 from warnet_tank_000006 with IP 100.222.90.204
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 7 from warnet_tank_000007 with IP 100.52.167.137
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 8 from warnet_tank_000008 with IP 100.233.48.77
2023-11-21 14:00:42,328 - warnet - INFO - Adding TestNode 9 from warnet_tank_000009 with IP 100.249.121.121
2023-11-21 14:00:42,334 - warnet - INFO - Adding TestNode 10 from warnet_tank_000010 with IP 100.35.21.88
2023-11-21 14:00:42,373 - warnet - INFO - Adding TestNode 11 from warnet_tank_000011 with IP 100.201.21.110
2023-11-21 14:00:42,380 - warnet - INFO - User supplied random seed 131260415370612
2023-11-21 14:00:42,380 - warnet - INFO - PRNG seed is: 131260415370612
2023-11-21 14:00:42,380 - warnet - INFO - Get LN nodes and wallet addresses
2023-11-21 14:00:42,380 - warnet - INFO - Fund LN wallets
2023-11-21 14:00:49,435 - warnet - INFO - Unexpected exception caught during testing
2023-11-21 14:00:49,436 - warnet - INFO - Traceback (most recent call last):
2023-11-21 14:00:49,437 - warnet - INFO -   File "/Users/carla/Work/warnet/src/test_framework/test_framework.py", line 132, in main
2023-11-21 14:00:49,437 - warnet - INFO -     self.run_test()
2023-11-21 14:00:49,437 - warnet - INFO -   File "/Users/carla/Work/warnet/src/scenarios/ln_init.py", line 23, in run_test
2023-11-21 14:00:49,437 - warnet - INFO -     miner = ensure_miner(self.nodes[3])
2023-11-21 14:00:49,437 - warnet - INFO -             ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-21 14:00:49,437 - warnet - INFO -   File "/Users/carla/Work/warnet/src/scenarios/utils.py", line 2, in ensure_miner
2023-11-21 14:00:49,437 - warnet - INFO -     wallets = node.listwallets()
2023-11-21 14:00:49,437 - warnet - INFO -               ^^^^^^^^^^^^^^^^^^
2023-11-21 14:00:49,438 - warnet - INFO -   File "/Users/carla/Work/warnet/src/test_framework/coverage.py", line 49, in __call__
2023-11-21 14:00:49,438 - warnet - INFO -     return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
2023-11-21 14:00:49,438 - warnet - INFO -                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-21 14:00:49,438 - warnet - INFO -   File "/Users/carla/Work/warnet/src/test_framework/authproxy.py", line 124, in __call__
2023-11-21 14:00:49,438 - warnet - INFO -     response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
2023-11-21 14:00:49,438 - warnet - INFO -                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-21 14:00:49,439 - warnet - INFO -   File "/Users/carla/Work/warnet/src/test_framework/authproxy.py", line 102, in _request
2023-11-21 14:00:49,439 - warnet - INFO -     self.__conn.request(method, path, postdata, headers)
2023-11-21 14:00:49,439 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1286, in request
2023-11-21 14:00:49,439 - warnet - INFO -     self._send_request(method, url, body, headers, encode_chunked)
2023-11-21 14:00:49,439 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1332, in _send_request
2023-11-21 14:00:49,439 - warnet - INFO -     self.endheaders(body, encode_chunked=encode_chunked)
2023-11-21 14:00:49,440 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1281, in endheaders
2023-11-21 14:00:49,440 - warnet - INFO -     self._send_output(message_body, encode_chunked=encode_chunked)
2023-11-21 14:00:49,440 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1041, in _send_output
2023-11-21 14:00:49,440 - warnet - INFO -     self.send(msg)
2023-11-21 14:00:49,440 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 979, in send
2023-11-21 14:00:49,440 - warnet - INFO -     self.connect()
2023-11-21 14:00:49,440 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 945, in connect
2023-11-21 14:00:49,441 - warnet - INFO -     self.sock = self._create_connection(
2023-11-21 14:00:49,441 - warnet - INFO -                 ^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-21 14:00:49,441 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/socket.py", line 851, in create_connection
2023-11-21 14:00:49,441 - warnet - INFO -     raise exceptions[0]
2023-11-21 14:00:49,441 - warnet - INFO -   File "/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/socket.py", line 836, in create_connection
2023-11-21 14:00:49,441 - warnet - INFO -     sock.connect(sa)
2023-11-21 14:00:49,441 - warnet - INFO - OSError: [Errno 51] Network is unreachable
2023-11-21 14:00:49,487 - warnet - INFO - Stopping nodes
2023-11-21 14:00:49,489 - warnet - INFO - Not cleaning up dir /var/folders/5v/n5_hx3dd22x5cfv1c2h7hbk80000gn/T/bitcoin_func_test_7l294o2s
2023-11-21 14:00:49,489 - warnet - INFO - Test failed. Test logging available at /var/folders/5v/n5_hx3dd22x5cfv1c2h7hbk80000gn/T/bitcoin_func_test_7l294o2s/test_framework.log
2023-11-21 14:00:49,491 - warnet - INFO -
2023-11-21 14:00:49,491 - warnet - INFO - Hint: Call /Users/carla/Work/warnet/src/combine_logs.py '/var/folders/5v/n5_hx3dd22x5cfv1c2h7hbk80000gn/T/bitcoin_func_test_7l294o2s' to consolidate all logs
2023-11-21 14:00:49,491 - warnet - INFO -
2023-11-21 14:00:49,491 - warnet - INFO - If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.

Full warnet.log.

carlaKC commented 6 months ago

Docker running everything correctly: 

CONTAINER ID   IMAGE                                 COMMAND                  CREATED              STATUS                        PORTS                                                              NAMES
a138268ab5b6   lightninglabs/lnd:v0.17.0-beta        "lnd --noseedbackup …"   About a minute ago   Up About a minute             9735/tcp, 10009/tcp                                                ln_ln_000000
12487b8bd5d9   lightninglabs/lnd:v0.17.0-beta        "lnd --noseedbackup …"   About a minute ago   Up About a minute             9735/tcp, 10009/tcp                                                ln_ln_000001
9f3a0faecb81   lightninglabs/lnd:v0.17.0-beta        "lnd --noseedbackup …"   About a minute ago   Up About a minute             9735/tcp, 10009/tcp                                                ln_ln_000002
6ac3596457e4   bitcoindevproject/bitcoin-core:25.1   "/entrypoint.sh bitc…"   About a minute ago   Up About a minute (healthy)   8332-8333/tcp, 18332-18333/tcp, 18443-18444/tcp, 38332-38333/tcp   ln_tank_000003
47d2e56bd572   bitcoindevproject/bitcoin-core:25.1   "/entrypoint.sh bitc…"   About a minute ago   Up About a minute (healthy)   8332-8333/tcp, 18332-18333/tcp, 18443-18444/tcp, 38332-38333/tcp   ln_tank_000001
2acedce1ea0d   bitcoindevproject/bitcoin-core:25.1   "/entrypoint.sh bitc…"   About a minute ago   Up About a minute (healthy)   8332-8333/tcp, 18332-18333/tcp, 18443-18444/tcp, 38332-38333/tcp   ln_tank_000002
5fff4a53f530   bitcoindevproject/bitcoin-core:25.1   "/entrypoint.sh bitc…"   About a minute ago   Up About a minute (healthy)   8332-8333/tcp, 18332-18333/tcp, 18443-18444/tcp, 38332-38333/tcp   ln_tank_000000
29c51222caeb   prom/prometheus:latest                "/bin/prometheus --c…"   15 minutes ago       Up 15 minutes                 0.0.0.0:9090->9090/tcp                                             ln_prometheus
8aa1d29222eb   grafana/grafana:latest                "/run.sh"                15 minutes ago       Up 15 minutes                 0.0.0.0:3000->3000/tcp                                             ln_grafana
8b8999c498f6   gcr.io/cadvisor/cadvisor:v0.47.2      "/usr/bin/cadvisor -…"   15 minutes ago       Up 15 minutes (healthy)       0.0.0.0:8080->8080/tcp                                             ln_cadvisor
280a252ac4e9   b10c/fork-observer:latest             "/bin/sh -c /usr/loc…"   15 minutes ago       Up 15 minutes                 0.0.0.0:12323->2323/tcp                                            ln_fork-observer

But all of the lightning nodes are stuck on syncing to chain - docker logs ln_ln_000001 has repeated: 

2023-11-21 19:12:31.938 [DBG] LTND: Syncing to block timestamp: 2011-02-02 23:16:42 +0000 UTC, is synced=false

(and thus unable to open channels, I imagine)

willcl-ark commented 6 months ago

That first log line appears to show network=warnet, when you used ln earlier.

The test added 10 nodes, but in the demo graph it should be 3 or 4 IIRC

willcl-ark commented 6 months ago

Perhaps reset and try the test command like this, if you change the network name:

warcli scenarios run ln_init --network=ln.

If afk right now but this might work

pinheadmz commented 6 months ago

I think Will is right. Probably easiest is just to never use --network= and let warnet use its default ("warnet"). We don't even really support running more than one network at a time anyway 😬

On our end, @willcl-ark any RPC that accepts a network parameter like scenarios run should check to see if that network exists and is running first! If we threw a "unknown network" error here I think that would help

carlaKC commented 6 months ago

warcli scenarios run ln_init --network=ln.

doh, yeah that's it!