From 63f5c4ecc730d6b5fe3a69b542e1024fcf5aedd3 Mon Sep 17 00:00:00 2001 From: Jose Olarte III Date: Mon, 18 May 2026 18:46:16 +0800 Subject: [PATCH] feat(notifications): add structured observability for push wake and refresh flows Introduce NotificationDebugEvents and [Notifications] console/panel logging for push handlers, token registration, refresh timing, schedule replacement, and WAKEUP_PING. --- src/components/dev/NotificationDebugPanel.vue | 13 +- .../NativeNotificationService.ts | 51 ++++++-- .../notifications/NotificationDebugEvents.ts | 74 ++++++++++++ .../notifications/NotificationDebugService.ts | 113 ++++++------------ .../notifications/NotificationService.ts | 42 ++++--- .../notifications/firebaseMessagingClient.ts | 8 ++ src/services/notifications/index.ts | 8 ++ src/services/notifications/notificationLog.ts | 111 +++++++++++++++++ 8 files changed, 316 insertions(+), 104 deletions(-) create mode 100644 src/services/notifications/NotificationDebugEvents.ts create mode 100644 src/services/notifications/notificationLog.ts diff --git a/src/components/dev/NotificationDebugPanel.vue b/src/components/dev/NotificationDebugPanel.vue index e959236f..98d08b72 100644 --- a/src/components/dev/NotificationDebugPanel.vue +++ b/src/components/dev/NotificationDebugPanel.vue @@ -277,8 +277,9 @@ diff --git a/src/services/notifications/NativeNotificationService.ts b/src/services/notifications/NativeNotificationService.ts index 6ba3a94a..d75f87f8 100644 --- a/src/services/notifications/NativeNotificationService.ts +++ b/src/services/notifications/NativeNotificationService.ts @@ -20,6 +20,14 @@ import { getNotificationApiBaseUrl, getTestMode, } from "./NotificationDebugConfig"; +import { + logNotificationClearing, + logRefreshFailure, + logRefreshStarted, + logRefreshSuccess, + logScheduleReplacement, +} from "./notificationLog"; +import { logNotification } from "./NotificationDebugEvents"; /** * Extended type for DailyNotification that includes the actual Swift implementation @@ -560,12 +568,19 @@ export type RefreshNotificationsResult = { * Re-applies native API fetcher credentials (JWT pool, active DID) so background * notification workers can run. No UI; safe from push handlers while backgrounded. */ -export async function refreshNotificationsWithDiagnostics(): Promise { +export async function refreshNotificationsWithDiagnostics(options?: { + source?: string; +}): Promise { + const startedAt = performance.now(); + logRefreshStarted(options?.source); + if (!Capacitor.isNativePlatform()) { + const errorMessage = "not a native platform"; + logRefreshFailure(startedAt, errorMessage); return { ok: false, scheduledCount: 0, - errorMessage: "not a native platform", + errorMessage, }; } @@ -581,15 +596,17 @@ export async function refreshNotificationsWithDiagnostics(): Promise typeof t === "number" && Number.isFinite(t)); if (timestamps.length === 0) { + logNotification("Schedule replacement skipped (no valid timestamps)"); return; } // Keep existing behavior: ensure background worker credentials are current. await configureNativeFetcherIfReady(); - // Backend (or debug harness) is the source of truth: apply exact timestamps. - // eslint-disable-next-line no-console - console.log("[Notifications] Applying timestamps:", nextNotifications); + logScheduleReplacement(timestamps.length); const plugin = DailyNotification as unknown as { clearAllNotifications?: () => Promise; @@ -667,14 +685,18 @@ export async function applyNotificationRefreshPayload( }; if (typeof plugin.clearAllNotifications === "function") { + logNotificationClearing("clearAllNotifications"); await plugin.clearAllNotifications(); } else if (typeof plugin.cancelAllNotifications === "function") { - // Back-compat: older builds expose cancelAllNotifications. + logNotificationClearing("cancelAllNotifications"); await plugin.cancelAllNotifications(); } else { logger.warn( "[NativeNotificationService] No clearAllNotifications/cancelAllNotifications on plugin; cannot replace schedule", ); + logNotification( + "Schedule replacement aborted (clear method unavailable on plugin)", + ); return; } @@ -682,10 +704,16 @@ export async function applyNotificationRefreshPayload( logger.warn( "[NativeNotificationService] scheduleNotifications not available on plugin; cannot apply timestamps", ); + logNotification( + "Schedule replacement aborted (scheduleNotifications unavailable)", + ); return; } await plugin.scheduleNotifications({ timestamps }); + logNotification( + `Schedule replacement applied (${timestamps.length} timestamp(s))`, + ); } /** @@ -695,6 +723,13 @@ export async function handleCapacitorPushNotificationReceived( notification: PushNotificationSchema, ): Promise { if (notification.data?.type === "WAKEUP_PING") { - await refreshNotifications(); + logNotification("WAKEUP_PING handler — invoking refresh"); + await refreshNotificationsWithDiagnostics({ source: "WAKEUP_PING" }); + return; } + const type = + typeof notification.data?.type === "string" + ? notification.data.type + : "(none)"; + logNotification(`push handler ignored type=${type}`); } diff --git a/src/services/notifications/NotificationDebugEvents.ts b/src/services/notifications/NotificationDebugEvents.ts new file mode 100644 index 00000000..a454574f --- /dev/null +++ b/src/services/notifications/NotificationDebugEvents.ts @@ -0,0 +1,74 @@ +/** + * Lightweight in-memory notification debug log + console observability. + * Used by production notification flows and the Notification Debug Panel. + */ + +export const NOTIFICATION_LOG_PREFIX = "[Notifications]"; + +const MAX_ENTRIES = 100; + +type LogListener = (entries: readonly string[]) => void; + +const entries: string[] = []; +const listeners = new Set(); + +function formatTime(d: Date): string { + const hh = d.getHours().toString().padStart(2, "0"); + const mm = d.getMinutes().toString().padStart(2, "0"); + const ss = d.getSeconds().toString().padStart(2, "0"); + return `${hh}:${mm}:${ss}`; +} + +function formatPanelLine(message: string): string { + return `[${formatTime(new Date())}] ${message}`; +} + +function notifyListeners(): void { + const snapshot = [...entries] as readonly string[]; + for (const listener of listeners) { + listener(snapshot); + } +} + +/** Append a timestamped line to the in-memory debug log (panel). */ +export function appendLog(message: string): void { + entries.push(formatPanelLine(message)); + if (entries.length > MAX_ENTRIES) { + entries.splice(0, entries.length - MAX_ENTRIES); + } + notifyListeners(); +} + +export function subscribe(listener: LogListener): () => void { + listeners.add(listener); + listener([...entries]); + return () => { + listeners.delete(listener); + }; +} + +export function clearNotificationDebugLogs(): void { + entries.length = 0; + notifyListeners(); +} + +export function getNotificationDebugLogEntries(): readonly string[] { + return [...entries]; +} + +/** + * Structured console log (`[Notifications] …`) plus debug panel entry. + */ +export function logNotification( + message: string, + detail?: Record, +): void { + if (detail !== undefined) { + // eslint-disable-next-line no-console + console.log(`${NOTIFICATION_LOG_PREFIX} ${message}`, detail); + } else { + // eslint-disable-next-line no-console + console.log(`${NOTIFICATION_LOG_PREFIX} ${message}`); + } + appendLog(message); +} diff --git a/src/services/notifications/NotificationDebugService.ts b/src/services/notifications/NotificationDebugService.ts index 4cff4728..36ebbe17 100644 --- a/src/services/notifications/NotificationDebugService.ts +++ b/src/services/notifications/NotificationDebugService.ts @@ -8,9 +8,13 @@ */ import { Capacitor } from "@capacitor/core"; -import { ref, readonly, type Ref } from "vue"; import type { PushNotificationSchema } from "@capacitor/push-notifications"; import { logger } from "@/utils/logger"; +import { + clearNotificationDebugLogs, + logNotification, +} from "./NotificationDebugEvents"; +import { logNotificationClearing } from "./notificationLog"; import { getBackendBaseUrl, getNotificationApiBaseUrl, @@ -56,40 +60,9 @@ function isUnimplementedError(e: unknown): boolean { const LOG = "[NotificationDebugService]"; -function formatTime(d: Date): string { - const hh = d.getHours().toString().padStart(2, "0"); - const mm = d.getMinutes().toString().padStart(2, "0"); - const ss = d.getSeconds().toString().padStart(2, "0"); - return `${hh}:${mm}:${ss}`; -} - -function logLine(message: string): string { - return `[${formatTime(new Date())}] ${message}`; -} - -function truncateToken(token: string): string { - const t = token.trim(); - if (t.length <= 24) { - return t; - } - return `${t.slice(0, 12)}…${t.slice(-8)}`; -} - -const _eventLog: Ref = ref([]); - -const EVENT_LOG_MAX = 100; - -function append(message: string): void { - const line = logLine(message); - _eventLog.value = [..._eventLog.value, line].slice(-EVENT_LOG_MAX); - logger.debug(`${LOG} ${message}`); -} - export const NotificationDebugService = { - eventLog: readonly(_eventLog), - clearDebugLogs(): void { - _eventLog.value = []; + clearNotificationDebugLogs(); }, getActiveBackendUrl(): string { @@ -102,7 +75,7 @@ export const NotificationDebugService = { saveBackendBaseUrl(url: string): void { setBackendBaseUrl(url); - append( + logNotification( url.trim() ? `Backend URL saved (${getNotificationApiBaseUrl()})` : "Backend URL cleared (using default)", @@ -111,7 +84,7 @@ export const NotificationDebugService = { setTestModeEnabled(enabled: boolean): void { setTestMode(enabled); - append(`Test mode ${enabled ? "enabled" : "disabled"}`); + logNotification(`Test mode ${enabled ? "enabled" : "disabled"}`); }, isTestModeEnabled(): boolean { @@ -123,34 +96,20 @@ export const NotificationDebugService = { }, async registerTokenNow(): Promise { - append("Register token started"); - try { - const token = await reregisterFcmTokenNow(); - append(`Register token success (${truncateToken(token)})`); - } catch (e: unknown) { - const msg = e instanceof Error ? e.message : String(e); - append(`Register token failure: ${msg}`); - throw e; - } + logNotification("Register token now (debug panel)"); + await reregisterFcmTokenNow(); }, async triggerBackendRefresh(): Promise { - append("Refresh started"); - const result = await refreshNotificationsWithDiagnostics(); - if (result.ok) { - append(`Refresh success`); - append(`Scheduled ${result.scheduledCount} notifications`); - } else { - const detail = result.errorMessage ?? "unknown error"; - const status = result.status != null ? ` (HTTP ${result.status})` : ""; - append(`Refresh failure: ${detail}${status}`); - } + await refreshNotificationsWithDiagnostics({ source: "debug panel" }); }, /** Local simulation: same API call as a WAKEUP_PING handler (no push payload). */ async simulateWakeupViaRefresh(): Promise { - append("WAKEUP_PING simulation started (local refresh API only)"); - await this.triggerBackendRefresh(); + logNotification("WAKEUP_PING simulation (local refresh API only)"); + await refreshNotificationsWithDiagnostics({ + source: "WAKEUP_PING simulation", + }); }, generateMockNotifications( @@ -167,31 +126,26 @@ export const NotificationDebugService = { }, async triggerMockRefresh(intervalMs?: number): Promise { - append("Refresh requested (mock)"); + logNotification("Mock refresh requested"); const payload = this.generateMockNotifications(intervalMs); const timestamps = payload.nextNotifications?.map((n) => n.timestamp) ?? []; - append(`Mock payload generated (${timestamps.length} timestamps)`); - for (const ts of timestamps) { - if (typeof ts === "number") { - append(`Scheduling timestamp ${ts}`); - } - } + logNotification(`Mock payload generated (${timestamps.length} timestamps)`); if (!Capacitor.isNativePlatform()) { - append("Skipped: not running on native platform"); + logNotification("Mock refresh skipped: not running on native platform"); return; } await applyNotificationRefreshPayload(payload); - append("Mock refresh applied"); + logNotification("Mock refresh applied"); }, async simulateWakeupPing(): Promise { - append("Simulating WAKEUP_PING"); + logNotification("Simulating WAKEUP_PING (production push handler)"); if (!Capacitor.isNativePlatform()) { - append("Skipped: not running on native platform"); + logNotification("WAKEUP_PING simulation skipped: not native platform"); return; } @@ -203,23 +157,22 @@ export const NotificationDebugService = { } as unknown as PushNotificationSchema; await handleCapacitorPushNotificationReceived(notification); - append("WAKEUP_PING handled (production handler)"); }, async runFloodTest(intervalMs?: number): Promise { - append("Flood test started (20 sequential refreshes)"); + logNotification("Flood test started (20 sequential refreshes)"); for (let i = 0; i < 20; i++) { - append(`Flood iteration ${i + 1}/20`); + logNotification(`Flood iteration ${i + 1}/20`); await this.triggerMockRefresh(intervalMs); } - append("Flood test completed"); + logNotification("Flood test completed"); }, async clearNotifications(): Promise { - append("Clearing notifications"); + logNotification("Clear notifications (debug panel)"); if (!Capacitor.isNativePlatform()) { - append("Skipped: not running on native platform"); + logNotification("Clear skipped: not running on native platform"); return; } @@ -229,29 +182,31 @@ export const NotificationDebugService = { }; if (typeof plugin.clearAllNotifications === "function") { + logNotificationClearing("clearAllNotifications"); await plugin.clearAllNotifications(); } else if (typeof plugin.cancelAllNotifications === "function") { + logNotificationClearing("cancelAllNotifications"); await plugin.cancelAllNotifications(); } else { - append("Clear not available (plugin method missing)"); + logNotification("Clear not available (plugin method missing)"); return; } - append("Cleared notifications"); + logNotification("Notifications cleared"); }, async getPendingNotifications(): Promise { - append("Fetching pending notifications"); + logNotification("Fetching pending notifications"); if (!Capacitor.isNativePlatform()) { - append("Skipped: not running on native platform"); + logNotification("Pending fetch skipped: not running on native platform"); return { pending: [] }; } try { const res = await NotificationInspector.getPendingNotifications(); const items = (res?.pending ?? []) as PendingNotificationInfo[]; - append(`Pending fetched (${items.length})`); + logNotification(`Pending fetched (${items.length})`); return { pending: items }; } catch (e: unknown) { if (isUnimplementedError(e)) { @@ -261,7 +216,7 @@ export const NotificationDebugService = { "Pending notification inspection is currently supported on iOS only.", }; } - append("Pending fetch failed"); + logNotification("Pending fetch failed"); logger.warn(`${LOG} getPendingNotifications failed`, e); return { pending: [] }; } diff --git a/src/services/notifications/NotificationService.ts b/src/services/notifications/NotificationService.ts index 1d6fa2aa..5b6bde98 100644 --- a/src/services/notifications/NotificationService.ts +++ b/src/services/notifications/NotificationService.ts @@ -20,6 +20,11 @@ import { getNotificationApiBaseUrl, getTestMode, } from "./NotificationDebugConfig"; +import { + logTokenRegistrationFailure, + logTokenRegistrationStarted, + logTokenRegistrationSuccess, +} from "./notificationLog"; import { NativeNotificationService } from "./NativeNotificationService"; import { WebPushNotificationService } from "./WebPushNotificationService"; @@ -27,24 +32,31 @@ import { WebPushNotificationService } from "./WebPushNotificationService"; * Registers an FCM device token with the app backend (native Capacitor token or web getToken). */ export async function registerToken(fcmToken: string): Promise { + logTokenRegistrationStarted(fcmToken); const deviceId = await getOrCreateDeviceId(); const baseUrl = getNotificationApiBaseUrl(); - const res = await fetch(`${baseUrl}/notifications/register`, { - method: "POST", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify({ - deviceId, - fcmToken, - platform: Capacitor.getPlatform(), - testMode: getTestMode(), - }), - }); - if (!res.ok) { - logger.warn("[NotificationService] registerToken failed", { - status: res.status, - statusText: res.statusText, + try { + const res = await fetch(`${baseUrl}/notifications/register`, { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ + deviceId, + fcmToken, + platform: Capacitor.getPlatform(), + testMode: getTestMode(), + }), }); - throw new Error(`registerToken failed: HTTP ${res.status}`); + if (!res.ok) { + logger.warn("[NotificationService] registerToken failed", { + status: res.status, + statusText: res.statusText, + }); + throw new Error(`registerToken failed: HTTP ${res.status}`); + } + logTokenRegistrationSuccess(fcmToken); + } catch (err) { + logTokenRegistrationFailure(fcmToken, err); + throw err; } } diff --git a/src/services/notifications/firebaseMessagingClient.ts b/src/services/notifications/firebaseMessagingClient.ts index f3e6233f..0dda6047 100644 --- a/src/services/notifications/firebaseMessagingClient.ts +++ b/src/services/notifications/firebaseMessagingClient.ts @@ -23,6 +23,11 @@ import { import { logger } from "@/utils/logger"; import { handleCapacitorPushNotificationReceived } from "./NativeNotificationService"; import { registerToken } from "./NotificationService"; +import { + logPushNotificationActionPerformed, + logPushNotificationReceived, + logTokenRegistrationSkippedDuplicate, +} from "./notificationLog"; const LOG = "[FirebaseMessaging]"; @@ -43,6 +48,7 @@ async function registerRetrievedToken( } lastSeenFcmToken = trimmed; if (!options?.force && trimmed === lastRegisteredFcmToken) { + logTokenRegistrationSkippedDuplicate(trimmed); return; } await registerToken(trimmed); @@ -246,6 +252,7 @@ async function initializeNativePushAndFirebaseMessagingImpl(): Promise { "pushNotificationReceived", (notification) => { logger.debug(`${LOG} pushNotificationReceived`, notification); + logPushNotificationReceived(notification); void handleCapacitorPushNotificationReceived(notification).catch( (err) => { logger.warn( @@ -261,6 +268,7 @@ async function initializeNativePushAndFirebaseMessagingImpl(): Promise { "pushNotificationActionPerformed", (action) => { logger.debug(`${LOG} pushNotificationActionPerformed`, action); + logPushNotificationActionPerformed(action); }, ); diff --git a/src/services/notifications/index.ts b/src/services/notifications/index.ts index dd2176fa..43006e0c 100644 --- a/src/services/notifications/index.ts +++ b/src/services/notifications/index.ts @@ -21,6 +21,14 @@ export { setBackendBaseUrl, setTestMode, } from "./NotificationDebugConfig"; +export { + appendLog, + clearNotificationDebugLogs, + getNotificationDebugLogEntries, + logNotification, + NOTIFICATION_LOG_PREFIX, + subscribe, +} from "./NotificationDebugEvents"; export { NotificationService, registerToken } from "./NotificationService"; export { NativeNotificationService } from "./NativeNotificationService"; export { WebPushNotificationService } from "./WebPushNotificationService"; diff --git a/src/services/notifications/notificationLog.ts b/src/services/notifications/notificationLog.ts new file mode 100644 index 00000000..99070743 --- /dev/null +++ b/src/services/notifications/notificationLog.ts @@ -0,0 +1,111 @@ +/** + * Shared observability helpers for notification flows (console + debug panel). + */ + +import { logNotification } from "./NotificationDebugEvents"; + +export function truncateFcmTokenForLog(token: string): string { + const t = token.trim(); + if (t.length <= 24) { + return t; + } + return `${t.slice(0, 12)}…${t.slice(-8)}`; +} + +export function logPushNotificationReceived(notification: { + title?: string; + data?: Record; +}): void { + const type = + typeof notification.data?.type === "string" + ? notification.data.type + : "(none)"; + logNotification(`pushNotificationReceived type=${type}`, { + title: notification.title, + dataType: type, + }); + if (type === "WAKEUP_PING") { + logNotification("WAKEUP_PING received — will trigger refresh"); + } +} + +export function logPushNotificationActionPerformed(action: { + actionId?: string; + notification?: { title?: string; data?: Record }; +}): void { + const type = + typeof action.notification?.data?.type === "string" + ? action.notification.data.type + : "(none)"; + logNotification( + `pushNotificationActionPerformed actionId=${action.actionId ?? "(none)"} type=${type}`, + { + actionId: action.actionId, + dataType: type, + }, + ); +} + +export function logTokenRegistrationStarted(token: string): void { + logNotification("Token registration started", { + token: truncateFcmTokenForLog(token), + }); +} + +export function logTokenRegistrationSuccess(token: string): void { + logNotification("Token registration success", { + token: truncateFcmTokenForLog(token), + }); +} + +export function logTokenRegistrationSkippedDuplicate(token: string): void { + logNotification("Token registration skipped (duplicate token)", { + token: truncateFcmTokenForLog(token), + }); +} + +export function logTokenRegistrationFailure( + token: string, + error: unknown, +): void { + const message = error instanceof Error ? error.message : String(error); + logNotification(`Token registration failure: ${message}`, { + token: truncateFcmTokenForLog(token), + }); +} + +export function logRefreshStarted(source?: string): void { + logNotification(source ? `Refresh started (${source})` : "Refresh started"); +} + +function elapsedMsSince(startedAt: number): number { + return performance.now() - startedAt; +} + +export function logRefreshSuccess( + startedAt: number, + scheduledCount: number, +): void { + logNotification( + `Refresh completed in ${Math.round(elapsedMsSince(startedAt))}ms (scheduled ${scheduledCount})`, + ); +} + +export function logRefreshFailure( + startedAt: number, + errorMessage: string, + status?: number, +): void { + const statusPart = status != null ? ` HTTP ${status}` : ""; + logNotification( + `Refresh failed in ${Math.round(elapsedMsSince(startedAt))}ms: ${errorMessage}${statusPart}`, + ); +} + +export function logNotificationClearing(method: string): void { + logNotification(`Clearing notifications via ${method}`); +} + +export function logScheduleReplacement(count: number): void { + logNotification(`Schedule replacement: ${count} notification(s)`); +}