nodejs/hookshot
nodejs/hookshot
1
0
Fork 0
mirror of https://github.com/matrix-org/matrix-hookshot.git synced 2025-03-10 13:17:08 +00:00
Code Issues Packages Projects Releases Wiki Activity

Add Logger tests (#478)

Browse Source 
* More json logger safety

* Don't log undefined

* typo

* Split out the static logger to it's own class for testing

* Refactor logger usage slightly

* Add a test for the logger wrapper

* changelog

* Update LogWrapper.ts

* Drop ?
This commit is contained in:
Will Hunt 2022-09-14 12:26:34 +01:00 committed by GitHub
parent e8159579b2
commit d85f2fd540
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 157 additions and 48 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
changelog.d/478.misc Normal file
View File

@ -0,0 +1 @@
Fix a bug where the bridge can crash when JSON logging is enabled.

6
src/App/BridgeApp.ts
View File

@ -8,7 +8,7 @@ import { UserNotificationWatcher } from "../Notifications/UserNotificationWatche
import { ListenerService } from "../ListenerService";
import { Logging } from "matrix-appservice-bridge";
LogWrapper.configureLogging({level: "info"});
LogWrapper.root.configureLogging({level: "info"});
const log = new LogWrapper("App");
async function start() {
@ -17,7 +17,7 @@ async function start() {
const config = await BridgeConfig.parseConfig(configFile, process.env);
const registration = await parseRegistrationFile(registrationFile);
const listener = new ListenerService(config.listeners);
LogWrapper.configureLogging(config.logging);
LogWrapper.root.configureLogging(config.logging);
// Bridge SDK doesn't support trace, use "debug" instead.
const bridgeSdkLevel = config.logging.level === "trace" ? "debug" : config.logging.level;
Logging.configure({console: bridgeSdkLevel });
@ -49,7 +49,7 @@ async function start() {
}
start().catch((ex) => {
if (LogWrapper.configured) {
if (LogWrapper.root.configured) {
log.error("BridgeApp encountered an error and has stopped:", ex);
} else {
// eslint-disable-next-line no-console

2
src/App/GithubWebhookApp.ts
View File

@ -11,7 +11,7 @@ const log = new LogWrapper("App");
async function start() {
const configFile = process.argv[2] || "./config.yml";
const config = await BridgeConfig.parseConfig(configFile, process.env);
LogWrapper.configureLogging(config.logging);
LogWrapper.root.configureLogging(config.logging);
const listener = new ListenerService(config.listeners);
if (config.metrics) {
if (!config.metrics.port) {

2
src/App/MatrixSenderApp.ts
View File

@ -12,7 +12,7 @@ async function start() {
const registrationFile = process.argv[3] || "./registration.yml";
const config = await BridgeConfig.parseConfig(configFile, process.env);
const registration = await parseRegistrationFile(registrationFile);
LogWrapper.configureLogging(config.logging);
LogWrapper.root.configureLogging(config.logging);
const listener = new ListenerService(config.listeners);
const sender = new MatrixSender(config, registration);
if (config.metrics) {

2
src/Config/Config.ts
View File

@ -661,7 +661,7 @@ export async function parseRegistrationFile(filename: string) {
// Can be called directly
if (require.main === module) {
LogWrapper.configureLogging({level: "info"});
LogWrapper.root.configureLogging({level: "info"});
BridgeConfig.parseConfig(process.argv[2] || "config.yml", process.env).then(() => {
// eslint-disable-next-line no-console
console.log('Config successfully validated.');

2
src/Connections/CommandConnection.ts
View File

@ -59,7 +59,7 @@ export abstract class CommandConnection<StateType extends IConnectionState = ICo
msgtype: "m.notice",
body: humanError ? `Failed to handle command: ${humanError}` : "Failed to handle command.",
});
log.warn(`Failed to handle command:`, error);
log.warn(`Failed to handle command:`, error ?? 'Unknown error');
return true;
} else {
const reaction = commandResult.result?.reaction || '✅';

100
src/LogWrapper.ts
View File

@ -27,36 +27,26 @@ function isMessageNoise(messageOrObject: MsgType[]) {
interface HookshotLogInfo extends winston.Logform.TransformableInfo {
data: MsgType[];
}
export default class LogWrapper {
export class GlobalLogger {
private isConfigured = false;
private static isConfigured: boolean;
public static get configured() {
public get configured() {
return this.isConfigured;
}
static formatMsgTypeArray(...data: MsgType[]): string {
data = data.flat();
return data.map(obj => {
if (typeof obj === "string") {
return obj;
}
return util.inspect(obj);
}).join(" ");
private winstonLog?: winston.Logger;
public get winston() {
return this.winstonLog;
}
static messageFormatter(info: HookshotLogInfo): string {
const logPrefix = `${info.level} ${info.timestamp} [${info.module}] `;
return logPrefix + this.formatMsgTypeArray(info.data);
}
static winstonLog: winston.Logger;
public static configureLogging(cfg: BridgeConfigLogging) {
public configureLogging(cfg: BridgeConfigLogging, debugStream?: NodeJS.WritableStream) {
if (typeof cfg === "string") {
cfg = { level: cfg };
}
this.winstonLog?.close();
const formatters = [
winston.format.timestamp({
format: cfg.timestampFormat || "HH:mm:ss:SSS",
@ -77,8 +67,8 @@ export default class LogWrapper {
if (cfg.json) {
formatters.push((format((info) => {
const hsData = {...info as HookshotLogInfo}.data;
const firstArg = hsData.shift();
const hsData = [...(info as HookshotLogInfo).data];
const firstArg = hsData.shift() ?? 'undefined';
const result: winston.Logform.TransformableInfo = {
level: info.level,
module: info.module,
@ -104,17 +94,25 @@ export default class LogWrapper {
formatters.push(winston.format.printf(i => LogWrapper.messageFormatter(i as HookshotLogInfo)));
}
const formatter = winston.format.combine(...formatters);
const log = this.winstonLog = winston.createLogger({
level: cfg.level,
transports: [
debugStream ? new winston.transports.Stream({
stream: debugStream,
format: formatter,
}) :
new winston.transports.Console({
format: winston.format.combine(...formatters),
format: formatter,
}),
],
});
function formatBotSdkMessage(module: string, ...messageOrObject: MsgType[]) {
return { module, data: [LogWrapper.formatMsgTypeArray(messageOrObject)] };
return {
module,
data: [LogWrapper.formatMsgTypeArray(messageOrObject)]
};
}
LogService.setLogger({
@ -128,7 +126,7 @@ export default class LogWrapper {
},
warn: (module: string, ...messageOrObject: MsgType[]) => {
if (isMessageNoise(messageOrObject)) {
log.debug(formatBotSdkMessage(module, ...messageOrObject));
log.log("debug", formatBotSdkMessage(module, ...messageOrObject));
return;
}
log.log("warn", formatBotSdkMessage(module, ...messageOrObject));
@ -150,41 +148,63 @@ export default class LogWrapper {
LogService.setLevel(LogLevel.fromString(cfg.level));
LogService.debug("LogWrapper", "Reconfigured logging");
LogWrapper.isConfigured = true;
this.isConfigured = true;
}
}
export default class LogWrapper {
static readonly root = new GlobalLogger();
static formatMsgTypeArray(...data: MsgType[]): string {
data = data.flat();
return data.map(obj => {
if (typeof obj === "string") {
return obj;
}
return util.inspect(obj);
}).join(" ");
}
constructor(private module: string) { }
static messageFormatter(info: HookshotLogInfo): string {
const logPrefix = `${info.level} ${info.timestamp} [${info.module}] `;
return logPrefix + this.formatMsgTypeArray(info.data ?? []);
}
constructor(private module: string, private readonly logger: GlobalLogger = LogWrapper.root) {
}
/**
* Logs to the DEBUG channel
* @param {string} module The module being logged
* @param {*[]} messageOrObject The data to log
* @param msg The message or data to log.
* @param additionalData Additional context.
*/
public debug(...messageOrObject: MsgType[]) {
LogWrapper.winstonLog.log("debug", { module: this.module, data: messageOrObject });
public debug(msg: MsgType, ...additionalData: MsgType[]) {
this.logger.winston?.log("debug", { module: this.module, data: [msg, ...additionalData] });
}
/**
* Logs to the ERROR channel
* @param {*[]} messageOrObject The data to log
* @param msg The message or data to log.
* @param additionalData Additional context.
*/
public error(...messageOrObject: MsgType[]) {
LogWrapper.winstonLog.log("error", { module: this.module, data: messageOrObject });
public error(msg: MsgType, ...additionalData: MsgType[]) {
this.logger.winston?.log("error", { module: this.module, data: [msg, ...additionalData] });
}
/**
* Logs to the INFO channel
* @param {*[]} messageOrObject The data to log
* @param msg The message or data to log.
* @param additionalData Additional context.
*/
public info(...messageOrObject: MsgType[]) {
LogWrapper.winstonLog.log("info", { module: this.module, data: messageOrObject });
public info(msg: MsgType, ...additionalData: MsgType[]) {
this.logger.winston?.log("info", { module: this.module, data: [msg, ...additionalData] });
}
/**
* Logs to the WARN channel
* @param {*[]} messageOrObject The data to log
* @param msg The message or data to log.
* @param additionalData Additional context.
*/
public warn(...messageOrObject: MsgType[]) {
LogWrapper.winstonLog.log("warn", { module: this.module, data: messageOrObject });
public warn(msg: MsgType, ...additionalData: MsgType[]) {
this.logger.winston?.log("warn", { module: this.module, data: [msg, ...additionalData] });
}
}

87
tests/LogWrapperTest.ts Normal file
View File

@ -0,0 +1,87 @@
import { expect } from "chai";
import { Writable } from "stream";
import LogWrapper, { GlobalLogger } from "../src/LogWrapper";
const tortureArgs: [unknown, ...unknown[]][] = [
["test-msg"],
[Number.MAX_VALUE],
[false],
[Buffer.from('foo')],
[new Error('Test')],
[undefined],
[null],
[NaN],
[[]],
[() => { /*dummy*/}],
["Foo", "test-msg"],
["Foo", Number.MAX_VALUE],
["Foo", false],
["Foo", Buffer.from('foo')],
["Foo", new Error('Test')],
["Foo", undefined],
["Foo", null],
["Foo", NaN],
["Foo", []],
["Foo", () => { /*dummy*/}],
]
const MODULE_NAME = 'LogTesting';
describe('LogWrapper', () => {
describe('text logger torture test', () => {
// eslint-disable-next-line @typescript-eslint/no-explicit-any
let data: any;
const global = new GlobalLogger();
global.configureLogging({
json: false,
level: 'debug',
}, new Writable({
write(chunk, _encoding, callback) {
data = chunk.toString();
callback();
},
}));
const log = new LogWrapper(MODULE_NAME, global);
for (const args of tortureArgs) {
it(`handles logging '${args.map(t => typeof t).join(', ')}'`, () => {
for (const level of ['debug', 'info', 'warn', 'error']) {
log[level as 'debug'|'info'|'warn'|'error'](args[0], ...args.slice(1));
expect(data).to.include(level.toUpperCase());
expect(data).to.include(MODULE_NAME);
expect(data).to.not.be.undefined;
}
})
}
});
describe('JSON logger torture test', () => {
// eslint-disable-next-line @typescript-eslint/no-explicit-any
let data: any;
const global = new GlobalLogger();
global.configureLogging({
json: true,
level: 'debug',
}, new Writable({
write(chunk, _encoding, callback) {
data = JSON.parse(chunk.toString());
callback();
},
}));
const log = new LogWrapper(MODULE_NAME, global);
for (const args of tortureArgs) {
it(`handles logging '${args.map(t => typeof t).join(', ')}'`, () => {
for (const level of ['debug', 'info', 'warn', 'error']) {
log[level as 'debug'|'info'|'warn'|'error'](args[0], ...args.slice(1));
expect(data.level).to.equal(level.toUpperCase());
expect(data.module).to.equal(MODULE_NAME);
expect(data.message).to.not.be.undefined;
expect(data.timestamp).to.not.be.undefined;
if (args.length > 1) {
expect(data.args).to.have.lengthOf(args.length-1);
}
}
})
}
});
});

3
tests/init.ts
View File

@ -1,2 +1,3 @@
import LogWrapper from "../src/LogWrapper";
LogWrapper.configureLogging({level: "info"});
LogWrapper.root.configureLogging({level: "info"});