Strange behavior: partial and intermittent logging

[koalabi]

Environment: node -v : v10.10.0 npm -v : 6.9.0 tsc -v : Version 3.2.2 grep log4j package-lock.json "@log4js2/core": { "resolved": "https://registry.npmjs.org/@log4js2/core/-/core-2.0.5.tgz"

Issue: (NOTE: index.ts implements a GraphQL server using the Prisma Yoga server) There are several strange aspects in this issue:

1. There are several loggers defined (imagechest.graphql, firebirdsql.queries, thumbnails.dbqueries ...) but only one (from the main file index.ts) produces output
2. Even for index.ts, nor the logging nor the console itself displays the very first logging lines (even with virtual console disabled) [see the first "console.log(...)" instruction below]
3. Logging actually only starts upon the first GraphQL query to index.ts - see log output below, whereas there are a number of logger.debug statements in the code before this point
4. Logging anomalies started after the functionality of the server got extended and source code became distributed among several source files. Until then, logging seemed quite normal.

--- begin excerpt of main file --- import { getLogger, configure, LogLevel } from '@log4js2/core';

import { readFileSync } from 'fs';

import { create } from 'rxjs-spy';

import { GraphQLServer } from 'graphql-yoga'

// import * as Firebird from 'node-firebird'; import { Database, Options, pool as Pool, ConnectionPool } from 'node-firebird';

import { sprintf } from 'sprintf-js'; import { isNullOrUndefined } from 'util';

import { Image, Tag, SecundaryTag, ImplicitCaptionRelation } from 'photos/src/public_api';

import { QueryResult, executeQuery as pExecuteQuery, executeSplitQuery as pExecuteSplitQuery } from './firebird-query'; // X import { Thumbnail, getThumbnailsForFilenameX } from './thumbnails-dbqueries';

// Compile & run commands (2019-01-11): tsc --lib esnext src/index && RXJSSPY_REGEX="^$" DB_CONF_FNAME=ImageChest-PRD-DSB2.json LOG_CONF_FNAME=log4js2-PRD-config.json node src/index // Compile & run commands (2019-03-24): tsc --lib esnext,dom --declaration src/index && RXJSSPY_REGEX="^$" DB_CONF_FNAME=ImageChest-PRD-DSB2.json LOG_CONF_FNAME=log4js2-TST-config.json node src/index

// ======================== PARAMETERS =================================

const GRAPHQL_PORT = 4004;

// ======================== PARAMETERS =================================

const opts = { port: GRAPHQL_PORT, endpoint: '/graphql', playgroundEndpoint: '/playground' }

const LOGGING_CONFIG_DEFAULT = { virtualConsole: true, // layout: '%d [%p] %c %M:%line:%column - %m %ex', level: LogLevel.DEBUG, appenders: ['Console'], loggers: [/{ tag: 'imagechest.graphql', level: LogLevel.TRACE }, { tag: 'thumbnails.dbqueries', level: LogLevel.TRACE }/] };

console.log(main: starting server with logger configuration...); // Logging configuration (with type "any" as IConfiguration is not exported) const logOptions = readParmsFromFileOrDefault(process.env.LOG_CONF_FNAME, LOGGING_CONFIG_DEFAULT); configure(logOptions);

function readParmsFromFileOrDefault(fnam: string | undefined, defval: T): T { let str = (fnam ? readFileSync(fnam, 'utf8') : undefined); console.info(Config: getting settings from ${fnam ? fnam : '<built-in default config>'}); return (str ? JSON.parse(str) : defval); }

// logger may only be instantiated after configuration; otherwise it doesn't output anything const logger = getLogger('imagechest.graphql'); console.info(Logging settings: ${JSON.stringify(logOptions)});

--- end excerpt of main file ---

Sample logging output (from the start) :

tsc --lib esnext,dom src/*.ts && RXJSSPY_REGEX="^$" DB_CONF_FNAME=ImageChest-PRD-DSB2.json node src/index 2019-03-25 18:44:34,643 [DEBUG] imagechest.graphql - getSecundaryTagsForId: entering ... (id=1898) 2019-03-25 18:44:34,946 [DEBUG] imagechest.graphql - getImagesById: entering ... (idList=23497,23498,23499,23500,23501,23729,23730,23731,23732,23733,30598,30599,30600,30601,30613,30614,30615,30616,30617) 2019-03-25 18:44:35,128 [DEBUG] imagechest.graphql - Image/caption_leaf: caption_leaf_id: 1855 2019-03-25 18:44:35,129 [DEBUG] imagechest.graphql - Image/caption_leaf: caption_leaf_id: 1854 2019-03-25 18:44:35,129 [DEBUG] imagechest.graphql - Image/caption_leaf: caption_leaf_id: 1852 2019-03-25 18:44:35,130 [DEBUG] imagechest.graphql - Image/caption_leaf: caption_leaf_id: 1852 2019-03-25 18:44:35,130 [DEBUG] imagechest.graphql - Image/caption_leaf: caption_leaf_id: 1852

Maybe not a bug but still strange and I have already investigated quite a lot: I find no obvious explanation to this behavior.

Below the generated index.js (first lines): Logger configuration is the first executed instruction after "require()"

"use strict"; // Compile command: tsc --lib esnext,dom src/index.ts var awaiter = (this && this.awaiter) || function (thisArg, _arguments, P, generator) { return new (P || (P = Promise))(function (resolve, reject) { function fulfilled(value) { try { step(generator.next(value)); } catch (e) { reject(e); } } function rejected(value) { try { step(generator"throw"); } catch (e) { reject(e); } } function step(result) { result.done ? resolve(result.value) : new P(function (resolve) { resolve(result.value); }).then(fulfilled, rejected); } step((generator = generator.apply(thisArg, arguments || [])).next()); }); }; var generator = (this && this.generator) || function (thisArg, body) { var = { label: 0, sent: function() { if (t[0] & 1) throw t[1]; return t[1]; }, trys: [], ops: [] }, f, y, t, g; return g = { next: verb(0), "throw": verb(1), "return": verb(2) }, typeof Symbol === "function" && (g[Symbol.iterator] = function() { return this; }), g; function verb(n) { return function (v) { return step([n, v]); }; } function step(op) { if (f) throw new TypeError("Generator is already executing."); while () try { if (f = 1, y && (t = op[0] & 2 ? y["return"] : op[0] ? y["throw"] || ((t = y["return"]) && t.call(y), 0) : y.next) && !(t = t.call(y, op[1])).done) return t; if (y = 0, t) op = [op[0] & 2, t.value]; switch (op[0]) { case 0: case 1: t = op; break; case 4: .label++; return { value: op[1], done: false }; case 5: .label++; y = op[1]; op = [0]; continue; case 7: op = .ops.pop(); .trys.pop(); continue; default: if (!(t = .trys, t = t.length > 0 && t[t.length - 1]) && (op[0] === 6 || op[0] === 2)) { = 0; continue; } if (op[0] === 3 && (!t || (op[1] > t[0] && op[1] < t[3]))) { .label = op[1]; break; } if (op[0] === 6 && .label < t[1]) { .label = t[1]; t = op; break; } if (t && .label < t[2]) { .label = t[2]; .ops.push(op); break; } if (t[2]) .ops.pop(); .trys.pop(); continue; } op = body.call(thisArg, ); } catch (e) { op = [6, e]; y = 0; } finally { f = t = 0; } if (op[0] & 5) throw op[1]; return { value: op[0] ? op[1] : void 0, done: true }; } }; var _this = this; exports.__esModule = true; var core_1 = require("@log4js2/core"); var fs_1 = require("fs"); var rxjs_spy_1 = require("rxjs-spy"); var graphql_yoga_1 = require("graphql-yoga"); // import as Firebird from 'node-firebird'; var node_firebird_1 = require("node-firebird"); var sprintf_js_1 = require("sprintf-js"); var firebird_query_1 = require("./firebird-query"); // X var thumbnails_dbqueries_1 = require("./thumbnails-dbqueries"); // Compile & run commands (2019-01-11): tsc --lib esnext src/index && RXJSSPY_REGEX="^$" DB_CONF_FNAME=ImageChest-PRD-DSB2.json LOG_CONF_FNAME=log4js2-PRD-config.json node src/index // Compile & run commands (2019-03-24): tsc --lib esnext,dom --declaration src/index && RXJSSPY_REGEX="^$" DB_CONF_FNAME=ImageChest-PRD-DSB2.json LOG_CONF_FNAME=log4js2-TST-config.json node src/index // ======================== PARAMETERS ================================= var GRAPHQL_PORT = 4004; // ======================== PARAMETERS ================================= var opts = { port: GRAPHQL_PORT, endpoint: '/graphql', playgroundEndpoint: '/playground' }; var LOGGING_CONFIG_DEFAULT = { virtualConsole: true, // layout: '%d [%p] %c %M:%line:%column - %m %ex', level: core_1.LogLevel.DEBUG, appenders: ['Console'], loggers: [ /{ tag: 'imagechest.graphql', level: LogLevel.TRACE }, { tag: 'thumbnails.dbqueries', level: LogLevel.TRACE }*/] }; console.log("main: starting server with logger configuration..."); // Logging configuration (with type "any" as IConfiguration is not exported) var logOptions = readParmsFromFileOrDefault(process.env.LOG_CONF_FNAME, LOGGING_CONFIG_DEFAULT); core_1.configure(logOptions); function readParmsFromFileOrDefault(fnam, defval) { var str = (fnam ? fs_1.readFileSync(fnam, 'utf8') : undefined); console.info("Config: getting settings from " + (fnam ? fnam : '')); return (str ? JSON.parse(str) : defval); }

Thanks in advance for any hint ... Regards, Alain

[koalabi]

Additional (troubleshooting) info: I currently have 3 files involved:

• index.ts (the main file)
• firebird-query.ts
• thumbnails-dbqueries.ts

All invoke invoke getLogger(tag: string). If I replace the getLogger() invocation by "const logger = console;", everything seems to come back to normal (as shown by the program logging at startup below:

Modified statement: const logger = console; // getLogger('firebirdsql.queries');

Logging output (of course, the output from the 2 subordinate files is not conform to the prescribed pattern) main: starting server with logger configuration... Config: getting settings from 2019-03-25 20:09:17,481 [INFO] main - Logging settings: {"virtualConsole":true,"level":500,"appenders":["Console"],"loggers":[{"tag":"main","level":500,"layout":"%d [%p] %c - %m"}],"layout":"%d [%p] %c - %m"} 2019-03-25 20:09:17,486 [INFO] main - rxjs-spy logger regexp: ^$ 2019-03-25 20:09:17,487 [INFO] main - Config: getting settings from ImageChest-PRD-DSB2.json 2019-03-25 20:09:17,487 [INFO] main - Database settings: host: DS_BLA002.local, database: /databases/ImageChest-PRD.fdb 2019-03-25 20:09:17,487 [INFO] main - Thumbnails database settings (single config): host: DS_BLA002.local, database: /databases/ImgThumbnails.fdb 2019-03-25 20:09:17,508 [INFO] main - Captions-Backend server is running on localhost:4004/graphql

[koalabi]

P.S.: I don't understand the last sentence from the "Configuration" documentation, below:

"Configure log4js using the configure() method. This must be the first thing you do. Otherwise, the first log you commit will not allow updates from this function."

What do you mean by "will not allow updates from this function"?

[koalabi]

(Wrong manipulation - No closing intended)

[anigenero]

So, any time you call getLogger() unintentionally before the configure() method (in the import), the configuration won't update. So, in your case, this is what looks like is happening - and it makes sense since it didn't start happening until you split your files.

Your import file:

const logger = getLogger('file2');

Your main file:

import {configure} from '@log4js2/core';
import './file2'; // <-- getLogger is called, sets configuration

configure(..config) // <-- configuration is sealed, no update

In this kind of instance, the getLogger method is called and a default configuration for log4js2 is used. Currently, log4js2 handles configuration in an immutable fashion, in that calling configure after calling into the logger won't change anything. Whichever comes first is what gets set. This is by design, but it's on my list of things I want to look into further to address, because it's a headache for me as well, especially when setting the logger as a static property on a class.

How I handle this right now is writing a log utility file like so:

import { configure, getLogger as log4jsGetLogger, LogFilterAction, LogLevel } from '@log4js2/core';

configure({
    appenders: ['Console'],
    layout: '%d [%p] %c - %msg %ex',
    level: LogLevel.DEBUG,
    virtualConsole: false
});

export const getLogger = (loggerName: string) => {
    return log4jsGetLogger(loggerName);
};

Then you use the getLogger method from your utility - and boom. Problem solved. Try that approach. If that doesn't fix the issue, then it is indeed a bug and I'll investigate further.

[koalabi]

Hi Robin, It looks indeed like this is the cause and that your recommended fix is OK. I'm refactoring and will let you know but the issue will most likely be closed. Thanks.