[TEST] workflows, added 10s timeout to lncli subprocess and logging (#1910)

* [FIX] workflows

testing why workflwos unstable instable

* debug run_command

* add timeout to process run

* log lncli output

* try catch json exception in clnrest

* settle does not return a json

* add 10 minutes timeout to regtests if they ever get stuck

* better subprocess handling

* fix race condition

* test 3

* remove

* run nr 4

* increase waits for race conditions

* revert clnrest

* better fiat amount test

.github/workflows/regtest.yml

@@ -19,7 +19,7 @@ on:
 jobs:
   regtest:
     runs-on: ${{ inputs.os-version }}
-
+    timeout-minutes: 10
     steps:
       - uses: actions/checkout@v3
 

tests/core/views/test_api.py

@@ -96,10 +96,14 @@ async def test_create_invoice_fiat_amount(client, inkey_headers_to):
     invoice = response.json()
     decode = bolt11.decode(invoice["payment_request"])
     assert decode.amount_msat != data["amount"] * 1000
+    assert decode.payment_hash
 
-    response = await client.get("/api/v1/payments?limit=1", headers=inkey_headers_to)
+    response = await client.get(
+        f"/api/v1/payments/{decode.payment_hash}", headers=inkey_headers_to
+    )
     assert response.is_success
-    extra = response.json()[0]["extra"]
+    res_data = response.json()
+    extra = res_data["details"]["extra"]
     assert extra["fiat_amount"] == data["amount"]
     assert extra["fiat_currency"] == data["unit"]
     assert extra["fiat_rate"]
@@ -456,10 +460,11 @@ async def test_pay_real_invoice(
     payment_status = response.json()
     assert payment_status["paid"]
 
+    WALLET = get_wallet_class()
     status = await WALLET.get_payment_status(invoice["payment_hash"])
     assert status.paid
 
-    await asyncio.sleep(0.3)
+    await asyncio.sleep(1)
     balance = await get_node_balance_sats()
     assert prev_balance - balance == 100
 
@@ -493,8 +498,9 @@ async def test_create_real_invoice(client, adminkey_headers_from, inkey_headers_
         assert found_checking_id
 
     task = asyncio.create_task(listen())
+    await asyncio.sleep(1)
     pay_real_invoice(invoice["payment_request"])
-    await asyncio.wait_for(task, timeout=3)
+    await asyncio.wait_for(task, timeout=10)
 
     response = await client.get(
         f'/api/v1/payments/{invoice["payment_hash"]}', headers=inkey_headers_from
@@ -503,7 +509,7 @@ async def test_create_real_invoice(client, adminkey_headers_from, inkey_headers_
     payment_status = response.json()
     assert payment_status["paid"]
 
-    await asyncio.sleep(0.3)
+    await asyncio.sleep(1)
     balance = await get_node_balance_sats()
     assert balance - prev_balance == create_invoice.amount
 
@@ -536,6 +542,7 @@ async def test_pay_real_invoice_set_pending_and_check_state(
     assert response["paid"]
 
     # make sure that the backend also thinks it's paid
+    WALLET = get_wallet_class()
     status = await WALLET.get_payment_status(invoice["payment_hash"])
     assert status.paid
 
@@ -712,13 +719,17 @@ async def test_receive_real_invoice_set_pending_and_check_state(
     assert not response["paid"]
 
     async def listen():
+        found_checking_id = False
         async for checking_id in get_wallet_class().paid_invoices_stream():
-            assert checking_id == invoice["checking_id"]
+            if checking_id == invoice["checking_id"]:
+                found_checking_id = True
                 return
+        assert found_checking_id
 
     task = asyncio.create_task(listen())
+    await asyncio.sleep(1)
     pay_real_invoice(invoice["payment_request"])
-    await asyncio.wait_for(task, timeout=3)
+    await asyncio.wait_for(task, timeout=10)
     response = await api_payment(
         invoice["payment_hash"], inkey_headers_from["X-Api-Key"]
     )

tests/helpers.py

@@ -3,9 +3,12 @@ import json
 import os
 import random
 import string
-from subprocess import PIPE, Popen, run
+import time
+from subprocess import PIPE, Popen, TimeoutExpired
 from typing import Tuple
 
+from loguru import logger
+
 from lnbits.wallets import get_wallet_class, set_wallet_class
 
 
@@ -26,64 +29,105 @@ is_fake: bool = WALLET.__class__.__name__ == "FakeWallet"
 is_regtest: bool = not is_fake
 
 
-docker_bitcoin_rpc = "lnbits"
-docker_prefix = "lnbits-legend"
-docker_cmd = "docker exec"
+docker_lightning_cli = [
+    "docker",
+    "exec",
+    "lnbits-legend-lnd-1-1",
+    "lncli",
+    "--network",
+    "regtest",
+    "--rpcserver=lnd-1",
+]
 
-docker_lightning = f"{docker_cmd} {docker_prefix}-lnd-1-1"
-docker_lightning_cli = f"{docker_lightning} lncli --network regtest --rpcserver=lnd-1"
-
-docker_bitcoin = f"{docker_cmd} {docker_prefix}-bitcoind-1-1"
-docker_bitcoin_cli = (
-    f"{docker_bitcoin} bitcoin-cli"
-    f" -rpcuser={docker_bitcoin_rpc} -rpcpassword={docker_bitcoin_rpc} -regtest"
-)
+docker_bitcoin_cli = [
+    "docker",
+    "exec",
+    "lnbits-legend-bitcoind-1-1" "bitcoin-cli",
+    "-rpcuser=lnbits",
+    "-rpcpassword=lnbits",
+    "-regtest",
+]
 
 
-def run_cmd(cmd: str) -> str:
-    return run(cmd, shell=True, capture_output=True).stdout.decode("UTF-8").strip()
+def run_cmd(cmd: list) -> str:
+    timeout = 20
+    process = Popen(cmd, stdout=PIPE, stderr=PIPE)
+
+    def process_communication(comm):
+        stdout, stderr = comm
+        output = stdout.decode("utf-8").strip()
+        error = stderr.decode("utf-8").strip()
+        return output, error
+
+    try:
+        now = time.time()
+        output, error = process_communication(process.communicate(timeout=timeout))
+        took = time.time() - now
+        logger.debug(f"ran command output: {output}, error: {error}, took: {took}s")
+        return output
+    except TimeoutExpired:
+        process.kill()
+        output, error = process_communication(process.communicate())
+        logger.error(f"timeout command: {cmd}, output: {output}, error: {error}")
+        raise
 
 
-def run_cmd_json(cmd: str) -> dict:
-    return json.loads(run_cmd(cmd))
+def run_cmd_json(cmd: list) -> dict:
+    output = run_cmd(cmd)
+    try:
+        return json.loads(output) if output else {}
+    except json.decoder.JSONDecodeError:
+        logger.error(f"failed to decode json from cmd `{cmd}`: {output}")
+        raise
 
 
 def get_hold_invoice(sats: int) -> Tuple[str, dict]:
     preimage = os.urandom(32)
     preimage_hash = hashlib.sha256(preimage).hexdigest()
-    json = run_cmd_json(f"{docker_lightning_cli} addholdinvoice {preimage_hash} {sats}")
+    cmd = docker_lightning_cli.copy()
+    cmd.extend(["addholdinvoice", preimage_hash, str(sats)])
+    json = run_cmd_json(cmd)
     return preimage.hex(), json
 
 
-def settle_invoice(preimage: str) -> dict:
-    return run_cmd_json(f"{docker_lightning_cli} settleinvoice {preimage}")
+def settle_invoice(preimage: str) -> str:
+    cmd = docker_lightning_cli.copy()
+    cmd.extend(["settleinvoice", preimage])
+    return run_cmd(cmd)
 
 
-def cancel_invoice(preimage_hash: str) -> dict:
-    return run_cmd_json(f"{docker_lightning_cli} cancelinvoice {preimage_hash}")
+def cancel_invoice(preimage_hash: str) -> str:
+    cmd = docker_lightning_cli.copy()
+    cmd.extend(["cancelinvoice", preimage_hash])
+    return run_cmd(cmd)
 
 
 def get_real_invoice(sats: int) -> dict:
-    return run_cmd_json(f"{docker_lightning_cli} addinvoice {sats}")
+    cmd = docker_lightning_cli.copy()
+    cmd.extend(["addinvoice", str(sats)])
+    return run_cmd_json(cmd)
 
 
-def pay_real_invoice(invoice: str) -> Popen:
-    return Popen(
-        f"{docker_lightning_cli} payinvoice --force {invoice}",
-        shell=True,
-        stdin=PIPE,
-        stdout=PIPE,
-    )
+def pay_real_invoice(invoice: str) -> str:
+    cmd = docker_lightning_cli.copy()
+    cmd.extend(["payinvoice", "--force", invoice])
+    return run_cmd(cmd)
 
 
 def mine_blocks(blocks: int = 1) -> str:
-    return run_cmd(f"{docker_bitcoin_cli} -generate {blocks}")
+    cmd = docker_bitcoin_cli.copy()
+    cmd.extend(["-generate", str(blocks)])
+    return run_cmd(cmd)
 
 
 def create_onchain_address(address_type: str = "bech32") -> str:
-    return run_cmd(f"{docker_bitcoin_cli} getnewaddress {address_type}")
+    cmd = docker_bitcoin_cli.copy()
+    cmd.extend(["getnewaddress", address_type])
+    return run_cmd(cmd)
 
 
 def pay_onchain(address: str, sats: int) -> str:
     btc = sats * 0.00000001
-    return run_cmd(f"{docker_bitcoin_cli} sendtoaddress {address} {btc}")
+    cmd = docker_bitcoin_cli.copy()
+    cmd.extend(["sendtoaddress", address, str(btc)])
+    return run_cmd(cmd)