[INTERNAL] traceSummary: Only trace when verbose logging is active

This especially resolves the two second timeout that prevents the CLI from exiting after a successful build

lib/tracing/traceSummary.js

@@ -47,6 +47,9 @@ function report() {
 }
 
 function someTraceStarted() {
+	if (!log.isLevelEnabled("verbose")) {
+		return;
+	}
 	if (!traceData) {
 		init();
 	}
@@ -60,9 +63,14 @@ function someTraceStarted() {
 
 function someTraceEnded() {
 	return new Promise(function(resolve, reject) {
+		if (!active) {
+			resolve();
+			return;
+		}
 		tracesRunning--;
 		if (tracesRunning > 0) {
 			resolve();
+			return;
 		}
 
 		if (timeoutId) {

package.json

@@ -100,6 +100,7 @@
 		"make-dir": "^2.0.0",
 		"micromatch": "^3.1.4",
 		"minimatch": "^3.0.3",
+		"mock-require": "^3.0.3",
 		"pretty-hrtime": "^1.0.3",
 		"random-int": "^1.0.0"
 	},

test/lib/tracing/traceSummary.js

@@ -1,17 +1,26 @@
 const {test} = require("ava");
 const sinon = require("sinon");
 const logger = require("@ui5/logger");
+const mock = require("mock-require");
 
-test("traceSummary", async (t) => {
+test.afterEach.always((t) => {
+	sinon.restore();
+});
+
+test.serial("traceSummary", async (t) => {
 	t.plan(2);
 
-	const myLoggerInstance = logger.getLogger("resources:tracing:total");
-	const loggerStub = sinon.stub(logger, "getLogger").returns(myLoggerInstance);
-	const logSpy = sinon.spy(myLoggerInstance, "verbose");
+	const myLoggerInstance = {
+		verbose: sinon.stub(),
+		isLevelEnabled: () => {
+			return true;
+		}
+	};
+	sinon.stub(logger, "getLogger").returns(myLoggerInstance);
 
 	// Measure always constant time
-	const hrtimeStub = sinon.stub(process, "hrtime").returns([3, 426604599]);
-	const traceSummary = require("../../../lib/tracing/traceSummary");
+	sinon.stub(process, "hrtime").returns([3, 426604599]);
+	const traceSummary = mock.reRequire("../../../lib/tracing/traceSummary");
 
 	const expectedReport = "==========================\n[=> TRACE SUMMARY:\n" +
 		"  3.43 s elapsed time \n" +
@@ -40,12 +49,44 @@ test("traceSummary", async (t) => {
 	traceSummary.globCall();
 
 	// Print reporting and reset tracing
-	return traceSummary.traceEnded().then(function() {
-		t.pass("Tracing has been reported and reset");
-		t.true(logSpy.calledWithExactly(expectedReport), "Correct report logged to the console");
-
-		loggerStub.restore();
-		logSpy.restore();
-		hrtimeStub.restore();
-	});
+	await traceSummary.traceEnded();
+
+	t.deepEqual(myLoggerInstance.verbose.callCount, 1, "Logger has been called exactly once");
+	t.deepEqual(myLoggerInstance.verbose.getCall(0).args[0], expectedReport, "Correct report logged to the console");
+});
+
+test.serial("traceSummary no verbose logging", async (t) => {
+	t.plan(1);
+
+	const myLoggerInstance = {
+		verbose: sinon.stub(),
+		isLevelEnabled: () => {
+			return false;
+		}
+	};
+	sinon.stub(logger, "getLogger").returns(myLoggerInstance);
+
+	const traceSummary = mock.reRequire("../../../lib/tracing/traceSummary");
+
+	// Add collection, byPath call and byGlob call w/o having a an active tracing started yet.
+	// Those calls will not be traced.
+	traceSummary.collection("collection_one");
+	traceSummary.pathCall();
+	traceSummary.globCall();
+
+	// Start tracing
+	traceSummary.traceStarted();
+
+	traceSummary.collection("collection_two");
+
+	// Add an already existing collection
+	traceSummary.collection("collection_two");
+
+	traceSummary.pathCall();
+	traceSummary.globCall();
+
+	// Print reporting and reset tracing
+	await traceSummary.traceEnded();
+
+	t.deepEqual(myLoggerInstance.verbose.callCount, 0, "Logger has not been called (due to disabled verbose logging)");
 });