diff --git a/src/api/middleware.ts b/src/api/middleware.ts index 0e41dba3e..ee4959bac 100644 --- a/src/api/middleware.ts +++ b/src/api/middleware.ts @@ -175,6 +175,10 @@ export function final(body: FinalBody, req: $RequestExtend, res: $ResponseExtend res.send(body); } +export const LOG_STATUS_MESSAGE = "@{status}, user: @{user}(@{remoteIP}), req: '@{request.method} @{request.url}'"; +export const LOG_VERDACCIO_ERROR = `${LOG_STATUS_MESSAGE}, error: @{!error}`; +export const LOG_VERDACCIO_BYTES = `${LOG_STATUS_MESSAGE}, bytes: @{bytes.in}/@{bytes.out}`; + export function log(req: $RequestExtend, res: $ResponseExtend, next: $NextFunctionVer): void { // logger req.log = logger.child({ sub: 'in' }); @@ -221,11 +225,11 @@ export function log(req: $RequestExtend, res: $ResponseExtend, next: $NextFuncti const forwardedFor = req.headers['x-forwarded-for']; const remoteAddress = req.connection.remoteAddress; const remoteIP = forwardedFor ? `${forwardedFor} via ${remoteAddress}` : remoteAddress; - let message = "@{status}, user: @{user}(@{remoteIP}), req: '@{request.method} @{request.url}'"; + let message; if (res._verdaccio_error) { - message += ', error: @{!error}'; + message = LOG_VERDACCIO_ERROR; } else { - message += ', bytes: @{bytes.in}/@{bytes.out}'; + message = LOG_VERDACCIO_BYTES; } req.url = req.originalUrl; diff --git a/src/lib/config-path.ts b/src/lib/config-path.ts index b055713ea..dae4c2519 100644 --- a/src/lib/config-path.ts +++ b/src/lib/config-path.ts @@ -68,7 +68,7 @@ function updateStorageLinks(configLocation, defaultConfig) { // $XDG_DATA_HOME defines the base directory relative to which user specific data files should be stored, // If $XDG_DATA_HOME is either not set or empty, a default equal to $HOME/.local/share should be used. // $FlowFixMe - let dataDir = process.env.XDG_DATA_HOME || Path.join(process.env.HOME, '.local', 'share'); + let dataDir = process.env.XDG_DATA_HOME || Path.join(process.env.HOME as string, '.local', 'share'); if (folderExists(dataDir)) { dataDir = Path.resolve(Path.join(dataDir, pkgJSON.name, 'storage')); return defaultConfig.replace(/^storage: .\/storage$/m, `storage: ${dataDir}`); diff --git a/src/lib/logger.ts b/src/lib/logger.ts index 5e752ed88..6a568591e 100644 --- a/src/lib/logger.ts +++ b/src/lib/logger.ts @@ -1,64 +1,50 @@ /* eslint-disable */ -import { isObject } from './utils'; +import {prettyTimestamped} from "./logger/format/pretty-timestamped"; +import {pretty} from "./logger/format/pretty"; +import {jsonFormat} from "./logger/format/json"; const cluster = require('cluster'); const Logger = require('bunyan'); const Error = require('http-errors'); const Stream = require('stream'); -const { red, yellow, cyan, magenta, green, white, black, blue } = require('kleur'); const pkgJSON = require('../../package.json'); const _ = require('lodash'); const dayjs = require('dayjs'); -/** - * Match the level based on buyan severity scale - * @param {*} x severity level - * @return {String} security level - */ -function calculateLevel(x) { - switch (true) { - case x < 15: - return 'trace'; - case x < 25: - return 'debug'; - case x < 35: - return 'info'; - case x == 35: - return 'http'; - case x < 45: - return 'warn'; - case x < 55: - return 'error'; - default: - return 'fatal'; - } -} - /** * A RotatingFileStream that modifes the message first */ class VerdaccioRotatingFileStream extends Logger.RotatingFileStream { // We depend on mv so that this is there write(obj) { - const msg = fillInMsgTemplate(obj.msg, obj, false); - super.write(JSON.stringify({ ...obj, msg }, Logger.safeCycles()) + '\n'); + super.write(jsonFormat(obj, false)); } } let logger; +export interface LoggerTarget { + type?: string; + format?: string; + level?: string; + options?: any; + path?: string; +} + +const DEFAULT_LOGGER_CONF = [{ type: 'stdout', format: 'pretty', level: 'http' }]; + /** * Setup the Buyan logger * @param {*} logs list of log configuration */ function setup(logs) { - const streams = []; + const streams: any = []; if (logs == null) { - logs = [{ type: 'stdout', format: 'pretty', level: 'http' }]; + logs = DEFAULT_LOGGER_CONF; } - logs.forEach(function(target) { + logs.forEach(function(target: LoggerTarget) { let level = target.level || 35; if (level === 'http') { level = 35; @@ -84,14 +70,16 @@ function setup(logs) { ) ); - streams.push({ + const rotateStream: any = { // @ts-ignore type: 'raw', // @ts-ignore level, // @ts-ignore stream, - }); + }; + + streams.push(rotateStream); } else { const stream = new Stream(); stream.writable = true; @@ -114,17 +102,16 @@ function setup(logs) { if (target.format === 'pretty') { // making fake stream for pretty printing stream.write = obj => { - destination.write(`${print(obj.level, obj.msg, obj, destinationIsTTY)}\n`); + destination.write(pretty(obj, destinationIsTTY)); }; } else if (target.format === 'pretty-timestamped') { // making fake stream for pretty printing stream.write = obj => { - destination.write(`[${dayjs(obj.time).format('YYYY-MM-DD HH:mm:ss')}] ${print(obj.level, obj.msg, obj, destinationIsTTY)}\n`); + destination.write(prettyTimestamped(obj, destinationIsTTY)); }; } else { stream.write = obj => { - const msg = fillInMsgTemplate(obj.msg, obj, destinationIsTTY); - destination.write(`${JSON.stringify({ ...obj, msg }, Logger.safeCycles())}\n`); + destination.write(jsonFormat(obj, destinationIsTTY)); }; } @@ -155,108 +142,4 @@ function setup(logs) { }); } -// adopted from socket.io -// this part was converted to coffee-script and back again over the years, -// so it might look weird - -// level to color -const levels = { - fatal: red, - error: red, - warn: yellow, - http: magenta, - info: cyan, - debug: green, - trace: white, -}; - -let max = 0; -for (const l in levels) { - if (Object.prototype.hasOwnProperty.call(levels, l)) { - max = Math.max(max, l.length); - } -} - -/** - * Apply whitespaces based on the length - * @param {*} str the log message - * @return {String} - */ -function pad(str) { - if (str.length < max) { - return str + ' '.repeat(max - str.length); - } - return str; -} - -function fillInMsgTemplate(msg, obj, colors) { - return msg.replace(/@{(!?[$A-Za-z_][$0-9A-Za-z\._]*)}/g, (_, name) => { - let str = obj; - let is_error; - if (name[0] === '!') { - name = name.substr(1); - is_error = true; - } - - const _ref = name.split('.'); - for (let _i = 0; _i < _ref.length; _i++) { - const id = _ref[_i]; - if (isObject(str) || Array.isArray(str)) { - str = str[id]; - } else { - str = undefined; - } - } - - if (typeof str === 'string') { - if (!colors || str.includes('\n')) { - return str; - } else if (is_error) { - return red(str); - } else { - return green(str); - } - } else { - return require('util').inspect(str, null, null, colors); - } - }); -} - -/** - * Apply colors to a string based on level parameters. - * @param {*} type - * @param {*} msg - * @param {*} obj - * @param {*} colors - * @return {String} - */ -function print(type, msg, obj, colors) { - if (typeof type === 'number') { - type = calculateLevel(type); - } - const finalMessage = fillInMsgTemplate(msg, obj, colors); - - const subsystems = [ - { - in: green('<--'), - out: yellow('-->'), - fs: black('-=-'), - default: blue('---'), - }, - { - in: '<--', - out: '-->', - fs: '-=-', - default: '---', - }, - ]; - - const sub = subsystems[colors ? 0 : 1][obj.sub] || subsystems[+!colors].default; - if (colors) { - return ` ${levels[type](pad(type))}${white(`${sub} ${finalMessage}`)}`; - } else { - return ` ${pad(type)}${sub} ${finalMessage}`; - } -} - export { setup, logger }; diff --git a/src/lib/logger/format/json.ts b/src/lib/logger/format/json.ts new file mode 100644 index 000000000..6afbca590 --- /dev/null +++ b/src/lib/logger/format/json.ts @@ -0,0 +1,10 @@ + +import {fillInMsgTemplate} from "../formatter"; + +const Logger = require('bunyan'); + +export function jsonFormat(obj, hasColors): string { + const msg = fillInMsgTemplate(obj.msg, obj, hasColors); + + return `${JSON.stringify({ ...obj, msg }, Logger.safeCycles())}\n`; +} diff --git a/src/lib/logger/format/pretty-timestamped.ts b/src/lib/logger/format/pretty-timestamped.ts new file mode 100644 index 000000000..e7b0a9e44 --- /dev/null +++ b/src/lib/logger/format/pretty-timestamped.ts @@ -0,0 +1,6 @@ +import {formatLoggingDate} from "../utils"; +import {printMessage} from "../formatter"; + +export function prettyTimestamped(obj, hasColors): string { + return `[${formatLoggingDate(obj.time)}] ${printMessage(obj.level, obj.msg, obj, hasColors)}\n`; +} diff --git a/src/lib/logger/format/pretty.ts b/src/lib/logger/format/pretty.ts new file mode 100644 index 000000000..c8f6875cc --- /dev/null +++ b/src/lib/logger/format/pretty.ts @@ -0,0 +1,5 @@ +import {printMessage} from "../formatter"; + +export function pretty(obj, hasColors): string { + return `${printMessage(obj.level, obj.msg, obj, hasColors)}\n`; +} diff --git a/src/lib/logger/formatter.ts b/src/lib/logger/formatter.ts new file mode 100644 index 000000000..eba466c37 --- /dev/null +++ b/src/lib/logger/formatter.ts @@ -0,0 +1,71 @@ +import { inspect } from 'util'; +import { isObject, pad } from '../utils'; +import { red, green } from 'kleur'; + +import { white } from 'kleur'; +import {calculateLevel, levels, subsystems} from "./levels"; + +let LEVEL_VALUE_MAX = 0; +for (const l in levels) { + if (Object.prototype.hasOwnProperty.call(levels, l)) { + LEVEL_VALUE_MAX = Math.max(LEVEL_VALUE_MAX, l.length); + } +} + +/** + * Apply colors to a string based on level parameters. + * @param {*} type + * @param {*} msg + * @param {*} templateObjects + * @param {*} hasColors + * @return {String} + */ +export function printMessage(type, msg, templateObjects, hasColors) { + if (typeof type === 'number') { + type = calculateLevel(type); + } + + const finalMessage = fillInMsgTemplate(msg, templateObjects, hasColors); + + const sub = subsystems[hasColors ? 0 : 1][templateObjects.sub] || subsystems[+!hasColors].default; + if (hasColors) { + return ` ${levels[type](pad(type, LEVEL_VALUE_MAX))}${white(`${sub} ${finalMessage}`)}`; + } else { + return ` ${pad(type, LEVEL_VALUE_MAX)}${sub} ${finalMessage}`; + } +} + +export function fillInMsgTemplate(msg, obj: unknown, colors): string { + return msg.replace(/@{(!?[$A-Za-z_][$0-9A-Za-z\._]*)}/g, (_, name): string => { + + let str = obj; + let is_error; + if (name[0] === '!') { + name = name.substr(1); + is_error = true; + } + + const _ref = name.split('.'); + for (let _i = 0; _i < _ref.length; _i++) { + const id = _ref[_i]; + if (isObject(str)) { + // @ts-ignore + str = str[id]; + } else { + str = undefined; + } + } + + if (typeof str === 'string') { + if (!colors || (str as string).includes('\n')) { + return str; + } else if (is_error) { + return red(str); + } else { + return green(str); + } + } else { + return inspect(str, undefined, null, colors); + } + }); +} diff --git a/src/lib/logger/levels.ts b/src/lib/logger/levels.ts new file mode 100644 index 000000000..5517083d5 --- /dev/null +++ b/src/lib/logger/levels.ts @@ -0,0 +1,51 @@ +import { yellow, green, black, blue, red, magenta, cyan, white } from 'kleur'; + +// level to color +export const levels = { + fatal: red, + error: red, + warn: yellow, + http: magenta, + info: cyan, + debug: green, + trace: white, +}; + +/** + * Match the level based on buyan severity scale + * @param {*} x severity level + * @return {String} security level + */ +export function calculateLevel(x) { + switch (true) { + case x < 15: + return 'trace'; + case x < 25: + return 'debug'; + case x < 35: + return 'info'; + case x == 35: + return 'http'; + case x < 45: + return 'warn'; + case x < 55: + return 'error'; + default: + return 'fatal'; + } +} + +export const subsystems = [ + { + in: green('<--'), + out: yellow('-->'), + fs: black('-=-'), + default: blue('---'), + }, + { + in: '<--', + out: '-->', + fs: '-=-', + default: '---', + }, +]; diff --git a/src/lib/logger/utils.ts b/src/lib/logger/utils.ts new file mode 100644 index 000000000..251bce4c1 --- /dev/null +++ b/src/lib/logger/utils.ts @@ -0,0 +1,7 @@ +import dayjs from 'dayjs'; + +export const FORMAT_DATE = 'YYYY-MM-DD HH:mm:ss'; + +export function formatLoggingDate(time: string): string { + return dayjs(time).format(FORMAT_DATE); +} diff --git a/src/lib/utils.ts b/src/lib/utils.ts index 1bc0ff545..e1d86be77 100644 --- a/src/lib/utils.ts +++ b/src/lib/utils.ts @@ -572,3 +572,15 @@ export function formatAuthor(author: AuthorFormat): any { export function isHTTPProtocol(uri: string): boolean { return /^(https?:)?\/\//.test(uri); } + +/** + * Apply whitespaces based on the length + * @param {*} str the log message + * @return {String} + */ +export function pad(str, max): string { + if (str.length < max) { + return str + ' '.repeat(max - str.length); + } + return str; +} diff --git a/test/unit/modules/api/api.spec.ts b/test/unit/modules/api/api.spec.ts index f6a464554..d025a4bb7 100644 --- a/test/unit/modules/api/api.spec.ts +++ b/test/unit/modules/api/api.spec.ts @@ -14,7 +14,9 @@ import {DOMAIN_SERVERS} from '../../../functional/config.functional'; import {buildToken} from '../../../../src/lib/utils'; import {getNewToken} from '../../__helper/api'; -require('../../../../src/lib/logger').setup([]); +require('../../../../src/lib/logger').setup([ + { type: 'stdout', format: 'pretty', level: 'info' } +]); const credentials = { name: 'jota', password: 'secretPass' }; const putPackage = (app, name, publishMetadata) => { diff --git a/test/unit/modules/logger/parser.spec.ts b/test/unit/modules/logger/parser.spec.ts new file mode 100644 index 000000000..6e984c54a --- /dev/null +++ b/test/unit/modules/logger/parser.spec.ts @@ -0,0 +1,121 @@ +import { fillInMsgTemplate } from "../../../../src/lib/logger/formatter"; +import {LOG_VERDACCIO_ERROR, LOG_VERDACCIO_BYTES} from "../../../../src/api/middleware"; +import { HTTP_STATUS } from "@verdaccio/commons-api"; + +// the following mocks avoid use colors, thus the strings can be matched + +jest.mock('kleur', () => { + // we emulate colors with this pattern color[msg] + return { + green: r => `g[${r}]`, + yellow: r => `y[${r}]`, + black: r => `b[${r}]`, + blue: r => `bu[${r}]`, + red: r => `r[${r}]`, + cyan: r => `c[${r}]`, + magenta: r => `m[${r}]`, + white: r => `w[${r}]`, + } +}); + +jest.mock('util', () => { + // we need to override only one method, but still we need others + const originalModule = jest.requireActual('util'); + return { + ...originalModule, + inspect: r => r, + } +}); + + +describe('Logger Parser', () => { + describe('basic messages', () => { + test('number object property', () => { + expect(fillInMsgTemplate('foo:@{foo}', {foo: 1}, false)).toEqual('foo:1'); + }); + + test('string object property', () => { + expect(fillInMsgTemplate('foo:@{foo}', {foo: 'bar'}, false)).toEqual('foo:bar'); + }); + + test('empty message no object property', () => { + expect(fillInMsgTemplate('foo', undefined, false)).toEqual('foo'); + }); + + test('string no object property', () => { + expect(fillInMsgTemplate('foo', null, false)).toEqual('foo'); + }); + + test('string no object property with break line ', () => { + expect(fillInMsgTemplate('foo \n bar', null, false)).toEqual('foo \n bar'); + }); + + test('string no object property with colors', () => { + expect(fillInMsgTemplate('foo', null, true)).toEqual('foo'); + }); + + test('string object property with colors', () => { + expect(fillInMsgTemplate('foo:@{foo}', {foo: 'bar'}, true)).toEqual(`foo:${'g[bar]'}`); + }); + }) + + describe('middleware log messages', () => { + describe('test errors log', () => { + const middlewareObject = { name: 'verdaccio', + request: { + method: 'POST', + url: '/-/npm/v1/user' + }, + user: 'userTest2001', + remoteIP: '::ffff:127.0.0.1', + status: HTTP_STATUS.UNAUTHORIZED, + error: 'some error', + msg: '@{status}, user: @{user}(@{remoteIP}), req: \'@{request.method} @{request.url}\', error: @{!error}' + }; + + test('should display error log', () => { + const expectedErrorMessage = `401, user: userTest2001(::ffff:127.0.0.1), req: 'POST /-/npm/v1/user', error: some error`; + expect(fillInMsgTemplate(LOG_VERDACCIO_ERROR, middlewareObject, false)) + .toEqual(expectedErrorMessage); + }); + + test('should display error log with colors', () => { + const expectedErrorMessage = `401, user: g[userTest2001](g[::ffff:127.0.0.1]), req: 'g[POST] g[/-/npm/v1/user]', error: r[some error]`; + expect(fillInMsgTemplate(LOG_VERDACCIO_ERROR, middlewareObject, true)) + .toEqual(expectedErrorMessage); + }); + }); + + describe('test bytes log', () => { + const middlewareObject = { name: 'verdaccio', + hostname: 'macbook-touch', + pid: 85621, + sub: 'in', + level: 35, + request: { + method: 'PUT', + url: '/-/user/org.couchdb.user:userTest2002' + }, + user: 'userTest2002', + remoteIP: '::ffff:127.0.0.1', + status: 201, + error: undefined, + bytes: { in: 50, out: 405 }, + msg: + '@{status}, user: @{user}(@{remoteIP}), req: \'@{request.method} @{request.url}\', bytes: @{bytes.in}/@{bytes.out}', + time: '2019-07-20T11:31:49.939Z', + v: 0 + } + + test('should display log with bytes', () => { + expect(fillInMsgTemplate(LOG_VERDACCIO_BYTES, middlewareObject, false)) + .toEqual(`201, user: userTest2002(::ffff:127.0.0.1), req: 'PUT /-/user/org.couchdb.user:userTest2002', bytes: 50/405`); + }); + + test('should display log with bytes with colors', () => { + expect(fillInMsgTemplate(LOG_VERDACCIO_BYTES, middlewareObject, true)) + .toEqual(`201, user: g[userTest2002](g[::ffff:127.0.0.1]), req: 'g[PUT] g[/-/user/org.couchdb.user:userTest2002]', bytes: 50/405`); + }); + }); + }); +}); diff --git a/tsconfig.json b/tsconfig.json index d7b62672e..90751aabd 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -19,7 +19,8 @@ "node_modules" ], "include": [ - "src/*.ts", + "src/**/*.ts", + "test/**/.ts", "types/*.d.ts" ] }