ng-eventually/packages/sdk/test/access-log.test.ts

/**
 * access-log.test.ts — behavioral tests for logAccess / setAccessLog / enabled
 * (src/access-log.ts), as wired through the docs primitives (src/docs.ts).
 *
 * Tests:
 * (a) OFF by default: reads + writes via sparqlQuery / sparqlUpdate / docCreate
 *     emit nothing to console.log.
 * (b) ON via configure({ debugAccessLog: true }): each read/write emits a line
 *     matching `[<identity>][polyfill] READ/WRITE <shortNuri> (<label>)` (identity
 *     FIRST, `[polyfill]` glued right after) plus row-count suffix on READs. The
 *     NURI is shortened by shortNuri (did:ng:o: prefix + :v: suffix stripped,
 *     RepoID truncated to 8 chars + ellipsis).
 * (c) ON via env var NG_EVENTUALLY_ACCESS_LOG=1: same behavior without changing
 *     calling code.
 * (d) Identity follows setCurrentUser: after setCurrentUser the prefix changes.
 *
 * Spy approach: replace console.log with a mock, restore it after each test.
 * Env var tests set/delete process.env.NG_EVENTUALLY_ACCESS_LOG and restore it.
 */

import { describe, it, expect, mock, beforeEach, afterEach, afterAll } from "bun:test";
import { setAccessLog, enabled, shortNuri } from "../src/shared-wallet/access-log";
import { docCreate, sparqlUpdate, sparqlQuery } from "../src/surface/docs";
import { configure } from "../src/index";
import { configureStoreRegistry, setCurrentUser } from "../src/shared-wallet/bootstrap";
import { connectedUser } from "../src/emulated-verifier/connect";
import { resetCaps, resetConfig, resetStoreRegistry } from "../src/shared-wallet/bootstrap";

// ---------------------------------------------------------------------------
// Helpers
// ---------------------------------------------------------------------------

function fakeNg() {
  return {
    doc_create: mock(async (..._a: unknown[]) => "did:ng:o:log-doc"),
    sparql_update: mock(async (..._a: unknown[]) => undefined),
    sparql_query: mock(async (..._a: unknown[]) => ({
      results: { bindings: [{ x: { value: "v" } }] }, // 1 row so row-count is visible
    })),
  };
}

function injectFake(debugAccessLog = false) {
  const ng = fakeNg();
  configure({ ng: ng as any, useShape: (() => {}) as any, debugAccessLog });
  configureStoreRegistry({
    getSession: async () => ({ sessionId: "sid-log", privateStoreId: "P" }),
  });
  return ng;
}

// Capture console.log lines for the duration of a test.
// Returns the captured lines array and a restore function.
function spyConsoleLog(): { lines: string[]; restore: () => void } {
  const lines: string[] = [];
  const orig = console.log;
  console.log = (...args: unknown[]) => {
    lines.push(args.map(String).join(" "));
  };
  return { lines, restore: () => { console.log = orig; } };
}

// ---------------------------------------------------------------------------
// Lifecycle: restore config state after each test to avoid cross-test bleed.
// ---------------------------------------------------------------------------

// Save the env var value that was present BEFORE any test ran, so tests
// that run in an environment where NG_EVENTUALLY_ACCESS_LOG is already set
// don't permanently destroy that value.
const _originalEnvVar = process.env?.NG_EVENTUALLY_ACCESS_LOG;

afterEach(() => {
  setAccessLog(false); // always reset the config toggle
  setCurrentUser(null); // clear active identity
  // Restore the original env var value (don't just delete — it may have existed before)
  if ((globalThis as any)?.process?.env) {
    if (_originalEnvVar === undefined) {
      delete process.env.NG_EVENTUALLY_ACCESS_LOG;
    } else {
      process.env.NG_EVENTUALLY_ACCESS_LOG = _originalEnvVar;
    }
  }
});

afterAll(() => {
  resetConfig();
  resetStoreRegistry();
  setAccessLog(false);
  setCurrentUser(null);
});

// ---------------------------------------------------------------------------
// Tests
// ---------------------------------------------------------------------------

// Two process-wide things bite this suite, which only wants to watch the log:
//   - the cap registry: once ANY cap exists the reach guard applies to every reader;
//   - connecting a user does WORK (restore + drain its inbox, see connect.ts), which
//     both logs and files caps, asynchronously.
// So: let any in-flight connection finish, THEN clear. Awaiting rather than hoping
// is what makes this deterministic — `setCurrentUser` is fire-and-forget by design.
beforeEach(async () => {
  await connectedUser();
  resetCaps();
});

describe("access-log: OFF by default", () => {
  beforeEach(() => {
    // Force the env var OFF for these tests, regardless of the shell environment.
    if ((globalThis as any)?.process?.env) {
      delete process.env.NG_EVENTUALLY_ACCESS_LOG;
    }
    setAccessLog(false);
  });

  it("no console.log output for sparqlQuery when disabled", async () => {
    injectFake(false);
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlQuery("sid-log", "SELECT * {}");
    } finally {
      restore();
    }
    expect(lines.length).toBe(0);
  });

  it("no console.log output for sparqlUpdate when disabled", async () => {
    injectFake(false);
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:x");
    } finally {
      restore();
    }
    expect(lines.length).toBe(0);
  });

  it("no console.log output for docCreate when disabled", async () => {
    injectFake(false);
    const { lines, restore } = spyConsoleLog();
    try {
      await docCreate("sid-log", "Graph", "data:graph", "store");
    } finally {
      restore();
    }
    expect(lines.length).toBe(0);
  });

  it("enabled() returns false when disabled", () => {
    setAccessLog(false);
    if (process.env) delete process.env.NG_EVENTUALLY_ACCESS_LOG;
    expect(enabled()).toBe(false);
  });
});

describe("access-log: ON via configure({ debugAccessLog: true })", () => {
  beforeEach(async () => {
    setCurrentUser("alice");
    await connectedUser(); // drain the connection work before counting log lines
    resetCaps();
  });

  it("sparqlQuery emits a READ line with identity, nuri, label, and row-count", async () => {
    injectFake(true);
    setCurrentUser("alice");
    // `setCurrentUser` FIRES the connection work; draining it here (and only then
    // dropping the caps it filed) is what keeps this test about the log and not about
    // whether a background connect happened to win the race.
    await connectedUser();
    resetCaps();
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlQuery("sid-log", "SELECT * {}", undefined, "did:ng:o:q", "myLabel");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(lines[0]).toMatch(/READ/);
    expect(lines[0]).toContain(shortNuri("did:ng:o:q")); // NURI shortened
    expect(lines[0]).not.toContain("did:ng:o:"); // full prefix stripped
    expect(lines[0]).toMatch(/myLabel/);
    expect(lines[0]).toMatch(/→ 1 triple-rows/); // triple-count from the 1-row fake result
  });

  it("sparqlUpdate emits a WRITE line with identity, anchor nuri, and label", async () => {
    injectFake(true);
    setCurrentUser("alice");
    // `setCurrentUser` FIRES the connection work; draining it here (and only then
    // dropping the caps it filed) is what keeps this test about the log and not about
    // whether a background connect happened to win the race.
    await connectedUser();
    resetCaps();
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:w", "writeLabel");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(lines[0]).toMatch(/WRITE/);
    expect(lines[0]).toContain(shortNuri("did:ng:o:w"));
    expect(lines[0]).toMatch(/writeLabel/);
  });

  it("docCreate emits a WRITE line with identity and the returned nuri", async () => {
    injectFake(true);
    setCurrentUser("alice");
    // `setCurrentUser` FIRES the connection work; draining it here (and only then
    // dropping the caps it filed) is what keeps this test about the log and not about
    // whether a background connect happened to win the race.
    await connectedUser();
    resetCaps();
    const { lines, restore } = spyConsoleLog();
    try {
      await docCreate("sid-log", "Graph", "data:graph", "store");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(lines[0]).toMatch(/WRITE/);
    // The nuri is the value returned by ng.doc_create, shortened by shortNuri.
    expect(lines[0]).toContain(shortNuri("did:ng:o:log-doc"));
  });

  it("enabled() returns true when set via setAccessLog", () => {
    setAccessLog(true);
    expect(enabled()).toBe(true);
  });
});

describe("access-log: ON via env var NG_EVENTUALLY_ACCESS_LOG=1", () => {
  it("emits READ line when env var is set, even without configure() setting", async () => {
    // Set env var but do NOT pass debugAccessLog=true to configure
    if (!(globalThis as any)?.process?.env) return; // skip in env-less runtimes
    process.env.NG_EVENTUALLY_ACCESS_LOG = "1";
    injectFake(false); // debugAccessLog = false explicitly
    setCurrentUser("bob");
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlQuery("sid-log", "SELECT * {}", undefined, "did:ng:o:env-q");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[bob\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(lines[0]).toMatch(/READ/);
    expect(lines[0]).toContain(shortNuri("did:ng:o:env-q"));
  });

  it("env var NG_EVENTUALLY_ACCESS_LOG=true also enables the log", async () => {
    if (!(globalThis as any)?.process?.env) return;
    process.env.NG_EVENTUALLY_ACCESS_LOG = "true";
    injectFake(false);
    setCurrentUser("charlie");
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:env-w");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[charlie\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(lines[0]).toMatch(/WRITE/);
  });

  it("enabled() returns true when env var is set", () => {
    if (!(globalThis as any)?.process?.env) return;
    process.env.NG_EVENTUALLY_ACCESS_LOG = "1";
    setAccessLog(false); // config toggle is off
    expect(enabled()).toBe(true);
  });
});

describe("access-log: identity follows setCurrentUser", () => {
  it("prefix changes after setCurrentUser", async () => {
    injectFake(true);
    setCurrentUser("first-user");
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:id1", "step1");
      setCurrentUser("second-user");
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:id2", "step2");
    } finally {
      restore();
    }
    // Only this test's own lines: connecting a user legitimately logs its own reads.
    const mine = lines.filter((l) => l.includes("step1") || l.includes("step2"));
    expect(mine.length).toBe(2);
    expect(mine[0]).toMatch(/^\[first-user\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
    expect(mine[1]).toMatch(/^\[second-user\]\[polyfill\] /);
  });

  it("prefix is (none) when no identity is set", async () => {
    injectFake(true);
    setCurrentUser(null); // no active identity
    const { lines, restore } = spyConsoleLog();
    try {
      await sparqlUpdate("sid-log", "INSERT DATA {}", "did:ng:o:anon");
    } finally {
      restore();
    }
    expect(lines.length).toBe(1);
    expect(lines[0]).toMatch(/^\[\(none\)\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
  });
});