sousa-gecko/testing/modules/tests/xpcshell/test_structuredlog.js

/* Any copyright is dedicated to the Public Domain.
   http://creativecommons.org/publicdomain/zero/1.0/ */

const { StructuredLogger } = ChromeUtils.importESModule(
  "resource://testing-common/StructuredLog.sys.mjs"
);

add_task(function test_StructuredLogger() {
  let testBuffer = [];

  let appendBuffer = function (msg) {
    testBuffer.push(JSON.stringify(msg));
  };

  let assertLastMsg = function (refData) {
    // Check all fields in refData agree with those in the
    // last message logged, and pop that message.
    let lastMsg = JSON.parse(testBuffer.pop());
    for (let field in refData) {
      deepEqual(lastMsg[field], refData[field]);
    }
    // The logger should always set the source to the logger name.
    equal(lastMsg.source, "test_log");
  };

  let logger = new StructuredLogger("test_log", appendBuffer);

  // Test unstructured logging
  logger.info("Test message");
  assertLastMsg({
    action: "log",
    message: "Test message",
    level: "INFO",
  });

  logger.info("Test message", { foo: "bar" });
  assertLastMsg({
    action: "log",
    message: "Test message",
    level: "INFO",
    extra: { foo: "bar" },
  });

  // Test end / start actions
  logger.testStart("aTest");
  assertLastMsg({
    test: "aTest",
    action: "test_start",
  });

  logger.testEnd("aTest", "OK");
  assertLastMsg({
    test: "aTest",
    action: "test_end",
    status: "OK",
  });

  // A failed test populates the "expected" field.
  logger.testStart("aTest");
  logger.testEnd("aTest", "FAIL", "PASS");
  assertLastMsg({
    action: "test_end",
    test: "aTest",
    status: "FAIL",
    expected: "PASS",
  });

  // A failed test populates the "expected" field.
  logger.testStart("aTest");
  logger.testEnd("aTest", "FAIL", "PASS", null, "Many\nlines\nof\nstack\n");
  assertLastMsg({
    action: "test_end",
    test: "aTest",
    status: "FAIL",
    expected: "PASS",
    stack: "Many\nlines\nof\nstack\n",
  });

  // Skipped tests don't log failures
  logger.testStart("aTest");
  logger.testEnd("aTest", "SKIP", "PASS");
  ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
  assertLastMsg({
    action: "test_end",
    test: "aTest",
    status: "SKIP",
  });

  logger.testStatus("aTest", "foo", "PASS", "PASS", "Passed test");
  ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
  assertLastMsg({
    action: "test_status",
    test: "aTest",
    subtest: "foo",
    status: "PASS",
    message: "Passed test",
  });

  logger.testStatus("aTest", "bar", "FAIL");
  assertLastMsg({
    action: "test_status",
    test: "aTest",
    subtest: "bar",
    status: "FAIL",
    expected: "PASS",
  });

  logger.testStatus(
    "aTest",
    "bar",
    "FAIL",
    "PASS",
    null,
    "Many\nlines\nof\nstack\n"
  );
  assertLastMsg({
    action: "test_status",
    test: "aTest",
    subtest: "bar",
    status: "FAIL",
    expected: "PASS",
    stack: "Many\nlines\nof\nstack\n",
  });

  // Skipped tests don't log failures
  logger.testStatus("aTest", "baz", "SKIP");
  ok(!JSON.parse(testBuffer[testBuffer.length - 1]).hasOwnProperty("expected"));
  assertLastMsg({
    action: "test_status",
    test: "aTest",
    subtest: "baz",
    status: "SKIP",
  });

  // Suite start and end messages.
  var ids = { aManifest: ["aTest"] };
  logger.suiteStart(ids);
  assertLastMsg({
    action: "suite_start",
    tests: { aManifest: ["aTest"] },
  });

  logger.suiteEnd();
  assertLastMsg({
    action: "suite_end",
  });
});

add_task(function test_StructuredLogger_with_dumpScope() {
  let testBuffer = [];
  let appendBuffer2 = msg => {
    testBuffer.push(msg);
  };

  let assertSeenMsg = (expected, checkExtra) => {
    const { action, message, level, extra } = testBuffer.shift();
    deepEqual({ action, message, level }, expected);
    ok(checkExtra(extra), `Extra: ${uneval(extra)}`);
  };

  // Regression test for bug 2007587: Logger gracefully handles clone failures.
  let logger2 = new StructuredLogger("test_dump", appendBuffer2, globalThis);
  const extraNotCloneable = { notCloneable: () => {} };
  logger2.info("Test non-cloneable", extraNotCloneable);

  assertSeenMsg(
    {
      action: "log",
      message:
        "Failed to cloneInto: Error: Permission denied to pass a Function via structured clone",
      level: "ERROR",
    },
    extra => extra === undefined
  );

  testBuffer[0].message = testBuffer[0].message.replace(/time:\d+/, "time:123");
  assertSeenMsg(
    {
      action: "log",
      message: `Tried to clone: ({action:"log", time:123, thread:null, pid:null, source:"test_dump", level:"INFO", message:"Test non-cloneable", extra:{notCloneable:() => {}}})`,
      level: "WARNING",
    },
    extra => extra === undefined
  );

  assertSeenMsg(
    { action: "log", message: "Test non-cloneable", level: "INFO" },
    extra => extra === extraNotCloneable
  );

  // Now verify the most common / desired behavior: clone where possible.
  const extraCloneable = { cloneable: "Yes I am" };
  logger2.info("Test cloneable", extraCloneable);

  assertSeenMsg(
    { action: "log", message: "Test cloneable", level: "INFO" },
    extra => {
      deepEqual(extra, extraCloneable);
      return extra !== extraCloneable;
    }
  );

  equal(testBuffer.length, 0, "No messages unaccounted for");
});