From ffba71c0cebed341ab4eba06f81debb61a3caac2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?dni=20=E2=9A=A1?= Date: Wed, 31 Jul 2024 11:41:19 +0200 Subject: [PATCH] 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 | 4 ++++ lnbits/core/services.py | 2 +- lnbits/exceptions.py | 4 ++-- lnbits/tasks.py | 13 +++++------ tests/regtest/test_real_invoice.py | 35 ++++++++++++++++++------------ 5 files changed, 34 insertions(+), 24 deletions(-) diff --git a/Makefile b/Makefile index 7bb79ce70..1bcc0c9c2 100644 --- a/Makefile +++ b/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 diff --git a/lnbits/core/services.py b/lnbits/core/services.py index eca515ab3..d24bb443b 100644 --- a/lnbits/core/services.py +++ b/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}") diff --git a/lnbits/exceptions.py b/lnbits/exceptions.py index 8d728e6e3..216d52212 100644 --- a/lnbits/exceptions.py +++ b/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}, diff --git a/lnbits/tasks.py b/lnbits/tasks.py index cbeb1f65b..9e8dcce8a 100644 --- a/lnbits/tasks.py +++ b/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) - create_task(invoice_callback_dispatcher(checking_id)) + logger.info(f"got an internal payment notification {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) diff --git a/tests/regtest/test_real_invoice.py b/tests/regtest/test_real_invoice.py index acf0e8f9a..1980b7799 100644 --- a/tests/regtest/test_real_invoice.py +++ b/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 - return - assert found_checking_id + # wait for the backend to update the payment status + await asyncio.sleep(1) + 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 - return - assert found_checking_id + # wait for the backend to update the payment status + await asyncio.sleep(1) + 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"]