mirror: add network request logging (#1562)

Logs network requests and responses into a table in the db. Also logs
an `UpdateId` that links the mutation to the network request/response
that generated it.

This is a breaking change to the Mirror database format; existing caches
will need to be regenerated.

Resolves #1450.

Test Plan:
Unit tests added, covering the core functionality and integration into
the public APIs. After loading a project and manually inspecting it in
an sqlite shell, the results in the `network_log` table looked
reasonable.

src/graphql/mirror.js

@@ -188,7 +188,7 @@ export class Mirror {
     // it requires bumping the version, bump it: requiring some extra
     // one-time cache resets is okay; doing the wrong thing is not.
     const blob = stringify({
-      version: "MIRROR_v7",
+      version: "MIRROR_v8",
       schema: this._schema,
       options: {
         blacklistedIds: this._blacklistedIds,
@@ -318,6 +318,21 @@ export class Mirror {
           CREATE INDEX idx_connection_entries__connection_id
           ON connection_entries (connection_id)
         `,
+        dedent`\
+          CREATE TABLE network_log (
+              rowid INTEGER PRIMARY KEY,
+              query TEXT,
+              query_parameters TEXT,  -- stringified JSON object
+              request_time_epoch_millis INTEGER,
+              response TEXT,
+              response_time_epoch_millis INTEGER,
+              update_id INTEGER,
+              CHECK((query IS NULL) = (query_parameters IS NULL)),
+              CHECK((request_time_epoch_millis IS NULL) = (query IS NULL)),
+              CHECK((response_time_epoch_millis IS NULL) = (response IS NULL)),
+              FOREIGN KEY(update_id) REFERENCES updates(rowid)
+          )
+        `,
       ];
       for (const sql of tables) {
         db.prepare(sql).run();
@@ -728,6 +743,74 @@ export class Mirror {
     }
   }
 
+  /**
+   * Save the request query and query parameters to the database.
+   */
+  _logRequest(
+    body: Queries.Body,
+    variables: {+[string]: any},
+    timestamp: Date
+  ): NetworkLogId {
+    const query = Queries.stringify.body(body, Queries.inlineLayout());
+    const queryParameters = stringify(variables);
+
+    return this._db
+      .prepare(
+        dedent`\
+          INSERT INTO network_log (
+              query, query_parameters, request_time_epoch_millis
+          )
+          VALUES (:query, :queryParameters, :requestTimestamp)
+        `
+      )
+      .run({
+        query,
+        queryParameters,
+        requestTimestamp: +timestamp,
+      }).lastInsertRowid;
+  }
+
+  /**
+   * Save the network response and response timestamp to the table row
+   * corresponding to the request that generated it.
+   */
+  _logResponse(
+    rowid: NetworkLogId,
+    jsonResponse: UpdateResult,
+    timestamp: Date
+  ): void {
+    const response = stringify(jsonResponse);
+
+    const stmt = this._db.prepare(
+      dedent`\
+        UPDATE network_log
+        SET
+            response = :response,
+            response_time_epoch_millis = :responseTimestamp
+        WHERE rowid = :rowid
+      `
+    );
+    const saveResponse = _makeSingleUpdateFunction(stmt);
+    saveResponse({response, responseTimestamp: +timestamp, rowid});
+  }
+
+  /**
+   * Save the UpdateId in the table row corresponding to the network request
+   * that generated it.
+   */
+  _logRequestUpdateId(rowid: NetworkLogId, updateId: UpdateId): void {
+    const stmt = this._db.prepare(
+      dedent`\
+        UPDATE network_log
+        SET
+            update_id = :updateId
+        WHERE rowid = :rowid
+      `
+    );
+    const saveUpdateId = _makeSingleUpdateFunction(stmt);
+    saveUpdateId({rowid, updateId});
+  }
+
   /**
    * Perform one step of the update loop: find outdated entities, fetch
    * their updates, and feed the results back into the database.
@@ -759,9 +842,14 @@ export class Mirror {
       connectionLimit: options.connectionLimit,
     });
     const body = [Queries.build.query("MirrorUpdate", [], querySelections)];
-    const result: UpdateResult = await postQuery({body, variables: {}});
+    const variables = {};
+    const requestRowId = this._logRequest(body, variables, options.now());
+    const result: UpdateResult = await postQuery({body, variables});
+    this._logResponse(requestRowId, result, options.now());
+
     _inTransaction(this._db, () => {
       const updateId = this._createUpdate(options.now());
+      this._logRequestUpdateId(requestRowId, updateId);
       this._nontransactionallyUpdateData(updateId, result);
     });
     return Promise.resolve(true);
@@ -1947,6 +2035,7 @@ export function _buildSchemaInfo(schema: Schema.Schema): SchemaInfo {
 }
 
 type UpdateId = number;
+type NetworkLogId = number;
 
 /**
  * A set of objects and connections that should be updated.

src/graphql/mirror.test.js

@@ -14,6 +14,7 @@ import {
   _makeSingleUpdateFunction,
   Mirror,
 } from "./mirror";
+import stringify from "json-stable-stringify";
 
 describe("graphql/mirror", () => {
   function issueTimelineItemClauses() {
@@ -148,6 +149,7 @@ describe("graphql/mirror", () => {
               "links",
               "connections",
               "connection_entries",
+              "network_log",
             ])
           ).sort()
         );
@@ -987,13 +989,30 @@ describe("graphql/mirror", () => {
         const spyFindOutdated = jest.spyOn(Mirror.prototype, "_findOutdated");
         const spyQueryFromPlan = jest.spyOn(Mirror.prototype, "_queryFromPlan");
         const spyCreateUpdate = jest.spyOn(Mirror.prototype, "_createUpdate");
-        const spies = [spyFindOutdated, spyQueryFromPlan, spyCreateUpdate];
+        const spyLogRequest = jest.spyOn(Mirror.prototype, "_logRequest");
+        const spyLogResponse = jest.spyOn(Mirror.prototype, "_logResponse");
+        const spyLogRequestUpdateId = jest.spyOn(
+          Mirror.prototype,
+          "_logRequestUpdateId"
+        );
+        const spies = [
+          spyFindOutdated,
+          spyQueryFromPlan,
+          spyCreateUpdate,
+          spyLogRequest,
+          spyLogResponse,
+          spyLogRequestUpdateId,
+        ];
 
         const postQuery = jest.fn();
         const now = jest
           .fn()
           .mockImplementationOnce(() => new Date(456))
-          .mockImplementationOnce(() => new Date(789));
+          .mockImplementationOnce(() => new Date(457))
+          .mockImplementationOnce(() => new Date(458))
+          .mockImplementationOnce(() => new Date(789))
+          .mockImplementationOnce(() => new Date(790))
+          .mockImplementationOnce(() => new Date(791));
 
         const db = new Database(":memory:");
         const mirror = new Mirror(db, buildGithubSchema());
@@ -1096,8 +1115,51 @@ describe("graphql/mirror", () => {
 
         // We should have created two updates with sequential dates.
         expect(spyCreateUpdate).toHaveBeenCalledTimes(2);
-        expect(spyCreateUpdate.mock.calls[0]).toEqual([new Date(456)]);
+        expect(spyCreateUpdate.mock.calls[0]).toEqual([new Date(458)]);
-        expect(spyCreateUpdate.mock.calls[1]).toEqual([new Date(789)]);
+        expect(spyCreateUpdate.mock.calls[1]).toEqual([new Date(791)]);
+
+        // We should have called logRequest twice with query,
+        // query parameters, and sequential timestamps.
+        expect(spyLogRequest).toHaveBeenCalledTimes(2);
+        expect(spyLogRequest.mock.calls[0]).toEqual([
+          postQuery.mock.calls[0][0].body,
+          postQuery.mock.calls[0][0].variables,
+          new Date(456),
+        ]);
+
+        expect(spyLogRequest).toHaveBeenCalledTimes(2);
+        expect(spyLogRequest.mock.calls[1]).toEqual([
+          postQuery.mock.calls[1][0].body,
+          postQuery.mock.calls[1][0].variables,
+          new Date(789),
+        ]);
+
+        // We should have called logResponse twice with response
+        // and sequential timestamps
+        expect(spyLogResponse).toHaveBeenCalledTimes(2);
+        expect(spyLogResponse.mock.calls[0]).toEqual([
+          spyLogRequest.mock.results[0].value,
+          await postQuery.mock.results[0].value,
+          new Date(457),
+        ]);
+
+        expect(spyLogResponse.mock.calls[1]).toEqual([
+          spyLogRequest.mock.results[1].value,
+          await postQuery.mock.results[1].value,
+          new Date(790),
+        ]);
+
+        // We should have called logRequestUpdateId with updateId
+        expect(spyLogRequestUpdateId).toHaveBeenCalledTimes(2);
+        expect(spyLogRequestUpdateId.mock.calls[0]).toEqual([
+          spyLogRequest.mock.results[0].value,
+          spyCreateUpdate.mock.results[0].value,
+        ]);
+
+        expect(spyLogRequestUpdateId.mock.calls[1]).toEqual([
+          spyLogRequest.mock.results[1].value,
+          spyCreateUpdate.mock.results[1].value,
+        ]);
 
         // We should now be able to extract the right data.
         const result = mirror.extract("repo:foo/bar");
@@ -3627,6 +3689,74 @@ describe("graphql/mirror", () => {
     });
   });
 
+  describe("logging network requests", () => {
+    describe("_logRequest", () => {
+      it("saves query, query parameters, and request timestamp", async () => {
+        const db = new Database(":memory:");
+        const mirror = new Mirror(db, buildGithubSchema());
+        const query = [
+          Queries.build.query("MirrorUpdate", [], [Queries.build.field("foo")]),
+        ];
+        const queryParameters = {foo: "bar"};
+        mirror._logRequest(query, queryParameters, new Date(123));
+        const results = await db
+          .prepare(
+            "SELECT query, query_parameters, request_time_epoch_millis FROM network_log"
+          )
+          .get();
+        const expected = Queries.stringify.body(query, Queries.inlineLayout());
+        expect(results.query).toEqual(expected);
+        expect(results.query_parameters).toEqual(stringify({foo: "bar"}));
+        expect(results.request_time_epoch_millis).toEqual(123);
+      });
+    });
+
+    describe("_logResponse", () => {
+      it("saves response and request timestamp", async () => {
+        const db = new Database(":memory:");
+        const mirror = new Mirror(db, buildGithubSchema());
+        const query = [Queries.build.query("Foo", [], [])];
+        const queryParameters = {};
+        const rowid = mirror._logRequest(query, queryParameters, new Date(123));
+
+        const response = {
+          owndata_0: [
+            {
+              __typename: "Repository",
+              id: "repo:foo/bar",
+              url: "url://foo/bar",
+            },
+          ],
+        };
+
+        mirror._logResponse(rowid, response, new Date(456));
+        const results = await db
+          .prepare(
+            "SELECT response, response_time_epoch_millis FROM network_log"
+          )
+          .get();
+        expect(results.response).toEqual(stringify(response));
+        expect(results.response_time_epoch_millis).toBe(456);
+      });
+    });
+
+    describe("_logRequestUpdateId", () => {
+      it("saves updateId", async () => {
+        const db = new Database(":memory:");
+        const mirror = new Mirror(db, buildGithubSchema());
+        const query = [Queries.build.query("Foo", [], [])];
+        const queryParameters = {};
+        const rowid = mirror._logRequest(query, queryParameters, new Date(123));
+        const updateId = mirror._createUpdate(new Date(456));
+        mirror._logRequestUpdateId(rowid, updateId);
+        const results = await db
+          .prepare("SELECT update_id FROM network_log")
+          .get();
+        expect(results.update_id).toBe(updateId);
+      });
+    });
+  });
+
   describe("_makeSingleUpdateFunction", () => {
     function createTestDb() {
       const db = new Database(":memory:");