Logger not wrapped properly

[DeividasJackus]

Would be great if we could use something like Pino as the logger:

const logger = require("pino")({ level: "info" });
const { ServiceBroker } = require("moleculer");
const broker = new ServiceBroker({ logger });
broker.logger.info("hi");

TypeError: Cannot read property 'write' of undefined at LOG (node_modules\pino\lib\tools.js:102:9) at EventEmitter. (node_modules\moleculer\src\logger.js:63:7)

After all, it's really fast and supports custom log levels and child loggers.

[icebob]

Thanks. It's weird. I will able to check it on the next week. I'm on holiday right now. Or you can send a fix PR if you found the problem.

[WoLfulus]

I'm having troubles with bunyan too :(

const bunyan = require("bunyan");
const { ServiceBroker } = require("moleculer");
const logger = bunyan.createLogger({ name: "my-broker" });
const broker = new ServiceBroker({ logger });
// Error

[DeividasJackus]

As I'm relying on some additional functionality offered by pino I opted in for a workaround.

Instead of providing a logger to moleculer's constructor I override the broker's logger and use mixins to override it per-service:

const logger = bindings => pino.child(bindings); // spawns child logger with additional base bindings

const broker = new ServiceBroker({ ... });
broker.logger = logger({ svc: "broker" });
broker.logLevel = broker.logger.level;

const loggerMixin = {
  created() {
    this.logger = logger({ svc: this.name });
  },
};

const serviceN = {
  mixins: [loggerMixin],
  ...
};

@WoLfulus: I assume you can use the same approach.

[WoLfulus]

My approach was a little bit different, and maybe uglier.

This is what I did:

    const logger = bunyan.createLogger({
        name: process.env.SERVICE_NAME || os.hostname(),
        level: process.env.LOG_LEVEL || "trace"
    });

    const log = (name, text) => {
        logger[name](text.toString("utf8"));
    };

    const broker = new ServiceBroker({
        logger: {
            trace: (text) => log("trace", text),
            debug: (text) => log("debug", text),
            info: (text) => log("info", text),
            warn: (text) => log("warn", text),
            error: (text) => log("error", text),
            fatal: (text) => log("fatal", text),
        },
    });

[icebob]

I'm considering this issue. I plan I'm going to extend the logger broker options. It can accept Function. In this case, the broker send every log entries to this function, so you can call your custom logger module.

Example:

const broker = new ServiceBroker({
    logger: function(entry) {
        myLogger[entry.level].apply(myLogger, entry.args)
    }
});

The entry is an object and have the following properties:

{
    nodeID: "node-100",     // Local nodeID
    module: "broker",   // Others: "service", "tx", "transit", ...etc
    service: "users",   // service name of the `module` is "service"
    level: "info",  // log level of `this.logger.info` method
    args: [     // Arguments of `this.logger.` method
        "Test message",
        {
            a: 5
        }
    ]
}

@deividasjackus @WoLfulus what do you think? It can solve the logger problems? Or any suggestion?

[WoLfulus]

LGTM.

Has all the info I need and I'll be able to get rid of those prefixes and put it into a proper field on the logs (easy to filter in kibana for example).

Also, I don't know if it's bunyan related, but I had to encode the message to utf8, or else all the messages were being printed as H e l l o w o r l d. on the console.

[DeividasJackus]

@icebob I like the proposal, but would like to propose that instead of passing a function that gets called w/ every logger call to the broker constructor, you pass a function that takes contextual logger w/ data provided by moleculer and returns a new logger instance. Example:

const broker = new ServiceBroker({
    logger: function(bindings) {
        return pino.child(bindings); // in the case of pino
        return bunyan.child(bindings); // in the case of bunyan
        return new WinstonContext(winston, '', bindings); // in the case of winston + winston-context
    },
});

In other words, moleculer calls the above user-supplied function only once per module/service during creation w/ { nodeID, module, service } as the arguments, uses the returned logger.

This also means that broker.logLevel gets deprecated in favor of broker.logger.level. FWIW, that being handled by any of the mentioned loggers instead of moleculer is a good thing 😉

Edit: the above means that users can still customize the loggers on a per-module/per-service basis in the above function (could just check bindings.module or bindings.service).

[icebob]

@deividasjackus Thanks, I'm going to consider your proposal.

Btw, I fixed the original bug. So from now you can use your original code without workaround in v0.8.5

// With Pino
const logger = require("pino")({ level: "info" });
const broker = new ServiceBroker({ logger });

// Or with Bunyan
const bunyan = require("bunyan");
const logger = bunyan.createLogger({ name: "my-broker" });
const broker = new ServiceBroker({ logger });

broker.logger.info("hi");

[icebob]

I'm working on it in the next-logger branch.

Current state:

Pino

const pino = require("pino")({ level: "debug" });
const broker = createBroker({ 
    logger: bindings => pino.child(bindings)
});

Output:

Bunyan

const bunyan = require("bunyan");
const logger = bunyan.createLogger({ name: "moleculer", level: "debug" });
const broker = createBroker({ 
    logger: bindings => logger.child(bindings)
});

Output:

Default console logger

const broker = createBroker({ 
    logger: console, 
    logLevel: "debug"
});

New console output:

The bindings contains

• module - type of module: broker, service, cacher, transit, transporter
• service - name of service if the module == "service"
• nodeID - nodeID from broker options
• namespace - namespace from broker options (new v0.9 feature)

What do you think @deividasjackus @WoLfulus ?

[DeividasJackus]

@icebob aside from the addition of namespace (great btw!) I can't see if there's anything different from what I proposed - so obviously I'm in love 😆. Default logger has been improved and now uses chalk as well, correct? Hope I didn't miss anything :)

So far I've continued to manually override the broker/service loggers, but have made slight changes to the bindings. Purely a matter of taste, but if there's ever a time to share mine I guess it's before v1.0:

• component instead of module (still don't like either one)
• ver to include service version (be aware that pino reserves v for storing the used log format version)
• ns instead of namespace (purely out of will to save 7 bytes per long line)

On a slight off-note:

You might know this already, but when you're using pino (can't speak for bunyan or winston) you can use either its .pretty formatter, or the bundled CLI version of the same formatter (for piping raw logs):

I've personally found their CLI formatter very easy to customize. Simple to make it:

• Use whatever bindings you decide on.
• Display the logs in any format you want.
• Add log processing logic, i.e. somewhat of a hook (e.g., sending logs to centralized storage).

Hope someone finds anything of the mentioned above useful :)

[icebob]

Thank you for your suggestion. I'm changing the bindings props to a shorter name. But in case the component is not too long? :) Maybe it can be comp ? The service version is a good idea. I missed to add it but it's important.

[DeividasJackus]

@icebob: I agree, module probably isn't the right name for it and component is too long. Brainstorm off the top of my not-yet-caffeinated head: unit, scope, part, comp, mod?

[icebob]

I prefer the comp or mod

[DeividasJackus]

Of those two options I'm actually leaning towards mod 😆 Also picking it would mean that time doesn't have to be spent on updating documentation 👍

[icebob]

:laughing: OK, mod is better :)

[icebob]

I finished the implementation. I'm starting to update changelog.

Btw, there is an other new feature what I implemented. If you are using the built-in logger: console you can set a logFormatter and you can change the format of log messages. E.g.:

const broker = new ServiceBroker({ 
    logger: console, 
    logFormatter(level, args, bindings) {
        return level.toUpperCase() + " " + bindings.nodeID + ": " + args.join(" ");
    }
});
broker.logger.warn("Warn message");
broker.logger.error("Error message");

Output:

WARN norbi-pc2: Warn message
ERROR norbi-pc2: Error message

I think from now every logging logic in Moleculer is customizable :)

[DeividasJackus]

@icebob excellent!

Last thing: think it's relevant to list the bindings moleculer uses itself in the documentation so users know what's considered reserved (overrides are still possible: broker.logger.error({ mod: "peanut" }).

[icebob]

Good point! I added it to changelog first.