From a53c25d2ae9628f1ae36905625de659c27b2fb91 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Fri, 12 Feb 2021 18:35:33 +0100 Subject: [PATCH] support logging in hsApi --- src/logging/LogItem.js | 25 +++++++++++-------------- src/logging/NullLogger.js | 12 +++++++++++- src/matrix/net/HomeServerApi.js | 31 ++++++++++++++++++++++++++----- 3 files changed, 48 insertions(+), 20 deletions(-) diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 02a0b941..ab51d220 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -32,7 +32,7 @@ export class LogItem { * Creates a new child item and runs it in `callback`. */ wrap(labelOrValues, callback, logLevel = this._logLevel) { - const item = this._createChild(labelOrValues, logLevel); + const item = this.child(labelOrValues, logLevel); return item.run(callback); } @@ -43,7 +43,7 @@ export class LogItem { * Hence, the child item is not returned. */ log(labelOrValues, logLevel = this._logLevel) { - const item = this._createChild(labelOrValues, logLevel); + const item = this.child(labelOrValues, logLevel); item.end = item.start; } @@ -105,14 +105,14 @@ export class LogItem { * * callback can return a Promise. * - * Can only be called once, and will throw after. + * Should only be called once. * * @param {Function} callback [description] * @return {[type]} [description] */ run(callback) { if (this._end !== null) { - throw new Error("item is finished"); + console.trace("log item is finished, additional logs will likely not be recorded"); } let result; try { @@ -122,18 +122,14 @@ export class LogItem { this.finish(); return promiseResult; }, err => { - this._catch(err); - this.finish(); - throw err; + throw this.catch(err); }); } else { this.finish(); return result; } } catch (err) { - this._catch(err); - this.finish(); - throw err; + throw this.catch(err); } } @@ -155,15 +151,16 @@ export class LogItem { return LogLevel; } - _catch(err) { + catch(err) { this._error = err; this._logLevel = LogLevel.Error; - console.error(`log item ${this.values.label} failed: ${err.message}:\n${err.stack}`); + this.finish(); + return err; } - _createChild(labelOrValues, logLevel) { + child(labelOrValues, logLevel) { if (this._end !== null) { - throw new Error("item is finished"); + console.trace("log item is finished, additional logs will likely not be recorded"); } const item = new LogItem(labelOrValues, logLevel, this._platform, this._anonymize); this._children.push(item); diff --git a/src/logging/NullLogger.js b/src/logging/NullLogger.js index b9803e55..1330ba23 100644 --- a/src/logging/NullLogger.js +++ b/src/logging/NullLogger.js @@ -20,7 +20,7 @@ export class NullLogger { this._item = new NullLogItem(); } - wrapLog(_, callback) { + run(_, callback) { callback(this._item); } @@ -44,4 +44,14 @@ class NullLogItem { get level() { return LogLevel; } + + catch(err) { + return err; + } + + child() { + return this; + } + + finish() {} } diff --git a/src/matrix/net/HomeServerApi.js b/src/matrix/net/HomeServerApi.js index 935c6889..fa560db6 100644 --- a/src/matrix/net/HomeServerApi.js +++ b/src/matrix/net/HomeServerApi.js @@ -19,24 +19,34 @@ import {HomeServerError, ConnectionError} from "../error.js"; import {encodeQueryParams} from "./common.js"; class RequestWrapper { - constructor(method, url, requestResult) { + constructor(method, url, requestResult, log) { + this._log = log; this._requestResult = requestResult; this._promise = requestResult.response().then(response => { + log?.set("status", response.status); // ok? if (response.status >= 200 && response.status < 300) { + log?.finish(); return response.body; } else { if (response.status >= 400 && !response.body?.errcode) { - throw new ConnectionError(`HTTP error status ${response.status} without errcode in body, assume this is a load balancer complaining the server is offline.`); + const err = new ConnectionError(`HTTP error status ${response.status} without errcode in body, assume this is a load balancer complaining the server is offline.`); + log?.catch(err); + throw err; } else { - throw new HomeServerError(method, url, response.body, response.status); + const err = new HomeServerError(method, url, response.body, response.status); + log?.catch(err); + throw err; } } }, err => { // if this._requestResult is still set, the abort error came not from calling abort here if (err.name === "AbortError" && this._requestResult) { - throw new Error(`Request ${method} ${url} was unexpectedly aborted, see #187.`); + const err = new Error(`Unexpectedly aborted, see #187.`); + log?.catch(err); + throw err; } else { + log?.catch(err); throw err; } }); @@ -44,6 +54,7 @@ class RequestWrapper { abort() { if (this._requestResult) { + this._log?.set("aborted", true); this._requestResult.abort(); // to mark that it was on purpose in above rejection handler this._requestResult = null; @@ -93,6 +104,15 @@ export class HomeServerApi { _baseRequest(method, url, queryParams, body, options, accessToken) { const queryString = encodeQueryParams(queryParams); url = `${url}?${queryString}`; + let log; + if (options?.log) { + const parent = options?.log; + log = parent.child({ + kind: "request", + url, + method, + }, parent.level.Info); + } let encodedBody; const headers = new Map(); if (accessToken) { @@ -105,6 +125,7 @@ export class HomeServerApi { headers.set("Content-Length", encoded.length); encodedBody = encoded.body; } + const requestResult = this._requestFn(url, { method, headers, @@ -114,7 +135,7 @@ export class HomeServerApi { format: "json" // response format }); - const wrapper = new RequestWrapper(method, url, requestResult); + const wrapper = new RequestWrapper(method, url, requestResult, log); if (this._reconnector) { wrapper.response().catch(err => {