feat(message): Add new message interface

[Symbitic]

This is a port of the Qt Message logging framework. In contrast to the application-oriented log standard library module, this is specifically designed to scale to hundreds or thousands of modules while giving applications full control over the output.

It does this by separating messages from their presentation. Modules emit messages, and the application takes care of if/how to present them.

This isn't a replacement for the log framework. Handler functions can use the logging module to print messages. This is intended for modules to emit categorized information that can be handled by the application.

What it offers

• Message patterns: An application can simply set a message pattern (e.g. [%{time yyyy/mm/dd}] %{message}) and all messages from every module will be printed in this format.
• Categorized messages: This is the key point. By categorizing modules, applications can control the output on a per-module basis.
• Message handlers: A global message handler can be installed to handle all messages. The function will be passed the message string as well as the category, to determine if the message should be printed or not.

Use cases

Consider two opposing use cases:

1. A command-line app that wants to print only its own messages and fatal errors from every module. No colors or message prefixes like "INFO"
2. A server that wants to print as much information as possible, including debug messages from hundreds of modules, possibly disabling messages from a few specific modules.

This accommodates both use cases. Because the application is responsible for the presentation, modules do not need to worry about printing too much information. Debug messages are disabled by default and must be enabled by the application.

---

Related issue: #2398

See also:

• https://doc.qt.io/qt-6/qmessagelogger.html
• https://doc.qt.io/qt-6/qloggingcategory.html
• https://doc.qt.io/qt-6/qtglobal.html#qInstallMessageHandler

[CLAassistant]

All committers have signed the CLA.

[iuioiua]

Gently pinging @kt3k and @cjihrig. Is this something we'd like to have?

[lino-levan]

This makes a lot of sense to me. Qt is pretty well battle-tested and this messaging framework seems to work well for them. My concerns are as follows:

• This will be confusing for end users, since the standard library will have ~2 different ways of having applications ask libraries to log their internal data
• This will require a pretty large warning reminding library authors not to make handler methods. This is really unintuitive imo since when I'm developing is when I would like to see my logs. This kind of forces TDD onto people when before it was more optional (which may be a good thing)

@kt3k thoughts?

[iuioiua]

WDYT, @kt3k?

[timreichen]

Instead of a second framework, I think we should rework the current log mod (there were attempts in the past. I tried for a class based logger approach here which seems similar in concept) and issues now (#2645) while making it more general and expandable to be suitable for more use cases.

I have some concerns of this specific PR:

• std mod should be as unopinionated as possible. This seems to me to be a very opinionated framework.
• It would need to be adapted to have a more native js feel
• double mustache brackets for patterns seem not optimal, since the same can be achieved by template strings (we removed such before in std in favour of template strings)
• log level names should be the same as in console (error instead of critical and fatal, warn instead of warning)

[Symbitic]

@timreichen
Those are some good points, but I'm not sure reworking logger would work.
It needs to be designed so that libraries can use it without making any assumptions about if/how the user will want to print that information. The logging framework is all about printing.

Some other responses:

• The log level names things is valid. I'll definitely change that.
• Template strings might be feasible, but:
  1. It will require passing more information to MessageLogContext (which might not be a bad thing).
  2. It will mean the user has to create a message handler function instead of just calling setMessagePattern()
• I actually thought this was a very unopinionated framework, especially compared to classes since it's just calling some functions.
• Why doesn't this feel like native JS? Can you be more specific?
• It might help to say in the documentation that message is lower-level and meant for libraries while logging is higher level and meant for applications.

I'll try changing it to use template strings and Console log name over the weekend and see if that helps.

I have nothing against extending std logging, I just want library developers to be able to supply more information without changing the control flow.
Consider a library that wraps fetch() with retries, or adding an option to std tar to continue even if a file is corrupted. A server application will likely want to print a range of information like that this is a network category message, the time it took place, and the message itself. A command-line application might want to print each retry message in color, or it might not want to at all if there's a --quiet flag.

[timreichen]

@timreichen Those are some good points, but I'm not sure reworking logger would work. It needs to be designed so that libraries can use it without making any assumptions about if/how the user will want to print that information. The logging framework is all about printing.

I think the two are compatible with the right structure.

• Why doesn't this feel like native JS? Can you be more specific?

Changing a global state with functions without reference to the state itself.
Taking enableCategory as an example: Rather than

enableCategory("driver.usb")

in js you would expect either a property set, a method call or a passing a reference of the state:

enableCategory(categories, "driver.usb")

or better

categories.enable("driver.usb")

or even better

categories["driver.usb"].enable = true

The problem with a global state approach is that it introduces anti-patterns (the current log implementation also does this with setup, which is why I think needs to reworked).

I have nothing against extending std logging, I just want library developers to be able to supply more information without changing the control flow. Consider a library that wraps fetch() with retries, or adding an option to std tar to continue even if a file is corrupted. A server application will likely want to print a range of information like that this is a network category message, the time it took place, and the message itself. A command-line application might want to print each retry message in color, or it might not want to at all if there's a --quiet flag.

I think if we took a scoped state approach instead, we could achieve basically the same with more clarity and a more native js feel. For example, if log mod introduced class based loggers (as proposed before), we simply can add MessageLogger which then can be exported and quiet toggled on or off by the consumer. As an example the first few lines in the readme example:

before:

// Create a new category.
 LOGGING_CATEGORY("driver.usb");

 warning("This is a test warning"); // Should print "This is a test warning"
 warning("driver.usb", "No USB devices found"); // Should print "driver.usb: No USB devices found"

 const logger = new MessageLogger("driver.gpu", MessageType.Debug);
 logger.debug("GPU Vendor = Intel"); // Should print "driver.gpu: GPU Vendor = Intel"

 // Shouldn't print anything (debug messages disabled by default).
 debug("driver.usb", "PCI device 1 found");

 enableCategory("driver.usb", MessageType.Debug);
 // Should print "driver.usb: PCI device 2 found"
 debug("driver.usb", "PCI device 2 found");

 disableCategory("driver.gpu"); // Disable all messages from `driver.gpu`
 warning("driver.gpu", "Old driver found"); // Shouldn't print anything

after:

const logger = new ConsoleLogger()
const usbLogger = new MessageLogger(MessageLogger.logLevels.trace, { formatter: () => … })

logger.warn("This is a test warning"); // Should print "This is a test warning"
usbLogger.warn("No USB devices found"); // Should print "driver.usb: No USB devices found"

const gpuLogger = new MessageLogger(MessageLogger.logLevels.debug, { formatter: () => … });
gpuLogger.debug("GPU Vendor = Intel"); // Should print "driver.gpu: GPU Vendor = Intel"

usbLogger.quiet = true
// Shouldn't print anything (debug messages disabled by default).
usbLogger.debug("driver.usb", "PCI device 1 found");

usbLogger.quiet = false
// Should print "driver.usb: PCI device 2 found"
usbLogger.debug("PCI device 2 found");

gpuLogger.quiet = true
gpuLogger.warn("Old driver found"); // Shouldn't print anything

export { usbLogger, gpuLogger }

some other file:

import { usbLogger, gpuLogger } from "…"
usbLogger.formatter = (logLevel, data) => `${new Date().toISOString()}: ${logLevel} -> ${data.join(" "}`
gpuLogger.quiet = true

[Symbitic]

I think if we took a scoped state approach instead, we could achieve basically the same with more clarity and a more native js feel. For example, if log mod introduced class based loggers (as proposed before), we simply can add MessageLogger which then can be exported and quiet toggled on or off by the consumer. As an example the first few lines in the readme example:

The problem with this is that it means each MessageLogger must have its own formatter. That almost certainly means that library developers will add their own formatter function. I just don't think that would scale to hundreds of modules.

Changing a global state with functions without reference to the state itself.

This I think is possible to get rid of. The only global would be a function: the message handler.

Example:

const usbLogger = new MessageCategory("driver.usb");
usbLogger.warn("No USB devices found");

const gpuLogger = new MessageCategory("driver.gpu");
gpuLogger.debug("GPU Vendor = Intel");

usbLogger.quiet = true
usbLogger.debug("driver.usb", "PCI device 1 found");

usbLogger.quiet = false
usbLogger.debug("PCI device 2 found");

gpuLogger.quiet = true
gpuLogger.warn("Old driver found");

By default, the output would be:

driver.usb: No USB devices found
driver.gpu: GPU Vendor = Intel
driver.usb: PCI device 2 found

If the user/application wanted to customize this, they could have this:

main.ts:

import { setMessageLogger, MessageCategory } from "https://deno.land/std/";
setMessageLogger((category: MessageCategory) => {
  // print what/however you want.
});

Or

import * as log from "https://deno.land/std/log/mod.ts";
await log.setup({
  logger: (msg: string, context: MessageContext, category: MessageCategory) => {
    // print what/however you want.
  }
})

Would this be better? The former feels like the native JS API for global addEventListener/dispatchEvent.

[timreichen]

I think the first approach is better.
Maybe having MessageLogger inherit EventTarget to be able to subscribe to events, similar to the websocket api?
Something like

export const usbMessageLogger = new MessageLogger()
usbMessageLogger.dispatchEvent("message", new MessageEvent({ data: { logLevel: logLevels.debug details: "information" }} ))

and

import { usbMessageLogger } from "…"
usbMessageLogger.addEventListener("message", ({ data }) => {
  console.log("from usb message logger:", data.logLevel, data.details)
})

[Symbitic]

I made some major changes to make it more JS-like. It's much smaller and hopefully less opinionated.

By default, nothing is printed. If the point of messages is for modules to supply information to applications, then applications should be in control of all output.

As far as EventTarget goes, I considered something like that, but there are two problems:
1. It could lead to problems with order-of-delivery.
2. Message categories/loggers shouldn't be exported by modules. Ideally, usb would create usbLogger in deps.ts and not make it visible to other modules.

[timreichen]

As far as EventTarget goes, I considered something like that, but there are two problems:

1. It could lead to problems with order-of-delivery.

How so? dispatchEvent is sync and goes through all listeners in order of subscription. Or am I not aware of something?

2. Message categories/loggers shouldn't be exported by modules. Ideally, usb would create usbLogger in deps.ts and not make it visible to other modules.

I disagree. How is the user to know what loggers there are if they are not exported? I think if something is meant to be used by external code, it should be exported as a gerneal pattern in js. It also solves the issue of category name overlaps.
Or what are your concerns?

[Symbitic]

I'm open to EventTarget, but my concern is that if it's being called in an async function or a callback, it could lead to some unexpected results for users. If dispatchEvent is synchronous though, that makes me feel better.

My concern (as always) is scalability. Imagine if every module in the Denoland registry used this. Applications would have to import hundreds of loggers. It would also create a coupling by making the application depend on a module dependency.

For naming overlap, it does put it on the module developer to pick category names (which is why the docs recommend modulename.subcategory), but this approach has worked well for Qt for decades. I think it should work here.

[kt3k]

In deno, log() and info() log messages in the same level (1), and debug() logs messages in lower level (0). ref. https://github.com/denoland/deno/blob/f729576b2db2aa6ce000a598ad2e45533f686213/ext/console/02_console.js#L1977-L2005

I think these methods should be align with it.

[kt3k]

Is this property necessary? What is the supposed usage?

[kt3k]

Ignoring empty msg feels confusing to me as console.log() prints a new line in JS

[0f-0b]

A logging library meant to scale to thousands of modules has to prepare for thousands of copies of the library itself present within the same application. Below is a hypothetical example with 2 copies of message/mod.ts.

// https://adder.example/add@0.1.0
import { MessageCategory } from "https://deno.land/std@0.171.0/message/mod.ts";

const logger = new MessageCategory("add.trace");

export function add(a: number, b: number): number {
  logger.info(`${a} + ${b}`);
  return a + b;
}

// main.ts
import { setMessageHandler } from "https://deno.land/std@0.172.0/message/mod.ts";
import { add } from "https://adder.example/add@0.1.0";

setMessageHandler((message) => console.log(message));
add(1, 2); // should print `1 + 2`, but would not with the current design

[timreichen]

My concern (as always) is scalability. Imagine if every module in the Denoland registry used this. Applications would have to import hundreds of loggers. It would also create a coupling by making the application depend on a module dependency.

If application used hunderts of mods they would have an import statement of each anyway and only needed to add a specifier for each required logger. This is transparent and has no leeway for unwanted behavior. It also solves the issue of mismatching versions @0f-0b described without any global variable.

I see two ways to solve the issue of scalability:

1. have a LoggerCollection class or something similar to combine multiple loggers for exports if needed
2. have each module export one logger and have a log event have a property to symbolize a category. One then only needs to subscribe to one logger per mod and can handle them based on that property in the eventtarget callback function (similar to AnimationEvent.animationName

[kt3k]

I agree with @Symbitic on the below

Message categories/loggers shouldn't be exported by modules. Ideally, usb would create usbLogger in deps.ts and not make it visible to other modules.

If logs are produced in transitive dependencies (ie. grandchildren, grandgradnchildren deps), it's difficult/messy to import those loggers/categories from them.

[jollytoad]

if the Deno mantra is to use the platform then why not just use console.* ?
console will always be there, you can't ignore it, as an app author you'll always need to consider what to do with these raw console logs regardless of some other logging layer, so why not just keep it simple. if we feel there is not enough control over console, ie. filtering/redirecting then maybe Deno itself should provide these abilities, maybe in the form of a layer of console event handlers. These could be passed the set of args, the level, the origin module, and use preventDefault to suppress the regular feed to stderr/stdout. maybe this could even become a web or wintercg standard?
this could even be polyfilled by monkey patching console

[kt3k]

Closing because of inactivity. If anyone feel strongly about this proposal, please open a new one.