From cd231badb72e1da75c1494ab17c3d2a0db06b510 Mon Sep 17 00:00:00 2001
From: Marc Udoff <mlucool@gmail.com>
Date: Fri, 24 Aug 2018 16:07:24 -0400
Subject: [PATCH] fix: bugs related to logging with type json (#893)

This commit cleans up some logging infra and ensures that the msg
in the json log are the same as what you get when you use pretty.
It also removes some confusing nulls that appear in the logs.
---
 src/api/middleware.js |  2 +-
 src/lib/logger.js     | 88 +++++++++++++++++++++++--------------------
 src/lib/up-storage.js |  2 +-
 3 files changed, 50 insertions(+), 42 deletions(-)

diff --git a/src/api/middleware.js b/src/api/middleware.js
index 313278783..2d2eef1fc 100644
--- a/src/api/middleware.js
+++ b/src/api/middleware.js
@@ -223,7 +223,7 @@ export function log(req: $RequestExtend, res: $ResponseExtend, next: $NextFuncti
         url: req.url,
       },
       level: 35, // http
-      user: req.remote_user && req.remote_user.name,
+      user: req.remote_user && req.remote_user.name || null,
       remoteIP,
       status: res.statusCode,
       error: res._verdaccio_error,
diff --git a/src/lib/logger.js b/src/lib/logger.js
index d1432700f..d4be8e059 100644
--- a/src/lib/logger.js
+++ b/src/lib/logger.js
@@ -37,41 +37,45 @@ function setup(logs) {
     const stream = new Stream();
     stream.writable = true;
 
-    if (target.type === 'stdout' || target.type === 'stderr') {
-      // destination stream
-      const dest = target.type === 'stdout' ? process.stdout : process.stderr;
+    let dest;
+    let destIsTTY = false;
+    const prettyPrint = (obj) => print(obj.level, obj.msg, obj, destIsTTY) + '\n';
+    const prettyTimestampedPrint = (obj) => obj.time.toISOString() + print(obj.level, obj.msg, obj, destIsTTY) + '\n';
+    const jsonPrint = (obj) => {
+      const msg = fillInMsgTemplate(obj.msg, obj, destIsTTY);
+      return JSON.stringify({...obj, msg}, Logger.safeCycles()) + '\n';
+    };
 
-      if (target.format === 'pretty') {
-        // making fake stream for prettypritting
-        stream.write = function(obj) {
-          dest.write(print(obj.level, obj.msg, obj, dest.isTTY) + '\n');
-        };
-      } else if (target.format === 'pretty-timestamped') {
-        // making fake stream for prettypritting
-        stream.write = function(obj) {
-          dest.write(obj.time.toISOString() + print(obj.level, obj.msg, obj, dest.isTTY) + '\n');
-        };
-      } else {
-        stream.write = function(obj) {
-          dest.write(JSON.stringify(obj, Logger.safeCycles()) + '\n');
-        };
-      }
-    } else if (target.type === 'file') {
-      const dest = require('fs').createWriteStream(target.path, {flags: 'a', encoding: 'utf8'});
+    if (target.type === 'file') {
+      // destination stream
+      dest = require('fs').createWriteStream(target.path, {flags: 'a', encoding: 'utf8'});
       dest.on('error', function(err) {
         Logger.emit('error', err);
       });
-      stream.write = function(obj) {
-        if (target.format === 'pretty') {
-          dest.write(print(obj.level, obj.msg, obj, false) + '\n');
-        } else {
-          dest.write(JSON.stringify(obj, Logger.safeCycles()) + '\n');
-        }
-      };
+    } else if (target.type === 'stdout' || target.type === 'stderr') {
+      dest = target.type === 'stdout' ? process.stdout : process.stderr;
+      destIsTTY = dest.isTTY;
     } else {
       throw Error('wrong target type for a log');
     }
 
+    if (target.format === 'pretty') {
+      // making fake stream for prettypritting
+      stream.write = (obj) => {
+        dest.write(prettyPrint(obj));
+      };
+    } else if (target.format === 'pretty-timestamped') {
+      // making fake stream for prettypritting
+      stream.write = (obj) => {
+        dest.write(prettyTimestampedPrint(obj));
+      };
+    } else {
+      stream.write = (obj) => {
+        dest.write(jsonPrint(obj));
+      };
+    }
+
+
     if (target.level === 'http') target.level = 35;
     streams.push({
       type: 'raw',
@@ -132,19 +136,8 @@ function pad(str) {
   return str;
 }
 
-/**
- * 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 = getlvl(type);
-  }
-  let finalmsg = msg.replace(/@{(!?[$A-Za-z_][$0-9A-Za-z\._]*)}/g, function(_, name) {
+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] === '!') {
@@ -174,6 +167,21 @@ function print(type, msg, obj, colors) {
       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 = getlvl(type);
+  }
+  const finalmsg = fillInMsgTemplate(msg, obj, colors);
 
   const subsystems = [{
     in: chalk.green('<--'),
diff --git a/src/lib/up-storage.js b/src/lib/up-storage.js
index 7ec176292..3fea3d657 100644
--- a/src/lib/up-storage.js
+++ b/src/lib/up-storage.js
@@ -181,7 +181,7 @@ class ProxyStorage implements IProxy {
           ? ', error: @{!error}'
           : ', bytes: @{bytes.in}/@{bytes.out}';
         self.logger.warn({
-          err: err,
+          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',