Merge pull request #1406 from verdaccio/refactor-logging

chore: refactor logging

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;

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}`);

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(jsonFormat(obj, false));
-    super.write(JSON.stringify({ ...obj, msg }, Logger.safeCycles()) + '\n');
   }
 }
 
 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(jsonFormat(obj, destinationIsTTY));
-          destination.write(`${JSON.stringify({ ...obj, msg }, Logger.safeCycles())}\n`);
         };
       }
 
@@ -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 };

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`;
+}

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`;
+}

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`;
+}

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);
+    }
+  });
+}

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: '---',
+    },
+];

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);
+}

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;
+}

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) => {

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`);
+      });
+    });
+  });
+});

tsconfig.json

@@ -19,7 +19,8 @@
     "node_modules"
   ],
   "include": [
-    "src/*.ts",
+    "src/**/*.ts",
+    "test/**/.ts",
     "types/*.d.ts"
   ]
 }