fix: Convert logger into a class (#22129)

This commit is contained in:
Nerivec
2024-04-07 20:52:55 +02:00
committed by GitHub
parent cabc9f5e2f
commit 3c1a4afcb7
3 changed files with 192 additions and 213 deletions
-2
View File
@@ -60,7 +60,6 @@ export class Controller {
private extensionArgs: ExtensionArgs;
constructor(restartCallback: () => void, exitCallback: (code: number, restart: boolean) => void) {
logger.init();
zhSetLogger(logger);
zhcSetLogger(logger);
this.eventBus = new EventBus();
@@ -99,7 +98,6 @@ export class Controller {
async start(): Promise<void> {
this.state.start();
logger.logOutput();
const info = await utils.getZigbee2MQTTVersion();
logger.info(`Starting Zigbee2MQTT version ${info.version} (commit #${info.commitHash})`);
+176 -172
View File
@@ -10,34 +10,48 @@ import assert from 'assert';
const LOG_LEVELS = ['error', 'warning', 'info', 'debug'] as const;
type LogLevel = typeof LOG_LEVELS[number];
let logger: winston.Logger;
let fileTransport : winston.transport;
let output: string[];
let directory: string;
let logFilename: string;
let transportsToUse: winston.transport[];
class Logger {
private level: LogLevel;
private readonly output: string[];
private readonly directory: string;
private readonly logger: winston.Logger;
private readonly fileTransport: winston.transports.FileTransportInstance;
function init(): void {
// What transports to enable
output = settings.get().advanced.log_output;
// Directory to log to
const timestamp = moment(Date.now()).format('YYYY-MM-DD.HH-mm-ss');
directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', timestamp);
logFilename = settings.get().advanced.log_file.replace('%TIMESTAMP%', timestamp);
// Determine the log level.
const settingLevel = settings.get().advanced.log_level;
// workaround for syslog<>npm level conflict
const level = settingLevel === 'warn' ? 'warning' : settingLevel;
constructor() {
// What transports to enable
this.output = settings.get().advanced.log_output;
// Directory to log to
const timestamp = moment(Date.now()).format('YYYY-MM-DD.HH-mm-ss');
this.directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', timestamp);
const logFilename = settings.get().advanced.log_file.replace('%TIMESTAMP%', timestamp);
// Determine the log level.
const settingLevel = settings.get().advanced.log_level;
// workaround for syslog<>npm level conflict
this.level = settingLevel === 'warn' ? 'warning' : settingLevel;
assert(LOG_LEVELS.includes(level), `'${level}' is not valid log_level, use one of '${LOG_LEVELS.join(', ')}'`);
assert(
LOG_LEVELS.includes(this.level),
`'${this.level}' is not valid log_level, use one of '${LOG_LEVELS.join(', ')}'`,
);
const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format);
const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format);
// Setup default console logger
transportsToUse = [
new winston.transports.Console({
level,
silent: !output.includes('console'),
this.logger = winston.createLogger({
level: this.level,
format: winston.format.combine(
winston.format.errors({stack: true}),
winston.format.timestamp({format: timestampFormat}),
),
levels: winston.config.syslog.levels,
});
const consoleSilenced = !this.output.includes('console');
// Print to user what logging is active
let logging = `Logging to console${consoleSilenced ? ' (silenced)' : ''}`;
// Setup default console logger
this.logger.add(new winston.transports.Console({
silent: consoleSilenced,
// winston.config.syslog.levels sets 'warning' as 'red'
format: winston.format.combine(
winston.format.colorize({colors: {debug: 'blue', info: 'green', warning: 'yellow', error: 'red'}}),
@@ -45,167 +59,157 @@ function init(): void {
return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
}),
),
}),
];
}));
if (output.includes('file')) {
// Make sure that log directory exists when not logging to stdout only
fx.mkdirSync(directory);
if (this.output.includes('file')) {
logging += `, file (filename: ${logFilename})`;
if (settings.get().advanced.log_symlink_current) {
const current = settings.get().advanced.log_directory.replace('%TIMESTAMP%', 'current');
const actual = './' + timestamp;
/* istanbul ignore next */
if (fs.existsSync(current)) {
fs.unlinkSync(current);
// Make sure that log directory exists when not logging to stdout only
fx.mkdirSync(this.directory);
if (settings.get().advanced.log_symlink_current) {
const current = settings.get().advanced.log_directory.replace('%TIMESTAMP%', 'current');
const actual = './' + timestamp;
/* istanbul ignore next */
if (fs.existsSync(current)) {
fs.unlinkSync(current);
}
fs.symlinkSync(actual, current);
}
fs.symlinkSync(actual, current);
// Add file logger when enabled
// eslint-disable-next-line max-len
// NOTE: the initiation of the logger even when not added as transport tries to create the logging directory
const transportFileOptions: KeyValue = {
filename: path.join(this.directory, logFilename),
json: false,
format: winston.format.printf(/* istanbul ignore next */(info) => {
return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
}),
};
if (settings.get().advanced.log_rotation) {
transportFileOptions.tailable = true;
transportFileOptions.maxFiles = 3; // Keep last 3 files
transportFileOptions.maxsize = 10000000; // 10MB
}
this.fileTransport = new winston.transports.File(transportFileOptions);
this.logger.add(this.fileTransport);
}
// Add file logger when enabled
// NOTE: the initiation of the logger, even when not added as transport tries to create the logging directory
const transportFileOptions: KeyValue = {
filename: path.join(directory, logFilename),
json: false,
level,
format: winston.format.printf(/* istanbul ignore next */(info) => {
return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
}),
};
/* istanbul ignore next */
if (this.output.includes('syslog')) {
logging += `, syslog`;
// eslint-disable-next-line
require('winston-syslog').Syslog;
if (settings.get().advanced.log_rotation) {
transportFileOptions.tailable = true;
transportFileOptions.maxFiles = 3; // Keep last 3 files
transportFileOptions.maxsize = 10000000; // 10MB
const options: KeyValue = {
app_name: 'Zigbee2MQTT',
format: winston.format.printf(/* istanbul ignore next */(info) => {
return `${info.namespace}: ${info.message}`;
}),
...settings.get().advanced.log_syslog,
};
if (options.hasOwnProperty('type')) {
options.type = options.type.toString();
}
// @ts-expect-error untyped transport
this.logger.add(new winston.transports.Syslog(options));
}
fileTransport = new winston.transports.File(transportFileOptions);
transportsToUse.push(fileTransport);
this.info(logging);
}
get winston(): winston.Logger {
return this.logger;
}
public addTransport(transport: winston.transport): void {
transport.level = this.level;
this.logger.add(transport);
}
public removeTransport(transport: winston.transport): void {
this.logger.remove(transport);
}
// TODO refactor Z2M level to 'warning' to simplify logic
public getLevel(): LogLevel | 'warn' {
return this.level === 'warning' ? 'warn' : this.level;
}
public setLevel(level: LogLevel | 'warn'): void {
if (level === 'warn') {
level = 'warning';
}
this.level = level;
this.logger.transports.forEach((transport) => transport.level = this.level);
}
public warning(message: string, namespace: string = 'z2m'): void {
this.logger.warning(message, {namespace});
}
public info(message: string, namespace: string = 'z2m'): void {
this.logger.info(message, {namespace});
}
public debug(message: string, namespace: string = 'z2m'): void {
if (this.level !== 'debug') {
return;
}
this.logger.debug(message, {namespace});
}
public error(message: string, namespace: string = 'z2m'): void {
this.logger.error(message, {namespace});
}
// Cleanup any old log directory.
public cleanup(): void {
if (settings.get().advanced.log_directory.includes('%TIMESTAMP%')) {
const rootDirectory = path.join(this.directory, '..');
let directories = fs.readdirSync(rootDirectory).map((d) => {
d = path.join(rootDirectory, d);
return {path: d, birth: fs.statSync(d).mtime};
});
directories.sort((a: KeyValue, b: KeyValue) => b.birth - a.birth);
directories = directories.slice(10, directories.length);
directories.forEach((dir) => {
this.debug(`Removing old log directory '${dir.path}'`);
rimrafSync(dir.path);
});
}
}
// Workaround for https://github.com/winstonjs/winston/issues/1629.
// https://github.com/Koenkk/zigbee2mqtt/pull/10905
/* istanbul ignore next */
if (output.includes('syslog')) {
// eslint-disable-next-line
require('winston-syslog').Syslog;
public async end(): Promise<void> {
this.logger.end();
const options: KeyValue = {
app_name: 'Zigbee2MQTT',
format: winston.format.printf(/* istanbul ignore next */(info) => {
return `${info.namespace}: ${info.message}`;
}),
...settings.get().advanced.log_syslog,
};
if (options.hasOwnProperty('type')) {
options.type = options.type.toString();
}
// @ts-expect-error custom transport
transportsToUse.push(new winston.transports.Syslog(options));
}
logger = winston.createLogger({
format: winston.format.combine(
winston.format.errors({stack: true}),
winston.format.timestamp({format: timestampFormat}),
),
transports: transportsToUse,
levels: winston.config.syslog.levels,
});
}
function addTransport(transport: winston.transport): void {
transport.level = transportsToUse[0].level;
logger.add(transport);
}
function removeTransport(transport: winston.transport): void {
logger.remove(transport);
}
// TODO refactor Z2M level to 'warning' to simplify logic
function getLevel(): LogLevel | 'warn' {
let level = transportsToUse[0].level;
if (level === 'warning') {
level = 'warn';
}
return transportsToUse[0].level as LogLevel | 'warn';
}
function setLevel(level: LogLevel | 'warn'): void {
if (level === 'warn') {
level = 'warning';
}
logger.transports.forEach((transport) => transport.level = level);
}
function warning(message: string, namespace: string = 'z2m'): void {
logger.warning(message, {namespace});
}
function info(message: string, namespace: string = 'z2m'): void {
logger.info(message, {namespace});
}
function debug(message: string, namespace: string = 'z2m'): void {
logger.debug(message, {namespace});
}
function error(message: string, namespace: string = 'z2m'): void {
logger.error(message, {namespace});
}
// Print to user what logging is enabled
function logOutput(): void {
const filename = output.includes('file') ? ` (filename: ${logFilename})` : ``;
info(`Logging to ${output.join(', ')}${filename}.`);
}
// Cleanup any old log directory.
function cleanup(): void {
if (settings.get().advanced.log_directory.includes('%TIMESTAMP%')) {
const rootDirectory = path.join(directory, '..');
let directories = fs.readdirSync(rootDirectory).map((d) => {
d = path.join(rootDirectory, d);
return {path: d, birth: fs.statSync(d).mtime};
});
directories.sort((a: KeyValue, b: KeyValue) => b.birth - a.birth);
directories = directories.slice(10, directories.length);
directories.forEach((dir) => {
debug(`Removing old log directory '${dir.path}'`);
rimrafSync(dir.path);
});
}
}
// Workaround for https://github.com/winstonjs/winston/issues/1629.
// https://github.com/Koenkk/zigbee2mqtt/pull/10905
/* istanbul ignore next */
async function end(): Promise<void> {
logger.end();
await new Promise<void>((resolve) => {
if (!fileTransport) {
process.nextTick(resolve);
} else {
// @ts-ignore
if (fileTransport._dest) {
// @ts-ignore
fileTransport._dest.on('finish', resolve);
await new Promise<void>((resolve) => {
if (!this.fileTransport) {
process.nextTick(resolve);
} else {
// @ts-ignore
fileTransport.on('open', () => fileTransport._dest.on('finish', resolve));
// @ts-expect-error workaround
if (this.fileTransport._dest) {
// @ts-expect-error workaround
this.fileTransport._dest.on('finish', resolve);
} else {
// @ts-expect-error workaround
this.fileTransport.on('open', () => this.fileTransport._dest.on('finish', resolve));
}
}
}
});
});
}
}
export default {
init, logOutput, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end, removeTransport,
winston: (): winston.Logger => logger,
};
export default new Logger();
+16 -39
View File
@@ -25,16 +25,12 @@ describe('Logger', () => {
it('Create log directory', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const dirs = fs.readdirSync(dir.name);
expect(dirs.length).toBe(1);
});
it('Should cleanup', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
for (const d of fs.readdirSync(dir.name)) {
rimrafSync(path.join(dir.name, d));
@@ -51,8 +47,6 @@ describe('Logger', () => {
it('Should not cleanup when there is no timestamp set', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
for (let i = 30; i < 40; i++) {
fs.mkdirSync(path.join(dir.name, `log_${i}`));
}
@@ -65,16 +59,14 @@ describe('Logger', () => {
it('Set and get log level', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
logger.setLevel('debug');
expect(logger.getLevel()).toBe('debug');
logger.setLevel('info');
expect(logger.getLevel()).toBe('info');
logger.setLevel('warning');
expect(logger.getLevel()).toBe('warning');
expect(logger.getLevel()).toBe('warn');// match old Z2M levels
logger.setLevel('warn');
expect(logger.getLevel()).toBe('warning');
expect(logger.getLevel()).toBe('warn');// match old Z2M levels
logger.setLevel('error');
expect(logger.getLevel()).toBe('error');
});
@@ -83,9 +75,7 @@ describe('Logger', () => {
settings.set(['advanced', 'log_level'], 'warn');
settings.reRead();
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
expect(logger.getLevel()).toBe('warning');
expect(logger.level).toBe('warning');// getLevel() reports old Z2M level to match display/value
settings.set(['advanced', 'log_level'], 'info');
settings.reRead();
});
@@ -97,20 +87,18 @@ describe('Logger', () => {
}
const logger = require('../lib/util/logger').default;
logger.init();
expect(logger.winston().transports.length).toBe(2);
expect(logger.winston.transports.length).toBe(2);
const transport = new DummyTransport();
logger.addTransport(transport);
expect(logger.winston().transports.length).toBe(3);
expect(logger.winston.transports.length).toBe(3);
logger.removeTransport(transport);
expect(logger.winston().transports.length).toBe(2);
expect(logger.winston.transports.length).toBe(2);
});
it('Logger should be console and file by default', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const pipes = logger.winston()._readableState.pipes;
const pipes = logger.winston._readableState.pipes;
console.log(pipes);
expect(pipes.length).toBe(2);
expect(pipes[0].constructor.name).toBe('Console');
expect(pipes[0].silent).toBe(false);
@@ -121,9 +109,7 @@ describe('Logger', () => {
it('Logger can be file only', () => {
settings.set(['advanced', 'log_output'], ['file']);
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const pipes = logger.winston()._readableState.pipes;
const pipes = logger.winston._readableState.pipes;
expect(pipes.length).toBe(2);
expect(pipes[0].constructor.name).toBe('Console');
expect(pipes[0].silent).toBe(true);
@@ -134,9 +120,7 @@ describe('Logger', () => {
it('Logger can be console only', () => {
settings.set(['advanced', 'log_output'], ['console']);
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const pipes = logger.winston()._readableState.pipes;
const pipes = logger.winston._readableState.pipes;
expect(pipes.constructor.name).toBe('Console');
expect(pipes.silent).toBe(false);
});
@@ -144,9 +128,7 @@ describe('Logger', () => {
it('Logger can be nothing', () => {
settings.set(['advanced', 'log_output'], []);
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const pipes = logger.winston()._readableState.pipes;
const pipes = logger.winston._readableState.pipes;
expect(pipes.constructor.name).toBe('Console');
expect(pipes.silent).toBe(true);
});
@@ -154,9 +136,7 @@ describe('Logger', () => {
it('Should allow to disable log rotation', () => {
settings.set(['advanced', 'log_rotation'], false);
const logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
const pipes = logger.winston()._readableState.pipes;
const pipes = logger.winston._readableState.pipes;
expect(pipes[1].constructor.name).toBe('File');
expect(pipes[1].maxFiles).toBeNull();
expect(pipes[1].tailable).toBeFalsy();
@@ -166,8 +146,6 @@ describe('Logger', () => {
it('Should allow to symlink logs to current directory', () => {
settings.set(['advanced', 'log_symlink_current'], true);
let logger = require('../lib/util/logger').default;
logger.init();
logger.logOutput();
expect(fs.readdirSync(dir.name).includes('current')).toBeTruthy()
jest.resetModules();
@@ -176,25 +154,24 @@ describe('Logger', () => {
it('Log', () => {
const logger = require('../lib/util/logger').default;
logger.init();
logger.setLevel('debug');
const debug = jest.spyOn(logger.winston(), 'debug');
const debug = jest.spyOn(logger.winston, 'debug');
logger.debug('debug');
expect(debug).toHaveBeenCalledWith('debug', {namespace: 'z2m'});
expect(debug).toHaveBeenCalledTimes(1);
const info = jest.spyOn(logger.winston(), 'info');
const info = jest.spyOn(logger.winston, 'info');
logger.info('info');
expect(info).toHaveBeenCalledWith('info', {namespace: 'z2m'});
expect(info).toHaveBeenCalledTimes(1);
const warning = jest.spyOn(logger.winston(), 'warning');
const warning = jest.spyOn(logger.winston, 'warning');
logger.warning('warning');
expect(warning).toHaveBeenCalledWith('warning', {namespace: 'z2m'});
expect(warning).toHaveBeenCalledTimes(1);
const error = jest.spyOn(logger.winston(), 'error');
const error = jest.spyOn(logger.winston, 'error');
logger.error('error');
expect(error).toHaveBeenCalledWith('error', {namespace: 'z2m'});