Add webhook evaluation logging with optional DEBUG mode

Log partial-payment decisions and email results to stdout for Portainer
logs; DEBUG enables full webhook payload tracing. Document BTCPay payload
and shutdown steps in WEBHOOK.md.

Co-authored-by: Cursor <cursoragent@cursor.com>

.env.example

@@ -17,6 +17,7 @@ POSTMARK_API_KEY=your_postmark_server_token
 BTCPAY_URL=https://payment.nxtgroup.org
 FROM_EMAIL=billing@nxtgroup.org
 BCC_EMAIL=admin@nxtgroup.org,finance@nxtgroup.org
+DEBUG=false
 
 # Test Postmark after deploy (docker exec or Portainer console):
 #   python app.py test-email you@example.com

WEBHOOK.md

@@ -0,0 +1,90 @@
+# BTCPay webhook reference
+
+## Endpoint
+
+```
+POST https://mailer.nxtgroup.org/btcpay-webhook?token=YOUR_WEBHOOK_SECRET
+```
+
+Auth is the `token` query parameter (must match `WEBHOOK_SECRET`). BTCPay’s optional webhook signing secret is not used by this app.
+
+## Disable quickly
+
+1. **BTCPay** → Store → Settings → **Webhooks** → delete or disable the webhook.
+2. **Portainer** → Stacks → `btcpaymailer` → stop/remove the stack.
+
+No emails are sent while the webhook is disabled or the stack is down.
+
+## Event subscribed
+
+Only **`InvoiceReceivedPayment`** is processed. All other event types return `200` with `"ignored"` and are silent unless `DEBUG=true`.
+
+## Webhook body (BTCPay → mailer)
+
+Typical payload:
+
+```json
+{
+  "deliveryId": "abc123",
+  "webhookId": "wh_xyz",
+  "originalDeliveryId": "abc123",
+  "isRedelivery": false,
+  "type": "InvoiceReceivedPayment",
+  "timestamp": 1717843200,
+  "storeId": "your-store-id",
+  "invoiceId": "invoice-id-here"
+}
+```
+
+Fields used by this app from the webhook:
+
+| Field | Use |
+|-------|-----|
+| `type` | Must be `InvoiceReceivedPayment` |
+| `storeId` | Fetch invoice from BTCPay API |
+| `invoiceId` | Fetch invoice from BTCPay API |
+
+The webhook does **not** include full payment amounts or buyer email. The app calls:
+
+```
+GET {BTCPAY_URL}/api/v1/stores/{storeId}/invoices/{invoiceId}
+```
+
+## Invoice fields used (BTCPay API response)
+
+| Field | Use |
+|-------|-----|
+| `amount` | Invoice total |
+| `amountPaid` | Paid so far |
+| `currency` | e.g. `USD`, `BTC` |
+| `status` | Must be `New` for partial-payment email |
+| `metadata.buyerEmail` | Recipient (required to send) |
+| `metadata.orderId` | Shown in email subject/body |
+
+## Send conditions (all must pass)
+
+1. `type == InvoiceReceivedPayment`
+2. BTCPay API returns invoice successfully
+3. `status == "New"`
+4. `0 < amountPaid < amount` (partial payment, not zero or full)
+5. `metadata.buyerEmail` is set
+
+Otherwise the handler returns `200` with `"ignored"` or `400` if buyer email is missing on a qualifying partial payment.
+
+## Logging
+
+| `DEBUG` | What appears in container logs |
+|---------|------------------------------|
+| `false` (default) | Evaluation + send result for `InvoiceReceivedPayment` only |
+| `true` | Every webhook, full payload, each decision step |
+
+View logs in **Portainer → Containers → btcpay-mailer → Logs**.
+
+## Response codes
+
+| Code | Meaning |
+|------|---------|
+| `401` | Wrong or missing `token` |
+| `400` | Partial payment but no `buyerEmail` |
+| `500` | BTCPay API or Postmark failure |
+| `200` | Ignored, or email sent successfully |

app.py

@@ -1,17 +1,40 @@
+import json
+import logging
 import os
+import sys
+
 import requests
 from flask import Flask, request, jsonify
 
 app = Flask(__name__)
 
 # --- Configuration ---
-# Ensure these are passed as environment variables
 WEBHOOK_SECRET = os.getenv("WEBHOOK_SECRET", "your_secret_token_here")
 BTCPAY_URL = os.getenv("BTCPAY_URL", "https://payment.nxtgroup.org")
-BTCPAY_API_KEY = os.getenv("BTCPAY_API_KEY") # Needs 'btcpay.store.canviewinvoices' permission
+BTCPAY_API_KEY = os.getenv("BTCPAY_API_KEY")
 POSTMARK_API_KEY = os.getenv("POSTMARK_API_KEY")
 FROM_EMAIL = os.getenv("FROM_EMAIL", "billing@nxtgroup.org")
 BCC_EMAIL = os.getenv("BCC_EMAIL", "admin@nxtgroup.org")
+DEBUG = os.getenv("DEBUG", "false").lower() in ("true", "1", "yes")
+
+logger = logging.getLogger("btcpaymailer")
+logger.setLevel(logging.DEBUG if DEBUG else logging.INFO)
+if not logger.handlers:
+    _handler = logging.StreamHandler(sys.stdout)
+    _handler.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] %(message)s"))
+    logger.addHandler(_handler)
+
+
+def log_debug(message, **fields):
+    if DEBUG:
+        suffix = f" | {json.dumps(fields, default=str)}" if fields else ""
+        logger.debug(f"{message}{suffix}")
+
+
+def log_evaluation(message, **fields):
+    suffix = f" | {json.dumps(fields, default=str)}" if fields else ""
+    logger.info(f"[evaluation] {message}{suffix}")
+
 
 def get_html_template(order_id, invoice_id, amount, currency, amount_paid, remaining):
     return f"""
@@ -57,6 +80,7 @@ def get_html_template(order_id, invoice_id, amount, currency, amount_paid, remai
     </div>
     """
 
+
 def send_postmark_email(to_email, subject, html_body):
     if not POSTMARK_API_KEY:
         return {"ok": False, "status_code": None, "error": "POSTMARK_API_KEY is not set"}
@@ -87,58 +111,136 @@ def send_test_email(to_email):
     subject = "BTCPay Mailer test email"
     return send_postmark_email(to_email, subject, html_body)
 
-@app.route('/btcpay-webhook', methods=['POST'])
-def btcpay_webhook():
-    # 1. Verify Secret Token
-    token = request.args.get('token')
-    if token != WEBHOOK_SECRET:
-        return jsonify({"error": "Unauthorized"}), 401
-
-    data = request.json
-    
-    # 2. Only process 'InvoiceReceivedPayment' events
-    if data.get('type') != 'InvoiceReceivedPayment':
-        return jsonify({"status": "ignored", "reason": "Not a payment event"}), 200
-
-    store_id = data.get('storeId')
-    invoice_id = data.get('invoiceId')
-
-    # 3. Fetch full invoice details from BTCPay API
-    headers = {"Authorization": f"token {BTCPAY_API_KEY}"}
-    invoice_resp = requests.get(f"{BTCPAY_URL}/api/v1/stores/{store_id}/invoices/{invoice_id}", headers=headers)
-    
-    if invoice_resp.status_code != 200:
-        return jsonify({"error": "Failed to fetch invoice"}), 500
-        
-    invoice_data = invoice_resp.json()
 
+def evaluate_partial_payment(invoice_data, invoice_id):
     amount = float(invoice_data.get('amount', 0))
     amount_paid = float(invoice_data.get('amountPaid', 0))
     currency = invoice_data.get('currency', '')
     status = invoice_data.get('status', '')
     metadata = invoice_data.get('metadata', {})
-    
     buyer_email = metadata.get('buyerEmail')
     order_id = metadata.get('orderId', invoice_id)
 
-    # 4. Check if it's a partial payment on an active invoice
+    is_new = status == 'New'
-    if status == 'New' and 0 < amount_paid < amount:
+    is_partial = 0 < amount_paid < amount
+    qualifies = is_new and is_partial
+
+    evaluation = {
+        "invoice_id": invoice_id,
+        "order_id": order_id,
+        "status": status,
+        "amount": amount,
+        "amount_paid": amount_paid,
+        "currency": currency,
+        "remaining": round(amount - amount_paid, 8) if amount_paid < amount else 0,
+        "checks": {
+            "status_is_new": is_new,
+            "amount_paid_gt_zero": amount_paid > 0,
+            "amount_paid_lt_total": amount_paid < amount,
+            "is_partial_payment": is_partial,
+            "qualifies_for_email": qualifies,
+            "has_buyer_email": bool(buyer_email),
+        },
+        "buyer_email": buyer_email,
+    }
+
+    log_evaluation("invoice evaluated", **evaluation)
+
+    if not qualifies:
+        reason = []
+        if not is_new:
+            reason.append(f"status is '{status}', expected 'New'")
+        if amount_paid <= 0:
+            reason.append("no payment received yet")
+        if amount_paid >= amount:
+            reason.append("payment meets or exceeds total")
+        log_evaluation("no email sent", decision="ignored", reasons=reason)
+        return None, evaluation
+
     if not buyer_email:
+        log_evaluation("no email sent", decision="rejected", reason="missing metadata.buyerEmail")
+        return "missing_email", evaluation
+
+    return "send", evaluation
+
+
+@app.route('/btcpay-webhook', methods=['POST'])
+def btcpay_webhook():
+    data = request.json or {}
+    event_type = data.get('type')
+
+    log_debug(
+        "webhook received",
+        event_type=event_type,
+        store_id=data.get('storeId'),
+        invoice_id=data.get('invoiceId'),
+        delivery_id=data.get('deliveryId'),
+        is_redelivery=data.get('isRedelivery'),
+        payload=data,
+    )
+
+    token = request.args.get('token')
+    if token != WEBHOOK_SECRET:
+        log_debug("webhook rejected", reason="invalid token")
+        return jsonify({"error": "Unauthorized"}), 401
+
+    if event_type != 'InvoiceReceivedPayment':
+        log_debug("webhook ignored", reason="not InvoiceReceivedPayment", event_type=event_type)
+        return jsonify({"status": "ignored", "reason": "Not a payment event"}), 200
+
+    store_id = data.get('storeId')
+    invoice_id = data.get('invoiceId')
+
+    log_debug("fetching invoice from BTCPay", store_id=store_id, invoice_id=invoice_id)
+
+    headers = {"Authorization": f"token {BTCPAY_API_KEY}"}
+    invoice_resp = requests.get(
+        f"{BTCPAY_URL}/api/v1/stores/{store_id}/invoices/{invoice_id}",
+        headers=headers,
+    )
+
+    if invoice_resp.status_code != 200:
+        logger.error(
+            "BTCPay API error | %s",
+            json.dumps({
+                "store_id": store_id,
+                "invoice_id": invoice_id,
+                "status_code": invoice_resp.status_code,
+                "body": invoice_resp.text,
+            }),
+        )
+        return jsonify({"error": "Failed to fetch invoice"}), 500
+
+    invoice_data = invoice_resp.json()
+    log_debug("invoice fetched", invoice_id=invoice_id, status=invoice_data.get('status'))
+
+    action, evaluation = evaluate_partial_payment(invoice_data, invoice_id)
+
+    if action is None:
+        return jsonify({"status": "ignored", "reason": "Payment meets total or invoice not in New state"}), 200
+
+    if action == "missing_email":
         return jsonify({"error": "No buyer email associated with invoice"}), 400
 
-        remaining = round(amount - amount_paid, 8)
+    buyer_email = evaluation["buyer_email"]
+    order_id = evaluation["order_id"]
+    remaining = evaluation["remaining"]
+    amount = evaluation["amount"]
+    amount_paid = evaluation["amount_paid"]
+    currency = evaluation["currency"]
 
-        # Generate HTML and Send Email
     html_body = get_html_template(order_id, invoice_id, amount, currency, amount_paid, remaining)
     subject = f"Action Required: Partial payment received for Order #{order_id}"
 
+    log_evaluation("sending email", to=buyer_email, order_id=order_id, bcc=BCC_EMAIL)
     result = send_postmark_email(buyer_email, subject, html_body)
 
     if result["ok"]:
+        log_evaluation("email sent", to=buyer_email, order_id=order_id, postmark_status=result["status_code"])
         return jsonify({"status": "success", "message": "Partial payment email sent"}), 200
-        return jsonify({"error": "Failed to send email via Postmark", "details": result}), 500
 
-    return jsonify({"status": "ignored", "reason": "Payment meets total or invoice not in New state"}), 200
+    log_evaluation("email failed", to=buyer_email, order_id=order_id, postmark_result=result)
+    return jsonify({"error": "Failed to send email via Postmark", "details": result}), 500
 
 
 @app.route('/test-email', methods=['POST'])
@@ -153,18 +255,18 @@ def test_email():
 
     result = send_test_email(to_email)
     if result["ok"]:
+        logger.info("test email sent | %s", json.dumps({"to": to_email, "from": FROM_EMAIL, "bcc": BCC_EMAIL}))
         return jsonify({
             "status": "success",
             "message": f"Test email sent to {to_email}",
             "from": FROM_EMAIL,
             "bcc": BCC_EMAIL,
         }), 200
+    logger.error("test email failed | %s", json.dumps({"to": to_email, "result": result}))
     return jsonify({"error": "Failed to send test email via Postmark", "details": result}), 500
 
 
 if __name__ == '__main__':
-    import sys
-
     if len(sys.argv) >= 3 and sys.argv[1] == 'test-email':
         to = sys.argv[2]
         outcome = send_test_email(to)

docker-compose.yml

@@ -14,3 +14,4 @@ services:
       POSTMARK_API_KEY: ${POSTMARK_API_KEY:?Set POSTMARK_API_KEY in .env or environment}
       FROM_EMAIL: ${FROM_EMAIL:-billing@nxtgroup.org}
       BCC_EMAIL: ${BCC_EMAIL:-admin@nxtgroup.org}
+      DEBUG: ${DEBUG:-false}