test: avoid confusing global state in regression test logger

The original code incorrectly assumed that a log4js logger had its own level. Instead, changing a logger's level changes the level of the logger's category system-wide. That leads to very confusing behavior that depends on the order in which you create projects or database adapters.

We're still changing global state for the trace level, but in a direct and more understandable way.

Author: Yogu

spec/dev/server.ts

@@ -3,7 +3,7 @@ import bodyParser from 'body-parser';
 import cors from 'cors';
 import express from 'express';
 import { resolve } from 'path';
-import { ArangoDBAdapter, Project } from '../..';
+import { ArangoDBAdapter, ExecutionOptions, Project } from '../..';
 import { globalContext } from '../../src/config/global';
 import { InMemoryAdapter } from '../../src/database/inmemory';
 import { getMetaSchema } from '../../src/meta-schema/meta-schema';
@@ -18,7 +18,7 @@ const databaseURL = 'http://root:@localhost:8529';
 // const databaseURL = 'http://root:@localhost:7050';
 
 export async function start() {
-    const loggerProvider = new Log4jsLoggerProvider('error');
+    const loggerProvider = new Log4jsLoggerProvider();
 
     let db;
     if (process.argv.includes('--db=in-memory')) {
@@ -44,7 +44,7 @@ export async function start() {
             );
         },
         getOperationIdentifier: ({ context }) => context as object, // each operation is executed with an unique context object
-        getExecutionOptions: ({ context }: { context: any }) => {
+        getExecutionOptions: ({ context }: { context: any }): ExecutionOptions => {
             return {
                 authContext: { authRoles: ['allusers'] },
                 recordTimings: true,

spec/helpers/log4js-logger-provider.ts

@@ -2,15 +2,10 @@ import { getLogger } from 'log4js';
 import { Logger, LoggerProvider } from '../../src/config/logging';
 
 export class Log4jsLoggerProvider implements LoggerProvider {
-    constructor(
-        public readonly level: string,
-        public readonly levelByCategory: { [category: string]: string } = {},
-    ) {}
-
     getLogger(category: string): Logger {
-        const logger = getLogger(category);
-        logger.level =
-            category in this.levelByCategory ? this.levelByCategory[category] : this.level;
-        return logger;
+        // note: we used to change the level here, but that does not work because in log4js,
+        // everything is global state (you're actually changing a category's level globally if you
+        // set .level on a logger)
+        return getLogger(category);
     }
 }

spec/helpers/warn-and-error-logger-provider.ts

@@ -0,0 +1,33 @@
+import { Logger, LoggerProvider } from '../../src/config/logging';
+
+export class WarnAndErrorLoggerProvider implements LoggerProvider {
+    getLogger(category: string): Logger {
+        // note: can't use log4js's getLogger because we can't set a log level on a logger
+        // (setting .level on a logger actually changes the level globally for that category)
+        return new WarnAndErrorLogger(category);
+    }
+}
+
+export class WarnAndErrorLogger implements Logger {
+    constructor(private category?: string) {}
+
+    trace = () => {};
+    debug = () => {};
+    info = () => {};
+    warn = (message: string, ...args: unknown[]) =>
+        console.warn(`[WARN] ${this.category}: ${message}`, ...args);
+    error = (message: string, ...args: unknown[]) =>
+        console.error(`[ERROR] ${this.category}: ${message}`, ...args);
+    fatal = (message: string, ...args: unknown[]) =>
+        console.error(`[FATAL] ${this.category}: ${message}`, ...args);
+
+    level = 'warn';
+
+    isLevelEnabled = (level: string) => ['warn', 'error', 'fatal'].includes(level.toLowerCase());
+    isTraceEnabled = () => false;
+    isDebugEnabled = () => false;
+    isInfoEnabled = () => false;
+    isWarnEnabled = () => true;
+    isErrorEnabled = () => true;
+    isFatalEnabled = () => true;
+}

spec/performance/support/helpers.ts

@@ -6,10 +6,10 @@ import { ArangoDBAdapter } from '../../../src/database/arangodb';
 import { Project } from '../../../src/project/project';
 import { loadProjectFromDir } from '../../../src/project/project-from-fs';
 import { range } from '../../../src/utils/utils';
-import { Log4jsLoggerProvider } from '../../helpers/log4js-logger-provider';
 import { createTempDatabase } from '../../regression/initialization';
+import { WarnAndErrorLoggerProvider } from '../../helpers/warn-and-error-logger-provider';
 
-// arangojs typings for this are completely broken
+// arangojs typings for this are completely bro ken
 export const aql: (template: TemplateStringsArray, ...args: ReadonlyArray<any>) => any =
     require('arangojs').aql;
 
@@ -22,7 +22,7 @@ export interface TestEnvironment {
 }
 
 const schemaContext: ProjectOptions = {
-    loggerProvider: new Log4jsLoggerProvider('warn'),
+    loggerProvider: new WarnAndErrorLoggerProvider(),
     getExecutionOptions: ({}) => ({ authContext: { authRoles: ['admin'] } }),
 };
 

spec/regression/regression-suite.ts

@@ -13,6 +13,8 @@ import { createTempDatabase, initTestData, TestDataEnvironment } from './initial
 import { ErrorWithCause } from '../../src/utils/error-with-cause';
 import { InitTestDataContext } from './init-test-data-context';
 import deepEqual = require('deep-equal');
+import { WarnAndErrorLoggerProvider } from '../helpers/warn-and-error-logger-provider';
+import { getLogger } from 'log4js';
 
 interface TestResult {
     readonly actualResult: any;
@@ -23,7 +25,6 @@ type DatabaseSpecifier = 'arangodb' | 'in-memory';
 
 export interface RegressionSuiteOptions {
     readonly saveActualAsExpected?: boolean;
-    readonly trace?: boolean;
     readonly database?: DatabaseSpecifier;
 }
 
@@ -105,20 +106,19 @@ export class RegressionSuite {
         };
         const warnLevelOptions = {
             ...generalOptions,
-            loggerProvider: new Log4jsLoggerProvider('warn'),
+            loggerProvider: new WarnAndErrorLoggerProvider(),
         };
         const debugLevelOptions = {
             ...generalOptions,
-            loggerProvider: new Log4jsLoggerProvider(this.options.trace ? 'trace' : 'warn', {
-                'schema-builder': 'warn',
-            }),
+            loggerProvider: new Log4jsLoggerProvider(),
         };
 
         // use a schema that logs less for initTestData and for schema migrations
         // the init db adapter also has a higher query memory limit
         const initProject = await loadProjectFromDir(resolve(this.path, 'model'), warnLevelOptions);
         const initAdapter = await this.createAdapter(warnLevelOptions, { isInitSchema: true });
         const initSchema = initProject.createSchema(initAdapter);
+        const initTestDataContext = new InitTestDataContext(initSchema);
 
         const project = await loadProjectFromDir(resolve(this.path, 'model'), debugLevelOptions);
         const adapter = await this.createAdapter(debugLevelOptions);
@@ -128,7 +128,6 @@ export class RegressionSuite {
 
         const testDataJsonPath = resolve(this.path, 'test-data.json');
         const testDataTsPath = resolve(this.path, 'test-data.ts');
-        const initTestDataContext = new InitTestDataContext(initSchema);
         if (existsSync(testDataJsonPath)) {
             this.testDataEnvironment = await initTestData(
                 resolve(this.path, 'test-data.json'),
@@ -160,7 +159,7 @@ export class RegressionSuite {
         }
 
         if (this.databaseSpecifier === 'arangodb') {
-            const version = await (adapter as ArangoDBAdapter).getArangoDBVersion();
+            const version = await (initAdapter as ArangoDBAdapter).getArangoDBVersion();
             if (version) {
                 this.databaseVersion = `${version.major}.${version.minor}`;
             }

spec/regression/regressions.spec.ts

@@ -3,6 +3,7 @@ import { readdirSync, statSync } from 'fs';
 import { resolve } from 'path';
 import { likePatternToRegExp } from '../../src/database/like-helpers';
 import { RegressionSuite, RegressionSuiteOptions } from './regression-suite';
+import { getLogger } from 'log4js';
 
 const regressionRootDir = __dirname;
 
@@ -28,6 +29,26 @@ describe('regression tests', async () => {
         testNameFilter = (name) => !!name.match(regex);
     }
 
+    // log levels can only bet set globally in log4js, so we're doing it here
+    const trace = process.argv.includes('--log-trace');
+    const traceLogNames = ['ArangoDBAdapter', 'InMemoryAdapter', 'query-resolvers'];
+    const traceLoggers = traceLogNames.map((name) => getLogger(name));
+    const previousLevels = traceLoggers.map((logger) => logger.level);
+    beforeEach(async () => {
+        if (trace) {
+            for (const logger of traceLoggers) {
+                logger.level = 'trace';
+            }
+        }
+    });
+    afterEach(async () => {
+        if (trace) {
+            for (let i = 0; i < traceLoggers.length; i++) {
+                traceLoggers[i].level = previousLevels[i];
+            }
+        }
+    });
+
     for (const database of databases) {
         describe(`for ${database}`, async () => {
             for (const suiteName of dirs) {
@@ -36,7 +57,6 @@ describe('regression tests', async () => {
                 // (first npm test run still marked as failure, subsequent runs will pass)
                 const options: RegressionSuiteOptions = {
                     saveActualAsExpected: process.argv.includes('--save-actual-as-expected'),
-                    trace: process.argv.includes('--log-trace'),
                     database,
                 };
                 const suite = new RegressionSuite(suitePath, options);