test: fix flaky regtest (#2616)

* add log for invoice success
* add internal flag
* sleeping inside the tasks to not block
* sleep was wrong decrease wait time

Makefile

@@ -39,24 +39,28 @@ dev:
 	poetry run lnbits --reload
 
 test-wallets:
+	LNBITS_DATA_FOLDER="./tests/data" \
 	LNBITS_BACKEND_WALLET_CLASS="FakeWallet" \
 	PYTHONUNBUFFERED=1 \
 	DEBUG=true \
 	poetry run pytest tests/wallets
 
 test-unit:
+	LNBITS_DATA_FOLDER="./tests/data" \
 	LNBITS_BACKEND_WALLET_CLASS="FakeWallet" \
 	PYTHONUNBUFFERED=1 \
 	DEBUG=true \
 	poetry run pytest tests/unit
 
 test-api:
+	LNBITS_DATA_FOLDER="./tests/data" \
 	LNBITS_BACKEND_WALLET_CLASS="FakeWallet" \
 	PYTHONUNBUFFERED=1 \
 	DEBUG=true \
 	poetry run pytest tests/api
 
 test-regtest:
+	LNBITS_DATA_FOLDER="./tests/data" \
 	PYTHONUNBUFFERED=1 \
 	DEBUG=true \
 	poetry run pytest tests/regtest

lnbits/core/services.py

@@ -365,7 +365,7 @@ async def pay_invoice(
                 )
                 if wallet and updated:
                     await send_payment_notification(wallet, updated)
-                logger.debug(f"payment successful {payment.checking_id}")
+                logger.success(f"payment successful {payment.checking_id}")
         elif payment.checking_id is None and payment.ok is False:
             # payment failed
             logger.debug(f"payment failed {temp_id}, {payment.error_message}")

lnbits/exceptions.py

@@ -90,7 +90,7 @@ def register_http_exception_handler(app: FastAPI):
 def register_payment_error_handler(app: FastAPI):
     @app.exception_handler(PaymentError)
     async def payment_error_handler(request: Request, exc: PaymentError):
-        logger.error(f"PaymentError: {exc.message}, {exc.status}")
+        logger.error(f"{exc.message}, {exc.status}")
         return JSONResponse(
             status_code=520,
             content={"detail": exc.message, "status": exc.status},
@@ -100,7 +100,7 @@ def register_payment_error_handler(app: FastAPI):
 def register_invoice_error_handler(app: FastAPI):
     @app.exception_handler(InvoiceError)
     async def invoice_error_handler(request: Request, exc: InvoiceError):
-        logger.error(f"InvoiceError: {exc.message}, Status: {exc.status}")
+        logger.error(f"{exc.message}, Status: {exc.status}")
         return JSONResponse(
             status_code=520,
             content={"detail": exc.message, "status": exc.status},

lnbits/tasks.py

@@ -110,8 +110,8 @@ async def internal_invoice_listener():
     """
     while settings.lnbits_running:
         checking_id = await internal_invoice_queue.get()
-        logger.info("> got internal payment notification", checking_id)
+        logger.info(f"got an internal payment notification {checking_id}")
-        create_task(invoice_callback_dispatcher(checking_id))
+        create_task(invoice_callback_dispatcher(checking_id, is_internal=True))
 
 
 async def invoice_listener():
@@ -123,7 +123,7 @@ async def invoice_listener():
     """
     funding_source = get_funding_source()
     async for checking_id in funding_source.paid_invoices_stream():
-        logger.info("> got a payment notification", checking_id)
+        logger.info(f"got a payment notification {checking_id}")
         create_task(invoice_callback_dispatcher(checking_id))
 
 
@@ -171,16 +171,13 @@ async def check_pending_payments():
         await asyncio.sleep(60 * 30)  # every 30 minutes
 
 
-async def invoice_callback_dispatcher(checking_id: str):
+async def invoice_callback_dispatcher(checking_id: str, is_internal: bool = False):
     """
     Takes an incoming payment, checks its status, and dispatches it to
     invoice_listeners from core and extensions.
     """
     payment = await get_standalone_payment(checking_id, incoming=True)
     if payment and payment.is_in:
-        logger.trace(
-            f"invoice listeners: sending invoice callback for payment {checking_id}"
-        )
         status = await payment.check_status()
         await update_payment_details(
             checking_id=payment.checking_id,
@@ -188,6 +185,8 @@ async def invoice_callback_dispatcher(checking_id: str):
             preimage=status.preimage,
             status=PaymentState.SUCCESS,
         )
+        internal = "internal" if is_internal else ""
+        logger.success(f"{internal} invoice {checking_id} settled")
         for name, send_chan in invoice_listeners.items():
             logger.trace(f"invoice listeners: sending to `{name}`")
             await send_chan.put(payment)

tests/regtest/test_real_invoice.py

@@ -80,19 +80,22 @@ async def test_create_real_invoice(client, adminkey_headers_from, inkey_headers_
     assert not payment_status["paid"]
 
     async def listen():
-        found_checking_id = False
         async for checking_id in get_funding_source().paid_invoices_stream():
             if checking_id == invoice["checking_id"]:
-                found_checking_id = True
+                # wait for the backend to update the payment status
-                return
+                await asyncio.sleep(1)
-        assert found_checking_id
+                return checking_id
 
     async def pay():
-        await asyncio.sleep(3)
+        # wait a sec to paid_invoices_stream to start listening
+        await asyncio.sleep(1)
         pay_real_invoice(invoice["payment_request"])
+        return True
+
+    checking_id, paid = await asyncio.gather(listen(), pay())
+    assert paid
+    assert checking_id == invoice["payment_hash"]
 
-    await asyncio.gather(listen(), pay())
-    await asyncio.sleep(3)
     response = await client.get(
         f'/api/v1/payments/{invoice["payment_hash"]}', headers=inkey_headers_from
     )
@@ -296,22 +299,26 @@ async def test_receive_real_invoice_set_pending_and_check_state(
     assert not payment_status["paid"]
 
     async def listen():
-        found_checking_id = False
         async for checking_id in get_funding_source().paid_invoices_stream():
             if checking_id == invoice["checking_id"]:
-                found_checking_id = True
+                # wait for the backend to update the payment status
-                return
+                await asyncio.sleep(1)
-        assert found_checking_id
+                return checking_id
 
     async def pay():
-        await asyncio.sleep(3)
+        # wait a sec to paid_invoices_stream to start listening
+        await asyncio.sleep(1)
         pay_real_invoice(invoice["payment_request"])
+        return True
+
+    checking_id, paid = await asyncio.gather(listen(), pay())
+    assert paid
+    assert checking_id == invoice["payment_hash"]
 
-    await asyncio.gather(listen(), pay())
-    await asyncio.sleep(3)
     response = await client.get(
         f'/api/v1/payments/{invoice["payment_hash"]}', headers=inkey_headers_from
     )
+    assert response.status_code < 300
     payment_status = response.json()
     assert payment_status["paid"]