pytest: fix test_channel_state_change_history

[morehouse]

The test fails because the closed channel is deleted by the time we check the state change history.

It appears the test was intended to only mine 100 blocks originally, but had an accidental copy-paste in it.

[morehouse]

On my machine, here's the failure output:

============================= test session starts ==============================
platform linux -- Python 3.8.10, pytest-7.1.2, pluggy-1.0.0 -- /home/matt/.cache/pypoetry/virtualenvs/cln-meta-project-dfJtkWA4-py3.8/bin/python3
cachedir: .pytest_cache
rootdir: /home/matt/Code/morehouse/lightning
plugins: xdist-2.5.0, custom-exit-code-0.3.0, forked-1.4.0, test-groups-1.0.3, timeout-2.1.0
collecting ... collected 528 items / 527 deselected / 1 selected

tests/test_plugin.py::test_channel_state_change_history FAILED           [100%]

=================================== FAILURES ===================================
______________________ test_channel_state_change_history _______________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f41bf5cd610>
bitcoind = <pyln.testing.utils.BitcoinD object at 0x7f41bf632c40>

    @pytest.mark.openchannel('v1')
    @pytest.mark.openchannel('v2')
    def test_channel_state_change_history(node_factory, bitcoind):
        """ We open and close a channel and check for state_canges entries.

        """
        l1, l2 = node_factory.line_graph(2)
        scid = l1.get_channel_scid(l2)

        l1.rpc.close(scid)
        bitcoind.generate_block(100)  # so it gets settled
        bitcoind.generate_block(100)  # so it gets settled

>       history = l1.rpc.listpeers()['peers'][0]['channels'][0]['state_changes']
E       IndexError: list index out of range

tests/test_plugin.py:1019: IndexError

Relevant stdout debug info:

----------------------------- Captured stdout call -----------------------------
<snip>
lightningd-2 2022-08-17T16:11:20.755Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_AWAITING_LOCKIN to CHANNELD_NORMAL
<snip>
lightningd-1 2022-08-17T16:11:28.694Z INFO    022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from CHANNELD_NORMAL to CHANNELD_SHUTTING_DOWN
<snip>
lightningd-2 2022-08-17T16:11:29.118Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_SHUTTING_DOWN to CLOSINGD_SIGEXCHANGE
<snip>
lightningd-2 2022-08-17T16:11:29.204Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CLOSINGD_SIGEXCHANGE to CLOSINGD_COMPLETE
<snip>
lightningd-1 2022-08-17T16:11:29.824Z INFO    022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from CLOSINGD_COMPLETE to FUNDING_SPEND_SEEN
<snip>
lightningd-1 2022-08-17T16:11:29.883Z INFO    022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from FUNDING_SPEND_SEEN to ONCHAIN
<snip>
lightningd-2 2022-08-17T16:11:29.892Z UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Peer permanent failure in CLOSINGD_COMPLETE: Funding transaction spent
<snip>
lightningd-2 2022-08-17T16:11:29.944Z DEBUG   gossipd: Deleting channel 103x1x1 due to the funding outpoint being spent
<snip>
lightningd-1 2022-08-17T16:11:30.081Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: All outputs resolved: waiting 100 more blocks before forgetting channel
lightningd-2 2022-08-17T16:11:30.098Z DEBUG   lightningd: Adding block 106: 3f795acdc826b3cc4907f61aba50c2eebca7281d530d4e036fc15075bc486479
<snip>
lightningd-2 2022-08-17T16:11:36.957Z DEBUG   lightningd: Adding block 206: 182079a300ab724a9cfbef1975f98370d3eac19709ea62b1b89de10300f3c181
<snip>
lightningd-2 2022-08-17T16:11:37.051Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 0 more blocks before forgetting channel
lightningd-2 2022-08-17T16:11:37.052Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: onchaind complete, forgetting peer
<snip>
lightningd-2 2022-08-17T16:11:38.042Z DEBUG   lightningd: Adding block 207: 5616f0952c80f6d7ce9f7b9384771ba7c651acfb79e8bc50204ecd9dd22a5334
<snip>
lightningd-2 2022-08-17T16:11:44.744Z DEBUG   lightningd: Adding block 290: 02a587faa615ab00f6070a1c6a34f9e408f7edb1c40576fd5b0fe3b1981df00c
<snip>
DEBUG:root:{
  "id": 1,
  "method": "listpeers",
  "params": {
    "id": null,
    "level": null
  }
}
DEBUG:root:Calling listpeers with payload {'id': None, 'level': None}
DEBUG:root:Received response for listpeers call: {'jsonrpc': '2.0', 'id': 1, 'result': {'peers': [{'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'connected': True, 'netaddr': ['127.0.0.1:36329'], 'features': '08a088082269a2', 'channels': []}]}}
DEBUG:root:{
  "id": 1,
  "result": {
    "peers": [
      {
        "id": "022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59",
        "connected": true,
        "netaddr": [
          "127.0.0.1:36329"
        ],
        "features": "08a088082269a2",
        "channels": []
      }
    ]
  }
}

So the channel is forgotten by the time listpeers is called, which causes l1.rpc.listpeers()['peers'][0]['channels'][0] to throw an IndexError.

Any ideas why this isn't failing in CI?

[SimonVrouwe]

Nice catch.

It appears the test was intended to only mine 100 blocks originally, but had an accidental copy-paste in it.

I think both lines bitcoind.generate_block(100) are obsolete and can be deleted. After a (successful) close command, the channel state is already CLOSINGD_COMPLETE

Any ideas why this isn't failing in CI?

Probably because the node l1 didn't catch up with the 100 blocks yet. You can check this by adding sync_blockheight(bitcoind, [l1]) after bitcoind.generate_block(100), then it should have forgotten the channel.

[morehouse]

I think both lines bitcoind.generate_block(100) are obsolete and can be deleted. After a (successful) close command, the channel state is already CLOSINGD_COMPLETE

Done in updated patch.

Any ideas why this isn't failing in CI?

Probably because the node l1 didn't catch up with the 100 blocks yet. You can check this by adding sync_blockheight(bitcoind, [l1]) after bitcoind.generate_block(100), then it should have forgotten the channel.

Yep, thanks! At 99 blocks the channel is still there. At exactly 100 the test starts failing again.

[SimonVrouwe]

ACK bfdc30b

[niftynei]

ACK bfdc30b63797c5a1433c3ae813ccc4cb3ecb3149