Improve message logging from communications module (#2514)

* fix ids in logging

* use new logger for child messages

* changefile

* Make shared message id printer

* Double id string

Author: AE-MS

.vscode/settings.json

@@ -1,5 +1,5 @@
 {
-  "cSpell.words": ["adal", "ipados", "teamspace", "uninitialize", "xvfb"],
+  "cSpell.words": ["adal", "frameless", "ipados", "teamspace", "uninitialize", "xvfb"],
   "editor.defaultFormatter": "esbenp.prettier-vscode",
   "eslint.workingDirectories": [
     "./apps/ssr-test-app/",

change/@microsoft-teams-js-b61435ce-c9da-47bc-9b65-2710406ac8d7.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "Updated logging for messages to be clearer",
+  "packageName": "@microsoft/teams-js",
+  "email": "[email protected]",
+  "dependentChangeType": "patch"
+}

packages/teams-js/src/internal/communication.ts

@@ -87,7 +87,7 @@ export function initializeCommunication(
   apiVersionTag: string,
 ): Promise<InitializeResponse> {
   // Listen for messages post to our window
-  CommunicationPrivate.messageListener = async (evt: DOMMessageEvent): Promise<void> => await processMessage(evt);
+  CommunicationPrivate.messageListener = (evt: DOMMessageEvent): Promise<void> => processIncomingMessage(evt);
 
   // If we are in an iframe, our parent window is the one hosting us (i.e., window.parent); otherwise,
   // it's the window that opened us (i.e., window.opener)
@@ -108,7 +108,7 @@ export function initializeCommunication(
     const extendedWindow = Communication.currentWindow as unknown as ExtendedWindow;
     if (extendedWindow.nativeInterface) {
       GlobalVars.isFramelessWindow = true;
-      extendedWindow.onNativeMessage = handleParentMessage;
+      extendedWindow.onNativeMessage = handleIncomingMessageFromParent;
     } else {
       // at this point we weren't able to find a parent to talk to, no way initialization will succeed
       return Promise.reject(new Error('Initialization Failed. No Parent window found.'));
@@ -368,7 +368,9 @@ export function sendNestedAuthRequestToTopWindow(message: string): NestedAppAuth
   const targetWindow = Communication.topWindow;
   const request = createNestedAppAuthRequest(message);
 
-  logger('Message %i information: %o', request.uuid, { actionName: request.func });
+  logger('Message %s information: %o', getMessageIdsAsLogString(request), {
+    actionName: request.func,
+  });
 
   return sendRequestToTargetWindowHelper(targetWindow, request) as NestedAppAuthRequest;
 }
@@ -389,7 +391,11 @@ function sendRequestToTargetWindowHelper(
 
   if (GlobalVars.isFramelessWindow) {
     if (Communication.currentWindow && Communication.currentWindow.nativeInterface) {
-      logger(`Sending message %i to ${targetWindowName} via framelessPostMessage interface`, request.uuidAsString);
+      logger(
+        'Sending message %s to %s via framelessPostMessage interface',
+        getMessageIdsAsLogString(request),
+        targetWindowName,
+      );
       (Communication.currentWindow as ExtendedWindow).nativeInterface.framelessPostMessage(JSON.stringify(request));
     }
   } else {
@@ -398,10 +404,10 @@ function sendRequestToTargetWindowHelper(
     // If the target window isn't closed and we already know its origin, send the message right away; otherwise,
     // queue the message and send it after the origin is established
     if (targetWindow && targetOrigin) {
-      logger(`Sending message %i to ${targetWindowName} via postMessage`, request.uuidAsString);
+      logger('Sending message %s to %s via postMessage', getMessageIdsAsLogString(request), targetWindowName);
       targetWindow.postMessage(request, targetOrigin);
     } else {
-      logger(`Adding message %i to ${targetWindowName} message queue`, request.uuidAsString);
+      logger('Adding message %s to %s message queue', getMessageIdsAsLogString(request), targetWindowName);
       getTargetMessageQueue(targetWindow).push(messageRequest);
     }
   }
@@ -424,21 +430,24 @@ function sendMessageToParentHelper(
   const targetWindow = Communication.parentWindow;
   const request = createMessageRequest(apiVersionTag, actionName, args);
 
-  logger('Message %i information: %o', request.uuid, { actionName, args });
+  logger('Message %s information: %o', getMessageIdsAsLogString(request), { actionName, args });
 
   return sendRequestToTargetWindowHelper(targetWindow, request);
 }
 
-const processMessageLogger = communicationLogger.extend('processMessage');
+const processIncomingMessageLogger = communicationLogger.extend('processIncomingMessage');
 
 /**
  * @internal
  * Limited to Microsoft-internal use
  */
-async function processMessage(evt: DOMMessageEvent): Promise<void> {
+async function processIncomingMessage(evt: DOMMessageEvent): Promise<void> {
   // Process only if we received a valid message
   if (!evt || !evt.data || typeof evt.data !== 'object') {
-    processMessageLogger('Unrecognized message format received by app, message being ignored. Message: %o', evt);
+    processIncomingMessageLogger(
+      'Unrecognized message format received by app, message being ignored. Message: %o',
+      evt,
+    );
     return;
   }
 
@@ -448,20 +457,23 @@ async function processMessage(evt: DOMMessageEvent): Promise<void> {
   const messageSource = evt.source || (evt.originalEvent && evt.originalEvent.source);
   const messageOrigin = evt.origin || (evt.originalEvent && evt.originalEvent.origin);
 
-  return shouldProcessMessage(messageSource, messageOrigin).then((result) => {
+  return shouldProcessIncomingMessage(messageSource, messageOrigin).then((result) => {
     if (!result) {
-      processMessageLogger(
-        'Message being ignored by app because it is either coming from the current window or a different window with an invalid origin',
+      processIncomingMessageLogger(
+        'Message being ignored by app because it is either coming from the current window or a different window with an invalid origin, message: %o, source: %o, origin: %o',
+        evt,
+        messageSource,
+        messageOrigin,
       );
       return;
     }
     // Update our parent and child relationships based on this message
     updateRelationships(messageSource, messageOrigin);
     // Handle the message
     if (messageSource === Communication.parentWindow) {
-      handleParentMessage(evt);
+      handleIncomingMessageFromParent(evt);
     } else if (messageSource === Communication.childWindow) {
-      handleChildMessage(evt);
+      handleIncomingMessageFromChild(evt);
     }
   });
 }
@@ -511,7 +523,7 @@ function processAuthBridgeMessage(evt: MessageEvent, onMessageReceived: (respons
     return;
   }
 
-  if (!shouldProcessMessage(messageSource, messageOrigin)) {
+  if (!shouldProcessIncomingMessage(messageSource, messageOrigin)) {
     logger(
       'Message being ignored by app because it is either coming from the current window or a different window with an invalid origin',
     );
@@ -542,7 +554,7 @@ function processAuthBridgeMessage(evt: MessageEvent, onMessageReceived: (respons
   onMessageReceived(message);
 }
 
-const shouldProcessMessageLogger = communicationLogger.extend('shouldProcessMessage');
+const shouldProcessIncomingMessageLogger = communicationLogger.extend('shouldProcessIncomingMessage');
 
 /**
  * @hidden
@@ -551,11 +563,11 @@ const shouldProcessMessageLogger = communicationLogger.extend('shouldProcessMess
  * @internal
  * Limited to Microsoft-internal use
  */
-async function shouldProcessMessage(messageSource: Window, messageOrigin: string): Promise<boolean> {
+async function shouldProcessIncomingMessage(messageSource: Window, messageOrigin: string): Promise<boolean> {
   // Process if message source is a different window and if origin is either in
   // Teams' pre-known whitelist or supplied as valid origin by user during initialization
   if (Communication.currentWindow && messageSource === Communication.currentWindow) {
-    shouldProcessMessageLogger('Should not process message because it is coming from the current window');
+    shouldProcessIncomingMessageLogger('Should not process message because it is coming from the current window');
     return false;
   } else if (
     Communication.currentWindow &&
@@ -569,13 +581,13 @@ async function shouldProcessMessage(messageSource: Window, messageOrigin: string
     try {
       messageOriginURL = new URL(messageOrigin);
     } catch (_) {
-      shouldProcessMessageLogger('Message has an invalid origin of %s', messageOrigin);
+      shouldProcessIncomingMessageLogger('Message has an invalid origin of %s', messageOrigin);
       return false;
     }
 
     const isOriginValid = await validateOrigin(messageOriginURL);
     if (!isOriginValid) {
-      shouldProcessMessageLogger('Message has an invalid origin of %s', messageOrigin);
+      shouldProcessIncomingMessageLogger('Message has an invalid origin of %s', messageOrigin);
     }
     return isOriginValid;
   }
@@ -619,14 +631,14 @@ function updateRelationships(messageSource: Window, messageOrigin: string): void
   flushMessageQueue(Communication.childWindow);
 }
 
-const handleParentMessageLogger = communicationLogger.extend('handleParentMessage');
+const handleIncomingMessageFromParentLogger = communicationLogger.extend('handleIncomingMessageFromParent');
 
 /**
  * @internal
  * Limited to Microsoft-internal use
  */
 function retrieveMessageUUIDFromResponse(response: MessageResponse): MessageUUID | undefined {
-  const logger = handleParentMessageLogger;
+  const logger = handleIncomingMessageFromParentLogger;
   if (response.uuid) {
     const responseUUID = response.uuid;
     const callbackUUID = retrieveMessageUUIDFromCallback(CommunicationPrivate.callbacks, responseUUID);
@@ -644,10 +656,7 @@ function retrieveMessageUUIDFromResponse(response: MessageResponse): MessageUUID
   } else {
     return CommunicationPrivate.legacyMessageIdsToUuidMap[response.id];
   }
-  logger(
-    `Received a message with uuid: ${response.uuid?.toString()} and legacyId: %i that failed to produce a callbackId`,
-    response.id,
-  );
+  logger('Received message %s that failed to produce a callbackId', getMessageIdsAsLogString(response));
   return undefined;
 }
 
@@ -657,7 +666,7 @@ function retrieveMessageUUIDFromResponse(response: MessageResponse): MessageUUID
  *
  * This function is used to compare a new MessageUUID object value to the key values in the specified callback and retrieving that key
  * We use this because two objects with the same value are not considered equivalent therefore we can't use the new MessageUUID object
- * as a key to retrieve the value assosciated with it and should use this function instead.
+ * as a key to retrieve the value associated with it and should use this function instead.
  */
 function retrieveMessageUUIDFromCallback(
   map: Map<MessageUUID, Function>,
@@ -695,8 +704,8 @@ function removeMessageHandlers(message: MessageResponse, map: Map<MessageUUID, F
  * @internal
  * Limited to Microsoft-internal use
  */
-function handleParentMessage(evt: DOMMessageEvent): void {
-  const logger = handleParentMessageLogger;
+function handleIncomingMessageFromParent(evt: DOMMessageEvent): void {
+  const logger = handleIncomingMessageFromParentLogger;
 
   if ('id' in evt.data && typeof evt.data.id === 'number') {
     // Call any associated Communication.callbacks
@@ -705,37 +714,49 @@ function handleParentMessage(evt: DOMMessageEvent): void {
     const callbackId = retrieveMessageUUIDFromResponse(message);
     if (callbackId) {
       const callback = CommunicationPrivate.callbacks.get(callbackId);
-      logger('Received a response from parent for message %i', callbackId);
+      logger('Received a response from parent for message %s', callbackId.toString());
       if (callback) {
-        logger('Invoking the registered callback for message %i with arguments %o', callbackId, message.args);
+        logger(
+          'Invoking the registered callback for message %s with arguments %o',
+          callbackId.toString(),
+          message.args,
+        );
         // eslint-disable-next-line @typescript-eslint/ban-ts-comment
         // @ts-ignore
         callback.apply(null, [...message.args, message.isPartialResponse]);
 
         // Remove the callback to ensure that the callback is called only once and to free up memory if response is a complete response
         if (!isPartialResponse(evt)) {
-          logger('Removing registered callback for message %i', callbackId);
+          logger('Removing registered callback for message %s', callbackId.toString());
           removeMessageHandlers(message, CommunicationPrivate.callbacks);
         }
       }
       const promiseCallback = CommunicationPrivate.promiseCallbacks.get(callbackId);
       if (promiseCallback) {
-        logger('Invoking the registered promise callback for message %i with arguments %o', callbackId, message.args);
+        logger(
+          'Invoking the registered promise callback for message %s with arguments %o',
+          callbackId.toString(),
+          message.args,
+        );
         promiseCallback(message.args);
 
-        logger('Removing registered promise callback for message %i', callbackId);
+        logger('Removing registered promise callback for message %s', callbackId.toString());
         removeMessageHandlers(message, CommunicationPrivate.promiseCallbacks);
       }
       const portCallback = CommunicationPrivate.portCallbacks.get(callbackId);
       if (portCallback) {
-        logger('Invoking the registered port callback for message %i with arguments %o', callbackId, message.args);
+        logger(
+          'Invoking the registered port callback for message %s with arguments %o',
+          callbackId.toString(),
+          message.args,
+        );
         let port: MessagePort | undefined;
         if (evt.ports && evt.ports[0] instanceof MessagePort) {
           port = evt.ports[0];
         }
         portCallback(port, message.args);
 
-        logger('Removing registered port callback for message %i', callbackId);
+        logger('Removing registered port callback for message %s', callbackId.toString());
         removeMessageHandlers(message, CommunicationPrivate.portCallbacks);
       }
       if (message.uuid) {
@@ -745,7 +766,7 @@ function handleParentMessage(evt: DOMMessageEvent): void {
   } else if ('func' in evt.data && typeof evt.data.func === 'string') {
     // Delegate the request to the proper handler
     const message = evt.data as MessageRequest;
-    logger('Received an action message %s from parent', message.func);
+    logger('Received a message from parent %s, action: "%s"', getMessageIdsAsLogString(message), message.func);
     callHandler(message.func, message.args);
   } else {
     logger('Received an unknown message: %O', evt);
@@ -760,28 +781,47 @@ function isPartialResponse(evt: DOMMessageEvent): boolean {
   return evt.data.isPartialResponse === true;
 }
 
+const handleIncomingMessageFromChildLogger = communicationLogger.extend('handleIncomingMessageFromChild');
+
 /**
  * @internal
  * Limited to Microsoft-internal use
  */
-function handleChildMessage(evt: DOMMessageEvent): void {
+function handleIncomingMessageFromChild(evt: DOMMessageEvent): void {
   if ('id' in evt.data && 'func' in evt.data) {
     // Try to delegate the request to the proper handler, if defined
     const message = deserializeMessageRequest(evt.data as SerializedMessageRequest);
     const [called, result] = callHandler(message.func, message.args);
     if (called && typeof result !== 'undefined') {
+      handleIncomingMessageFromChildLogger(
+        'Returning message %s from child back to child, action: %s.',
+        getMessageIdsAsLogString(message),
+        message.func,
+      );
+
       // eslint-disable-next-line @typescript-eslint/ban-ts-comment
       // @ts-ignore
       sendMessageResponseToChild(message.id, message.uuid, Array.isArray(result) ? result : [result]);
     } else {
       // No handler, proxy to parent
+
+      handleIncomingMessageFromChildLogger(
+        'Relaying message %s from child to parent, action: %s. Relayed message will have a new id.',
+        getMessageIdsAsLogString(message),
+        message.func,
+      );
+
       sendMessageToParent(
         getApiVersionTag(ApiVersionNumber.V_2, ApiName.Tasks_StartTask),
         message.func,
         message.args,
         (...args: any[]): void => {
           if (Communication.childWindow) {
             const isPartialResponse = args.pop();
+            handleIncomingMessageFromChildLogger(
+              'Message from parent being relayed to child, id: %s',
+              getMessageIdsAsLogString(message),
+            );
             // eslint-disable-next-line @typescript-eslint/ban-ts-comment
             // @ts-ignore
             sendMessageResponseToChild(message.id, message.uuid, args, isPartialResponse);
@@ -869,8 +909,9 @@ function flushMessageQueue(targetWindow: Window | any): void {
 
       /* eslint-disable-next-line strict-null-checks/all */ /* Fix tracked by 5730662 */
       flushMessageQueueLogger(
-        'Flushing message %i from ' + target + ' message queue via postMessage.',
-        request?.uuidAsString,
+        'Flushing message %s from %s message queue via postMessage.',
+        getMessageIdsAsLogString(request),
+        target,
       );
 
       targetWindow.postMessage(request, targetOrigin);
@@ -1020,3 +1061,21 @@ function createMessageEvent(func: string, args?: any[]): MessageRequest {
     args: args || [],
   };
 }
+
+function getMessageIdsAsLogString(
+  message:
+    | SerializedMessageRequest
+    | SerializedMessageResponse
+    | MessageRequestWithRequiredProperties
+    | MessageRequest
+    | MessageResponse
+    | NestedAppAuthRequest,
+): string {
+  if ('uuidAsString' in message) {
+    return `${message.uuidAsString} (legacy id: ${message.id})`;
+  } else if ('uuid' in message && message.uuid !== undefined) {
+    return `${message.uuid.toString()} (legacy id: ${message.id})`;
+  } else {
+    return `legacy id: ${message.id} (no uuid)`;
+  }
+}