Improve logging and error handling, fix date formatting (#88)

* Improve logging

* Fix incorrect timezone on results message

* Format

* update siirtovahti > Siirtovahti

---------

Co-authored-by: Tarmo Sundström <tarmo.sundstrom@druid.fi>

Author: hyrsky

conf/kymp.json

@@ -12,22 +12,22 @@
       "sv": "https://makasiini.hel.ninja/helsinki-logos/helsinki-logo-black-sv-h45.png"
     },
     "email_subject_confirmation": {
-      "fi": "Vahvista ajoneuvojen siirtovahdin tilaus",
+      "fi": "Vahvista ajoneuvojen Siirtovahdin tilaus",
       "en": "Confirm your Vehicle Removal Alert Service subscription",
       "sv": "Bekräfta beställningen av flyttningsvakten för fordon"
     },
     "email_subject_expiry": {
-      "fi": "Ajoneuvojen siirtovahtisi on vanhentumassa",
+      "fi": "Ajoneuvojen Siirtovahtisi on vanhentumassa",
       "en": "Your Vehicle Removal Alert Service subscription is about to expire",
       "sv": "Din flyttningsvakt för fordon håller på att gå ut"
     },
     "email_subject_newhits": {
-      "fi": "Uusia osumia ajoneuvojen siirtovahdillasi",
+      "fi": "Uusia osumia ajoneuvojen Siirtovahdillasi",
       "en": "The Vehicle Removal Alert Service has found new matches for you",
       "sv": "Nya träffar från din flyttningsvakt för fordon"
     },
     "email_confirmation_title": {
-      "fi": "Vahvista ajoneuvojen siirtovahdin tilaus Helsingin kaupungilta",
+      "fi": "Vahvista ajoneuvojen Siirtovahdin tilaus Helsingin kaupungilta",
       "en": "Confirm your Vehicle Removal Alert Service subscription with the City of Helsinki",
       "sv": "Bekräfta beställning av flyttningsvakten för fordon från Helsingfors stad"
     },

src/bin/hav-populate-queue.ts

@@ -149,6 +149,10 @@ const getNewHitsFromElasticsearch = async (
 
     const matchField = siteConfig.matchField;
 
+    console.info(
+      `Matched ${elasticResponse?.hits?.total?.value ?? 0} hits for ${subscription._id} from ${siteConfig.name}`,
+    );
+
     // Filter out new hits:
     return (elasticResponse?.hits?.hits ?? [])
       .filter((hit: { _source?: Record<string, unknown> }) => {
@@ -176,7 +180,7 @@ const getNewHitsFromElasticsearch = async (
  * @param siteConfig - The site configuration to process
  * @param stats - Statistics object to track processing
  * @param isDryRun - Do not write changes
- * @return {Promise<void>} A Promise that resolves when processing is complete
+ * @return A Promise that resolves when processing is complete
  */
 const processSiteSubscriptions = async (
   server: Server,
@@ -205,8 +209,12 @@ const processSiteSubscriptions = async (
 
   // Process subscriptions sequentially to avoid overwhelming the system
   await result.reduce(async (previousPromise, subscription) => {
+    // @todo move this to a for loop, using
+    //   reduce() here is quite hard to reason.
     await previousPromise;
 
+    console.info(`Processing subscription ${subscription._id} for site ${siteConfig.id}`);
+
     // Resolve user data from ATV if stored there
     let resolvedQuery: string = subscription.query;
     let resolvedSearchDescription: string = subscription.search_description ?? '';
@@ -218,8 +226,11 @@ const processSiteSubscriptions = async (
         resolvedQuery = atvData.query ?? '';
         resolvedSearchDescription = atvData.search_description ?? '';
         resolvedElasticQuery = atvData.elastic_query;
+
+        console.info(`Subscription details loaded from ATV for ${subscription._id} (site: ${siteConfig.id})`);
       } catch (e) {
         console.error(`Failed to load user data from ATV for ${subscription._id}`, e);
+        server.Sentry?.captureException(e);
         return Promise.resolve();
       }
     }
@@ -230,15 +241,16 @@ const processSiteSubscriptions = async (
     const subscriptionValidForDays = siteConfig.subscription.maxAge;
 
     // Sync ATV delete_after if needed (handles config changes and legacy subscriptions)
+    // @todo: why do we need this?
     const expectedDeleteAfter = calculateExpectedDeleteAfter(new Date(subscription.created), subscriptionValidForDays);
     if (needsDeleteAfterSync(subscription.delete_after, expectedDeleteAfter)) {
-      if (isDryRun) {
-        console.log(
-          `[DRY RUN] Would sync ATV delete_after for ${subscription._id} ` +
-            `(stored: ${subscription.delete_after?.toISOString().substring(0, 10) ?? 'none'}, ` +
-            `expected: ${expectedDeleteAfter.toISOString().substring(0, 10)})`,
-        );
-      } else {
+      console.info(
+        `Sync ATV delete_after for ${subscription._id} ` +
+          `(stored: ${subscription.delete_after?.toISOString().substring(0, 10) ?? 'none'}, ` +
+          `expected: ${expectedDeleteAfter.toISOString().substring(0, 10)})`,
+      );
+
+      if (!isDryRun) {
         try {
           await server.atv.updateDocumentDeleteAfter(
             ATV.getAtvId(subscription),
@@ -262,41 +274,50 @@ const processSiteSubscriptions = async (
 
     // If subscription should expire soon, send an expiration email
     if (checkShouldSendExpiryNotification(subscription as Partial<SubscriptionCollectionType>, siteConfig)) {
-      if (isDryRun) {
-        console.log(`[DRY RUN] Would send expiry email to ${ATV.getAtvId(subscription)} (site: ${siteConfig.id})`);
-      } else {
+      console.info(`Sending expiry email to ${ATV.getAtvId(subscription)} (site: ${siteConfig.id})`);
+
+      // @fixme: dry run keeps spamming the messages and should
+      //   newer be used in production. Why do we need dry-run feature?
+      if (!isDryRun) {
         await collection.updateOne({ _id: subscription._id }, { $set: { expiry_notification_sent: 1 } });
       }
 
-      const expiryEmailContent = await expiryEmail(
-        subscription.lang,
-        {
-          search_description: resolvedSearchDescription,
-          link: siteConfig.urls.base + resolvedQuery,
-          removal_date: formattedExpiryDate,
-          remove_link: `${localizedBaseUrl}/hakuvahti/unsubscribe?subscription=${subscription._id}&hash=${subscription.hash}`,
-          renewal_link: `${localizedBaseUrl}/hakuvahti/renew?subscription=${subscription._id}&hash=${subscription.hash}`,
-          search_link: resolvedQuery,
-        },
-        siteConfig,
-      );
-
       // Queue expiry email if email is active
       if (isEmailActive(subscription as Partial<SubscriptionCollectionType>)) {
-        const expiryEmailToQueue: QueueInsertDocument = {
-          type: 'email',
-          atv_id: ATV.getAtvId(subscription),
-          content: expiryEmailContent,
-        };
+        try {
+          const expiryEmailContent = await expiryEmail(
+            subscription.lang,
+            {
+              search_description: resolvedSearchDescription,
+              link: siteConfig.urls.base + resolvedQuery,
+              removal_date: formattedExpiryDate,
+              remove_link: `${localizedBaseUrl}/hakuvahti/unsubscribe?subscription=${subscription._id}&hash=${subscription.hash}`,
+              renewal_link: `${localizedBaseUrl}/hakuvahti/renew?subscription=${subscription._id}&hash=${subscription.hash}`,
+              search_link: resolvedQuery,
+            },
+            siteConfig,
+          );
 
-        if (!isDryRun) {
-          await queueCollection.insertOne(expiryEmailToQueue);
+          const expiryEmailToQueue: QueueInsertDocument = {
+            type: 'email',
+            atv_id: ATV.getAtvId(subscription),
+            content: expiryEmailContent,
+          };
+
+          if (!isDryRun) {
+            await queueCollection.insertOne(expiryEmailToQueue);
+          }
+          stats.expiryEmailsQueued++;
+        } catch (error) {
+          console.error(`Error queueing expiry email for subscription ${subscription._id}:`, error);
+          server.Sentry?.captureException(error);
         }
-        stats.expiryEmailsQueued++;
       }
 
       // Queue renewal SMS if subscription has SMS and site supports it
       if (isSmsActive(subscription as Partial<SubscriptionCollectionType>) && siteConfig.subscription.enableSms) {
+        console.info(`Sending expiry SMS for ${subscription._id} (site: ${siteConfig.id})`);
+
         try {
           const smsContent = await renewalSms(
             subscription.lang,
@@ -314,14 +335,14 @@ const processSiteSubscriptions = async (
             content: smsContent,
           };
 
-          if (isDryRun) {
-            console.log(`[DRY RUN] Would queue renewal SMS for ${subscription._id}`);
+          if (!isDryRun) {
           } else {
             await queueCollection.insertOne(smsToQueue);
           }
           stats.smsQueued++;
         } catch (error) {
           console.error(`Error queueing renewal SMS for subscription ${subscription._id}:`, error);
+          server.Sentry?.captureException(error);
         }
       }
     }
@@ -335,6 +356,7 @@ const processSiteSubscriptions = async (
 
     // No new hits
     if (newHits.length === 0) {
+      console.info(`No hits for ${subscription._id} from ${siteConfig.name}`);
       return Promise.resolve();
     }
 
@@ -348,41 +370,46 @@ const processSiteSubscriptions = async (
     const pad = (n: number) => n.toString().padStart(2, '0');
     const formattedCreatedDate = `${pad(date.getDate())}.${pad(date.getMonth() + 1)}.${date.getFullYear()}`;
 
-    const emailContent = await newHitsEmail(
-      subscription.lang,
-      {
-        created_date: formattedCreatedDate,
-        expiry_date: formattedExpiryDate,
-        search_description: resolvedSearchDescription,
-        search_link: resolvedQuery,
-        remove_link: `${localizedBaseUrl}/hakuvahti/unsubscribe?subscription=${subscription._id}&hash=${subscription.hash}`,
-        hits: hitsForEmail,
-      },
-      siteConfig,
-    );
+    // Update last_checked regardless of channel
+    if (!isDryRun) {
+      const dateUnixtime: number = Math.floor(Date.now() / 1000);
+      await collection.updateOne({ _id: subscription._id }, { $set: { last_checked: dateUnixtime } });
+    }
 
     // Queue new hits email if email is active
     if (isEmailActive(subscription as Partial<SubscriptionCollectionType>)) {
-      const email: QueueInsertDocument = {
-        type: 'email',
-        atv_id: ATV.getAtvId(subscription),
-        content: emailContent,
-      };
-
-      if (isDryRun) {
-        console.log(
-          `[DRY RUN] Would queue email for ${ATV.getAtvId(subscription)}: ${newHits.length} new result(s) (site: ${siteConfig.id})`,
+      try {
+        const emailContent = await newHitsEmail(
+          subscription.lang,
+          {
+            created_date: formattedCreatedDate,
+            expiry_date: formattedExpiryDate,
+            search_description: resolvedSearchDescription,
+            search_link: resolvedQuery,
+            remove_link: `${localizedBaseUrl}/hakuvahti/unsubscribe?subscription=${subscription._id}&hash=${subscription.hash}`,
+            hits: hitsForEmail,
+          },
+          siteConfig,
         );
-      } else {
-        await queueCollection.insertOne(email);
-      }
-      stats.newResultsEmailsQueued++;
-    }
 
-    // Update last_checked regardless of channel
-    if (!isDryRun) {
-      const dateUnixtime: number = Math.floor(Date.now() / 1000);
-      await collection.updateOne({ _id: subscription._id }, { $set: { last_checked: dateUnixtime } });
+        const email: QueueInsertDocument = {
+          type: 'email',
+          atv_id: ATV.getAtvId(subscription),
+          content: emailContent,
+        };
+
+        console.info(
+          `New email for ${ATV.getAtvId(subscription)}: ${newHits.length} new result(s) (site: ${siteConfig.id})`,
+        );
+
+        if (!isDryRun) {
+          await queueCollection.insertOne(email);
+        }
+        stats.newResultsEmailsQueued++;
+      } catch (error) {
+        // Log error but don't break email sending
+        console.error(`Error queueing SMS for subscription ${subscription._id}:`, error);
+      }
     }
 
     // Queue SMS if subscription has SMS confirmed and SMS is enabled for site
@@ -404,9 +431,9 @@ const processSiteSubscriptions = async (
           content: smsContent,
         };
 
-        if (isDryRun) {
-          console.log(`[DRY RUN] Would queue SMS for ${subscription._id}`);
-        } else {
+        console.log(`New SMS for ${subscription._id}: ${newHits.length} new result(s) (site: ${siteConfig.id})`);
+
+        if (!isDryRun) {
           await queueCollection.insertOne(smsToQueue);
         }
         stats.smsQueued++;

src/lib/email.ts

@@ -10,9 +10,12 @@ const TEMPLATE_BASE_PATH = 'dist/templates';
 const fieldFormatters: Record<string, (val: unknown, siteConfig: SiteConfigurationType) => string> = {
   date: (val) => {
     if (typeof val !== 'number') return '';
-    const d = new Date(val * 1000);
-    const pad = (n: number) => n.toString().padStart(2, '0');
-    return `${pad(d.getDate())}.${pad(d.getMonth() + 1)}.${d.getFullYear()}`;
+    return new Date(val * 1000).toLocaleDateString('fi-FI', {
+      timeZone: 'Europe/Helsinki',
+      day: '2-digit',
+      month: '2-digit',
+      year: 'numeric',
+    });
   },
   url: (val, siteConfig) => siteConfig.urls.base + String(val ?? ''),
 };