Add portal auth timing logs and payment error handling

public/engine.js

@@ -185,6 +185,13 @@
 
   // ── Auth with code ────────────────────────────────────────────────────────
   async function authorizeWithCode(code) {
+    if (!P.clientMac) {
+      purchaseInFlight = false;
+      showScreen('code');
+      showError('code-error', 'This page was opened outside the WiFi login flow. Reopen the hotspot portal on the device that is joining the WiFi.');
+      return;
+    }
+
     try {
       const res  = await fetch(`/portal/${P.siteId}/auth`, {
         method:  'POST',
@@ -264,6 +271,9 @@
       if (!code || code.length < 9) {
         return showError('code-error', 'Enter a valid 8-character code (XXXX-XXXX).');
       }
+      if (!P.clientMac) {
+        return showError('code-error', 'Open this portal from the WiFi login page on the device you want to connect.');
+      }
 
       codeSubmitBtn.disabled = true;
       codeSubmitBtn.textContent = 'Connecting...';

src/routes/devices.routes.js

@@ -785,7 +785,18 @@ router.post("/:id/renew", async (req, res) => {
         metadata: { reference, type: "device_renewal", device_id: String(device.id) },
       });
     } catch (payErr) {
-      console.error("[devices/renew] Snippe error:", payErr.message, payErr.response?.data);
+      const paymentError = snippe.extractPaymentError(payErr, "Could not start renewal payment");
+      console.error("[devices/renew] Snippe error:", paymentError.message, paymentError.raw);
+      await db.query(
+        `UPDATE device_payments
+         SET status = 'failed'
+         WHERE reference = ? AND status = 'pending'`,
+        [reference],
+      );
+      return res.status(paymentError.status).json({
+        error: paymentError.message,
+        code: paymentError.code,
+      });
     }
 
     res.json({

src/routes/portal.routes.js

@@ -35,6 +35,38 @@ function wait(ms) {
   return new Promise(resolve => setTimeout(resolve, ms));
 }
 
+async function failPortalPayment(reference) {
+  await db.query(
+    `UPDATE payments
+     SET status = 'failed'
+     WHERE reference = ? AND status = 'pending'`,
+    [reference]
+  );
+}
+
+function createAuthTrace({ siteId, mac, code }) {
+  const startedAt = Date.now();
+  let lastAt = startedAt;
+
+  return {
+    step(label, extra = null) {
+      const now = Date.now();
+      const stepMs = now - lastAt;
+      const totalMs = now - startedAt;
+      lastAt = now;
+
+      if (extra !== null) {
+        console.log(`[portal/auth] step=${label} stepMs=${stepMs} totalMs=${totalMs} site=${siteId} mac=${mac} code=${code}`, extra);
+      } else {
+        console.log(`[portal/auth] step=${label} stepMs=${stepMs} totalMs=${totalMs} site=${siteId} mac=${mac} code=${code}`);
+      }
+    },
+    total() {
+      return Date.now() - startedAt;
+    },
+  };
+}
+
 function tokenRateLimitOptions(token) {
   return {
     downLimit: token.down_limit,
@@ -314,8 +346,13 @@ router.post('/:siteId/purchase', purchaseLimiter, async (req, res) => {
         },
       });
     } catch (payErr) {
-      console.error('[portal/purchase] Snippe error:', payErr.message, payErr.response?.data);
-      // Don't fail — webhook will confirm; guest can poll
+      const paymentError = snippe.extractPaymentError(payErr, 'Could not start payment');
+      console.error('[portal/purchase] Snippe error:', paymentError.message, paymentError.raw);
+      await failPortalPayment(reference);
+      return res.status(paymentError.status).json({
+        error: paymentError.message,
+        code: paymentError.code,
+      });
     }
 
     res.json({ reference, status: 'pending' });
@@ -368,46 +405,72 @@ router.post('/:siteId/auth', portalAuthLimiter, async (req, res) => {
   }
 
   const mac = clientMac.toUpperCase().replace(/:/g, '-');
+  const normalizedCode = code.toUpperCase();
+  const trace = createAuthTrace({ siteId, mac, code: normalizedCode });
 
   try {
+    trace.step('request_received');
+
     const token = await db.query(
       `SELECT t.*, d.omada_site_id
        FROM access_tokens t
        JOIN devices d ON d.id = t.device_id
        WHERE t.code = ? AND d.omada_site_id = ? LIMIT 1`,
-      [code.toUpperCase(), siteId]
+      [normalizedCode, siteId]
     ).then(r => r[0]);
-
-    if (!token) return res.status(404).json({ error: 'Invalid code' });
+    trace.step('token_lookup_complete', token ? {
+      tokenId: token.id,
+      tokenStatus: token.status,
+      lockedMac: token.locked_mac,
+      expiresAt: token.expires_at,
+    } : { tokenFound: false });
+
+    if (!token) {
+      trace.step('token_not_found');
+      return res.status(404).json({ error: 'Invalid code' });
+    }
 
     if (token.status === 'expired' || token.status === 'revoked') {
+      trace.step('token_rejected_terminal_status', { tokenStatus: token.status });
       return res.status(410).json({ error: 'Code has expired' });
     }
 
     if (token.status === 'active') {
-      // Reconnect — verify same MAC
+      trace.step('active_token_validation_start');
+
       if (token.locked_mac && token.locked_mac.toUpperCase() !== mac) {
+        trace.step('token_rejected_locked_mac', { lockedMac: token.locked_mac });
         return res.status(403).json({ error: 'Code is locked to another device' });
       }
-      // Check not expired
+
       if (token.expires_at && new Date(token.expires_at) < new Date()) {
         await db.query(`UPDATE access_tokens SET status = 'expired' WHERE id = ?`, [token.id]);
+        trace.step('token_marked_expired');
         return res.status(410).json({ error: 'Code has expired' });
       }
+
+      trace.step('active_token_validation_complete');
     }
 
     if (token.status !== 'unused' && token.status !== 'active') {
+      trace.step('token_rejected_invalid_state', { tokenStatus: token.status });
       return res.status(400).json({ error: 'Code cannot be used' });
     }
+    trace.step('token_validation_complete');
 
-    // Authorize on Omada. Rate-limit updates are applied after success so they do
-    // not keep guests waiting on a slower client PATCH call.
     try {
+      trace.step('omada_authorize_start');
       await omada.authorizeClient(siteId, mac);
+      trace.step('omada_authorize_complete');
     } catch (omadaErr) {
-      console.error('[portal/auth] Omada auth failed:', omadaErr.message);
+      console.error('[portal/auth] Omada auth failed:', omadaErr.message, {
+        siteId,
+        mac,
+        code: normalizedCode,
+        totalMs: trace.total(),
+      });
       alertAdmin(
-        `portal-auth:${siteId}:${mac}:${code.toUpperCase()}:omada`,
+        `portal-auth:${siteId}:${mac}:${normalizedCode}:omada`,
         formatPortalAuthAlert({
           deviceName: token.name || token.device_name,
           siteId,
@@ -420,10 +483,11 @@ router.post('/:siteId/auth', portalAuthLimiter, async (req, res) => {
     }
 
     applyRateLimitLater(siteId, mac, token);
+    trace.step('rate_limit_worker_dispatched');
 
-    // Activate unused token once; active tokens keep their existing expiry window.
     const now = new Date();
     let expiresAt = token.expires_at ? new Date(token.expires_at) : null;
+    trace.step('expiry_window_prepared', { existingExpiresAt: token.expires_at });
 
     if (token.status === 'unused') {
       expiresAt = new Date(now.getTime() + token.duration_seconds * 1000);
@@ -437,19 +501,21 @@ router.post('/:siteId/auth', portalAuthLimiter, async (req, res) => {
          WHERE id = ?`,
         [mac, now, expiresAt, token.id]
       );
+      trace.step('token_activated', { expiresAt: expiresAt.toISOString() });
     } else if (!expiresAt) {
       expiresAt = new Date(now.getTime() + token.duration_seconds * 1000);
       await db.query(
         `UPDATE access_tokens SET expires_at = ? WHERE id = ?`,
         [expiresAt, token.id]
       );
+      trace.step('token_expiry_backfilled', { expiresAt: expiresAt.toISOString() });
     }
 
-    // Start or refresh an active session immediately when the device is online.
     const activeSession = await db.query(
       'SELECT id FROM sessions WHERE access_token_id = ? AND client_mac = ? AND is_active = 1 LIMIT 1',
       [token.id, mac]
     ).then(r => r[0]);
+    trace.step('session_lookup_complete', activeSession ? { sessionId: activeSession.id } : { sessionFound: false });
 
     if (activeSession) {
       await db.query(
@@ -458,16 +524,19 @@ router.post('/:siteId/auth', portalAuthLimiter, async (req, res) => {
          WHERE id = ?`,
         [activeSession.id]
       );
+      trace.step('session_refreshed', { sessionId: activeSession.id });
     } else {
       await db.query(
         `INSERT INTO sessions (access_token_id, client_id, device_id, client_mac, started_at, last_seen_at, is_active)
          VALUES (?, ?, ?, ?, NOW(), NOW(), 1)`,
         [token.id, token.client_id, token.device_id, mac]
       );
+      trace.step('session_created');
     }
 
     const unitLabel = (v, u) => `${v}${u === 2 ? 'Mbps' : 'Kbps'}`;
     const secsLeft  = Math.floor((expiresAt - now) / 1000);
+    trace.step('response_ready', { secsLeft, expiresAt: expiresAt.toISOString() });
 
     res.json({
       success:    true,
@@ -477,15 +546,21 @@ router.post('/:siteId/auth', portalAuthLimiter, async (req, res) => {
       speedDown:  unitLabel(token.down_limit, token.down_unit),
       speedUp:    unitLabel(token.up_limit,   token.up_unit),
     });
+    trace.step('response_sent');
   } catch (err) {
-    console.error('[portal/auth]', err.message);
+    console.error('[portal/auth]', err.message, {
+      siteId,
+      mac,
+      code: normalizedCode,
+      totalMs: trace.total(),
+    });
     alertAdmin(
-      `portal-auth:${siteId}:${mac}:${code.toUpperCase()}:fatal`,
+      `portal-auth:${siteId}:${mac}:${normalizedCode}:fatal`,
       formatPortalAuthAlert({
         deviceName: null,
         siteId,
         mac,
-        code: String(code || '').toUpperCase(),
+        code: normalizedCode,
         error: err.message || 'Authorization failed',
       })
     ).catch(() => {});

src/services/snippe.js

@@ -53,6 +53,19 @@ async function createPayment({ reference, amount, phone, webhookUrl, metadata =
   }, ikey('pay', reference));
 }
 
+function extractPaymentError(err, fallbackMessage = 'Payment request failed') {
+  const data = err?.response?.data || {};
+  const message = data.message || err?.message || fallbackMessage;
+
+  return {
+    status: err?.response?.status || 500,
+    code: data.error_code || null,
+    message,
+    retryable: !(err?.response?.status >= 400 && err?.response?.status < 500),
+    raw: data,
+  };
+}
+
 async function getPayment(reference) {
   return snippeRequest('GET', `/v1/payments/${reference}`);
 }
@@ -103,6 +116,7 @@ function verifyWebhookSignature(rawBody, headers) {
 
 module.exports = {
   createPayment,
+  extractPaymentError,
   getPayment,
   getPayoutFee,
   createPayout,