How to write tests for CLN plugins

Now that we know how to test if a dynamic plugin starts correctly, let's add the new test test_myplugin which will test myconnect command.

We modify myplugin.py to make it runs correctly thought it does nothing:

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

plugin.run()

In the test, once a node l1 is started using node_factory we can access builtin commands with its method rpc. For instance, in a test we use the getinfo command and get the node's information like this l1.rpc.getinfo(). In the same vein, if a plugin is started correctly and defines the command mycommand we can use it in the test like this l1.rpc.mycommand().

Let's write a failing test that tests if myconnect method returns the value 1:

def test_myplugin(node_factory):
    l1 = node_factory.get_node()
    l1.rpc.plugin_start(plugin_path)
    assert l1.rpc.myconnect() == 1

When we run the following test

(.venv) ◉ tony@tony:~/clnlive:
$ pytest test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py F                                                                      [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7fa80bc21750>

    def test_myplugin(node_factory):
        l1 = node_factory.get_node()
        l1.rpc.plugin_start(plugin_path)
>       assert l1.rpc.myconnect() == 1

test_myplugin.py:15:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.venv/lib/python3.10/site-packages/pyln/client/lightning.py:338: in wrapper
    return self.call(name, payload=kwargs)
.venv/lib/python3.10/site-packages/pyln/testing/utils.py:706: in call
    res = LightningRpc.call(self, method, payload, cmdprefix, filter)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pyln.testing.utils.PrettyPrintingLightningRpc object at 0x7fa80bc21990>
method = 'myconnect', payload = {}, cmdprefix = None, filter = None

    def call(self, method, payload=None, cmdprefix=None, filter=None):
        ...
        if not isinstance(resp, dict):
            raise ValueError("Malformed response, response is not a dictionary %s." % resp)
        elif "error" in resp:
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: myconnect, payload: {}, error: {'code': -32601, 'message': "Unknown command 'myconnect'"}

.venv/lib/python3.10/site-packages/pyln/client/lightning.py:422: RpcError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-k5zwc5aq
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 0.00038909912109375 seconds




2023-04-27T14:24:32.799Z DEBUG   lightningd: Opened log file -
2023-04-27T14:24:32.799Z DEBUG   lightningd: Opened log file /tmp/ltests-k5zwc5aq/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:24:32.799Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:24:32.799Z DEBUG   lightningd: Opened log file /tmp/ltests-k5zwc5aq/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:24:32.802Z DEBUG   plugin-manager: started(292772) /usr/local/libexec/c-lightning/plugins/autoclean
...
lightningd-1 2023-04-27T14:24:34.254Z DEBUG   plugin-manager: started(292807) /home/tony/clnlive/myplugin.py
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:24:34.505Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-1 2023-04-27T14:24:34.508Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - pyln.client.lightning.RpcError: RPC call failed: method: myconnect, payload: {}, error: {'...
===================================== 1 failed in 22.58s ======================================

we get a "Rpc call failed" error due to the command myconnect that is unknown. We can prettify the error message like this:

pyln.client.lightning.RpcError: RPC call failed:
method: myconnect,
payload: {},
error: {
  'code': -32601,
  'message': "Unknown command 'myconnect'"
}

This is normal because in the test we try to use myconnect method which we didn't define in myplugin.py plugin.

Now let's define myconnect method in our plugin and make it return {"foo":"bar"} object:

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

@plugin.method("myconnect")
def myplugin_func(plugin):
    return {"foo":"bar"}

plugin.run()

In our test (left unchanged), we can call myconnect method. But as we are still testing if myconnect returns the value 1 we get another error as we can see running our test again:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f656dd21480>

    def test_myplugin(node_factory):
        l1 = node_factory.get_node()
        l1.rpc.plugin_start(plugin_path)
>       assert l1.rpc.myconnect() == 1
E       AssertionError: assert {'foo': 'bar'} == 1
E        +  where {'foo': 'bar'} = <function UnixDomainSocketRpc.__getattr__.<locals>.wrapper at 0x7f656dd78ee0>()
E        +    where <function UnixDomainSocketRpc.__getattr__.<locals>.wrapper at 0x7f656dd78ee0> = <pyln.testing.utils.PrettyPrintingLightningRpc object at 0x7f656dd21900>.myconnect
E        +      where <pyln.testing.utils.PrettyPrintingLightningRpc object at 0x7f656dd21900> = <pyln.testing.utils.LightningNode object at 0x7f656dd21210>.rpc

test_myplugin.py:15: AssertionError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-ceywfrqi
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 1.0016329288482666 seconds




2023-04-27T14:26:28.250Z DEBUG   lightningd: Opened log file -
2023-04-27T14:26:28.250Z DEBUG   lightningd: Opened log file /tmp/ltests-ceywfrqi/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:26:28.250Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:26:28.250Z DEBUG   lightningd: Opened log file /tmp/ltests-ceywfrqi/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:26:28.252Z DEBUG   plugin-manager: started(292880) /usr/local/libexec/c-lightning/plugins/autoclean
...
lightningd-1 2023-04-27T14:26:29.336Z INFO    plugin-myplugin.py: RPC method 'myconnect' does not have a docstring.
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:26:29.373Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-1 2023-04-27T14:26:29.376Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - AssertionError: assert {'foo': 'bar'} == 1
===================================== 1 failed in 22.28s ======================================

Now the error is no longer an RPC call error but an assertion error

AssertionError: assert {'foo': 'bar'} == 1

which means that our plugin runs and registers successfully a new JSON-RPC method to lightningd.

It would be great to have the test passing, isn't it?

To do so, we modify our assertion to test that myconnect returns {"foo":"bar"} object (which is the case)

def test_myplugin(node_factory):
    l1 = node_factory.get_node()
    l1.rpc.plugin_start(plugin_path)
    assert l1.rpc.myconnect() == {"foo":"bar"}

and we check that the test passes:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 22.11s ======================================

Starting test function with test_

Speed up the test with VALGRIND=0

(.venv) ◉ tony@tony:~/clnlive:
$ VALGRIND=0 pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 21.66s ======================================

Let's modify our test so that it starts 2 nodes. To do this we use get_nodes method of node_factory object:

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)

Before modifying more our test, let's go back to our terminal and play with the builtin command connect to remember what do we need to now about the node l2 in order to connect l1 to l2 using the command connect of the node l1.

Let's start two Lightning nodes running on the Bitcoin regtest chain by sourcing the script lightning/contrib/startup_regtest.sh provided in CLN repository and by running the command start_ln:

(.venv) ◉ tony@tony:~/clnlive:
$ source lightning/contrib/startup_regtest.sh
lightning-cli is /usr/local/bin/lightning-cli
lightningd is /usr/local/bin/lightningd
Useful commands:
  start_ln 3: start three nodes, l1, l2, l3
  connect 1 2: connect l1 and l2
  fund_nodes: connect all nodes with channels, in a row
  stop_ln: shutdown
  destroy_ln: remove ln directories
(.venv) ◉ tony@tony:~/clnlive:
$ start_ln
Bitcoin Core starting
awaiting bitcoind...
Making "default" bitcoind wallet.
[1] 293269
[2] 293303
WARNING: eatmydata not found: instal it for faster testing
Commands:
        l1-cli, l1-log,
        l2-cli, l2-log,
        bt-cli, stop_ln, fund_nodes

We use getinfo command to get the id of the node l2, its address and port:

(.venv) ◉ tony@tony:~/clnlive:
$ l2-cli -F getinfo | rg 'id|binding'
id=036a5807fe754b10e9c43d6c8e0ae570ce36ec61bd2d9e572a4a00860e0bfa13c5
binding[0].type=ipv4
binding[0].address=127.0.0.1
binding[0].port=7272

We check that l1 node is not connect to any peer:

(.venv) ◉ tony@tony:~/clnlive:
$ l1-cli listpeers
{
   "peers": []
}

We connect the node l1 to the node l2

(.venv) ◉ tony@tony:~/clnlive:
$ l1-cli connect 036a5807fe754b10e9c43d6c8e0ae570ce36ec61bd2d9e572a4a00860e0bfa13c5@127.0.0.1:7272
{
   "id": "036a5807fe754b10e9c43d6c8e0ae570ce36ec61bd2d9e572a4a00860e0bfa13c5",
   "features": "08a000080269a2",
   "direction": "out",
   "address": {
      "type": "ipv4",
      "address": "127.0.0.1",
      "port": 7272
   }
}

and finally check that they are connected:

(.venv) ◉ tony@tony:~/clnlive:
$ l1-cli listpeers
{
   "peers": [
      {
         "id": "036a5807fe754b10e9c43d6c8e0ae570ce36ec61bd2d9e572a4a00860e0bfa13c5",
         "connected": true,
         "num_channels": 0,
         "netaddr": [
            "127.0.0.1:7272"
         ],
         "features": "08a000080269a2"
      }
   ]
}

Back to our test we can do something similar to get the information of the node l2 that we pass as the first argument of l1.rpc.myconnect() function (Note that there is an error: l1.rpc.getinfo should be l2.rpc.getinfo. We catch it later in the live):

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)
    l2_info = l1.rpc.getinfo()
    l2_node_id = l2_info["id"]
    l2_address = l2_info["binding"][0]["address"]
    l2_port = l2_info["binding"][0]["port"]
    l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
    assert l1.rpc.myconnect(l2_id) == {"foo":"bar"}

In our terminal we run that failing test:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f947a32d6c0>

    def test_myplugin(node_factory):
        l1, l2 = node_factory.get_nodes(2)
        l1.rpc.plugin_start(plugin_path)
        l2_info = l1.rpc.getinfo()
        l2_node_id = l2_info["id"]
        l2_address = l2_info["binding"][0]["address"]
        l2_port = l2_info["binding"][0]["port"]
        l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
>       assert l1.rpc.myconnect(l2_id) == {"foo":"bar"}

test_myplugin.py:20:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.venv/lib/python3.10/site-packages/pyln/client/lightning.py:336: in wrapper
    return self.call(name, payload=args)
.venv/lib/python3.10/site-packages/pyln/testing/utils.py:706: in call
    res = LightningRpc.call(self, method, payload, cmdprefix, filter)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pyln.testing.utils.PrettyPrintingLightningRpc object at 0x7f947a32d750>
method = 'myconnect'
payload = ('0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518@127.0.0.1:32989',)
cmdprefix = None, filter = None

    def call(self, method, payload=None, cmdprefix=None, filter=None):
        ...
        if not isinstance(resp, dict):
            raise ValueError("Malformed response, response is not a dictionary %s." % resp)
        elif "error" in resp:
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: myconnect, payload: ('0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518@127.0.0.1:32989',), error: {'code': -32600, 'message': 'Error while processing myconnect: too many positional arguments', 'traceback': 'Traceback (most recent call last):\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 639, in _dispatch_request\n    result = self._exec_func(method.func, request)\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 615, in _exec_func\n    ba = self._bind_pos(func, params, request)\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 582, in _bind_pos\n    ba = sig.bind(*params)\n  File "/usr/lib/python3.10/inspect.py", line 3179, in bind\n    return self._bind(args, kwargs)\n  File "/usr/lib/python3.10/inspect.py", line 3100, in _bind\n    raise TypeError(\'too many positional arguments\') from None\nTypeError: too many positional arguments\n'}

.venv/lib/python3.10/site-packages/pyln/client/lightning.py:422: RpcError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-hwletc1x
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 0.0008728504180908203 seconds




2023-04-27T14:38:52.481Z DEBUG   lightningd: Opened log file -
2023-04-27T14:38:52.481Z DEBUG   lightningd: Opened log file /tmp/ltests-hwletc1x/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:38:52.481Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:38:52.481Z DEBUG   lightningd: Opened log file /tmp/ltests-hwletc1x/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:38:52.490Z DEBUG   plugin-manager: started(293692) /usr/local/libexec/c-lightning/plugins/autoclean
...
lightningd-1 2023-04-27T14:38:54.550Z DEBUG   plugin-manager: started(293775) /home/tony/clnlive/myplugin.py
lightningd-1 2023-04-27T14:38:54.693Z INFO    plugin-myplugin.py: RPC method 'myconnect' does not have a docstring.
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py: Traceback (most recent call last):
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:   File \"/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py\", line 639, in _dispatch_request
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:     result = self._exec_func(method.func, request)
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:   File \"/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py\", line 582, in _bind_pos
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:     ba = sig.bind(*params)
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:   File \"/usr/lib/python3.10/inspect.py\", line 3179, in bind
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:     return self._bind(args, kwargs)
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:   File \"/usr/lib/python3.10/inspect.py\", line 3100, in _bind
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:     raise TypeError('too many positional arguments') from None
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py: TypeError: too many positional arguments
lightningd-1 2023-04-27T14:38:54.697Z INFO    plugin-myplugin.py:
lightningd-1 2023-04-27T14:38:54.811Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-2 2023-04-27T14:38:54.819Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - pyln.client.lightning.RpcError: RPC call failed: method: myconnect, payload: ('0266e4598d1...
===================================== 1 failed in 23.18s ======================================

We get a "RPC call failed" error that we can prettify like this

pyln.client.lightning.RpcError: RPC call failed:
method: myconnect,
payload: ('0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518@127.0.0.1:32989',),
error: {
  'code': -32600,
  'message': 'Error while processing myconnect: too many positional arguments', 'traceback': 'Traceback (most recent call last):\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 639, in _dispatch_request\n    result = self._exec_func(method.func, request)\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 615, in _exec_func\n    ba = self._bind_pos(func, params, request)\n  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 582, in _bind_pos\n    ba = sig.bind(*params)\n  File "/usr/lib/python3.10/inspect.py", line 3179, in bind\n    return self._bind(args, kwargs)\n  File "/usr/lib/python3.10/inspect.py", line 3100, in _bind\n    raise TypeError(\'too many positional arguments\') from None\nTypeError: too many positional arguments\n'
}

with the traceback prettified being:

Traceback (most recent call last):
  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 639, in _dispatch_request
    result = self._exec_func(method.func, request)
  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 615, in _exec_func
    ba = self._bind_pos(func, params, request)
  File "/home/tony/clnlive/.venv/lib/python3.10/site-packages/pyln/client/plugin.py", line 582, in _bind_pos
    ba = sig.bind(*params)
  File "/usr/lib/python3.10/inspect.py", line 3179, in bind
    return self._bind(args, kwargs)
  File "/usr/lib/python3.10/inspect.py", line 3100, in _bind
    raise TypeError('too many positional arguments') from None
TypeError: too many positional arguments

We get that error because in the test we call myconnect method with an argument but in our plugin myconnect takes no argument.

Let's fix this like this:

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

@plugin.method("myconnect")
def myplugin_func(plugin,id):
    return {"foo":"bar"}

plugin.run()

We can run the test again and see it passes:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 24.26s ======================================

Let's modify in the test what we expect myconnect method to return (we use connect_to key but we'll change it for connected_to after):

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)
    l2_info = l1.rpc.getinfo()
    l2_node_id = l2_info["id"]
    l2_address = l2_info["binding"][0]["address"]
    l2_port = l2_info["binding"][0]["port"]
    l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
    assert l1.rpc.myconnect(l2_id) == {"connect_to": l2_id}

Back to our terminal, we see that our test fails because myconnect method still returns {"foo":"bar"} object:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f8ac252d6c0>

    def test_myplugin(node_factory):
        l1, l2 = node_factory.get_nodes(2)
        l1.rpc.plugin_start(plugin_path)
        l2_info = l1.rpc.getinfo()
        l2_node_id = l2_info["id"]
        l2_address = l2_info["binding"][0]["address"]
        l2_port = l2_info["binding"][0]["port"]
        l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
>       assert l1.rpc.myconnect(l2_id) == {"connect_to": l2_id}
E       AssertionError: assert {'foo': 'bar'} == {'connect_to'....0.0.1:42149'}
E         Left contains 1 more item:
E         {'foo': 'bar'}
E         Right contains 1 more item:
E         {'connect_to': '0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518@127.0.0.1:42149'}
E         Full diff:
E         - {'connect_to': '0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518@127.0.0.1:42149'}
E         + {'foo': 'bar'}

test_myplugin.py:20: AssertionError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-c6ntvlsh
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 1.0021874904632568 seconds
Throttler delayed startup for 1.0169610977172852 seconds




2023-04-27T14:42:29.189Z DEBUG   lightningd: Opened log file -
2023-04-27T14:42:29.189Z DEBUG   lightningd: Opened log file /tmp/ltests-c6ntvlsh/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:42:29.189Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:42:29.189Z DEBUG   lightningd: Opened log file /tmp/ltests-c6ntvlsh/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:42:29.193Z DEBUG   plugin-manager: started(294152) /usr/local/libexec/c-lightning/plugins/autoclean
...
lightningd-1 2023-04-27T14:42:30.825Z INFO    plugin-myplugin.py: RPC method 'myconnect' does not have a docstring.
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:42:30.868Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-2 2023-04-27T14:42:30.876Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - AssertionError: assert {'foo': 'bar'} == {'connect_to'....0.0.1:42149'}
===================================== 1 failed in 25.02s ======================================

We modified our plugin to return an object with the key connected_to

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

@plugin.method("myconnect")
def myplugin_func(plugin,id):
    return {"connected_to":id}

plugin.run()

and we also replace connect_to by connected_to in our test.

This leads us to a passing test:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 23.13s ======================================

Interesting, but not enough. Indeed, myconnect method doesn't connect the node l1 to the node l2 yet.

Let's write a test for this.

Since listpeers command returns in its member peers the array of the nodes connected to the node calling that command

(.venv) ◉ tony@tony:~/clnlive:
$ l1-cli listpeers
{
   "peers": [
      {
         "id": "036a5807fe754b10e9c43d6c8e0ae570ce36ec61bd2d9e572a4a00860e0bfa13c5",
         "connected": true,
         "num_channels": 0,
         "netaddr": [
            "127.0.0.1:7272"
         ],
         "features": "08a000080269a2"
      }
   ]
}

we can use the length of that array to check if myconnect method can connect nodes together.

Here is our test:

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)
    l2_info = l2.rpc.getinfo()
    l2_node_id = l2_info["id"]
    l2_address = l2_info["binding"][0]["address"]
    l2_port = l2_info["binding"][0]["port"]
    l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
    assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
    l1_peers = l1.rpc.listpeers()["peers"]
    assert len(l1_peers) == 1

Since we haven't implemented the connection in myplugin.py yet, this test fails:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f8c1851d600>

    def test_myplugin(node_factory):
        l1, l2 = node_factory.get_nodes(2)
        l1.rpc.plugin_start(plugin_path)
        l2_info = l1.rpc.getinfo()
        l2_node_id = l2_info["id"]
        l2_address = l2_info["binding"][0]["address"]
        l2_port = l2_info["binding"][0]["port"]
        l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
        assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
        l1_peers = l1.rpc.listpeers()["peers"]
>       assert len(l1_peers) == 1
E       assert 0 == 1
E        +  where 0 = len([])

test_myplugin.py:22: AssertionError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-45q52ryy
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 0.0008282661437988281 seconds




2023-04-27T14:47:10.668Z DEBUG   lightningd: Opened log file -
2023-04-27T14:47:10.668Z DEBUG   lightningd: Opened log file /tmp/ltests-45q52ryy/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:47:10.668Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:47:10.668Z DEBUG   lightningd: Opened log file /tmp/ltests-45q52ryy/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:47:10.671Z DEBUG   plugin-manager: started(294585) /usr/local/libexec/c-lightning/plugins/autoclean
...
lightningd-1 2023-04-27T14:47:12.633Z INFO    plugin-myplugin.py: RPC method 'myconnect' does not have a docstring.
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:47:12.676Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-2 2023-04-27T14:47:12.691Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - assert 0 == 1
===================================== 1 failed in 23.29s ======================================

Let's use the builtin connect command in our plugin to make myconnect method connects to the node with the information (id@address:host) we pass to myconnect as argument like this:

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

@plugin.method("myconnect")
def myplugin_func(plugin,id):
    plugin.rpc.connect(id)
    return {"connected_to":id}

plugin.run()

We should expect the test to pass, but this is not the case because there is an error in the test itself (l1.rpc.getinfo should be l2.rpc.getinfo) that we catch and fix just after. But for now, here is the failing test:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f5ba89215d0>

    def test_myplugin(node_factory):
        l1, l2 = node_factory.get_nodes(2)
        l1.rpc.plugin_start(plugin_path)
        l2_info = l1.rpc.getinfo()
        l2_node_id = l2_info["id"]
        l2_address = l2_info["binding"][0]["address"]
        l2_port = l2_info["binding"][0]["port"]
        l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
        assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
        l1_peers = l1.rpc.listpeers()["peers"]
>       assert len(l1_peers) == 1
E       assert 0 == 1
E        +  where 0 = len([])

test_myplugin.py:22: AssertionError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-bq3n9qi4
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 0.0009438991546630859 seconds




2023-04-27T14:49:02.428Z DEBUG   lightningd: Opened log file -
2023-04-27T14:49:02.428Z DEBUG   lightningd: Opened log file /tmp/ltests-bq3n9qi4/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:49:02.428Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:49:02.428Z DEBUG   lightningd: Opened log file /tmp/ltests-bq3n9qi4/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:49:02.431Z DEBUG   plugin-manager: started(294771) /usr/local/libexec/c-lightning/plugins/autoclean
...
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:49:04.479Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-2 2023-04-27T14:49:04.493Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - assert 0 == 1
===================================== 1 failed in 22.71s ======================================

As we've just said, we know the error in the test and we fix it by replacing l1.rpc.getinfo by l2.rpc.getinfo

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)
    l2_info = l2.rpc.getinfo()
    l2_node_id = l2_info["id"]
    l2_address = l2_info["binding"][0]["address"]
    l2_port = l2_info["binding"][0]["port"]
    l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
    assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
    l1_peers = l1.rpc.listpeers()["peers"]
    assert len(l1_peers) == 1

which leads to a passing test:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 24.03s ======================================

Let's say that we want myconnect to log some information in the node's log file and we also want to test this.

In the test, assuming l1 is a node started with node_factory object, we can use the method wait_for_log of the property daemon of the l1 to test that something happened in the log file of l1. The second argument of wait_for_log is the timeout.

So, let's modify our test to check that myconnect write FOO 'myconnect' in l1's log file with a timeout of 5 seconds by adding the expression l1.daemon.wait_for_log("FOO 'myconnect'", 5):

def test_myplugin(node_factory):
    l1, l2 = node_factory.get_nodes(2)
    l1.rpc.plugin_start(plugin_path)
    l2_info = l2.rpc.getinfo()
    l2_node_id = l2_info["id"]
    l2_address = l2_info["binding"][0]["address"]
    l2_port = l2_info["binding"][0]["port"]
    l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
    assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
    l1_peers = l1.rpc.listpeers()["peers"]
    assert len(l1_peers) == 1
    l1.daemon.wait_for_log("FOO 'myconnect'", 5)

Since myconnect method doesn't write in the logs, the test fails as we can see in our terminal:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin FAILED                                                  [100%]

========================================== FAILURES ===========================================
________________________________________ test_myplugin ________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f560441d690>

    def test_myplugin(node_factory):
        l1, l2 = node_factory.get_nodes(2)
        l1.rpc.plugin_start(plugin_path)
        l2_info = l2.rpc.getinfo()
        l2_node_id = l2_info["id"]
        l2_address = l2_info["binding"][0]["address"]
        l2_port = l2_info["binding"][0]["port"]
        l2_id = l2_node_id + "@" + l2_address + ":" + str(l2_port)
        assert l1.rpc.myconnect(l2_id) == {"connected_to": l2_id}
        l1_peers = l1.rpc.listpeers()["peers"]
        assert len(l1_peers) == 1
>       l1.daemon.wait_for_log("FOO 'myconnect'", 5)

test_myplugin.py:23:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.venv/lib/python3.10/site-packages/pyln/testing/utils.py:348: in wait_for_log
    return self.wait_for_logs([regex], timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pyln.testing.utils.LightningD object at 0x7f560441ee00>, regexs = ["FOO 'myconnect'"]
timeout = 5

    def wait_for_logs(self, regexs, timeout=TIMEOUT):
        """Look for `regexs` in the logs.

        The logs contain tailed stdout of the process. We look for each regex
        in `regexs`, starting from `logsearch_start` which normally is the
        position of the last found entry of a previous wait-for logs call.
        The ordering inside `regexs` doesn't matter.

        We fail if the timeout is exceeded or if the underlying process
        exits before all the `regexs` were found.

        If timeout is None, no time-out is applied.
        """
        logging.debug("Waiting for {} in the logs".format(regexs))
        exs = [re.compile(r) for r in regexs]
        start_time = time.time()
        while True:
            if self.logsearch_start >= len(self.logs):
                if not self.logs_catchup():
                    time.sleep(0.25)

                if timeout is not None and time.time() > start_time + timeout:
                    print("Time-out: can't find {} in logs".format(exs))
                    for r in exs:
                        if self.is_in_log(r):
                            print("({} was previously in logs!)".format(r))
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile("FOO 'myconnect'")]" in logs.

.venv/lib/python3.10/site-packages/pyln/testing/utils.py:329: TimeoutError
------------------------------------ Captured stdout setup ------------------------------------
Running tests in /tmp/ltests-mqu7gs64
------------------------------------ Captured stdout call -------------------------------------
Throttler delayed startup for 0.0009188652038574219 seconds
Throttler delayed startup for 0.10099434852600098 seconds




2023-04-27T14:59:04.999Z DEBUG   lightningd: Opened log file -
2023-04-27T14:59:04.999Z DEBUG   lightningd: Opened log file /tmp/ltests-mqu7gs64/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:59:04.999Z DEBUG   lightningd: Opened log file -
lightningd-1 2023-04-27T14:59:04.999Z DEBUG   lightningd: Opened log file /tmp/ltests-mqu7gs64/test_myplugin_1/lightning-1/log
lightningd-1 2023-04-27T14:59:05.002Z DEBUG   plugin-manager: started(295607) /usr/local/libexec/c-lightning/plugins/autoclean
...
Time-out: can't find [re.compile("FOO 'myconnect'")] in logs
---------------------------------- Captured stdout teardown -----------------------------------
lightningd-1 2023-04-27T14:59:12.393Z UNUSUAL lightningd: JSON-RPC shutdown
...
lightningd-2 2023-04-27T14:59:12.403Z DEBUG   hsmd: Shutting down
=================================== short test summary info ===================================
FAILED test_myplugin.py::test_myplugin - TimeoutError: Unable to find "[re.compile("FOO 'myconnect'")]" in logs.
===================================== 1 failed in 28.62s ======================================

Specifically, we get a timeout error:

TimeoutError: Unable to find "[re.compile("FOO 'myconnect'")]" in logs.

We fix that error by adding plugin.log("FOO 'myconnect'") in our plugin like this:

#!/usr/bin/env python

# this line produces an error

from pyln.client import Plugin

plugin = Plugin()

@plugin.method("myconnect")
def myplugin_func(plugin,id):
    plugin.rpc.connect(id)
    plugin.log("FOO 'myconnect'")
    return {"connected_to":id}

plugin.run()

Finally, we run the test and happily see it passing:

(.venv) ◉ tony@tony:~/clnlive:
$ pytest -v test_myplugin.py
===================================== test session starts =====================================
platform linux -- Python 3.10.6, pytest-7.3.1, pluggy-1.0.0 -- /home/tony/clnlive/.venv/bin/python
cachedir: .pytest_cache
rootdir: /home/tony/clnlive
collected 1 item

test_myplugin.py::test_myplugin PASSED                                                  [100%]

===================================== 1 passed in 24.00s ======================================

We are done.