Logging Optimization and Restructuring

CHANGELOG.md

@@ -12,7 +12,6 @@ The main work (all changes without a GitHub username in brackets in the below li
 ## __WORK IN PROGRESS__
 
 -   @matter/node
-    - Enhancement: Matter protocol initialization now runs independently of and after behavior initialization, giving behaviors more flexibility in participating in protocol setup
     - Enhancement: Each new PASE session now automatically arms the failsafe timer for 60s as required by specs
     - Fix: Fixes withBehaviors() method on endpoints
 
@@ -22,6 +21,7 @@ The main work (all changes without a GitHub username in brackets in the below li
 -   @matter/protocol
     - Feature: Reworks Event server handling and optionally allow Non-Volatile event storage (currently mainly used in tests)
     - Enhancement: Adds a too-fast-resubmission guard for Unicast MDNS messages
+    - Enhancement: Optimized Logging for messages in various places
     - Fix: Corrects some Batch invoke checks and logic
     - Fix: Fixes MDNS discovery duration for retransmission cases to be 5s
     - Fix: Processes all TXT/SRV records in MDNS messages and optimized the processing

packages/general/src/log/Diagnostic.ts

@@ -60,6 +60,11 @@ export namespace Diagnostic {
          */
         Weak = "weak",
 
+        /**
+         * A keylike diagnostic to list flags.  The key gets suppressed and the value is rendered as a key.
+         */
+        Flag = "flag",
+
         /**
          * An error message diagnostic.
          */
@@ -179,6 +184,13 @@ export namespace Diagnostic {
         return Diagnostic(Diagnostic.Presentation.Weak, value);
     }
 
+    /**
+     * Create a value presented as key
+     */
+    export function flag(value: string) {
+        return Diagnostic(Diagnostic.Presentation.Flag, value);
+    }
+
     /**
      * Create a value identifying the source of a diagnostic event.
      */
@@ -237,11 +249,19 @@ export namespace Diagnostic {
     /**
      * Create a K/V map that presents with formatted keys.
      */
-    export function dict(entries: object): Record<string, unknown> & Diagnostic {
-        return {
+    export function dict(entries: object, suppressUndefinedValues = true): Record<string, unknown> & Diagnostic {
+        const result: any = {
             ...entries,
             [presentation]: Diagnostic.Presentation.Dictionary,
         };
+        if (suppressUndefinedValues) {
+            for (const key in result) {
+                if (result[key] === undefined) {
+                    delete result[key];
+                }
+            }
+        }
+        return result;
     }
 
     /**
@@ -353,6 +373,23 @@ export namespace Diagnostic {
     export function hex(value: number | bigint) {
         return `0x${value.toString(16)}`;
     }
+
+    /**
+     * Convert an object with keys to a flag list listing the truthy keys in a keylike/flag presentation.
+     */
+    export function asFlags(flags: Record<string, unknown>) {
+        return Diagnostic.flag(Diagnostic.toFlagString(flags));
+    }
+
+    /**
+     * Convert an object with keys to a space-separated list of truthy keys.
+     */
+    export function toFlagString(flags: Record<string, unknown>) {
+        return Object.entries(flags)
+            .filter(([, value]) => !!value)
+            .map(([key]) => key)
+            .join(" ");
+    }
 }
 
 function formatError(error: any, options: { messagePrefix?: string; parentStack?: string[] } = {}) {

packages/general/src/log/LogFormat.ts

@@ -8,6 +8,7 @@ import { ImplementationError, InternalError, MatterError } from "../MatterError.
 import { Bytes } from "../util/Bytes.js";
 import { Lifecycle } from "../util/Lifecycle.js";
 import { serialize } from "../util/String.js";
+import { isObject } from "../util/Type.js";
 import { Diagnostic } from "./Diagnostic.js";
 import { LogLevel } from "./LogLevel.js";
 
@@ -67,6 +68,7 @@ interface Formatter {
     indent(producer: DiagnosticProducer): string;
     break(): string;
     key(text: string): string;
+    keylike(text: string): string;
     value(producer: DiagnosticProducer): string;
     strong(producer: DiagnosticProducer): string;
     weak(producer: DiagnosticProducer): string;
@@ -133,6 +135,7 @@ function formatPlain(diagnostic: unknown, indents = 0) {
             } ${message.facility} ${message.prefix}${formattedValues}`;
         },
         key: text => creator.text(`${text}: `),
+        keylike: text => creator.text(`${text}`),
         value: producer => creator.text(producer()),
         strong: producer => creator.text(`*${producer()}*`),
         weak: producer => creator.text(producer()),
@@ -270,6 +273,8 @@ function formatAnsi(diagnostic: unknown, indents = 0) {
 
         key: text => creator.text(style("key", `${text}: `)),
 
+        keylike: text => creator.text(style("key", `${text}`)),
+
         value: producer => {
             styles.push("value");
             const result = producer();
@@ -433,6 +438,7 @@ function formatHtml(diagnostic: unknown) {
         break: () => "<br/>",
         indent: producer => htmlSpan("indent", producer()),
         key: text => htmlSpan("key", `${escape(text)}:`) + " ",
+        keylike: text => htmlSpan("key", `${escape(text)}`),
         value: producer => htmlSpan("value", producer()),
         strong: producer => `<em>${producer()}</em>`,
         weak: producer => htmlSpan("weak", producer()),
@@ -523,8 +529,19 @@ function renderDictionary(value: object, formatter: Formatter) {
         if (parts.length) {
             parts.push(" ");
         }
-        parts.push(formatter.key(k));
-        parts.push(formatter.value(() => renderDiagnostic(v, formatter)));
+        const suppressKey = isObject(v) && (v as Diagnostic)[Diagnostic.presentation] === Diagnostic.Presentation.Flag;
+        if (!suppressKey) {
+            parts.push(formatter.key(k));
+        }
+        const formattedValue = formatter.value(() => renderDiagnostic(v, formatter));
+        if (!suppressKey || formattedValue.length) {
+            parts.push(formattedValue);
+        } else {
+            // if flag but the value is empty we need to remove the last  space if added above
+            if (parts.length && parts[parts.length - 1] === " ") {
+                parts.pop();
+            }
+        }
     }
 
     return parts.join("");
@@ -598,6 +615,9 @@ function renderDiagnostic(value: unknown, formatter: Formatter): string {
         case Diagnostic.Presentation.Deleted:
             return formatter.deleted(() => renderDiagnostic(value, formatter));
 
+        case Diagnostic.Presentation.Flag:
+            return (value as string).length ? formatter.keylike(value as string) : "";
+
         case Diagnostic.Presentation.Error:
             return formatter.error(() => renderDiagnostic(value, formatter));
 

packages/nodejs/test/IntegrationTest.ts

@@ -413,7 +413,7 @@ describe("Integration Test", () => {
                     { timedRequestTimeoutMs: 1 },
                 );
                 await assert.rejects(async () => await promise, {
-                    message: "(148) Received error status: 148", // Timeout expired
+                    message: "(148) Received error status: 148 (InvokeResponse)", // Timeout expired
                 });
             });
 
@@ -431,7 +431,7 @@ describe("Integration Test", () => {
                 );
                 const promise = onoffCluster.toggle(undefined, { timedRequestTimeoutMs: 1 });
                 await assert.rejects(async () => await promise, {
-                    message: "(148) Received error status: 148", // Timeout expired
+                    message: "(148) Received error status: 148 (InvokeResponse)", // Timeout expired
                 });
             });
 

packages/protocol/src/codec/MessageCodec.ts

@@ -5,7 +5,9 @@
  */
 
 import { Bytes, DataReader, DataWriter, Diagnostic, Endian, NotImplementedError, UnexpectedDataError } from "#general";
-import { GroupId, NodeId } from "#types";
+import { ExchangeLogContext } from "#protocol/index.js";
+import { GroupId, INTERACTION_PROTOCOL_ID, NodeId, SECURE_CHANNEL_PROTOCOL_ID, SecureMessageType } from "#types";
+import { MessageType } from "../interaction/InteractionMessenger.js";
 
 export interface PacketHeader {
     sessionId: number;
@@ -84,6 +86,22 @@ const enum SecurityFlag {
     HasMessageExtension = 0b00100000,
 }
 
+function mapProtocolAndMessageType(protocolId: number, messageType: number): { type: string; for?: string } {
+    const msgTypeHex = Diagnostic.hex(messageType);
+    const type = `${Diagnostic.hex(protocolId)}/${msgTypeHex}`;
+    switch (protocolId) {
+        case SECURE_CHANNEL_PROTOCOL_ID: {
+            return { type, for: `SC/${SecureMessageType[messageType] ?? msgTypeHex}` };
+        }
+        case INTERACTION_PROTOCOL_ID: {
+            return { type, for: `I/${MessageType[messageType] ?? msgTypeHex}` };
+        }
+        // TODO Add BDX and UDC once we support it
+        default:
+            return { type };
+    }
+}
+
 export class MessageCodec {
     static decodePacket(data: Uint8Array): DecodedPacket {
         const reader = new DataReader(data, Endian.Little);
@@ -238,16 +256,30 @@ export class MessageCodec {
             payloadHeader: { exchangeId, messageType, protocolId, ackedMessageId, requiresAck },
             payload,
         }: Message,
-        isDuplicate = false,
+        logContext?: ExchangeLogContext,
     ) {
-        return Diagnostic.dict({
-            id: `${sessionId}/${exchangeId}/${messageId}`,
-            type: `${protocolId}/${messageType}`,
-            acked: ackedMessageId,
-            reqAck: requiresAck,
-            duplicate: isDuplicate,
-            payload: payload,
-        });
+        const duplicate = !!logContext?.duplicate;
+        const forInfo = logContext?.for;
+        const log = { ...logContext };
+        delete log.duplicate;
+        delete log.for;
+        const { type, for: forType } = mapProtocolAndMessageType(protocolId, messageType);
+        return Diagnostic.dict(
+            {
+                for: forInfo ?? forType,
+                ...log,
+                msgId: `${sessionId}/${exchangeId}/${messageId}`,
+                type,
+                acked: ackedMessageId,
+                msgFlags: Diagnostic.asFlags({
+                    reqAck: requiresAck,
+                    dup: duplicate,
+                }),
+                size: payload.length ? payload.length : undefined,
+                payload: payload.length ? payload : undefined,
+            },
+            true,
+        );
     }
 
     private static encodePayloadHeader({

packages/protocol/src/interaction/InteractionClient.ts

@@ -621,7 +621,6 @@ export class InteractionClient {
             updateReceived?.();
 
             if (!Array.isArray(dataReport.attributeReports) || !dataReport.attributeReports.length) {
-                logger.debug(`Subscription result empty for subscription ID ${dataReport.subscriptionId}`);
                 return;
             }
 
@@ -715,7 +714,6 @@ export class InteractionClient {
             updateReceived?.();
 
             if (!Array.isArray(dataReport.eventReports) || !dataReport.eventReports.length) {
-                logger.debug(`Subscription result empty for subscription ID ${dataReport.subscriptionId}`);
                 return;
             }
 
@@ -889,7 +887,6 @@ export class InteractionClient {
                 (!Array.isArray(dataReport.attributeReports) || !dataReport.attributeReports.length) &&
                 (!Array.isArray(dataReport.eventReports) || !dataReport.eventReports.length)
             ) {
-                logger.debug(`Subscription result empty for subscription ID ${dataReport.subscriptionId}`);
                 return;
             }
             const { attributeReports, eventReports } = dataReport;