From 56abf74e6e59c7184c283ab48ab86877e10a1690 Mon Sep 17 00:00:00 2001 From: valere Date: Mon, 19 Jun 2023 15:44:05 +0200 Subject: [PATCH 1/9] Simple request logging with status and duration --- src/http-api/fetch.ts | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/http-api/fetch.ts b/src/http-api/fetch.ts index 4599b4b615a..d42634dd8c4 100644 --- a/src/http-api/fetch.ts +++ b/src/http-api/fetch.ts @@ -25,6 +25,7 @@ import { ConnectionError, MatrixError } from "./errors"; import { HttpApiEvent, HttpApiEventHandlerMap, IHttpOpts, IRequestOpts } from "./interface"; import { anySignal, parseErrorResponse, timeoutSignal } from "./utils"; import { QueryDict } from "../utils"; +import { logger } from "../logger"; type Body = Record | BodyInit; @@ -225,6 +226,8 @@ export class FetchHttpApi { body?: Body, opts: Pick = {}, ): Promise> { + logger.debug(`FetchHttpApi: ${method} --> ${url}`); + const headers = Object.assign({}, opts.headers || {}); const json = opts.json ?? true; // We can't use getPrototypeOf here as objects made in other contexts e.g. over postMessage won't have same ref @@ -260,6 +263,7 @@ export class FetchHttpApi { const { signal, cleanup } = anySignal(signals); let res: Response; + const start = Date.now(); try { res = await this.fetch(url, { signal, @@ -274,7 +278,10 @@ export class FetchHttpApi { credentials: "omit", // we send credentials via headers keepalive: keepAlive, }); + + logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${url}`); } catch (e) { + logger.debug(`FetchHttpApi: <-- ${e} ${url}`); if ((e).name === "AbortError") { throw e; } From ecb9e4a5c078f47cc4a3c95ee242319550b3f6ff Mon Sep 17 00:00:00 2001 From: valere Date: Mon, 3 Jul 2023 11:54:23 +0200 Subject: [PATCH 2/9] remove url params from logs --- src/http-api/fetch.ts | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) diff --git a/src/http-api/fetch.ts b/src/http-api/fetch.ts index d42634dd8c4..f646d2e9865 100644 --- a/src/http-api/fetch.ts +++ b/src/http-api/fetch.ts @@ -226,7 +226,8 @@ export class FetchHttpApi { body?: Body, opts: Pick = {}, ): Promise> { - logger.debug(`FetchHttpApi: ${method} --> ${url}`); + const urlForLogs = this.clearUrlParamsForLogs(url); + logger.debug(`FetchHttpApi: ${method} --> ${urlForLogs}`); const headers = Object.assign({}, opts.headers || {}); const json = opts.json ?? true; @@ -279,9 +280,9 @@ export class FetchHttpApi { keepalive: keepAlive, }); - logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${url}`); + logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${urlForLogs}`); } catch (e) { - logger.debug(`FetchHttpApi: <-- ${e} ${url}`); + logger.debug(`FetchHttpApi: <-- ${e} ${Date.now() - start}ms ${urlForLogs}`); if ((e).name === "AbortError") { throw e; } @@ -300,6 +301,22 @@ export class FetchHttpApi { return res as ResponseType; } + private clearUrlParamsForLogs(url: URL | string): string { + try { + let asUrl: URL; + if (typeof url === "string") { + asUrl = new URL(url); + } else { + asUrl = url; + } + // get just the path to remove any potential url param that could have + // some potential secrets + return asUrl.pathname.toString(); + } catch (error) { + // defensive coding for malformed url + return "??"; + } + } /** * Form and return a homeserver request URL based on the given path params and prefix. * @param path - The HTTP path after the supplied prefix e.g. "/createRoom". From 69167236f134809039d8fb15b5a3746a2345bdca Mon Sep 17 00:00:00 2001 From: valere Date: Mon, 3 Jul 2023 12:33:30 +0200 Subject: [PATCH 3/9] superfluous toString() --- src/http-api/fetch.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/http-api/fetch.ts b/src/http-api/fetch.ts index f646d2e9865..e274e84d762 100644 --- a/src/http-api/fetch.ts +++ b/src/http-api/fetch.ts @@ -311,7 +311,7 @@ export class FetchHttpApi { } // get just the path to remove any potential url param that could have // some potential secrets - return asUrl.pathname.toString(); + return asUrl.pathname; } catch (error) { // defensive coding for malformed url return "??"; From b0d665cdadebbec52647e3bc18e93bcef7f698ab Mon Sep 17 00:00:00 2001 From: Michael Telatynski <7t3chguy@gmail.com> Date: Fri, 7 Jul 2023 12:45:37 +0100 Subject: [PATCH 4/9] Add tests --- spec/unit/http-api/fetch.spec.ts | 31 ++++++++++++++++++++++++++++++- 1 file changed, 30 insertions(+), 1 deletion(-) diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index 77ac2e3a4c6..cba79caf276 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -14,11 +14,14 @@ See the License for the specific language governing permissions and limitations under the License. */ +import { mocked } from "jest-mock"; + import { FetchHttpApi } from "../../../src/http-api/fetch"; import { TypedEventEmitter } from "../../../src/models/typed-event-emitter"; import { ClientPrefix, HttpApiEvent, HttpApiEventHandlerMap, IdentityPrefix, IHttpOpts, Method } from "../../../src"; import { emitPromise } from "../../test-utils/test-utils"; -import { QueryDict } from "../../../src/utils"; +import { defer, QueryDict } from "../../../src/utils"; +import { logger } from "../../../src/logger"; describe("FetchHttpApi", () => { const baseUrl = "http://baseUrl"; @@ -290,4 +293,30 @@ describe("FetchHttpApi", () => { runTests(baseUrlWithTrailingSlash); }); }); + + it("should not log query parameters", async () => { + jest.useFakeTimers(); + const deferred = defer(); + const fetchFn = jest.fn().mockReturnValue(deferred.promise); + jest.spyOn(logger, "debug").mockImplementation(() => {}); + const api = new FetchHttpApi(new TypedEventEmitter(), { baseUrl, prefix, fetchFn }); + const prom = api.requestOtherUrl(Method.Get, "https://server:1234/some/path#fragment?query=param"); + jest.advanceTimersByTime(1234); + deferred.resolve({ ok: true, text: () => Promise.resolve("RESPONSE") } as Response); + await prom; + expect(logger.debug).not.toHaveBeenCalledWith("fragment"); + expect(logger.debug).not.toHaveBeenCalledWith("query"); + expect(logger.debug).not.toHaveBeenCalledWith("param"); + expect(logger.debug).toHaveBeenCalledTimes(2); + expect(mocked(logger.debug).mock.calls[0]).toMatchInlineSnapshot(` + [ + "FetchHttpApi: GET --> /some/path", + ] + `); + expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` + [ + "FetchHttpApi: <-- undefined 1234ms /some/path", + ] + `); + }); }); From 5a925d1ff90c5fb42e90aea40b696bbe1ad7e097 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 11 Jul 2023 16:50:13 +0100 Subject: [PATCH 5/9] Apply suggestions from code review --- src/http-api/fetch.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/http-api/fetch.ts b/src/http-api/fetch.ts index e274e84d762..fa84158177c 100644 --- a/src/http-api/fetch.ts +++ b/src/http-api/fetch.ts @@ -227,7 +227,7 @@ export class FetchHttpApi { opts: Pick = {}, ): Promise> { const urlForLogs = this.clearUrlParamsForLogs(url); - logger.debug(`FetchHttpApi: ${method} --> ${urlForLogs}`); + logger.debug(`FetchHttpApi: --> ${method} ${urlForLogs}`); const headers = Object.assign({}, opts.headers || {}); const json = opts.json ?? true; @@ -280,9 +280,9 @@ export class FetchHttpApi { keepalive: keepAlive, }); - logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${urlForLogs}`); + logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${method} ${urlForLogs}`); } catch (e) { - logger.debug(`FetchHttpApi: <-- ${e} ${Date.now() - start}ms ${urlForLogs}`); + logger.debug(`FetchHttpApi: <-- ${e} ${Date.now() - start}ms ${method} ${urlForLogs}`); if ((e).name === "AbortError") { throw e; } @@ -311,7 +311,7 @@ export class FetchHttpApi { } // get just the path to remove any potential url param that could have // some potential secrets - return asUrl.pathname; + return asUrl.origin + asUrl.pathname; } catch (error) { // defensive coding for malformed url return "??"; From ce45066b92d730631b4c46643227a5d2854c36fd Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 11 Jul 2023 16:51:03 +0100 Subject: [PATCH 6/9] update snapshots --- spec/unit/http-api/fetch.spec.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index cba79caf276..e72f35233c3 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -310,12 +310,12 @@ describe("FetchHttpApi", () => { expect(logger.debug).toHaveBeenCalledTimes(2); expect(mocked(logger.debug).mock.calls[0]).toMatchInlineSnapshot(` [ - "FetchHttpApi: GET --> /some/path", + "FetchHttpApi: --> GET https://server:1234/some/path", ] `); expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` [ - "FetchHttpApi: <-- undefined 1234ms /some/path", + "FetchHttpApi: <-- undefined 1234ms GET https://server:1234/some/path", ] `); }); From 31d5603ea413e7b74446680ec7167f4586908329 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 11 Jul 2023 18:18:43 +0100 Subject: [PATCH 7/9] update log format --- spec/unit/http-api/fetch.spec.ts | 2 +- src/http-api/fetch.ts | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index e72f35233c3..8c110372782 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -315,7 +315,7 @@ describe("FetchHttpApi", () => { `); expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` [ - "FetchHttpApi: <-- undefined 1234ms GET https://server:1234/some/path", + "FetchHttpApi: <-- GET https://server:1234/some/path [1234ms undefined]", ] `); }); diff --git a/src/http-api/fetch.ts b/src/http-api/fetch.ts index fa84158177c..c527c8ea7c4 100644 --- a/src/http-api/fetch.ts +++ b/src/http-api/fetch.ts @@ -280,9 +280,9 @@ export class FetchHttpApi { keepalive: keepAlive, }); - logger.debug(`FetchHttpApi: <-- ${res.status} ${Date.now() - start}ms ${method} ${urlForLogs}`); + logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${res.status}]`); } catch (e) { - logger.debug(`FetchHttpApi: <-- ${e} ${Date.now() - start}ms ${method} ${urlForLogs}`); + logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${e}]`); if ((e).name === "AbortError") { throw e; } From f19e80154927edd44fc26d34cc3b0afc63d51430 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 11 Jul 2023 18:19:36 +0100 Subject: [PATCH 8/9] Apply suggestions from code review Co-authored-by: Michael Telatynski <7t3chguy@gmail.com> --- spec/unit/http-api/fetch.spec.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index 8c110372782..c10813aa67a 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -300,9 +300,9 @@ describe("FetchHttpApi", () => { const fetchFn = jest.fn().mockReturnValue(deferred.promise); jest.spyOn(logger, "debug").mockImplementation(() => {}); const api = new FetchHttpApi(new TypedEventEmitter(), { baseUrl, prefix, fetchFn }); - const prom = api.requestOtherUrl(Method.Get, "https://server:1234/some/path#fragment?query=param"); + const prom = api.requestOtherUrl(Method.Get, "https://server:8448/some/path#fragment?query=param"); jest.advanceTimersByTime(1234); - deferred.resolve({ ok: true, text: () => Promise.resolve("RESPONSE") } as Response); + deferred.resolve({ ok: true, status: 200, text: () => Promise.resolve("RESPONSE") } as Response); await prom; expect(logger.debug).not.toHaveBeenCalledWith("fragment"); expect(logger.debug).not.toHaveBeenCalledWith("query"); @@ -310,12 +310,12 @@ describe("FetchHttpApi", () => { expect(logger.debug).toHaveBeenCalledTimes(2); expect(mocked(logger.debug).mock.calls[0]).toMatchInlineSnapshot(` [ - "FetchHttpApi: --> GET https://server:1234/some/path", + "FetchHttpApi: --> GET https://server:8448/some/path", ] `); expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` [ - "FetchHttpApi: <-- GET https://server:1234/some/path [1234ms undefined]", + "FetchHttpApi: <-- GET https://server:8448/some/path [1234ms undefined]", ] `); }); From 091c0ca59f02645df7e2927596bfe2cb190c2f69 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 11 Jul 2023 18:20:06 +0100 Subject: [PATCH 9/9] update snapshot --- spec/unit/http-api/fetch.spec.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index c10813aa67a..236fbe1c32f 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -315,7 +315,7 @@ describe("FetchHttpApi", () => { `); expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` [ - "FetchHttpApi: <-- GET https://server:8448/some/path [1234ms undefined]", + "FetchHttpApi: <-- GET https://server:8448/some/path [1234ms 200]", ] `); });