chore(logging): normalize wakeup flow observability with timings and summaries

Standardize console prefixes across scheduler, push, refresh, register,
auth, and debug endpoints. Add pass-level scheduler summaries, elapsed-time
logs, and masked-token-only push failure messages while reducing per-device
noise in scheduler loops.

src/middleware/auth.ts

@@ -50,8 +50,8 @@ export async function requireAuth(
       const errorTime = new Date().toISOString();
       console.log("[Auth] Authentication failed");
       console.error(
-        errorTime,
+        "[Auth] Invalid JWT at",
-        "Got invalid JWT in Authorization header:",
+        errorTime + ":",
         verified
       );
       res.status(401).json({
@@ -72,7 +72,11 @@ export async function requireAuth(
   } catch (err) {
     const errorTime = new Date().toISOString();
     console.log("[Auth] Authentication failed");
-    console.error(errorTime, "Got invalid JWT in Authorization header:", err);
+    console.error(
+      "[Auth] Invalid JWT at",
+      errorTime + ":",
+      err
+    );
     res.status(401).json({
       success: false,
       message:

src/routes/debug.ts

@@ -5,6 +5,7 @@ import {
   computeNextEligibleAt,
   sendPushToDevice,
 } from "../services/pushService.js";
+import { formatElapsedMs } from "../util/formatElapsed.js";
 import { maskToken } from "../util/maskToken.js";
 
 // TODO: Protect this endpoint before production deployment
@@ -47,6 +48,7 @@ function sendWakeupFailureReason(
 
 // TODO: Protect this endpoint before production deployment
 debugRouter.get("/device/:token", async (req, res) => {
+  const started = Date.now();
   const userId = req.did;
   if (userId === undefined) {
     res.status(401).json({ success: false, message: "Unauthorized" });
@@ -54,25 +56,33 @@ debugRouter.get("/device/:token", async (req, res) => {
   }
 
   const fcmToken = decodeURIComponent(req.params.token);
+  const suffix = maskToken(fcmToken);
+  console.log("[DebugEndpoint] Device lookup request, token suffix:", suffix);
+
   const row = await db.resolveOwnedDevice(userId, { fcmToken });
   if (row === undefined) {
     console.log(
-      "[DebugEndpoint] Device lookup not found for user, token suffix:",
+      "[DebugEndpoint] Device lookup not found in",
-      maskToken(fcmToken)
+      formatElapsedMs(Date.now() - started) + ",",
+      "token suffix:",
+      suffix
     );
     res.status(404).json({ error: "Device not found" });
     return;
   }
 
-  console.log(
-    "[DebugEndpoint] Device lookup for user, token suffix:",
-    maskToken(fcmToken)
-  );
   res.json(deviceDebugPayload(row));
+  console.log(
+    "[DebugEndpoint] Device lookup completed in",
+    formatElapsedMs(Date.now() - started) + ",",
+    "token suffix:",
+    suffix
+  );
 });
 
 // TODO: Protect this endpoint before production deployment
 debugRouter.post("/send-wakeup", async (req, res) => {
+  const started = Date.now();
   const userId = req.did;
   if (userId === undefined) {
     res.status(401).json({ success: false, message: "Unauthorized" });
@@ -81,6 +91,11 @@ debugRouter.post("/send-wakeup", async (req, res) => {
 
   const { fcmToken } = req.body as { fcmToken?: unknown };
   if (typeof fcmToken !== "string" || fcmToken.length === 0) {
+    console.log(
+      "[DebugEndpoint] Send-wakeup rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "fcmToken is required"
+    );
     res.status(400).json({
       success: false,
       failureReason: "fcmToken is required",
@@ -88,38 +103,41 @@ debugRouter.post("/send-wakeup", async (req, res) => {
     return;
   }
 
+  const suffix = maskToken(fcmToken);
+  console.log("[DebugEndpoint] Send-wakeup request, token suffix:", suffix);
+
   const row = await db.resolveOwnedDevice(userId, { fcmToken });
   if (row === undefined) {
     console.log(
-      "[DebugEndpoint] Send-wakeup rejected, token suffix:",
+      "[DebugEndpoint] Send-wakeup rejected in",
-      maskToken(fcmToken)
+      formatElapsedMs(Date.now() - started) + ",",
+      "token suffix:",
+      suffix + ",",
+      "reason: Device not found"
     );
     res.status(404).json({
       success: false,
       failureReason: "Device not found",
-      fcmTokenSuffix: maskToken(fcmToken),
+      fcmTokenSuffix: suffix,
     });
     return;
   }
 
-  console.log(
-    "[DebugEndpoint] Send-wakeup for token suffix:",
-    maskToken(fcmToken)
-  );
   const result = await sendPushToDevice(fcmToken);
   const success = result === "sent";
   const failureReason = sendWakeupFailureReason(result);
 
-  console.log(
-    "[DebugEndpoint] Send-wakeup result:",
-    success ? "success" : result,
-    "token suffix:",
-    maskToken(fcmToken)
-  );
-
   res.json({
     success,
     ...(failureReason !== undefined ? { failureReason } : {}),
-    fcmTokenSuffix: maskToken(fcmToken),
+    fcmTokenSuffix: suffix,
   });
+
+  console.log(
+    "[DebugEndpoint] Send-wakeup completed in",
+    formatElapsedMs(Date.now() - started) + ",",
+    success ? "success" : result + ",",
+    "token suffix:",
+    suffix
+  );
 });

src/routes/notifications.ts

@@ -1,6 +1,7 @@
 import { Router } from "express";
 import { db } from "../db/fcmTokens.js";
 import { requireAuth } from "../middleware/auth.js";
+import { errorMessage, formatElapsedMs } from "../util/formatElapsed.js";
 import { maskToken } from "../util/maskToken.js";
 
 export const notificationsRouter = Router();
@@ -10,6 +11,7 @@ notificationsRouter.get("/", (_req, res) => {
 });
 
 notificationsRouter.post("/refresh", requireAuth, async (req, res) => {
+  const started = Date.now();
   const userId = req.did;
   if (userId === undefined) {
     res.status(401).json({ success: false, message: "Unauthorized" });
@@ -26,10 +28,21 @@ notificationsRouter.post("/refresh", requireAuth, async (req, res) => {
   const token =
     typeof fcmToken === "string" && fcmToken.length > 0 ? fcmToken : undefined;
 
+  console.log(
+    "[Refresh] Request received",
+    canonicalDeviceId !== undefined ? `deviceId=${canonicalDeviceId}` : "",
+    token !== undefined ? `token suffix=${maskToken(token)}` : ""
+  );
+
   if (
     (canonicalDeviceId === undefined || canonicalDeviceId.length === 0) &&
     token === undefined
   ) {
+    console.log(
+      "[Refresh] Rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "deviceId or fcmToken is required"
+    );
     res.status(400).json({ error: "deviceId or fcmToken is required" });
     return;
   }
@@ -41,8 +54,8 @@ notificationsRouter.post("/refresh", requireAuth, async (req, res) => {
 
   if (device === undefined) {
     console.log(
-      "[Refresh] Device lookup failed for user:",
+      "[Refresh] Device not found in",
-      userId,
+      formatElapsedMs(Date.now() - started),
       canonicalDeviceId !== undefined
         ? `deviceId=${canonicalDeviceId}`
         : "",
@@ -52,20 +65,21 @@ notificationsRouter.post("/refresh", requireAuth, async (req, res) => {
     return;
   }
 
-  console.log(
-    "[Refresh] Device ownership validated:",
-    device.deviceId,
-    maskToken(device.fcmToken)
-  );
   const now = Date.now();
-
   res.json({
     shouldNotify: true,
     nextNotifications: [{ timestamp: now + 600000 }],
   });
+  console.log(
+    "[Refresh] Completed in",
+    formatElapsedMs(Date.now() - started) + ",",
+    "deviceId=" + device.deviceId + ",",
+    "token suffix=" + maskToken(device.fcmToken)
+  );
 });
 
 notificationsRouter.post("/register", requireAuth, async (req, res) => {
+  const started = Date.now();
   const userId = req.did;
   if (userId === undefined) {
     res.status(401).json({ success: false, message: "Unauthorized" });
@@ -77,6 +91,11 @@ notificationsRouter.post("/register", requireAuth, async (req, res) => {
     typeof req.body === "object" &&
     "userId" in req.body
   ) {
+    console.log(
+      "[Register] Rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "userId must not be sent in the request body"
+    );
     res.status(400).json({
       error: "userId must not be sent in the request body",
     });
@@ -91,39 +110,49 @@ notificationsRouter.post("/register", requireAuth, async (req, res) => {
   };
 
   if (typeof deviceId !== "string" || deviceId.trim().length === 0) {
+    console.log(
+      "[Register] Rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "deviceId is required"
+    );
     res.status(400).json({ error: "deviceId is required" });
     return;
   }
   if (typeof fcmToken !== "string" || fcmToken.length === 0) {
+    console.log(
+      "[Register] Rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "fcmToken is required"
+    );
     res.status(400).json({ error: "fcmToken is required" });
     return;
   }
   if (typeof platform !== "string" || platform.length === 0) {
+    console.log(
+      "[Register] Rejected in",
+      formatElapsedMs(Date.now() - started) + ":",
+      "platform is required"
+    );
     res.status(400).json({ error: "platform is required" });
     return;
   }
 
   const canonicalDeviceId = deviceId.trim();
+  console.log(
+    "[Register] Request received,",
+    "deviceId=" + canonicalDeviceId + ",",
+    "platform=" + platform + ",",
+    "token suffix=" + maskToken(fcmToken)
+  );
 
   try {
     const existing = await db.getByDeviceId(userId, canonicalDeviceId);
-    if (existing !== undefined) {
+    const action =
-      if (existing.fcmToken !== fcmToken) {
+      existing === undefined
-        console.log(
+        ? "create"
-          "[Register] Updating existing device token:",
+        : existing.fcmToken !== fcmToken
-          canonicalDeviceId,
+          ? "update-token"
-          maskToken(fcmToken)
+          : "update";
-        );
-      } else {
-        console.log("[Register] Updating existing device:", canonicalDeviceId);
-      }
-    } else {
-      console.log(
-        "[Register] Creating new device registration:",
-        canonicalDeviceId,
-        maskToken(fcmToken)
-      );
-    }
 
     await db.upsert({
       userId,
@@ -134,8 +163,19 @@ notificationsRouter.post("/register", requireAuth, async (req, res) => {
       updatedAt: new Date(),
     });
     res.sendStatus(200);
+    console.log(
+      "[Register] Completed in",
+      formatElapsedMs(Date.now() - started) + ",",
+      "deviceId=" + canonicalDeviceId + ",",
+      "action=" + action
+    );
   } catch (err) {
-    console.error("register failed", err);
+    console.error(
+      "[Register] Failed in",
+      formatElapsedMs(Date.now() - started) + ",",
+      "deviceId=" + canonicalDeviceId + ":",
+      errorMessage(err)
+    );
     res.sendStatus(500);
   }
 });

src/scheduler.ts

@@ -1,6 +1,6 @@
 import { db } from "./db/fcmTokens.js";
 import { sendPushToDevice } from "./services/pushService.js";
-import { maskToken } from "./util/maskToken.js";
+import { errorMessage, formatElapsedMs } from "./util/formatElapsed.js";
 
 let intervalId: ReturnType<typeof setInterval> | undefined;
 
@@ -8,25 +8,52 @@ export function startScheduler(): void {
   if (intervalId !== undefined) return;
 
   intervalId = setInterval(async () => {
+    const passStarted = Date.now();
+    console.log("[Scheduler] Pass started");
+
     try {
-      console.log("[Scheduler] Checking devices...");
       const devices = await db.getAllForScheduler();
       const seenTokens = new Set<string>();
+      let checked = 0;
+      let sent = 0;
+      let skipped = 0;
+      let failed = 0;
+      let duplicates = 0;
 
       for (const d of devices) {
         if (seenTokens.has(d.fcmToken)) {
-          console.log(
+          duplicates++;
-            "[Scheduler] Duplicate device skipped:",
-            d.deviceId,
-            maskToken(d.fcmToken)
-          );
           continue;
         }
         seenTokens.add(d.fcmToken);
-        await sendPushToDevice(d.fcmToken);
+        checked++;
+
+        const result = await sendPushToDevice(d.fcmToken);
+        if (result === "sent") sent++;
+        else if (result === "skipped") skipped++;
+        else failed++;
       }
+
+      const summaryParts = [
+        `Checked ${checked} devices`,
+        `sent ${sent} pushes`,
+        `skipped ${skipped}`,
+      ];
+      if (failed > 0) summaryParts.push(`failed ${failed}`);
+      if (duplicates > 0) {
+        summaryParts.push(`${duplicates} duplicates ignored`);
+      }
+      console.log("[Scheduler]", summaryParts.join(", "));
+      console.log(
+        "[Scheduler] Pass completed in",
+        formatElapsedMs(Date.now() - passStarted)
+      );
     } catch (err) {
-      console.error("[Scheduler] Tick failed", err);
+      console.error(
+        "[Scheduler] Pass failed in",
+        formatElapsedMs(Date.now() - passStarted) + ":",
+        errorMessage(err)
+      );
     }
   }, 5 * 60 * 1000);
 }

src/services/pushService.ts

@@ -1,4 +1,5 @@
 import { db, type StoredRow } from "../db/fcmTokens.js";
+import { errorMessage, formatElapsedMs } from "../util/formatElapsed.js";
 import { maskToken } from "../util/maskToken.js";
 import { messaging } from "./firebase.js";
 
@@ -46,6 +47,7 @@ export async function sendPushToDevice(
   fcmToken: string,
   payload: Record<string, unknown> = {}
 ): Promise<"sent" | "skipped" | "failed"> {
+  const suffix = maskToken(fcmToken);
   const row = await db.getByFcmToken(fcmToken);
   const now = Date.now();
   const last = lastNotifiedMs(row);
@@ -54,23 +56,20 @@ export async function sendPushToDevice(
     last !== undefined &&
     now - last < notifyThresholdMs(row?.testMode)
   ) {
-    const device = { id: row?.id ?? "unknown" };
-    console.log("[Skip] Recently notified:", device.id);
     return "skipped";
   }
 
+  const sendStarted = Date.now();
+  console.log("[Push] Send attempt, token suffix:", suffix);
+
   try {
-    const device = { fcmToken };
     const data: Record<string, string> = {
       ...stringifyData(payload),
       type: "WAKEUP_PING",
     };
 
-    const token = maskToken(fcmToken);
-    console.log("[Push] Sending to:", token);
-
     await messaging.send({
-      token: device.fcmToken,
+      token: fcmToken,
       apns: {
         headers: {
           "apns-push-type": "background",
@@ -89,10 +88,21 @@ export async function sendPushToDevice(
     if (persisted !== undefined) {
       await db.update(persisted.id, { lastNotifiedAt: Date.now() });
     }
-    console.log("[Push] Success:", token);
+    console.log(
+      "[Push] Send completed in",
+      formatElapsedMs(Date.now() - sendStarted) + ",",
+      "token suffix:",
+      suffix
+    );
     return "sent";
   } catch (err) {
-    console.error("[Push] Failed:", err);
+    console.error(
+      "[Push] Send failed in",
+      formatElapsedMs(Date.now() - sendStarted) + ",",
+      "token suffix:",
+      suffix + ":",
+      errorMessage(err)
+    );
     return "failed";
   }
 }

src/util/formatElapsed.ts

@@ -0,0 +1,17 @@
+/** Human-readable duration for console logs (e.g. 842ms, 2.1s). */
+export function formatElapsedMs(elapsedMs: number): string {
+  if (elapsedMs < 1000) {
+    return `${Math.round(elapsedMs)}ms`;
+  }
+  return `${(elapsedMs / 1000).toFixed(1)}s`;
+}
+
+export function errorMessage(err: unknown): string {
+  if (err instanceof Error && err.message.length > 0) {
+    return err.message;
+  }
+  if (typeof err === "string" && err.length > 0) {
+    return err;
+  }
+  return "Unknown error";
+}