Adds more verbose logging (#7)

CreateMessage/handler.ts

@@ -391,11 +391,9 @@ export function CreateMessageHandler(
       isSuccess: boolean
     ): void =>
       context.log.verbose(
-        `CreateMessageHandler|${
-          isSuccess ? "SUCCESS" : "FAILURE"
-        }|SERVICE_ID=${serviceId}|RECIPIENT=${fiscalCode}|RESPONSE=${r.kind}|${
-          r.detail
-        }`
+        `CreateMessageHandler|SERVICE_ID=${serviceId}|RECIPIENT=${fiscalCode}|RESPONSE=${
+          r.kind
+        }|${r.detail}|RESULT=${isSuccess ? "SUCCESS" : "FAILURE"}`
       );
 
     // here we create an async Task that processes the request

CreateNotificationActivity/handler.ts

@@ -31,14 +31,13 @@ import { ISuccessfulStoreMessageContentActivityResult } from "../StoreMessageCon
  * Attempt to resolve an email address from
  * the recipient profile.
  */
-function getEmailAddressFromProfile(
+const getEmailAddressFromProfile = (
   profile: RetrievedProfile
-): Option<NotificationChannelEmail> {
-  return fromNullable(profile.email).map(email => ({
+): Option<NotificationChannelEmail> =>
+  fromNullable(profile.email).map(email => ({
     addressSource: NotificationAddressSourceEnum.PROFILE_ADDRESS,
     toAddress: email
   }));
-}
 
 /**
  * Try to create (save) a new notification
@@ -102,6 +101,10 @@ export const getCreateNotificationActivityHandler = (
 ): Promise<ICreateNotificationActivityResult> => {
   const { createdMessageEvent, storeMessageContentActivityResult } = input;
 
+  const logPrefix = `CreateNotificationActivity|MESSAGE_ID=${createdMessageEvent.message.id}|RECIPIENT=${createdMessageEvent.message.fiscalCode}`;
+
+  context.log.verbose(`${logPrefix}|STARTING`);
+
   const {
     senderMetadata,
     message: newMessageWithoutContent
@@ -118,14 +121,15 @@ export const getCreateNotificationActivityHandler = (
   const isEmailBlockedForService =
     blockedInboxOrChannels.indexOf(BlockedInboxOrChannelEnum.EMAIL) >= 0;
 
+  const emailFromProfile = getEmailAddressFromProfile(profile);
+
   const maybeAllowedEmailNotification = isEmailBlockedForService
     ? none
-    : getEmailAddressFromProfile(profile).orElse(() => {
-        context.log.verbose(
-          `CreateNotificationActivity|User profile has no email address set|${profile.fiscalCode}`
-        );
-        return none;
-      });
+    : emailFromProfile;
+
+  context.log.verbose(
+    `${logPrefix}|CHANNEL=EMAIL|SERVICE_BLOCKED=${isEmailBlockedForService}|PROFILE_EMAIL=${emailFromProfile.isSome()}|WILL_NOTIFY=${maybeAllowedEmailNotification.isSome()}`
+  );
 
   //
   //  Webhook notification
@@ -136,17 +140,21 @@ export const getCreateNotificationActivityHandler = (
     blockedInboxOrChannels.indexOf(BlockedInboxOrChannelEnum.WEBHOOK) >= 0;
 
   // whether the recipient wants us to send notifications to the app backend
-  const isWebhookBlockedInProfile = profile.isWebhookEnabled === true;
+  const isWebhookEnabledInProfile = profile.isWebhookEnabled === true;
 
   const isWebhookEnabled =
-    !isWebhookBlockedForService && isWebhookBlockedInProfile;
+    !isWebhookBlockedForService && isWebhookEnabledInProfile;
 
   const maybeAllowedWebhookNotification = isWebhookEnabled
     ? some({
         url: lDefaultWebhookUrl
       })
     : none;
 
+  context.log.verbose(
+    `${logPrefix}|CHANNEL=WEBHOOK|CHANNEL_ENABLED=${isWebhookEnabledInProfile}|SERVICE_BLOCKED=${isWebhookBlockedForService}|WILL_NOTIFY=${maybeAllowedWebhookNotification.isSome()}`
+  );
+
   // store fiscalCode -> serviceId
   const errorOrSenderService = await lSenderServiceModel.createOrUpdate(
     newSenderService(
@@ -159,6 +167,7 @@ export const getCreateNotificationActivityHandler = (
   );
 
   if (isLeft(errorOrSenderService)) {
+    context.log.error(`${logPrefix}|ERROR=${errorOrSenderService.value.body}`);
     throw new Error(
       `Cannot save sender service id: ${errorOrSenderService.value.body}`
     );
@@ -170,9 +179,7 @@ export const getCreateNotificationActivityHandler = (
   ].every(_ => _.isNone());
 
   if (noChannelsConfigured) {
-    context.log.verbose(
-      `CreateNotificationActivity|No channels configured for the user ${newMessageWithoutContent.fiscalCode} and no default address provided`
-    );
+    context.log.warn(`${logPrefix}|RESULT=NO_CHANNELS_ENABLED`);
     // return no notifications
     return { kind: "none" };
   }
@@ -198,6 +205,8 @@ export const getCreateNotificationActivityHandler = (
     newNotification
   );
 
+  context.log.verbose(`${logPrefix}|RESULT=SUCCESS`);
+
   // output notification events (one for each channel)
   return {
     hasEmail: maybeAllowedEmailNotification.isSome(),

EmailNotificationActivity/handler.ts

@@ -72,6 +72,8 @@ export const getEmailNotificationActivityHandler = (
 
   const emailNotificationEvent = decodedEmailNotification.value;
 
+  const logPrefix = `EmailNotificationActivity|MESSAGE_ID=${emailNotificationEvent.message.id}|RECIPIENT=${emailNotificationEvent.message.fiscalCode}|NOTIFICATION_ID=${emailNotificationEvent.notificationId}`;
+
   const {
     message,
     content,
@@ -102,9 +104,7 @@ export const getEmailNotificationActivityHandler = (
     message.timeToLiveSeconds * 1000
   ) {
     // if the message is expired no more processing is necessary
-    context.log.verbose(
-      `EmailNotificationActivity|Message expired|MESSAGE_ID=${message.id}`
-    );
+    context.log.warn(`${logPrefix}|RESULT=TTL_EXPIRED`);
     return { kind: "SUCCESS", result: "EXPIRED" };
   }
 
@@ -116,28 +116,24 @@ export const getEmailNotificationActivityHandler = (
   if (isLeft(errorOrMaybeNotification)) {
     const error = errorOrMaybeNotification.value;
     // we got an error while fetching the notification
-    throw new Error(
-      `EmailNotificationActivity|Error while fetching the notification|NOTIFICATION_ID=${notificationId}|MESSAGE_ID=${message.id}|ERROR=${error.code}`
-    );
+    context.log.warn(`${logPrefix}|ERROR=${error.body}`);
+    throw new Error(`Error while fetching the notification: ${error.body}`);
   }
   const maybeEmailNotification = errorOrMaybeNotification.value;
   if (isNone(maybeEmailNotification)) {
     // it may happen that the object is not yet visible to this function due to latency
     // as the notification object is retrieved from database and we may be hitting a
     // replica that is not yet in sync
-    throw new Error(
-      `EmailNotificationActivity|Notification not found|NOTIFICATION_ID=${notificationId}|MESSAGE_ID=${message.id}`
-    );
+    context.log.warn(`${logPrefix}|RESULT=NOTIFICATION_NOT_FOUND`);
+    throw new Error(`Notification not found`);
   }
   const errorOrEmailNotification = EmailNotification.decode(
     maybeEmailNotification.value
   );
   if (isLeft(errorOrEmailNotification)) {
     // The notification object is not compatible with this code
     const error = readableReport(errorOrEmailNotification.value);
-    context.log.error(
-      `EmailNotificationActivity|Wrong format for email notification|NOTIFICATION_ID=${notificationId}|MESSAGE_ID=${message.id}|ERROR=${error}`
-    );
+    context.log.error(`${logPrefix}|ERROR=${error}`);
     return { kind: "FAILURE", reason: "WRONG_FORMAT" };
   }
   const emailNotification = errorOrEmailNotification.value.channels.EMAIL;
@@ -189,9 +185,7 @@ export const getEmailNotificationActivityHandler = (
       resultCode: error.name,
       success: false
     });
-    context.log.error(
-      `EmailNotificationActivity|Error while sending email|NOTIFICATION_ID=${notificationId}|MESSAGE_ID=${message.id}|ERROR=${error.message}`
-    );
+    context.log.error(`${logPrefix}|ERROR=${error.message}`);
     throw new Error("Error while sending email");
   }
 
@@ -213,6 +207,8 @@ export const getEmailNotificationActivityHandler = (
     }
   });
 
+  context.log.verbose(`${logPrefix}|RESULT=SUCCESS`);
+
   // TODO: handling bounces and delivery updates
   // see https://nodemailer.com/usage/#sending-mail
   // see #150597597

MessageStatusUpdaterActivity/handler.ts

@@ -26,7 +26,7 @@ export const getMessageStatusUpdaterActivityHandler = (
   const decodedInput = Input.decode(input);
   if (decodedInput.isLeft()) {
     context.log.error(
-      `MessageStatusUpdaterActivity|Cannot decode input|ERROR=${ReadableReporter.report(
+      `MessageStatusUpdaterActivity|ERROR=${ReadableReporter.report(
         decodedInput
       ).join(" / ")}`
     );
@@ -44,13 +44,13 @@ export const getMessageStatusUpdaterActivityHandler = (
 
   if (result.isLeft()) {
     context.log.error(
-      `MessageStatusUpdaterActivity|Error while updating message status|MESSAGE_ID=${messageId}|STATUS=${status}|ERROR=${result.value.message}`
+      `MessageStatusUpdaterActivity|MESSAGE_ID=${messageId}|STATUS=${status}|ERROR=${result.value.message}`
     );
     throw new Error(result.value.message);
   }
 
   context.log.verbose(
-    `MessageStatusUpdaterActivity|Message status updated|MESSAGE_ID=${messageId}|STATUS=${status}`
+    `MessageStatusUpdaterActivity|MESSAGE_ID=${messageId}|STATUS=${status}|RESULT=SUCCESS`
   );
 
   return { kind: "SUCCESS" };

NotificationStatusUpdaterActivity/handler.ts

@@ -58,13 +58,13 @@ export const getNotificationStatusUpdaterActivityHandler = (
 
   if (errorOrUpdatedNotificationStatus.isLeft()) {
     context.log.warn(
-      `NotificationStatusUpdaterActivity|Error while updating|MESSAGE_ID=${messageId}|NOTIFICATION_ID=${notificationId}|CHANNEL=${channel}|STATUS=${status}|ERROR=${errorOrUpdatedNotificationStatus.value}`
+      `NotificationStatusUpdaterActivity|MESSAGE_ID=${messageId}|NOTIFICATION_ID=${notificationId}|CHANNEL=${channel}|STATUS=${status}|ERROR=${errorOrUpdatedNotificationStatus.value}`
     );
     throw new Error(errorOrUpdatedNotificationStatus.value.message);
   }
 
   context.log.verbose(
-    `NotificationStatusUpdaterActivity|Notification status updated|MESSAGE_ID=${messageId}|NOTIFICATION_ID=${notificationId}|CHANNEL=${channel}|STATUS=${status}`
+    `NotificationStatusUpdaterActivity|MESSAGE_ID=${messageId}|NOTIFICATION_ID=${notificationId}|CHANNEL=${channel}|STATUS=${status}|RESULT=SUCCESS`
   );
 
   return { kind: "SUCCESS" };

StoreMessageContentActivity/handler.ts

@@ -43,9 +43,9 @@ export const getStoreMessageContentActivityHandler = (
 ): Promise<StoreMessageContentActivityResult> => {
   const newMessageWithoutContent = createdMessageEvent.message;
 
-  context.log.verbose(
-    `StoreMessageContentActivity|Received createdMessageEvent|MESSAGE_ID=${newMessageWithoutContent.id}|RECIPIENT=${newMessageWithoutContent.fiscalCode}`
-  );
+  const logPrefix = `StoreMessageContentActivity|MESSAGE_ID=${newMessageWithoutContent.id}|RECIPIENT=${newMessageWithoutContent.fiscalCode}`;
+
+  context.log.verbose(`${logPrefix}|STARTING`);
 
   // fetch user's profile associated to the fiscal code
   // of the recipient of the message
@@ -54,16 +54,18 @@ export const getStoreMessageContentActivityHandler = (
   );
 
   if (isLeft(errorOrMaybeProfile)) {
-    // The query has failed, we consider this as a trainsient error.
+    // The query has failed, we consider this as a transient error.
     // It's *critical* to trigger a retry here, otherwise no message
     // content will be saved.
+    context.log.error(`${logPrefix}|ERROR=${errorOrMaybeProfile.value.body}`);
     throw Error("Error while fetching profile");
   }
 
   const maybeProfile = errorOrMaybeProfile.value;
 
   if (isNone(maybeProfile)) {
     // the recipient doesn't have any profile yet
+    context.log.warn(`${logPrefix}|RESULT=PROFILE_NOT_FOUND`);
     return { kind: "FAILURE", reason: "PROFILE_NOT_FOUND" };
   }
 
@@ -77,9 +79,7 @@ export const getStoreMessageContentActivityHandler = (
     .getOrElse(new Set());
 
   context.log.verbose(
-    "StoreMessageContentActivityHandler|Blocked Channels(%s): %s",
-    newMessageWithoutContent.fiscalCode,
-    JSON.stringify(blockedInboxOrChannels)
+    `${logPrefix}|BLOCKED_CHANNELS=${JSON.stringify(blockedInboxOrChannels)}`
   );
 
   //
@@ -91,6 +91,7 @@ export const getStoreMessageContentActivityHandler = (
 
   if (!isInboxEnabled) {
     // the recipient's inbox is disabled
+    context.log.warn(`${logPrefix}|RESULT=MASTER_INBOX_DISABLED`);
     return { kind: "FAILURE", reason: "MASTER_INBOX_DISABLED" };
   }
 
@@ -101,6 +102,7 @@ export const getStoreMessageContentActivityHandler = (
 
   if (isMessageStorageBlockedForService) {
     // the recipient's inbox is disabled
+    context.log.warn(`${logPrefix}|RESULT=SENDER_BLOCKED`);
     return { kind: "FAILURE", reason: "SENDER_BLOCKED" };
   }
 
@@ -115,6 +117,7 @@ export const getStoreMessageContentActivityHandler = (
   );
 
   if (isLeft(errorOrAttachment)) {
+    context.log.error(`${logPrefix}|ERROR=${errorOrAttachment.value}`);
     throw new Error("Error while storing message content");
   }
 
@@ -129,9 +132,12 @@ export const getStoreMessageContentActivityHandler = (
   );
 
   if (isLeft(updatedMessageOrError)) {
+    context.log.error(`${logPrefix}|ERROR=${updatedMessageOrError.value.body}`);
     throw new Error("Error while updating message pending status");
   }
 
+  context.log.verbose(`${logPrefix}|RESULT=SUCCESS`);
+
   return {
     // being blockedInboxOrChannels a Set, we explicitly convert it to an array
     // since a Set can't be serialized to JSON