Improve logging of http requests to aid debugging (#3485)

* Simple request logging with status and duration

* remove url params from logs

* superfluous toString()

* Add tests

* Apply suggestions from code review

* update snapshots

* update log format

* Apply suggestions from code review

Co-authored-by: Michael Telatynski <7t3chguy@gmail.com>

* update snapshot

---------

Co-authored-by: Michael Telatynski <7t3chguy@gmail.com>
Co-authored-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com>
Co-authored-by: Richard van der Hoff <richard@matrix.org>

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<Response>();
+        const fetchFn = jest.fn().mockReturnValue(deferred.promise);
+        jest.spyOn(logger, "debug").mockImplementation(() => {});
+        const api = new FetchHttpApi(new TypedEventEmitter<any, any>(), { baseUrl, prefix, fetchFn });
+        const prom = api.requestOtherUrl(Method.Get, "https://server:8448/some/path#fragment?query=param");
+        jest.advanceTimersByTime(1234);
+        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");
+        expect(logger.debug).not.toHaveBeenCalledWith("param");
+        expect(logger.debug).toHaveBeenCalledTimes(2);
+        expect(mocked(logger.debug).mock.calls[0]).toMatchInlineSnapshot(`
+            [
+              "FetchHttpApi: --> GET https://server:8448/some/path",
+            ]
+        `);
+        expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(`
+            [
+              "FetchHttpApi: <-- GET https://server:8448/some/path [1234ms 200]",
+            ]
+        `);
+    });
 });

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<string, any> | BodyInit;
 
@@ -225,6 +226,9 @@ export class FetchHttpApi<O extends IHttpOpts> {
         body?: Body,
         opts: Pick<IRequestOpts, "headers" | "json" | "localTimeoutMs" | "keepAlive" | "abortSignal"> = {},
     ): Promise<ResponseType<T, O>> {
+        const urlForLogs = this.clearUrlParamsForLogs(url);
+        logger.debug(`FetchHttpApi: --> ${method} ${urlForLogs}`);
+
         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 +264,7 @@ export class FetchHttpApi<O extends IHttpOpts> {
         const { signal, cleanup } = anySignal(signals);
 
         let res: Response;
+        const start = Date.now();
         try {
             res = await this.fetch(url, {
                 signal,
@@ -274,7 +279,10 @@ export class FetchHttpApi<O extends IHttpOpts> {
                 credentials: "omit", // we send credentials via headers
                 keepalive: keepAlive,
             });
+
+            logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${res.status}]`);
         } catch (e) {
+            logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${e}]`);
             if ((<Error>e).name === "AbortError") {
                 throw e;
             }
@@ -293,6 +301,22 @@ export class FetchHttpApi<O extends IHttpOpts> {
         return res as ResponseType<T, O>;
     }
 
+    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.origin + asUrl.pathname;
+        } 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 <b>after</b> the supplied prefix e.g. "/createRoom".