fix: using correctly logging levels (#2153)

* fix: using correctly logging levels

* chore: update deps

.github/workflows/ci-e2e.yml

@@ -20,10 +20,8 @@ jobs:
         with:
           node-version: ${{ matrix.node_version }}
       - name: Install
-        run: yarn install --immutable
+        run: yarn install
       - name: Build
         run: yarn code:build
       - name: Test CLI
         run: yarn test:e2e:cli
-        env:
-          NODE_ENV: production

package.json

@@ -41,8 +41,10 @@
     "jsonwebtoken": "8.5.1",
     "kleur": "4.1.4",
     "lodash": "4.17.21",
+    "lru-cache": "6.0.0",
     "lunr-mutable-indexes": "2.3.2",
     "marked": "2.0.1",
+    "memoizee": "0.4.15",
     "mime": "2.5.2",
     "minimatch": "3.0.4",
     "mkdirp": "1.0.4",
@@ -126,7 +128,6 @@
     "jest-junit": "9.0.0",
     "lint-staged": "8.2.1",
     "lockfile-lint": "4.3.7",
-    "lru-cache": "6.0.0",
     "nock": "12.0.3",
     "node-mocks-http": "^1.10.1",
     "prettier": "2.2.1",
@@ -171,6 +172,7 @@
     "lint:ts": "eslint \"**/*.{js,jsx,ts,tsx}\"",
     "lint:lockfile": "lockfile-lint --path yarn.lock --type yarn --validate-https --allowed-hosts verdaccio npm yarn",
     "start": "yarn babel-node --extensions \".ts,.tsx\" src/lib/cli",
+    "start:debug": "yarn node debug/bootstrap.js",
     "code:build": "yarn babel src/ --out-dir build/ --copy-files --extensions \".ts,.tsx\" --source-maps inline",
     "code:docker-build": "yarn babel src/ --out-dir build/ --copy-files --extensions \".ts,.tsx\"",
     "docker": "docker build -t verdaccio/verdaccio:pr-2122 . --no-cache",

src/api/middleware.ts

@@ -227,9 +227,6 @@ export const LOG_VERDACCIO_BYTES = `${LOG_STATUS_MESSAGE}, bytes: @{bytes.in}/@{
 
 export function log(config: Config) {
   return function (req: $RequestExtend, res: $ResponseExtend, next: $NextFunctionVer): void {
-    // logger
-    req.log = logger.child({ sub: 'in' });
-
     const _auth = req.headers.authorization;
     if (_.isNil(_auth) === false) {
       req.headers.authorization = '<Classified>';
@@ -243,7 +240,7 @@ export function log(config: Config) {
     req.url = req.originalUrl;
     // avoid log noise data from static content
     if (req.originalUrl.match(/static/) === null) {
-      req.log.info({ req: req, ip: req.ip }, "@{ip} requested '@{req.method} @{req.url}'");
+      logger.http({ req: req, ip: req.ip }, "@{ip} requested '@{req.method} @{req.url}'");
     }
     req.originalUrl = req.url;
 
@@ -293,13 +290,12 @@ export function log(config: Config) {
       req.url = req.originalUrl;
       // avoid log noise data from static content
       if (req.url.match(/static/) === null) {
-        req.log.warn(
+        logger.http(
           {
             request: {
               method: req.method,
               url: req.url,
             },
-            level: 35, // http
             user: (req.remote_user && req.remote_user.name) || null,
             remoteIP,
             status: res.statusCode,

src/lib/auth.ts

@@ -18,6 +18,7 @@ import loadPlugin from '../lib/plugin-loader';
 import { $RequestExtend, $ResponseExtend, IAuth, AESPayload } from '../../types';
 import { API_ERROR, SUPPORT_ERRORS, TOKEN_BASIC, TOKEN_BEARER } from './constants';
 import { aesEncrypt, signPayload } from './crypto-utils';
+import { logger } from './logger';
 import {
   getDefaultPlugins,
   getMiddlewareCredentials,
@@ -33,9 +34,6 @@ import {
 import { convertPayloadToBase64, ErrorCode } from './utils';
 import { getMatchedPackagesSpec } from './config-utils';
 
-/* eslint-disable @typescript-eslint/no-var-requires */
-const LoggerApi = require('./logger');
-
 class Auth implements IAuth {
   public config: Config;
   public logger: Logger;
@@ -44,7 +42,7 @@ class Auth implements IAuth {
 
   public constructor(config: Config) {
     this.config = config;
-    this.logger = LoggerApi.logger.child({ sub: 'auth' });
+    this.logger = logger;
     this.secret = config.secret;
     this.plugins = this._loadPlugin(config);
     this._applyDefaultPlugins();

src/lib/local-storage.ts

@@ -48,7 +48,7 @@ class LocalStorage implements IStorage {
   public logger: Logger;
 
   public constructor(config: Config, logger: Logger) {
-    this.logger = logger.child({ sub: 'fs' });
+    this.logger = logger;
     this.config = config;
     this.storagePlugin = this._loadStorage(config, logger);
   }

src/lib/logger/levels.ts

@@ -6,18 +6,20 @@ export type LevelCode = number;
 
 export function calculateLevel(levelCode: LevelCode): LogLevel {
     switch (true) {
-        case levelCode < 15:
+        case levelCode === 10:
             return 'trace';
-        case levelCode < 25:
+        case levelCode === 20:
             return 'debug';
-        case levelCode < 35:
-            return 'info';
-        case levelCode == 35:
+        case levelCode === 25:
             return 'http';
-        case levelCode < 45:
+        case levelCode === 30:
+            return 'info';
+        case levelCode === 40:
             return 'warn';
-        case levelCode < 55:
+        case levelCode === 50:
             return 'error';
+        case levelCode === 60:
+            return 'fatal';
         default:
             return 'fatal';
     }

src/lib/logger/logger.ts

@@ -21,7 +21,7 @@ export type LogType = 'file' | 'stdout';
 export type LogFormat = 'json' | 'pretty-timestamped' | 'pretty';
 
 export function createLogger(
-  options = {},
+  options = {level: 'http'},
   destination = pino.destination(1),
   format: LogFormat = DEFAULT_LOG_FORMAT,
   prettyPrintOptions = {
@@ -35,10 +35,11 @@ export function createLogger(
   }
 
   let pinoConfig = {
-    ...options,
     customLevels: {
-      http: 35,
+      http: 25,
     },
+    ...options,
+    level: options.level,
     serializers: {
       err: pino.stdSerializers.err,
       req: pino.stdSerializers.req,
@@ -60,13 +61,20 @@ export function createLogger(
       prettifier: require('./formatter'),
     });
   }
+  const logger = pino(pinoConfig, destination);
 
-  return pino(pinoConfig, destination);
+  if(process.env.DEBUG) {
+    logger.on('level-change', (lvl, val, prevLvl, prevVal) => {
+      debug('%s (%d) was changed to %s (%d)', lvl, val, prevLvl, prevVal);
+    })
+  }
+
+  return logger;
 }
 
 export function getLogger() {
   if (_.isNil(logger)) {
-    console.warn('logger is not defined');
+    process.emitWarning('logger is not defined');
     return;
   }
 
@@ -94,8 +102,7 @@ export function setup(options: LoggerConfig | LoggerConfigItem = [DEFAULT_LOGGER
   const isLegacyConf = Array.isArray(options);
   if (isLegacyConf) {
     const deprecateMessage = 'deprecate: multiple logger configuration is deprecated, please check the migration guide.';
-    // eslint-disable-next-line no-console
-    console.log(yellow(padLeft(deprecateMessage)));
+    process.emitWarning(deprecateMessage);
   }
 
   // verdaccio 5 does not allow multiple logger configuration
@@ -103,20 +110,16 @@ export function setup(options: LoggerConfig | LoggerConfigItem = [DEFAULT_LOGGER
   // next major will thrown an error
   let loggerConfig = isLegacyConf ? options[0] : options;
   if (!loggerConfig?.level) {
-    loggerConfig = Object.assign({}, loggerConfig, {
+    loggerConfig = Object.assign({}, {
       level: 'http',
-    });
+    }, loggerConfig);
   }
-
   const pinoConfig = { level: loggerConfig.level };
   if (loggerConfig.type === 'file') {
     debug('logging file enabled');
     logger = createLogger(pinoConfig, pino.destination(loggerConfig.path), loggerConfig.format);
   } else if (loggerConfig.type === 'rotating-file') {
-    // eslint-disable-next-line no-console
-    console.log(yellow(padLeft('rotating-file type is not longer supported, consider use [logrotate] instead')));
-    // eslint-disable-next-line no-console
-    console.log(yellow(padLeft('fallback to stdout configuration triggered')));
+    process.emitWarning('rotating-file type is not longer supported, consider use [logrotate] instead');
     debug('logging stdout enabled');
     logger = createLogger(pinoConfig, pino.destination(1), loggerConfig.format);
   } else {

src/lib/storage.ts

@@ -55,7 +55,7 @@ class Storage implements IStorageHandler {
   public constructor(config: Config) {
     this.config = config;
     this.uplinks = setupUpLinks(config);
-    this.logger = logger.child({module: 'storage'});
+    this.logger = logger;
     this.filters = [];
     // @ts-ignore
     this.localStorage = null;

src/lib/up-storage.ts

@@ -8,6 +8,7 @@ import { ReadTarball } from '@verdaccio/streams';
 import { Config, Callback, Headers, Logger, Package } from '@verdaccio/types';
 import { IProxy, UpLinkConfLocal } from '../../types';
 import { parseInterval, isObject, ErrorCode, buildToken } from './utils';
+import { logger} from './logger';
 import {
   ERROR_CODE,
   TOKEN_BASIC,
@@ -18,7 +19,6 @@ import {
   HEADER_TYPE,
   CHARACTER_ENCODING
 } from './constants';
-const LoggerApi = require('./logger');
 
 const encode = function (thing): string {
   return encodeURIComponent(thing).replace(/^%40/, '@');
@@ -71,7 +71,7 @@ class ProxyStorage implements IProxy {
     this.failed_requests = 0;
     this.userAgent = mainConfig.user_agent;
     this.ca = config.ca;
-    this.logger = LoggerApi.logger.child({ sub: 'out' });
+    this.logger = logger;
     this.server_id = mainConfig.server_id;
 
     this.url = URL.parse(this.config.url);
@@ -194,11 +194,10 @@ class ProxyStorage implements IProxy {
           function logActivity(): void {
             let message = "@{!status}, req: '@{request.method} @{request.url}'";
             message += error ? ', error: @{!error}' : ', bytes: @{bytes.in}/@{bytes.out}';
-            self.logger.warn(
+            self.logger.http(
               {
                 err: err || undefined, // if error is null/false change this to undefined so it wont log
                 request: { method: method, url: uri },
-                level: 35, // http
                 status: res != null ? res.statusCode : 'ERR',
                 error: error,
                 bytes: {
@@ -245,13 +244,12 @@ class ProxyStorage implements IProxy {
       if (_.isNil(requestCallback) === false) {
         (function do_log(): void {
           const message = "@{!status}, req: '@{request.method} @{request.url}' (streaming)";
-          self.logger.warn(
+          self.logger.http(
             {
               request: {
                 method: method,
                 url: uri
               },
-              level: 35, // http
               status: _.isNull(res) === false ? res.statusCode : 'ERR'
             },
             message

src/lib/utils.ts

@@ -6,6 +6,7 @@ import buildDebug from 'debug';
 import semver from 'semver';
 import YAML from 'js-yaml';
 import validator from 'validator';
+import memoizee from 'memoizee';
 import sanitizyReadme from '@verdaccio/readme';
 
 import { Package, Version, Author } from '@verdaccio/types';
@@ -143,6 +144,8 @@ export function convertDistRemoteToLocalTarballUrls(pkg: Package, req: Request,
   return pkg;
 }
 
+const memoizedgetPublicUrl = memoizee(getPublicUrl);
+
 /**
  * Filter a tarball url.
  * @param {*} uri
@@ -155,7 +158,7 @@ export function getLocalRegistryTarballUri(uri: string, pkgName: string, req: Re
     return uri;
   }
   const tarballName = extractTarballFromUrl(uri);
-  const domainRegistry = getPublicUrl(urlPrefix || '', req);
+  const domainRegistry = memoizedgetPublicUrl(urlPrefix || '', req);
 
   return `${domainRegistry}${encodeScopedUri(pkgName)}/-/${tarballName}`;
 }
@@ -368,8 +371,10 @@ export function parseConfigFile(configPath: string): any {
     if (/\.ya?ml$/i.test(configPath)) {
       return YAML.load(fs.readFileSync(configPath, CHARACTER_ENCODING.UTF8));
     }
+    debug('yaml parsed');
     return require(configPath);
   } catch (e) {
+    debug('yaml parse failed');
     if (e.code !== 'MODULE_NOT_FOUND') {
       e.message = APP_ERROR.CONFIG_NOT_VALID;
     }

test/e2e-cli/config/_bootstrap_verdaccio.yaml

@@ -13,7 +13,7 @@ uplinks:
   npmjs:
     url: https://registry.verdaccio.org/
 
-logs: { type: stdout, format: json, level: trace }
+logs: { type: stdout, format: json, level: http }
 
 packages:
   '@*/*':

test/e2e-cli/config/default.yaml

@@ -17,7 +17,7 @@ uplinks:
   local:
     url: http://localhost:4873
 
-logs: { type: stdout, format: json, level: warn }
+logs: { type: stdout, format: json, level: http }
 
 packages:
   '@*/*':

yarn.lock

@@ -5397,6 +5397,16 @@ __metadata:
   languageName: node
   linkType: hard
 
+"d@npm:1, d@npm:^1.0.1":
+  version: 1.0.1
+  resolution: "d@npm:1.0.1"
+  dependencies:
+    es5-ext: ^0.10.50
+    type: ^1.0.1
+  checksum: cf9b770965fa4876f7aff46784e4f1a1ee71cc5df7e05c9c36bee52a74340b312b6f7ab224c8bfcc83f4b18c6f6a24e7b50bcd449ba4464c1df69874941324ae
+  languageName: node
+  linkType: hard
+
 "damerau-levenshtein@npm:^1.0.6":
   version: 1.0.6
   resolution: "damerau-levenshtein@npm:1.0.6"
@@ -5985,6 +5995,50 @@ __metadata:
   languageName: node
   linkType: hard
 
+"es5-ext@npm:^0.10.35, es5-ext@npm:^0.10.46, es5-ext@npm:^0.10.50, es5-ext@npm:^0.10.53, es5-ext@npm:~0.10.14, es5-ext@npm:~0.10.2, es5-ext@npm:~0.10.46":
+  version: 0.10.53
+  resolution: "es5-ext@npm:0.10.53"
+  dependencies:
+    es6-iterator: ~2.0.3
+    es6-symbol: ~3.1.3
+    next-tick: ~1.0.0
+  checksum: 99e8115c2f99674d0defc1e077bb0061cd9e1fc996e93605f83441cc5b3b200b7b3646f9cda9313aa877a05c47b4577ead99a26177136a0ca3f208f67a7b4418
+  languageName: node
+  linkType: hard
+
+"es6-iterator@npm:^2.0.3, es6-iterator@npm:~2.0.3":
+  version: 2.0.3
+  resolution: "es6-iterator@npm:2.0.3"
+  dependencies:
+    d: 1
+    es5-ext: ^0.10.35
+    es6-symbol: ^3.1.1
+  checksum: 1880ce31210da874cbb92b404c3128bdf68f616f3a902b2ca1d12f268aaedb11c5e6a2d9d364cde762de0130652a0474ba91abc09fa35f4abf6a8f22a592265e
+  languageName: node
+  linkType: hard
+
+"es6-symbol@npm:^3.1.1, es6-symbol@npm:~3.1.3":
+  version: 3.1.3
+  resolution: "es6-symbol@npm:3.1.3"
+  dependencies:
+    d: ^1.0.1
+    ext: ^1.1.2
+  checksum: 0915d72de8760b56b69ca4360276123a4f61de5a3172fe340ce9288271cf48bcebe3ee46ca8ee0f2fd73206bbbefa7c4a40a6673d278a87c97d3a155de778931
+  languageName: node
+  linkType: hard
+
+"es6-weak-map@npm:^2.0.3":
+  version: 2.0.3
+  resolution: "es6-weak-map@npm:2.0.3"
+  dependencies:
+    d: 1
+    es5-ext: ^0.10.46
+    es6-iterator: ^2.0.3
+    es6-symbol: ^3.1.1
+  checksum: 8dfd50b2919e16cf246ea9d5f9271eef466924248bc98a48a718cc149d0f67b708628c8e4bd32fa945a813c7780f94270f21ac16fff33c854a348db7e19f084d
+  languageName: node
+  linkType: hard
+
 "escalade@npm:^3.1.1":
   version: 3.1.1
   resolution: "escalade@npm:3.1.1"
@@ -6463,6 +6517,16 @@ __metadata:
   languageName: node
   linkType: hard
 
+"event-emitter@npm:^0.3.5":
+  version: 0.3.5
+  resolution: "event-emitter@npm:0.3.5"
+  dependencies:
+    d: 1
+    es5-ext: ~0.10.14
+  checksum: 92107b89703222355070b8c49208baf9426ce015d54b646a80f6652d348ab6064c5e13f1756ae20c750d8368f4b3cde48bafc56484667ba0e12d07c50b645f21
+  languageName: node
+  linkType: hard
+
 "exec-sh@npm:^0.3.2":
   version: 0.3.2
   resolution: "exec-sh@npm:0.3.2"
@@ -6577,6 +6641,15 @@ __metadata:
   languageName: node
   linkType: hard
 
+"ext@npm:^1.1.2":
+  version: 1.4.0
+  resolution: "ext@npm:1.4.0"
+  dependencies:
+    type: ^2.0.0
+  checksum: c94102371fecdee9f48d1acac2d0e49d49906af457c79d1d7cf1a0a14317ed3e4c99cd8a2e6f9a00e93d54306ee2872e2542edd0aa58bccc4fc72aa429ef215c
+  languageName: node
+  linkType: hard
+
 "extend-shallow@npm:^2.0.1":
   version: 2.0.1
   resolution: "extend-shallow@npm:2.0.1"
@@ -8334,6 +8407,13 @@ fsevents@~2.1.2:
   languageName: node
   linkType: hard
 
+"is-promise@npm:^2.2.2":
+  version: 2.2.2
+  resolution: "is-promise@npm:2.2.2"
+  checksum: 6fe84293b8750d3604a909979a7517a38b1618817f1fbbfdaf4d6138642117c85fbee12927b4d51349a5bcd9bdf8d1bf181f09145ede2d7eb41f4b394ab2ce7d
+  languageName: node
+  linkType: hard
+
 "is-regex@npm:^1.0.4":
   version: 1.0.4
   resolution: "is-regex@npm:1.0.4"
@@ -9881,6 +9961,15 @@ fsevents@~2.1.2:
   languageName: node
   linkType: hard
 
+"lru-queue@npm:^0.1.0":
+  version: 0.1.0
+  resolution: "lru-queue@npm:0.1.0"
+  dependencies:
+    es5-ext: ~0.10.2
+  checksum: 2eab98cdfb3101dab91ef6b8b50fce616440fa29d27ef1a1b99aa6be13422d03d6ebee15c1eb4873971c34baee27d64376aebc64560aecb37a328c82e3f40169
+  languageName: node
+  linkType: hard
+
 "lunr-mutable-indexes@npm:2.3.2":
   version: 2.3.2
   resolution: "lunr-mutable-indexes@npm:2.3.2"
@@ -10003,6 +10092,22 @@ fsevents@~2.1.2:
   languageName: node
   linkType: hard
 
+"memoizee@npm:0.4.15":
+  version: 0.4.15
+  resolution: "memoizee@npm:0.4.15"
+  dependencies:
+    d: ^1.0.1
+    es5-ext: ^0.10.53
+    es6-weak-map: ^2.0.3
+    event-emitter: ^0.3.5
+    is-promise: ^2.2.2
+    lru-queue: ^0.1.0
+    next-tick: ^1.1.0
+    timers-ext: ^0.1.7
+  checksum: 2ec67072cbd49c2611e7fd7317cf2074c8982a3bfdb06a8a24b52fbb72fad6254a119a7ef66dc04ebdb45c220622fcbdd907fcf48c5cdb5019860d7d5487eb87
+  languageName: node
+  linkType: hard
+
 "memory-fs@npm:0.5.0":
   version: 0.5.0
   resolution: "memory-fs@npm:0.5.0"
@@ -10422,6 +10527,20 @@ fsevents@~2.1.2:
   languageName: node
   linkType: hard
 
+"next-tick@npm:1, next-tick@npm:^1.1.0":
+  version: 1.1.0
+  resolution: "next-tick@npm:1.1.0"
+  checksum: 586cc85dcd8ec759b03269b39c8e3d899a27dbe49c472e7fb2b6a98b14a5b46d8c3b1b9a5fae29eb22881d9efa6d882d44617c51268b49d92e98ba8f20d42000
+  languageName: node
+  linkType: hard
+
+"next-tick@npm:~1.0.0":
+  version: 1.0.0
+  resolution: "next-tick@npm:1.0.0"
+  checksum: 18db63c447c6e65a23235b91da9ccdae53f74f9194cfbc71a1fd3170cdf81bd157d9676e47c2ea4ea5bd20e09fb019917b0a45d8e1a63e377175fc083f285234
+  languageName: node
+  linkType: hard
+
 "nice-try@npm:^1.0.4":
   version: 1.0.5
   resolution: "nice-try@npm:1.0.5"
@@ -13461,6 +13580,16 @@ resolve@1.1.7:
   languageName: node
   linkType: hard
 
+"timers-ext@npm:^0.1.7":
+  version: 0.1.7
+  resolution: "timers-ext@npm:0.1.7"
+  dependencies:
+    es5-ext: ~0.10.46
+    next-tick: 1
+  checksum: 4593b57c397934fc7ddf7b240a8ff8468cdd7006407a442ec48c291bd85dcb7268858b72d1132bc55309e29d8eeae796f9edf378b0b45feff56b51f350e723b6
+  languageName: node
+  linkType: hard
+
 "tmp@npm:^0.0.33":
   version: 0.0.33
   resolution: "tmp@npm:0.0.33"
@@ -13722,6 +13851,20 @@ resolve@1.1.7:
   languageName: node
   linkType: hard
 
+"type@npm:^1.0.1":
+  version: 1.2.0
+  resolution: "type@npm:1.2.0"
+  checksum: 1589416fd9d0a0a1bf18c62dbc7452b0f22017efd5bfc2912050bb57421b084801563ff13b3e3efd60df45590f23e1f3d27d892aeeec9b3ed142c917a4858812
+  languageName: node
+  linkType: hard
+
+"type@npm:^2.0.0":
+  version: 2.5.0
+  resolution: "type@npm:2.5.0"
+  checksum: 56dd61c60ed02dc75bae7029f95d1e457a9b174f60a75025ce9dc911a01e3918df29a9a29f0bc58d88a2baf18fa399f3898f2fa26d512d61cf9726c2c69920a0
+  languageName: node
+  linkType: hard
+
 "typedarray-to-buffer@npm:^3.1.5":
   version: 3.1.5
   resolution: "typedarray-to-buffer@npm:3.1.5"
@@ -14143,6 +14286,7 @@ typescript@3.9.9:
     lru-cache: 6.0.0
     lunr-mutable-indexes: 2.3.2
     marked: 2.0.1
+    memoizee: 0.4.15
     mime: 2.5.2
     minimatch: 3.0.4
     mkdirp: 1.0.4