Integrating a logging library

[javagl]

Addresses #31

There are many logging libraries for Node.js. I did not go though the list of (currently) 7610 packages that are found when naively searching for logging on npm. Even evaulating the ones that have more-than-seven-digit 'Weekly Downloads' (e.g. winston, bunyan, pino, morgan, ts-log, npmlog....) is beyond what could be justified here.

Maybe pino? Yeah, why not 🤷‍♂️ ... So this PR adds https://github.com/pinojs/pino/ as a logging library.

One reason why I'd still hesitate is that the logging library is something very fundamental. Changing it later can be a pain in the back. I considered to add a "thin layer" around the logging library, just to decouple the code from the library that is used. But there are too many unknowns to sensibly tackle this now. Maybe it will still happen later in this PR...

Right now, the way how this logger can be used is shown in the LoggingDemo.ts. The gist is

import { LoggerFactory } from "../src/logging/LoggerFactory";

// Create a default logger to use in this file.
// (The __fileName is optional)
const logger = LoggerFactory(__filename);

logger.info("info");

Yes, the LoggerFactory already is some sort of decoupling from the more specific import pino.... But it also serves the purpose of having a point to "hook in" for certain configuration options. The exact options that are required here still have to be evaluated.

Beyond that, it currently does return a pino Logger object. And the question of abstraction and compatibiltiy then largely depends on how this will be used. Ideally, the only assumptions about that object should be...

• it has functions called trace, debug, info, warn, error, and fatal
• these functions can receive a string (or an 'Error' object)

The pino Logger actually offers more than that. This includes variable-arguments and message formatting like
logger.info("Some printf-like %d values %O", someNumber, someObject);
or the creation of "child loggers". But these are details that are specific for pino. Not using them may make it easier to switch to another library later.

I replaced the first few console.log statements that have been in the code with the corresponding log calls. An example output from running the upgrade command was shown in #31 . With the pino library, the output will look like this:

(Note that this was created with the trace log level, which is the highest level. With the default level, info, only the last line would be printed)

Alternatively, the log can also be written in JSON form, like this ...

{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"Executing upgrade"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"  input: specs\\data\\TilesetOfTilesets\\tileset.json"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"  output: output\\upgraded"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"  force: true"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"  targetVersion: 1.0"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.387Z","name":"CLI","msg":"  gltfUpgradeOptions: {}"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.390Z","name":"upgrade","msg":"Upgrading asset version number"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.390Z","name":"upgrade","msg":"Upgrading refine to be in uppercase"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.390Z","name":"upgrade","msg":"Upgrading content.url to content.uri"}
{"level":"TRACE","time":"2023-08-31T14:24:27.390Z","name":"upgrade","msg":"  Renaming 'url' property for content tileset2.json to 'uri'"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.393Z","name":"upgrade","msg":"  Upgrading external tileset in tileset2.json"}
{"level":"DEBUG","time":"2023-08-31T14:24:27.393Z","name":"upgrade","msg":"Upgrading asset version number"}

---

Some open questions:

• Where should the log level be configured?
  Right now, it is possible via process.env.LOG_LEVEL, but that may not always be the best solution. E.g. maybe there should be a --debug/--trace CLI option, or a more generic --logLevel trace one....
• Where should the output target be configured?
  This refers to whether the output should be pretty-printed on the console, or dumped into a file as newline-separated JSON. This could be a CLI option like --logOutput myFile or so...
• How will all this be done when the 3D Tiles Tools are used as a library in the future?
• Why the heck do so many logging libraries not allow you to configure which level should be used for log messages?

---

The last one really bugs me. One can sprinkle one file with

logger.debug("Start");
...
logger.debug("End");

messages. But when the level there has to be changed, then the only way to accomplish this is with a Search-And-Replace. I'd really prefer if it was possible to configure this as in

private level = "debug";
...
logger.log(level, "Begin");
...
logger.log(level, "End");

so that only the value of the level variable has to be changed, e.g. to trace, to change the level for all these messages.

[javagl]

The 'open questions' mentioned above referred to the logging configuration on the CLI/API level.

One thing that still should be addressed on the implementation level:

The pino loggers inherit the log level from their parent. But they only inherit this at creation time. This has the effect that in the following snippet, the output of the child logger will not appear:

import { LoggerFactory } from "./src/logging/LoggerFactory";

const rootLogger = LoggerFactory();

rootLogger.level = "info";
const childLogger = LoggerFactory("child");

// This will not affect the childLogger:
rootLogger.level = "trace";

rootLogger.trace("trace");
childLogger.trace("trace");

The child logger inherited the "info" level at creation time. Changing the level in the root logger to trace will not have an effect on the child logger.

It is not entirely clear what the expectations could be here, but I'll think about some possible approaches for handling that...

[javagl]

One possible solution for the problem in the previous comment is to not create the child loggers each time that they are requested, but instead store them and offer an option to set the level of all loggers that have been created. So the example from the previous comment would now look like this:

import { Loggers } from "./src/logging/Loggers";

const rootLogger = Loggers.get();

rootLogger.level = "info";
const childLogger = Loggers.get("child");

// This will not affect the childLogger:
rootLogger.level = "trace";

rootLogger.trace("trace");
childLogger.trace("trace");

// This will affect the childLogger:
Loggers.setLevel("trace");

rootLogger.trace("trace");
childLogger.trace("trace");

I think this looks "nicer" than the LoggerFactory, approach. But should be reviewed in terms of best practices (and possible caveats of storing the loggers that I might have overlooked).

[javagl]

The last commit adds options for configuring the logging via the CLI (to some extent). As added to the README.md:

Flag	Description	Required
--logLevel	The log level. Valid values are trace, debug, info, warn, error, fatal, and silent	No, default info
--logJson	Print log messages as JSON instead of pretty-printed	No, default false

Modifying the "target" (i.e. the implementation of the logJson functionality) is a bit quirky. The pino loggers can only be created with a certain configuration, but they cannot be modified. The logger that is used in the part that parses the command line ... would have to be modified, depending on the command line. The current solution is to re-initialize the "default logger" (i.e. the root logger of all loggers that are created). This implementation may have to be changed in the future, if there is demand for more fine-grained configurations (like defining a log output file, or (then) setting different log levels for the console and the file).