Add verbose logging in onPush listener (#724)

* refactor: Use log function in service worker

* Add verbose logging on push listener

* Fix TypeError: Cannot read properties of null (reading 'postMessage')

navigator.serviceWorker.controller is null on forced refreshes:

"""
This property returns null if the request is a force refresh (Shift + refresh) or if there is no active worker.
"""

-- https://developer.mozilla.org/en-US/docs/Web/API/ServiceWorkerContainer/controller

This means when we unregister a service worker manually (like I do for debugging purposes) and then reload the page, there is no service worker available when this code is run.

Adding a check with a more helpful error message should improve UX.

This error might also happen in other cases where a page refresh should also help.

---------

Co-authored-by: ekzyis <ek@stacker.news>

components/serviceworker.js

@@ -58,6 +58,11 @@ export const ServiceWorkerProvider = ({ children }) => {
   })
 
   const subscribeToPushNotifications = async () => {
+    // serviceWorker.controller is null on forced refreshes
+    // see https://w3c.github.io/ServiceWorker/#navigator-service-worker-controller
+    if (!navigator.serviceWorker.controller) {
+      throw new Error('no active service worker found. try refreshing page.')
+    }
     const subscribeOptions = { userVisibleOnly: true, applicationServerKey }
     // Brave users must enable a flag in brave://settings/privacy first
     // see https://stackoverflow.com/a/69624651

sw/eventListener.js

@@ -13,54 +13,67 @@ let actionChannelPort
 // current push notification count for badge purposes
 let activeCount = 0
 
+const log = (message, level = 'info', context) => {
+  messageChannelPort?.postMessage({ level, message, context })
+  if (level === 'error') console.error(message)
+  else console.log(message)
+}
+
 export function onPush (sw) {
   return async (event) => {
     const payload = event.data?.json()
     if (!payload) return
     const { tag } = payload.options
     event.waitUntil((async () => {
+      // generate random ID for every incoming push for better tracing in logs
+      const nid = crypto.randomUUID()
+      log(`[sw:push] ${nid} - received notification with tag ${tag}`)
+
+      // due to missing proper tag support in Safari on iOS, we can't rely on the tag built-in filter.
+      // we therefore fetch all notifications with the same tag and manually filter them, too.
+      // see https://bugs.webkit.org/show_bug.cgi?id=258922
+      const notifications = await sw.registration.getNotifications({ tag })
+      log(`[sw:push] ${nid} - found ${notifications.length} ${tag} notifications`)
+      log(`[sw:push] ${nid} - built-in tag filter: ${JSON.stringify(notifications.map(({ tag }) => tag))}`)
+
+      // we're not sure if the built-in tag filter actually filters by tag on iOS
+      // or if it just returns all currently displayed notifications (?)
+      const filtered = notifications.filter(({ tag: nTag }) => nTag === tag)
+      log(`[sw:push] ${nid} - found ${filtered.length} ${tag} notifications after manual tag filter`)
+      log(`[sw:push] ${nid} - manual tag filter: ${JSON.stringify(filtered.map(({ tag }) => tag))}`)
+
       if (immediatelyShowNotification(tag)) {
+        // we can't rely on the tag property to replace notifications on Safari on iOS.
+        // we therefore close them manually and then we display the notification.
+        log(`[sw:push] ${nid} - ${tag} notifications replace previous notifications`)
         setAppBadge(sw, ++activeCount)
-        // due to missing proper tag support in Safari on iOS, we can't rely on the tag property to replace notifications.
+        log(`[sw:push] ${nid} - closing existing notifications`)
-        // see https://bugs.webkit.org/show_bug.cgi?id=258922 for more information
+        filtered.forEach(n => n.close())
-        // we therefore fetch all notifications with the same tag (+ manual filter),
+        log(`[sw:push] ${nid} - show notification: ${payload.title} ${JSON.stringify(payload.options)}`)
-        // close them and then we display the notification.
-        const notifications = await sw.registration.getNotifications({ tag })
-        notifications.filter(({ tag: nTag }) => nTag === tag).forEach(n => n.close())
         return await sw.registration.showNotification(payload.title, payload.options)
       }
 
-      // fetch existing notifications with same tag
-      let notifications = await sw.registration.getNotifications({ tag })
-
       // according to the spec, there should only be zero or one notification since we used a tag filter
       // handle zero case here
       if (notifications.length === 0) {
         // incoming notification is first notification with this tag
+        log(`[sw:push] ${nid} - no existing ${tag} notifications found`)
         setAppBadge(sw, ++activeCount)
+        log(`[sw:push] ${nid} - show notification: ${payload.title} ${JSON.stringify(payload.options)}`)
         return await sw.registration.showNotification(payload.title, payload.options)
       }
 
       // handle unexpected case here
       if (notifications.length > 1) {
-        const message = `[sw:push] more than one notification with tag ${tag} found`
+        log(`[sw:push] ${nid} - more than one notification with tag ${tag} found`, 'error')
-        messageChannelPort?.postMessage({ level: 'error', message })
-        console.error(message)
         // due to missing proper tag support in Safari on iOS,
         // we only acknowledge this error in our logs and don't bail here anymore
         // see https://bugs.webkit.org/show_bug.cgi?id=258922 for more information
-        const message2 = '[sw:push] skip bail -- merging notifications manually'
+        log(`[sw:push] ${nid} - skip bail -- merging notifications with tag ${tag} manually`)
-        messageChannelPort?.postMessage({ level: 'info', message: message2 })
-        console.log(message2)
         // return null
       }
 
-      // we manually filter notifications by their tag since iOS doesn't properly support tag
+      return await mergeAndShowNotification(sw, payload, notifications, tag, nid)
-      // and we're not sure if the built-in tag filter actually filters by tag on iOS
-      // or if it just returns all currently displayed notifications.
-      notifications = notifications.filter(({ tag: nTag }) => nTag === tag)
-
-      return await mergeAndShowNotification(sw, payload, notifications, tag)
     })())
   }
 }
@@ -69,21 +82,22 @@ export function onPush (sw) {
 // we don't need to merge notifications and thus the notification should be immediately shown using `showNotification`
 const immediatelyShowNotification = (tag) => !tag || ['TIP', 'FORWARDEDTIP', 'EARN', 'STREAK'].includes(tag.split('-')[0])
 
-const mergeAndShowNotification = async (sw, payload, currentNotifications, tag) => {
+const mergeAndShowNotification = async (sw, payload, currentNotifications, tag, nid) => {
   // sanity check
   const otherTagNotifications = currentNotifications.filter(({ tag: nTag }) => nTag !== tag)
   if (otherTagNotifications.length > 0) {
     // we can't recover from this here. bail.
-    const message = `[sw:push] more than one notification with tag ${tag} after filter`
+    const message = `[sw:push] ${nid} - bailing -- more than one notification with tag ${tag} found after manual filter`
-    messageChannelPort?.postMessage({ level: 'error', message })
+    log(message, 'error')
-    console.error(message)
     return
   }
 
   const { data: incomingData } = payload.options
+  log(`[sw:push] ${nid} - incoming payload.options.data: ${JSON.stringify(incomingData)}`)
 
   // we can ignore everything after the first dash in the tag for our control flow
   const compareTag = tag.split('-')[0]
+  log(`[sw:push] ${nid} - using ${compareTag} for control flow`)
 
   // merge notifications into single notification payload
   // ---
@@ -93,6 +107,7 @@ const mergeAndShowNotification = async (sw, payload, currentNotifications, tag)
   const SUM_SATS_TAGS = ['DEPOSIT']
   // this should reflect the amount of notifications that were already merged before
   const initialAmount = currentNotifications[0].data?.amount || 1
+  log(`[sw:push] ${nid} - initial amount: ${initialAmount}`)
   const mergedPayload = currentNotifications.reduce((acc, { data }) => {
     let newAmount, newSats
     if (AMOUNT_TAGS.includes(compareTag)) {
@@ -105,6 +120,8 @@ const mergeAndShowNotification = async (sw, payload, currentNotifications, tag)
     return newPayload
   }, { ...incomingData, amount: initialAmount })
 
+  log(`[sw:push] ${nid} - merged payload: ${JSON.stringify(mergedPayload)}`)
+
   // calculate title from merged payload
   const { amount, followeeName, subType, sats } = mergedPayload
   let title = ''
@@ -124,10 +141,14 @@ const mergeAndShowNotification = async (sw, payload, currentNotifications, tag)
     // there is only DEPOSIT in this array
     title = `${numWithUnits(sats, { abbreviate: false })} were deposited in your account`
   }
+  log(`[sw:push] ${nid} - calculated title: ${title}`)
 
   // close all current notifications before showing new one to "merge" notifications
+  log(`[sw:push] ${nid} - closing existing notifications`)
   currentNotifications.forEach(n => n.close())
+
   const options = { icon: payload.options?.icon, tag, data: { url: '/notifications', ...mergedPayload } }
+  log(`[sw:push] ${nid} - show notification: ${title} ${JSON.stringify(options)}`)
   return await sw.registration.showNotification(title, options)
 }
 
@@ -155,7 +176,7 @@ export function onPushSubscriptionChange (sw) {
     let { oldSubscription, newSubscription } = event
     // https://developer.mozilla.org/en-US/docs/Web/API/ServiceWorkerGlobalScope/pushsubscriptionchange_event
     // fallbacks since browser may not set oldSubscription and newSubscription
-    messageChannelPort?.postMessage({ message: '[sw:handlePushSubscriptionChange] invoked' })
+    log('[sw:handlePushSubscriptionChange] invoked')
     oldSubscription ??= await storage.getItem('subscription')
     newSubscription ??= await sw.registration.pushManager.getSubscription()
     if (!newSubscription) {
@@ -164,17 +185,17 @@ export function onPushSubscriptionChange (sw) {
         // see https://github.com/stackernews/stacker.news/issues/411#issuecomment-1790675861
         // NOTE: this is only run on IndexedDB subscriptions stored under service worker version 2 since this is not backwards compatible
         // see discussion in https://github.com/stackernews/stacker.news/pull/597
-        messageChannelPort?.postMessage({ message: '[sw:handlePushSubscriptionChange] service worker lost subscription' })
+        log('[sw:handlePushSubscriptionChange] service worker lost subscription')
         actionChannelPort?.postMessage({ action: 'RESUBSCRIBE' })
         return
       }
       // no subscription exists at the moment
-      messageChannelPort?.postMessage({ message: '[sw:handlePushSubscriptionChange] no existing subscription found' })
+      log('[sw:handlePushSubscriptionChange] no existing subscription found')
       return
     }
     if (oldSubscription?.endpoint === newSubscription.endpoint) {
     // subscription did not change. no need to sync with server
-      messageChannelPort?.postMessage({ message: '[sw:handlePushSubscriptionChange] old subscription matches existing subscription' })
+      log('[sw:handlePushSubscriptionChange] old subscription matches existing subscription')
       return
     }
     // convert keys from ArrayBuffer to string
@@ -199,7 +220,7 @@ export function onPushSubscriptionChange (sw) {
       },
       body
     })
-    messageChannelPort?.postMessage({ message: '[sw:handlePushSubscriptionChange] synced push subscription with server', context: { endpoint: variables.endpoint, oldEndpoint: variables.oldEndpoint } })
+    log('[sw:handlePushSubscriptionChange] synced push subscription with server', 'info', { endpoint: variables.endpoint, oldEndpoint: variables.oldEndpoint })
     await storage.setItem('subscription', JSON.parse(JSON.stringify(newSubscription)))
   }
 }
@@ -213,9 +234,9 @@ export function onMessage (sw) {
     if (event.data.action === 'MESSAGE_PORT') {
       messageChannelPort = event.ports[0]
     }
-    messageChannelPort?.postMessage({ message: '[sw:message] received message', context: { action: event.data.action } })
+    log('[sw:message] received message', 'info', { action: event.data.action })
     if (event.data.action === 'STORE_SUBSCRIPTION') {
-      messageChannelPort?.postMessage({ message: '[sw:message] storing subscription in IndexedDB', context: { endpoint: event.data.subscription.endpoint } })
+      log('[sw:message] storing subscription in IndexedDB', 'info', { endpoint: event.data.subscription.endpoint })
       return event.waitUntil(storage.setItem('subscription', { ...event.data.subscription, swVersion: 2 }))
     }
     if (event.data.action === 'SYNC_SUBSCRIPTION') {