Winston adapter is broken

[shadz3rg]

Prerequisites

Please answer the following questions for yourself before submitting an issue.

• [x] I am running the latest version
• [x] I checked the documentation and found no answer
• [x] I checked to make sure that this issue has not already been filed
• [x] I'm reporting the issue to the correct repository

Current Behavior

Winston logger adapter can't log payload w/ more than 2 items.

Expected Behavior

Full message payload should be logged.

Failure Information

Steps to Reproduce

Simulate any error.

Reproduce code snippet

const winston = require("winston");
const {ServiceBroker} = require("moleculer");

const broker = new ServiceBroker({
    logger: {
        type: "Winston",
        options: {
            level: "debug",
            winston: {
                // More settings: https://github.com/winstonjs/winston#creating-your-own-logger
                transports: [
                    new winston.transports.Console(),
                    new winston.transports.File({ filename: "logs/moleculer.log" })
                ]
            }
        },
    },
});

broker.createService({
    name: "test",
    actions: {
        testMe: {
            params: {
                test: {type: "string"}
            },
            handler(ctx) {
                console.log('Test');
            }
        }
    },
});

broker.start()
    // Call the service
    .then(() => broker.call("test.testMe", {test: 123}));

Context

• Moleculer version: 0.14.4
• NodeJS version: 12.16.0
• Operating System: Ubuntu 20.04.1

Notes

It seems what winston doesnt support arguments spread, atleast i can't find it in current version. https://github.com/winstonjs/winston/blob/2625f60c5c85b8c4926c65e98a591f8b42e0db9a/lib/winston/logger.js#L179 https://github.com/moleculerjs/moleculer/blob/6e3e4d34ecbb951117ac240d6bcc5b3aab561a7f/src/loggers/winston.js#L71

With console.log(args) just before switch - output will be something like this:

[
  "The 'test.testMe' request is rejected.",
  { requestID: '80311be5-c87d-4e5f-9b6f-5a3725f6f77b' },
  ValidationError: Parameters validation error!
      at validateContextParams (/home/RANDOM_USER/Code/RANDOM_PROJECT/node_modules/moleculer/src/validators/base.js:75:37)
      at ServiceBroker.timeoutMiddleware (/home/RANDOM_USER/Code/RANDOM_PROJECT/node_modules/moleculer/src/middlewares/timeout.js:35:14)
      at ServiceBroker.fallbackMiddleware (/home/RANDOM_USER/Code/RANDOM_PROJECT/node_modules/moleculer/src/middlewares/fallback.js:29:11)
      at ServiceBroker.errorHandlerMiddleware (/home/RANDOM_USER/Code/RANDOM_PROJECT/node_modules/moleculer/src/middlewares/error-handler.js:14:10)
      at ServiceBroker.call (/home/RANDOM_USER/Code/RANDOM_PROJECT/node_modules/moleculer/src/service-broker.js:1089:31)
      at /home/RANDOM_USER/Code/RANDOM_PROJECT/src/test.js:36:21
      at processTicksAndRejections (internal/process/task_queues.js:97:5) {
    code: 422,
    type: 'VALIDATION_ERROR',
    data: [ [Object] ],
    retryable: false
  }
]
{"level":"debug","nodeID":"RANDOM_USER-desktop-233341","ns":"","mod":"broker","requestID":"80311be5-c87d-4e5f-9b6f-5a3725f6f77b","message":"The 'test.testMe' request is rejected."}

As we can see obj with requestID is logged as meta arg, actual error is skipped. Cant really propose a quick solution here since im not really a JS-dev (or PhD in configuring winston 😀).

[icebob]

I don't think, we can fix it, because it's not handled by Winston:

const { createLogger, format, transports } = require("winston");
const { combine, timestamp, label, json } = format;

const logger = createLogger({
    format: combine(
        label({ label: "right meow!" }),
        timestamp(),
        json()
    ),
    transports: [new transports.Console()]
});

logger.info("Something happened", { a: 5 }, { b: "John" });

[shadz3rg]

@icebob i ended up with custom logger on top of Winston adapter and args processing via util.format other loggers do that under the hood, so i think it is OK solution https://github.com/trentm/node-bunyan/blob/0ff1ae29cc9e028c6c11cd6b60e3b90217b66a10/lib/bunyan.js#L982

/**
 *
 * @param {object} bindings
 */
getLogHandler(bindings) {
    let level = bindings ? this.getLogLevel(bindings.mod) : null;
    if (!level)
        return null;

    const levelIdx = BaseLogger.LEVELS.indexOf(level);

    const logger = isFunction(this.opts.createLogger) ? this.opts.createLogger(level, bindings) : this.winston.child({ level, ...bindings });

    return (type, args) => {
        const typeIdx = BaseLogger.LEVELS.indexOf(type);
        if (typeIdx > levelIdx) return;

        const readableArgs = util.format(...args);

        switch(type) {
            case "info": return logger.info(readableArgs);
            case "fatal":
            case "error": return logger.error(readableArgs);
            case "warn": return logger.warn(readableArgs);
            case "debug": return logger.debug(readableArgs);
            case "trace": return logger.log("silly", readableArgs);
            default: {
                /* istanbul ignore next*/
                if (logger[type])
                    return logger[type](readableArgs);

                /* istanbul ignore next*/
                return logger.info(readableArgs);
            }
        }
    };
}

another solution is inspired by nest-js, but it requires strict(ish) arguments for each log level https://github.com/gremo/nest-winston/blob/ab030cf1b0678f163f0e490589ba5152131fafe6/src/winston.classes.ts