fix: make integration services fail fast

.github/workflows/test.yml

@@ -7,6 +7,7 @@ on:
 jobs:
   test:
     runs-on: ubuntu-latest
+    timeout-minutes: 15
 
     steps:
       - name: Checkout code
@@ -50,3 +51,16 @@ jobs:
           pip install pytest-asyncio
           cd $cdir
           pytest tests/integration/*.py -s
+
+      - name: Show integration service logs
+        if: failure()
+        run: |
+          docker ps -a
+          docker logs --tail 200 lnbits_nwcprovider_ext_nostr_test || true
+          docker exec lnbits_nwcprovider_ext_lnbits_test tail -n 200 /tmp/lnbits.log || true
+
+      - name: Stop integration services
+        if: always()
+        run: |
+          docker rm -f lnbits_nwcprovider_ext_lnbits_test lnbits_nwcprovider_ext_nostr_test || true
+          docker network rm lnbits_nwcprovider_ext_test_network || true

tests/integration/.env

@@ -199,7 +199,9 @@ LNBITS_HIDE_API=false
 
 # Extensions to be installed by default. If an extension from this list is uninstalled then it will be re-installed on the next restart.
 # The extension must be removed from this list in order to not be re-installed.
-LNBITS_EXTENSIONS_DEFAULT_INSTALL="tpos"
+# The tpos extension is no longer shipped with the LNbits dev tree. Keep the
+# integration fixture focused on the extension under test.
+LNBITS_EXTENSIONS_DEFAULT_INSTALL=""
 
 # Database: to use SQLite, specify LNBITS_DATA_FOLDER
 #           to use PostgreSQL, specify LNBITS_DATABASE_URL=postgres://...
@@ -249,4 +251,4 @@ LOG_ROTATION="100 MB"
 LOG_RETENTION="3 months"
 
 # for database cleanup commands
-# CLEANUP_WALLETS_DAYS=90
+# CLEANUP_WALLETS_DAYS=90

tests/integration/start.sh

@@ -28,6 +28,19 @@ ghcr.io/hoytech/strfry:latest
 rm -Rf lnbits_itest_data
 unzip data.zip
 
+# The fixture was created with the standalone tpos extension installed. tpos
+# is no longer part of the LNbits dev tree, so leaving its database metadata in
+# the fixture makes current LNbits attempt to import a module that is absent.
+# The integration suite only exercises nwcprovider.
+python3 - <<'PY'
+import sqlite3
+
+with sqlite3.connect("lnbits_itest_data/database.sqlite3") as conn:
+    conn.execute("DELETE FROM installed_extensions WHERE id = 'tpos'")
+    conn.execute("DELETE FROM dbversions WHERE db = 'tpos'")
+PY
+rm -f lnbits_itest_data/ext_tpos.sqlite3 lnbits_itest_data/zips/tpos.zip
+
 id=$(id -u)
 gid=$(id -g)
 
@@ -45,24 +58,50 @@ docker run --name=lnbits_nwcprovider_ext_lnbits_test \
 -v ${PWD}/../../.devcontainer/pre-setup.sh:/pre-setup.sh:ro \
 mcr.microsoft.com/devcontainers/python:1-3.12 bash -c "while true; do sleep 1000; done"
 
-docker network create lnbits_nwcprovider_ext_test_network || true
+if ! docker network inspect lnbits_nwcprovider_ext_test_network >/dev/null 2>&1; then
-docker network connect lnbits_nwcprovider_ext_test_network lnbits_nwcprovider_ext_nostr_test --alias nostr|| true
+    docker network create lnbits_nwcprovider_ext_test_network
-docker network connect lnbits_nwcprovider_ext_test_network lnbits_nwcprovider_ext_lnbits_test --alias lnbits|| true
+fi
+docker network connect lnbits_nwcprovider_ext_test_network lnbits_nwcprovider_ext_nostr_test --alias nostr
+docker network connect lnbits_nwcprovider_ext_test_network lnbits_nwcprovider_ext_lnbits_test --alias lnbits
 
 docker exec -u root lnbits_nwcprovider_ext_lnbits_test bash -c "id -u $id &>/dev/null || useradd -m -u $id tester"
 docker exec -u root lnbits_nwcprovider_ext_lnbits_test bash -c "bash /pre-setup.sh"
 docker exec --user $id:$gid lnbits_nwcprovider_ext_lnbits_test  bash -c "curl -sSL https://install.python-poetry.org | python3 -"
 
-set +e
 docker exec --user $id:$gid lnbits_nwcprovider_ext_lnbits_test bash -c "export PATH=\"\$HOME/.local/bin:\$PATH\" && bash /setup.sh /nwcprovider"
 docker exec --user $id:$gid lnbits_nwcprovider_ext_lnbits_test bash -c "ln -s /app/.env \$HOME/lnbits/.env"
 
 
-ARGS=""
 if [ "$HEADLESS" != "" ];
 then
-    ARGS="-d"
+    # Keep the server log inside the container so a failed health check can
-fi
+    # show the actual startup error instead of silently swallowing it.
+    docker exec --user $id:$gid -d lnbits_nwcprovider_ext_lnbits_test bash -c "export PATH=\"\$HOME/.local/bin:\$PATH\" && cd \$HOME/lnbits && poetry run lnbits > /tmp/lnbits.log 2>&1"
 
-docker exec --user $id:$gid $ARGS lnbits_nwcprovider_ext_lnbits_test bash -c "export PATH=\"\$HOME/.local/bin:\$PATH\" && cd \$HOME/lnbits && poetry run lnbits"
+    wait_for_http() {
- 
+        local service="$1"
+        local url="$2"
+        local timeout_seconds="$3"
+        local deadline=$((SECONDS + timeout_seconds))
+
+        until curl --fail --silent --show-error --max-time 2 "$url" >/dev/null 2>&1; do
+            if [ "$SECONDS" -ge "$deadline" ]; then
+                echo "Timed out waiting for $service at $url" >&2
+                docker ps -a >&2
+                if [ "$service" = "LNbits" ]; then
+                    docker exec lnbits_nwcprovider_ext_lnbits_test tail -n 100 /tmp/lnbits.log >&2 || true
+                else
+                    docker logs --tail 100 lnbits_nwcprovider_ext_nostr_test >&2 || true
+                fi
+                return 1
+            fi
+            sleep 1
+        done
+    }
+
+    # LNbits may need a few minutes for a fresh database migration.
+    wait_for_http "nostr relay" "http://localhost:7777" 180
+    wait_for_http "LNbits" "http://localhost:5002" 180
+else
+    docker exec --user $id:$gid lnbits_nwcprovider_ext_lnbits_test bash -c "export PATH=\"\$HOME/.local/bin:\$PATH\" && cd \$HOME/lnbits && poetry run lnbits"
+fi

tests/integration/test_all.py

@@ -12,6 +12,10 @@ from loguru import logger
 from pynostr.key import PrivateKey
 from websockets.legacy.client import connect
 
+SERVICE_STARTUP_TIMEOUT_SECONDS = 180
+NWC_CONNECTION_TIMEOUT_SECONDS = 60
+NWC_RESPONSE_TIMEOUT_SECONDS = 60
+
 wallets = {
     "wallet1": {
         "name": "wallet1",
@@ -41,35 +45,29 @@ wallets = {
 
 
 async def check_services():
-    # wait for http server in localhost:7777
+    async def wait_for_service(name: str, url: str):
-    while True:
+        deadline = time.monotonic() + SERVICE_STARTUP_TIMEOUT_SECONDS
         try:
             async with httpx.AsyncClient() as client:
-                resp = await client.get("http://localhost:7777")
+                while True:
-                assert resp.status_code == 200
+                    try:
-                break
+                        resp = await client.get(url)
-        except Exception:
+                        if resp.status_code == 200:
-            logger.info("Waiting for nostr relay @ http://localhost:7777")
+                            return
-            logger.info(
+                    except httpx.HTTPError:
-                """Please start the required services by running\
+                        pass
- `bash start.sh` if you haven't already"""
+                    if time.monotonic() >= deadline:
-            )
+                        raise RuntimeError(
-            await asyncio.sleep(1)
+                            f"Timed out waiting for {name} at {url}. "
+                            "Start the integration services with `bash start.sh`."
+                        )
+                    logger.info(f"Waiting for {name} @ {url}")
+                    await asyncio.sleep(1)
+        except httpx.HTTPError as exc:
+            raise RuntimeError(f"Unable to check {name} at {url}: {exc}") from exc
 
-    # wait lnbits @ localhost:5000
+    await wait_for_service("nostr relay", "http://localhost:7777")
-    while True:
+    await wait_for_service("LNbits", "http://localhost:5002")
-        try:
-            async with httpx.AsyncClient() as client:
-                resp = await client.get("http://localhost:5002")
-                assert resp.status_code == 200
-                break
-        except Exception:
-            logger.info("Waiting for lnbits @ http://localhost:5002")
-            logger.info(
-                """Please start the required services by running\
- `bash start.sh` if you haven't already"""
-            )
-            await asyncio.sleep(1)
 
 
 async def get_wallet_balance(w: str):
@@ -179,15 +177,21 @@ class NWCWallet:
 
     async def _wait_for_connection(self):
         while not self.connected:
-            try:
+            await asyncio.sleep(0.2)
-                await asyncio.sleep(0.2)
-            except asyncio.CancelledError:
-                logger.debug("Connection wait cancelled")
-                return
 
     async def start(self):
         self.task = asyncio.create_task(self._run())
-        await self._wait_for_connection()
+        try:
+            await asyncio.wait_for(
+                self._wait_for_connection(), timeout=NWC_CONNECTION_TIMEOUT_SECONDS
+            )
+        except asyncio.TimeoutError as exc:
+            self.task.cancel()
+            await asyncio.gather(self.task, return_exceptions=True)
+            self.task = None
+            raise RuntimeError(
+                f"Timed out connecting to NWC relay {self.relay}"
+            ) from exc
 
     def _is_shutting_down(self):
         return self.shutdown
@@ -304,7 +308,11 @@ class NWCWallet:
         await self.ws.send(self._json_dumps(["EVENT", event]))
 
     async def wait_for(
-        self, result_type, callback=None, on_error_callback=None, timeout=60000
+        self,
+        result_type,
+        callback=None,
+        on_error_callback=None,
+        timeout=NWC_RESPONSE_TIMEOUT_SECONDS,
     ):
         now = time.time()
         while True: