From 90c76a502382023b43bdc8ef793db2e2173c9147 Mon Sep 17 00:00:00 2001 From: Brian Litwin Date: Sun, 19 Jan 2020 20:58:49 -0500 Subject: [PATCH] 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 | 93 ++++++++++++++++++++++++- src/graphql/mirror.test.js | 138 +++++++++++++++++++++++++++++++++++-- 2 files changed, 225 insertions(+), 6 deletions(-) diff --git a/src/graphql/mirror.js b/src/graphql/mirror.js index 9fbb267..07c7c6d 100644 --- a/src/graphql/mirror.js +++ b/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. diff --git a/src/graphql/mirror.test.js b/src/graphql/mirror.test.js index 0667c4c..89ce2c8 100644 --- a/src/graphql/mirror.test.js +++ b/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[1]).toEqual([new Date(789)]); + expect(spyCreateUpdate.mock.calls[0]).toEqual([new Date(458)]); + 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:");