fix: logger fails to print null objects

In case you try printing the following:
```
const obj1 = null;
this.$logger.info("value %s", obj1);
```
Our implementation fails with error: `Cannot read property hasOwnProperty of null`.
The problem is in the way we check for passed logger options in the args passed to `logger` methods. The `typeof null` returns object, so next parts of the code fail.

Also passed logger options are handled by priority, i.e. the first passed option should be used. This allows callers of methods that specify some logger options internaly, to overwrite their values. Add unit tests for this behavior.
Fix the case when same logger option is passed multiple times in different objects - currently only one of the instances is removed and the other one is included in the message visible to the user. Now all such objects are removed.
Add unit tests for all of the described cases.

Author: rosen-vladimirov

lib/common/logger/logger.ts

@@ -154,31 +154,40 @@ export class Logger implements ILogger {
 	}
 
 	private getLogOptionsForMessage(data: any[]): { data: any[], [key: string]: any } {
-		const opts = _.keys(LoggerConfigData);
+		const loggerOptionKeys = _.keys(LoggerConfigData);
+		const dataToCheck = data.filter(el => {
+			// objects created with Object.create(null) do not have `hasOwnProperty` function
+			if (!!el && typeof el === "object" && el.hasOwnProperty && typeof el.hasOwnProperty === "function") {
+				for (const key of loggerOptionKeys) {
+					if (el.hasOwnProperty(key)) {
+						// include only the elements which have one of the keys we've specified as logger options
+						return true;
+					}
+				}
+			}
 
-		const result: any = {};
-		const cleanedData = _.cloneDeep(data);
+			return false;
+		});
 
-		// objects created with Object.create(null) do not have `hasOwnProperty` function
-		const dataToCheck = data.filter(el => typeof el === "object" && el.hasOwnProperty && typeof el.hasOwnProperty === "function");
+		const result: any = {
+			data: _.difference(data, dataToCheck)
+		};
 
 		for (const element of dataToCheck) {
-			if (opts.length === 0) {
+			if (loggerOptionKeys.length === 0) {
 				break;
 			}
 
-			const remainingOpts = _.cloneDeep(opts);
+			const remainingOpts = _.cloneDeep(loggerOptionKeys);
 			for (const prop of remainingOpts) {
 				const hasProp = element && element.hasOwnProperty(prop);
 				if (hasProp) {
-					opts.splice(opts.indexOf(prop), 1);
+					loggerOptionKeys.splice(loggerOptionKeys.indexOf(prop), 1);
 					result[prop] = element[prop];
-					cleanedData.splice(cleanedData.indexOf(element), 1);
 				}
 			}
 		}
 
-		result.data = cleanedData;
 		return result;
 	}
 
@@ -195,7 +204,7 @@ export class Logger implements ILogger {
 	/*******************************************************************************************
 	 * Metods below are deprecated. Delete them in 6.0.0 release:                              *
 	 * Present only for backwards compatibility as some plugins (nativescript-plugin-firebase) *
-	 * use these methods in their hooks                                                          *
+	 * use these methods in their hooks                                                        *
 	 *******************************************************************************************/
 
 	out(...args: any[]): void {

lib/common/test/unit-tests/logger.ts

@@ -1,8 +1,10 @@
 import { Yok } from "../../yok";
 import { Logger } from "../../logger/logger";
 import * as path from "path";
+import * as util from "util";
 import { assert } from "chai";
 import * as fileSystemFile from "../../file-system";
+import { LoggerConfigData } from "../../../constants";
 
 const passwordReplacement = "*******";
 const debugTrace = ["debug", "trace"];
@@ -33,7 +35,11 @@ describe("logger", () => {
 		fs = testInjector.resolve("fs");
 		outputs = {
 			debug: "",
-			trace: ""
+			trace: "",
+			info: "",
+			error: "",
+			context: {},
+			removedContext: {}
 		};
 
 		const log4jsLogger = {
@@ -42,6 +48,18 @@ describe("logger", () => {
 			},
 			trace: (...args: string[]) => {
 				outputs.trace += args.join("");
+			},
+			info: (...args: string[]) => {
+				outputs.info += util.format.apply(null, args);
+			},
+			error: (...args: string[]) => {
+				outputs.error += util.format.apply(null, args);
+			},
+			addContext(key: string, value: any): void {
+				outputs.context[key] = value;
+			},
+			removeContext(key: string): void {
+				outputs.removedContext[key] = true;
 			}
 		};
 
@@ -139,4 +157,67 @@ describe("logger", () => {
 			assert.deepEqual(outputs.trace, `${request}${requestBody}`, "logger.trace should not obfuscate body of request unless it is towards api/itmstransporter");
 		});
 	});
+
+	describe("info", () => {
+		[undefined, null, false, "string value", 42, { obj: 1 }, ["string value 1", "string value 2"]].forEach(value => {
+			it(`handles formatted message with '${value}' value in one of the args`, () => {
+				logger.info("test %s", value);
+				assert.equal(outputs.info, `test ${value}`);
+				assert.deepEqual(outputs.context, {}, "Nothing should be added to logger context.");
+				assert.deepEqual(outputs.removedContext, {}, "Removed context should be empty.");
+			});
+
+			it(`handles formatted message with '${value}' value in one of the args and additional values passed to context`, () => {
+				logger.info("test %s", value, { [LoggerConfigData.skipNewLine]: true });
+				assert.equal(outputs.info, `test ${value}`);
+				assert.deepEqual(outputs.context, { [LoggerConfigData.skipNewLine]: true }, `${LoggerConfigData.skipNewLine} should be set with value true.`);
+				assert.deepEqual(outputs.removedContext, { [LoggerConfigData.skipNewLine]: true }, `Removed context should contain ${LoggerConfigData.skipNewLine}`);
+			});
+		});
+
+		it("sets correct context when multiple logger options are passed in one object", () => {
+			logger.info("test", { [LoggerConfigData.skipNewLine]: true, [LoggerConfigData.useStderr]: true });
+			assert.equal(outputs.info, "test");
+			assert.deepEqual(outputs.context, { [LoggerConfigData.skipNewLine]: true, [LoggerConfigData.useStderr]: true });
+			assert.deepEqual(outputs.removedContext, { [LoggerConfigData.skipNewLine]: true, [LoggerConfigData.useStderr]: true });
+		});
+
+		it("sets correct context when multiple logger options are passed in multiple objects", () => {
+			logger.info({ [LoggerConfigData.useStderr]: true }, "test", { [LoggerConfigData.skipNewLine]: true });
+			assert.equal(outputs.info, "test");
+			assert.deepEqual(outputs.context, { [LoggerConfigData.skipNewLine]: true, [LoggerConfigData.useStderr]: true });
+			assert.deepEqual(outputs.removedContext, { [LoggerConfigData.skipNewLine]: true, [LoggerConfigData.useStderr]: true });
+		});
+	});
+
+	describe("printMarkdown", () => {
+		it(`passes markdown formatted text to log4js.info method`, () => {
+			logger.printMarkdown("header text\n==");
+			assert.isTrue(outputs.info.indexOf("# header text") !== -1);
+		});
+
+		it(`passes skipNewLine to log4js context`, () => {
+			logger.printMarkdown("`coloured` text");
+			assert.isTrue(outputs.info.indexOf("coloured") !== -1);
+			assert.deepEqual(outputs.context, { [LoggerConfigData.skipNewLine]: true }, `${LoggerConfigData.skipNewLine} should be set with value true.`);
+			assert.deepEqual(outputs.removedContext, { [LoggerConfigData.skipNewLine]: true }, `Removed context should contain ${LoggerConfigData.skipNewLine}`);
+		});
+	});
+
+	describe("error", () => {
+		const errorMessage = "this is error message";
+		it(`passes useStderr to log4js context`, () => {
+			logger.error(errorMessage);
+			assert.equal(outputs.error, errorMessage);
+			assert.deepEqual(outputs.context, { [LoggerConfigData.useStderr]: true }, `${LoggerConfigData.useStderr} should be set with value true.`);
+			assert.deepEqual(outputs.removedContext, { [LoggerConfigData.useStderr]: true }, `Removed context should contain ${LoggerConfigData.useStderr}`);
+		});
+
+		it(`allows overwrite of useStderr`, () => {
+			logger.error(errorMessage, { [LoggerConfigData.useStderr]: false });
+			assert.equal(outputs.error, errorMessage);
+			assert.deepEqual(outputs.context, { [LoggerConfigData.useStderr]: false }, `${LoggerConfigData.useStderr} should be set with value false.`);
+			assert.deepEqual(outputs.removedContext, { [LoggerConfigData.useStderr]: true }, `Removed context should contain ${LoggerConfigData.useStderr}`);
+		});
+	});
 });