fix(operations): test nesting against the rows being grouped

CHANGELOG.md

@@ -43,6 +43,7 @@ _If you are upgrading from 1.x: please see [Migrating from 1.x](MIGRATING.md)._
 
 ### Fixed
 
+- Report a grouped `apexlog_list_slow_operations` `durationTotalMs` below the row's own `durationSelfMs`, which is impossible and which no caller can detect. A group counted a member as nested when an operation above it in the log shared the group's key, even where `kind` or `namespace` had excluded that operation from the ranking. Nesting is now tested against the rows being grouped: 114 rows in 111,624 across 124 real logs and every selection ([#101])
 - Declare `apexlog_execute_anonymous` destructive, so clients stop treating it as safe to run unprompted ([#52])
 - Warn when a caller-given `apexlog_execute_anonymous` `outputDir` resolves outside every root the client declared. The log is still written, and the response names where it went ([#109])
 - Close cleanly on `SIGTERM`, so a supervised restart or a container stop no longer kills the server mid-shutdown ([#109])

src/tools/operations.ts

@@ -250,6 +250,12 @@ export function groupOperations(
   const groups = new Map<string, Operation>();
   const identityOf = IDENTITY_BY_GROUP[by];
 
+  // `parent` is the log's chain, not this call's. When a caller narrows the
+  // operations by kind or namespace, an ancestor outside the selection can share
+  // a group's key without being in the group, and suppressing on it would report
+  // a total below the row's own self time.
+  const members = new Set(operations);
+
   // Memoized: the nesting test walks the ancestors of every member, and a deep
   // Apex stack would otherwise rebuild the same key at every level of it.
   const keys = new Map<Operation, string>();
@@ -267,7 +273,8 @@ export function groupOperations(
 
   const nestedInGroup = (operation: Operation, key: string): boolean =>
     operation.parent !== null &&
-    (keyOf(operation.parent) === key || nestedInGroup(operation.parent, key));
+    ((members.has(operation.parent) && keyOf(operation.parent) === key) ||
+      nestedInGroup(operation.parent, key));
 
   operations.forEach((operation) => {
     const key = keyOf(operation);

tests/operations.test.ts

@@ -5,6 +5,7 @@
 import type { ApexLog } from "../src/ApexLogParser";
 import { LOG_CATEGORIES } from "../src/salesforce/debugLevels";
 import {
+  GROUP_BY,
   groupOperations,
   listOperations,
   logCategoryOf,
@@ -236,6 +237,92 @@ describe("groupOperations", () => {
     });
   });
 
+  /**
+   * The shape a `namespace` filter reaches: the two inner code units share a
+   * calling namespace with the code unit above them, which the filter drops.
+   */
+  const nestedAcrossANamespace = () =>
+    listOperations(
+      logOf({
+        type: "DML_BEGIN",
+        subCategory: "DML",
+        text: "DML Insert Account",
+        namespace: "Custom",
+        totalNs: 100_000_000,
+        selfNs: 0,
+        children: [
+          {
+            type: "CODE_UNIT_STARTED",
+            subCategory: "Code Unit",
+            text: "Outer",
+            namespace: "default",
+            totalNs: 100_000_000,
+            selfNs: 30_000_000,
+            children: [
+              {
+                type: "DML_BEGIN",
+                subCategory: "DML",
+                text: "DML Update Account",
+                namespace: "Custom",
+                totalNs: 70_000_000,
+                selfNs: 0,
+                children: [
+                  {
+                    type: "CODE_UNIT_STARTED",
+                    subCategory: "Code Unit",
+                    text: "Inner",
+                    namespace: "Custom",
+                    totalNs: 40_000_000,
+                  },
+                  {
+                    type: "CODE_UNIT_STARTED",
+                    subCategory: "Code Unit",
+                    text: "Inner",
+                    namespace: "Custom",
+                    totalNs: 30_000_000,
+                  },
+                ],
+              },
+            ],
+          },
+        ],
+      }),
+    );
+
+  it("counts a member whose matching ancestor the caller filtered away", () => {
+    const selected = nestedAcrossANamespace().filter(
+      (operation) => operation.namespace === "Custom",
+    );
+
+    expect(
+      groupOperations(selected, "callerNamespace").find(
+        (operation) => operation.kind === "codeUnit",
+      ),
+    ).toMatchObject({ callCount: 2, durationTotalNs: 70_000_000 });
+  });
+
+  it("never reports a total below the self time it contains", () => {
+    const operations = nestedAcrossANamespace();
+    const namespaces = [undefined, "default", "Custom"];
+
+    namespaces.forEach((namespace) =>
+      GROUP_BY.forEach((by) => {
+        const selected = operations.filter(
+          (operation) => !namespace || operation.namespace === namespace,
+        );
+
+        groupOperations(selected, by).forEach((group) =>
+          expect({
+            namespace,
+            by,
+            name: group.name,
+            impossible: group.durationTotalNs < group.durationSelfNs,
+          }).toMatchObject({ impossible: false }),
+        );
+      }),
+    );
+  });
+
   it("groups by namespace, and names the row after it", () => {
     const operations = listOperations(
       logOf(repeatedQuery("default", 1), repeatedQuery("Custom", 2)),