Issue 2678 - fixes for nodejs 14 upgrade (#2682)

* ISSUE #2678 removed fs.extra dependency

* Remove unused libraries, replace ip-to-location with geoip-lite

* ISSUE #2678 centralise UUID generation in utils

* ISSUE #2678 couple more upgrades

* ISSUE #2678 linter fix

* ISSUE #2678 fix uuid lib update

* ISSUE #2678 format logger

* ISSUE #2678 log user name to request if available

* ISSUE #2678 option to have no colours on the log

* ISSUE #2678 track network latency, reformat the log

* ISSUE #2678 add network label on all network io logging

* ISSUE #2678 NET instead of NETWORK

* ISSUE #2678 more log formatting, pass req to genResponseLog on the streaming version

* ISSUE #2678 mocha now needs a recursive flag

* ISSUE #2678 fix user creations

* ISSUE #2678 downgrade socket io - it's not working

* ISSUE #2678 fix all createUser calls

* ISSUE #2678 mocha needs to run with --exit; only log if there's transporters

* ISSUE #2678 remove tag check

* ISSUE #2678 only run meta - struggling to reproduce.

* Revert "ISSUE #2678 only run meta - struggling to reproduce."

This reverts commit 9f2368d.

* ISSUE #2678 if no collaborator/issues?

* ISSUE #2678 try downgrading mocha

* ISSUE #2678 debug logging on metadata endpoint

* ISSUE #2678 more debugging

* ISSUE #2678 more debugging

* ISSUE #2678 more debugging

* ISSUE #2678 downgrade nyc

* ISSUE #2678 don't run code coverage?

* ISSUE #2678 move mocha back to v9

.travis.yml

@@ -66,7 +66,7 @@ matrix:
       script:
         - cd ../backend
         - mkdir coverage
-        - unbuffer yarn test:coverall
+        - unbuffer yarn test
         - cd ../
         - NODE_ENV=test NODE_CONFIG_DIR='./config' node "./backend/3drepo.js" &
         - cd ./frontend

backend/3drepo.js

@@ -212,8 +212,7 @@ function logCreateService(serverConfig) {
 		"Loading " +
 		serverConfig.service +
 		" on " + serverConfig.hostname + ":" +
-		serverConfig.port,
-		serverConfig.host_dir
+		serverConfig.port
 	);
 }
 

backend/config.js

@@ -235,7 +235,7 @@ config.default_format = coalesce(config.default_format, "html");
 // config.external = (config.js_debug_level === "debug") ? frontend_scripts.debug_scripts : frontend_scripts.prod_scripts;
 
 // Log file options
-config.logfile = coalesce(config.logfile, {});
+config.logfile = config.logfile || {};
 
 if (!config.logfile.filename) {
 	config.logfile.logDirectory = coalesce(config.logfile.logDirectory, "/var/log");

backend/handler/fs.js

@@ -20,7 +20,6 @@ const fs = require("fs");
 const path = require("path");
 const ResponseCodes = require("../response_codes");
 const systemLogger = require("../logger").systemLogger;
-const nodeuuid = require("uuid/v1");
 const farmhash = require("farmhash");
 const utils = require("../utils");
 
@@ -72,7 +71,7 @@ class FSHandler {
 	}
 
 	storeFile(data) {
-		const _id = nodeuuid();
+		const _id = utils.generateUUID({string: true});
 		const folderNames = generateFoldernames(_id, config.fs.levels);
 		const link = path.posix.join(folderNames, _id);
 

backend/handler/gridfs.js

@@ -18,7 +18,7 @@
 "use strict";
 
 const DB = require("./db");
-const nodeuuid = require("uuid/v1");
+const utils = require("../utils");
 
 class GridFSHandler {
 	constructor() {
@@ -40,7 +40,7 @@ class GridFSHandler {
 	}
 
 	storeFile(account, col, data) {
-		const _id = nodeuuid();
+		const _id = utils.generateUUID({string: true});
 		return DB.storeFileInGridFS(account, this.cleanColName(col), _id, data).then(() => (
 			{_id, link: _id, size: data.length, type: "gridfs"}
 		));

backend/logger.js

@@ -20,88 +20,55 @@ const config = require("./config.js");
 const winston = require("winston");
 require("winston-daily-rotate-file");
 
-let log;
+const stringFormat = ({ level, message, label, timestamp }) => `${timestamp} [${level}] [${label || "APP"}] ${message}`;
 
-/**
- * The repoLogger init and factory
- *
- * @param {Object} req - Express request object
- * @param {Object} res - Express response object
- * @param {string} id - Unique logger ID
- * @returns
- */
-const repoLogger = function (req, res, id) {
-
-	const self = this instanceof repoLogger ? this : Object.create(repoLogger.prototype);
-
-	self.uid = id;
-
-	if (req) {
-		self.session = req.session;
-		self.req = req;
-	}
-
-	self.res = res;
-
-	if (!log) {
-		log = createLogger();
-	}
-
-	self.logger = log;
-	self.startTime = (new Date())
-		.getTime();
-
-	return self;
-};
+const logger = createLogger();
+const SystemLogger = {};
 
 function createLogger() {
-
-	// Custom logging levels for logger
-	const customLevels = {
-		levels: {
-			nothing: -1,
-			fatal: 0,
-			error: 1,
-			warn: 2,
-			info: 3,
-			debug: 4,
-			trace: 5
-		}
-	};
-
-	let fileOutTransport;
+	const transporters = [];
 
 	if (config.logfile.logDirectory) {
-		fileOutTransport = new winston.transports.DailyRotateFile({
-			filename: config.logfile.logDirectory + "/3drepo",
-			datePattern: "-yyyy-MM-dd.log",
-			level: config.logfile.file_level
-		});
-	} else {
-		fileOutTransport = new winston.transports.File({
-			level: config.logfile.file_level,
-			filename: config.logfile.filename
-		});
+		transporters.push(
+			new winston.transports.DailyRotateFile({
+				filename: config.logfile.logDirectory + "/3drepo",
+				datePattern: "-yyyy-MM-dd.log",
+				timestamp: true,
+				level: config.logfile.file_level
+			})
+		);
 	}
 
-	const transports = [
-		fileOutTransport
-	];
-
 	if (config.logfile.silent === undefined || config.logfile.silent === false) {
-		transports.push(new winston.transports.Console({
+		transporters.push(new winston.transports.Console({
+			timestamp: true,
 			colorize: true,
 			level: config.logfile.console_level
 		}));
 	}
 
+	let format = winston.format.combine(
+		winston.format.timestamp(),
+		winston.format.align(),
+		winston.format.printf(stringFormat)
+	);
+
+	if (!config.logfile.noColors) {
+		format = winston.format.combine(
+			winston.format.colorize(),
+			format
+		);
+	}
+
 	// Creates logger which outputs to both the console
 	// and a log file simultaneously
 	// Levels are set separately in the config.
-	return winston.createLogger({
-		levels: customLevels.levels,
-		transports: transports
-	});
+	if (transporters.length > 0) {
+		return winston.createLogger({
+			transports: transporters,
+			format
+		});
+	}
 }
 
 /**
@@ -112,38 +79,16 @@ function createLogger() {
  * @param {string} msg - Message to log
  * @param {Object} meta - Extra data to put into the log file
  */
-repoLogger.prototype.logMessage = function (type, msg, meta) {
-	const currentTime = (new Date())
-		.getTime();
-	const timeDiff = currentTime - this.startTime;
-
-	const metadata = Object.assign({}, meta);
-
-	if (this.session && this.session.user) {
-		metadata.username = this.session.user.username;
-	}
-
-	if (this.req) {
-		if (this.req.method) {
-			metadata.method = this.req.method;
-		}
-		if (this.req.originalUrl) {
-			metadata.url = this.req.originalUrl;
-		}
-	}
-
-	this.logger.log(type, (new Date())
-		.toISOString() + "\t" + this.uid + "\t" + msg + " [" + timeDiff + " ms]", {message: JSON.stringify(metadata)});
-};
+const logMessage = (msg, meta, label) => `${msg} ${meta ? JSON.stringify(meta, label) : ""}`;
 
 /**
  * Function to log an info message
  *
  * @param {string} msg - Information message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logInfo = function (msg, meta) {
-	this.logMessage("info", msg, meta);
+SystemLogger.logInfo = (msg, meta, label) => {
+	logger && logger.info(logMessage(msg, meta, label), {label});
 };
 
 /**
@@ -152,8 +97,8 @@ repoLogger.prototype.logInfo = function (msg, meta) {
  * @param {string} msg - Error message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logError = function (msg, meta) {
-	this.logMessage("error", msg, meta);
+SystemLogger.logError = (msg, meta, label) => {
+	logger && logger.error(logMessage(msg, meta, label), {label});
 };
 
 /**
@@ -162,8 +107,8 @@ repoLogger.prototype.logError = function (msg, meta) {
  * @param {string} msg - Debug message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logDebug = function (msg, meta) {
-	this.logMessage("debug", msg, meta);
+SystemLogger.logDebug = (msg, meta, label) => {
+	logger && logger.debug(logMessage(msg, meta, label), {label});
 };
 
 /**
@@ -172,8 +117,8 @@ repoLogger.prototype.logDebug = function (msg, meta) {
  * @param {string} msg - Warning message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logWarning = function (msg, meta) {
-	this.logMessage("warn", msg, meta);
+SystemLogger.logWarning = (msg, meta, label) => {
+	logger && logger.warning(logMessage(msg, meta, label), {label});
 };
 
 /**
@@ -182,8 +127,8 @@ repoLogger.prototype.logWarning = function (msg, meta) {
  * @param {string} msg - Warning message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logTrace = function (msg, meta) {
-	this.logMessage("trace", msg, meta);
+SystemLogger.logTrace = (msg, meta, label) => {
+	logger && logger.trace(logMessage(msg, meta, label), {label});
 };
 
 /**
@@ -192,31 +137,12 @@ repoLogger.prototype.logTrace = function (msg, meta) {
  * @param {string} msg - Fatal message
  * @param {Object} meta - Extra informative metadata
  */
-repoLogger.prototype.logFatal = function (msg, meta) {
-	this.logMessage("fatal", msg, meta);
+SystemLogger.logFatal = (msg, meta, label) => {
+	logger && logger.fatal(logMessage(msg, meta, label), {label});
 };
 
-const systemLogger = new repoLogger(null, null, "system");
-
-/**
- * Middleware to call at the start of every request to
- * initialize logger
- *
- * @param {Object} req - Express request object
- * @param {Object} res - Express response object
- * @param {function} next - Next middleware
- * @returns
- */
-module.exports.startRequest = function (req, res, next) {
-
-	const C = require("./constants");
-
-	req[C.REQ_REPO] = {};
-	req[C.REQ_REPO].logger = systemLogger;
-
-	// req[C.REQ_REPO].logger = new repoLogger(req, res, shortid.generate()); // Create logger for this request
-
-	next();
+module.exports.systemLogger = SystemLogger;
+module.exports.logLabels = {
+	network: "NET"
 };
 
-module.exports.systemLogger = systemLogger;

backend/middlewares/sessionManager.js

@@ -16,7 +16,7 @@
  */
 
 "use strict";
-const C = require("../constants");
+const { systemLogger } = require("../logger");
 const config = require("../config");
 const session = require("../services/session").session(config);
 
@@ -30,9 +30,9 @@ module.exports = async (req, res, next) => {
 	session(req, res, function(err) {
 		if(err) {
 			// something is wrong with the library or the session (i.e. corrupted json file) itself, log the user out
-			req[C.REQ_REPO].logger.logError(`express-session internal error: ${err}`);
-			req[C.REQ_REPO].logger.logError(`express-session internal error: ${JSON.stringify(err)}`);
-			req[C.REQ_REPO].logger.logError(`express-session internal error: ${err.stack}`);
+			systemLogger.logError(`express-session internal error: ${err}`);
+			systemLogger.logError(`express-session internal error: ${JSON.stringify(err)}`);
+			systemLogger.logError(`express-session internal error: ${err.stack}`);
 		} else {
 			next();
 		}

backend/models/fileRef.js

@@ -21,7 +21,7 @@ const Mailer = require("../mailer/mailer");
 const ExternalServices = require("../handler/externalServices");
 const ResponseCodes = require("../response_codes");
 const systemLogger = require("../logger.js").systemLogger;
-const nodeuuid = require("uuid/v1");
+const utils = require("../utils");
 
 const ORIGINAL_FILE_REF_EXT = ".history.ref";
 const UNITY_BUNDLE_REF_EXT = ".stash.unity3d.ref";
@@ -302,7 +302,7 @@ FileRef.storeFile = async function(account, collection, user, name, data, extraF
 
 FileRef.storeUrlAsResource = async function(account, model, user, name, link, extraFields = null) {
 	const collName = model + RESOURCES_FILE_REF_EXT;
-	const refInfo = {_id: nodeuuid(), link, type: "http", ...extraFields  };
+	const refInfo = {_id: utils.generateUUID({string: true}), link, type: "http", ...extraFields  };
 	const ref = await insertRef(account, collName, user, name, refInfo);
 	return ref;
 };

backend/models/group.js

@@ -18,7 +18,6 @@
 "use strict";
 
 const utils = require("../utils");
-const nodeuuid = require("uuid/v1");
 const responseCodes = require("../response_codes.js");
 const Meta = require("./meta");
 const { checkRulesValidity } = require("./helper/rule");
@@ -282,7 +281,7 @@ Group.create = async function (account, model, branch = "master", rid = null, se
 	});
 
 	if (typeCorrect) {
-		newGroup._id = utils.stringToUUID(nodeuuid());
+		newGroup._id = utils.generateUUID();
 		newGroup.author = creator;
 		newGroup.createdAt = Date.now();
 

backend/models/helper/model.js

@@ -182,7 +182,7 @@ async function importSuccess(account, model, sharedSpacePath, user) {
 		]);
 
 		if (setting) {
-			systemLogger.logInfo(`Model status changed to ${setting.status} and correlation ID reset`);
+			systemLogger.logDebug(`Model status changed to ${setting.status} and correlation ID reset`);
 
 			const updatedSetting = await setModelImportSuccess(account, model, setting.type === "toy" || setting.type === "sample");
 
@@ -271,7 +271,7 @@ function importFail(account, model, sharedSpacePath, user, errCode, errMsg) {
 async function setStatus(account, model, status, user) {
 	try {
 		const setting = await setModelStatus(account, model, status);
-		systemLogger.logInfo(`Model status changed to ${status}`);
+		systemLogger.logDebug(`Model status changed to ${status}`);
 		ChatEvent.modelStatusChanged(null, account, model, { status, user });
 
 		return setting;