Failure in ln_init scenario
Closed this issue · 5 comments
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.
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)
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
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
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
warcli scenarios run ln_init --network=ln.
doh, yeah that's it!