Use an overridable method for all logging

[synsteve]

Hi,

I currently use middleware to wrap the service logger with context info and place it in the ctx - this allows me to add tracing/session information to the log entries automagically that binds them together which is very useful in a busy multi-user system.

All my logging statements then use ctx.logger instead of this.logger and in my api services I have overridden logRequest and logResponse so I can use req.$ctx.logger instead of this.logger.

This is working well, but some of the logging statements in moleculer-web don't "work" because they are directly written using this.logger. Example in callAction:

if (route.logging) {
    if (this.settings.logRequest && this.settings.logRequest in this.logger)
        this.logger[this.settings.logRequest](`   Call '${actionName}' action`);
    if (this.settings.logRequestParams && this.settings.logRequestParams in this.logger)
        this.logger[this.settings.logRequestParams]("   Params:", params);
}

Would it be possible to send all "generic" logging to a method, e.g. "log" with parameters level, req (if available) and message? That way I could override it and if req exists and has $ctx, I can use that. The default implementation would be something like:

log(req, level,message) {
    if (level in this.logger) this.logger[level](message);
}

and the above code would change to:

if (route.logging) {
    if (this.settings.logRequest)
        this.log(req, this.settings.logRequest,`   Call '${actionName}' action`);
    if (this.settings.logRequestParams)
        this.log(req, this.settings.logRequestParams, "   Params:", params);
}

Then, I can override "log" and use req.$ctx.logger. There may even be a neater way you can think of?

Many thanks, S.

[icebob]

What if you overwrite the this.logger in the service created hook? And in this case, you can catch all log messages in the services.

[synsteve]

The trouble is, there won't be any context info in the logging args. I'm trying to create a system where the developers don't need to worry about supplying context to their log messages, it happens automatically (by using ctx.logger) but that logger has to be created on every action/event invocation (I've got code in the localAction and localEvent hooks to wrap this.logger with ctx.logger).

If I overwrite this.logger in created - it will be the same for all invocations I think.

[icebob]

And what if you use AsyncLocalStorage to storing ctx and you can access to it where you need? Here is a sample middleware for it: https://github.com/moleculerjs/moleculer/blob/master/dev/async-local-storage.js

[synsteve]

Very interesting, but doesn't that still rely on the method/action using the store info? I can't repoint this.logger to anything as that would affect concurrent requests. I don't think I can get the logging statements inside moleculer-web to use my logger unless it's through overridden methods can I?

[synsteve]

Hi icebob,

You're a genius. I was playing around with the AsyncLocalStorage and it solves all my problems. Using it for the localAction and localEvent hooks, I can then retrieve it in the newLogEntry hook and add in all the session/trace data that makes it into Google Cloud Logging.

Thanks a million!

[icebob]

Awesome. Maybe would be good if you can share some code of your solution that can help others 👍

[synsteve]

You bet, here's a summary:

In my case, the problem was that we run a highly multi-user system with several different moleculer applications (each with dozens of services) that talk to each other. This is all running in the cloud and we wanted to make use of the cloud logging a tracing tools to link up the spans and logs for a single user "session" (initiated by the first API call in).

With the standard moleculer logging you don't get access to the ctx so you have to get the developers to put ctx info in their messages which is a pain and error prone. Plus this still doesn't provide the necessary tracing info for the cloud logging/trace tools.

Our solution is specific to Google Cloud and uses the Winston logger with the LoggingWinston (@google-cloud/logging-winston) transport.

Thanks to advice from @icebob , all we need to do to automatically get the session and tracing information into the LogEntry objects that are sent to GCP is to implement a couple of middleware hooks:

const { LoggingWinston } = require("@google-cloud/logging-winston");
const _ = require("lodash");
const { AsyncLocalStorage } = require("async_hooks");
const asyncLocalStorage = new AsyncLocalStorage();
const util = require("util");

module.exports = {
    name: "SessionLoggingMiddleware",

    localAction(next, action) {
        return (ctx) => asyncLocalStorage.run(ctx, () => next(ctx));
    },
    localEvent(next, action) {
        return (ctx) => asyncLocalStorage.run(ctx, () => next(ctx));
    },
    newLogEntry(type, args, bindings) {
        // Get the context
        const ctx = asyncLocalStorage.getStore();
        if (process.env.LOGGERTYPE === "cloud") {
            if (ctx) {
                // Add in the tracing info
                let opts = {};
                opts.timestamp = new Date();
                if (ctx.requestID && _.has(ctx, "broker.options.cloudinfo.resource.labels.project_id")) {
                    const traceValue = `projects/${ctx.broker.options.cloudinfo.resource.labels.project_id}/traces/${ctx.requestID}`;
                    opts[LoggingWinston.LOGGING_TRACE_KEY] = traceValue;
                }
                if (ctx.id) {
                    const spanId = ctx.id.replace(/-/g, "").substring(0, 16);
                    opts["logging.googleapis.com/spanId"] = spanId;
                }

                args.push(opts);
            }

            // Use the bindings to add namespace and module data to log entry as
            // the LoggingWinston transport doesn't respect the format options at the moment
            // We end up with 2 args: the message and the options
            // The options will be the last arg and will be an object
            let opts = args.pop();
            if (!_.isObject(opts) || !opts.timestamp) {
                // Not a logging-winston object so put back in the args array
                args.push(opts);
                opts = null;
            }
            // Now format the message
            const printArgs = (args) => {
                return args.map((p) => {
                    if (_.isObject(p) || Array.isArray(p)) {
                        let objPrinter = module.exports.defaultObjectPrinter;
                        if (ctx) objPrinter = _.get(ctx, "broker.options.logger.options.objectPrinter", objPrinter);
                        return objPrinter(p);
                    }
                    return p;
                });
            };
            args[0] = `${bindings.ns}/${bindings.mod.toUpperCase()}: ${printArgs(args).join(" ")}`;
            args[1] = opts;
            args.splice(2);
        } else {
            // Console logger
            if (ctx && ctx.requestID) args[0] = `[RequestID=${ctx.requestID}] ${args[0]}`;
        }
    },

    defaultObjectPrinter: (o) => util.inspect(o, { showHidden: false, depth: 2, colors: false, breakLength: Number.POSITIVE_INFINITY }),
};

Then in moleculer-config.js:

    /// Register custom middlewares
    middlewares: ["SessionLoggingMiddleware"],

Using the AsyncLocalStorage to store the ctx means we can retrieve it in the newLogEntry and perform the steps needed to format the log entry and add the tracing info to the options. We also have a simpler entry when using the default console logger (still outputs the "session" id).

This in combination with the rootCallOptions feature added in #225 means we can link all of our applications together and they all use the same session id. This results in the whole chain of calls across actions and events over 5 or 6 applications is presented in a single place - a godsend for the operations team.

Thanks again to the contributors to the moleculer eco-system, we've found it to be great code with a great community.

[icebob]

Awesome, thanks for sharing!

[bmarchbank]

@synsteve @icebob

Hello,

I have a similar issue to the one described above and ran into an edge case that I hope one of you can help me with.

The solution provided works great whenever I make requests via the gateway service, however when I request with broker.call instead from another service (using AMQP transporter), the "localAction" hook in the middleware doesn't fire prior to the "before: *" hooks in the service's mixins. So whenever a "newLogEntry" event is triggered via a log in one of these mixin hooks, the context in the asyncLocalStorage is undefined. Once the mixin hooks finish and "localAction" kicks in, it works perfectly for all logs after that.

Any ideas/tips that could help me with this issue?

[icebob]

Try to reorder the middlewares. E.g: https://github.com/moleculerjs/moleculer/issues/971#issuecomment-923162702