winston: Passing multiple parameters to logging functions doesn't behave as expected

This is a HUGE breaking change for us. If it is intentional, it should be detailed in https://github.com/winstonjs/winston/blob/master/UPGRADE-3.0.md

I understand major versions introduce breaking changes, but my goodness…

It’s disappointing that this issue still has not been resolved, and that my related issue has been locked.
I’m working with many different teams and they all share the frustration of losing previous DX when migrating to v3.

I’ve spent a whole day trying things out.
The above solutions were close but I was missing the colorization and line breaking of extra arguments.

IMO, logging to the Console should be delightful.
Here’s my attempt to make it happen…

v2 setup for comparison

const winston = require('winston');
const chalk = require('chalk');

const logger = new winston.Logger({
  transports: [
    new winston.transports.Console({
      level: 'info',
      colorize: true,
      prettyPrint: true,
      timestamp: true
    })
  ]
});

logger.info({ one: 1, two: 2, three: 3 });
logger.info(chalk.blue('[TEST]:'), { one: 1, two: 2, three: 3 }, [4, 5, 6]);
logger.info(chalk.blue('[TEST]:'), null, undefined, 'one', 2, { 3: 3, 4: '4' });
logger.info(chalk.blue('[TEST]:'), chalk.yellow('Bombastic'), () => {}, /foo/);
logger.error(chalk.blue('[ERR]:'), new Error('Error number 1'));
logger.error(new Error('Error number 2'));

v3 setup

const { createLogger, format, transports } = require('winston');
const { inspect } = require('util');
const chalk = require('chalk');
const hasAnsi = require('has-ansi');

function isPrimitive(val) {
  return val === null || (typeof val !== 'object' && typeof val !== 'function');
}
function formatWithInspect(val) {
  const prefix = isPrimitive(val) ? '' : '\n';
  const shouldFormat = typeof val !== 'string' || !hasAnsi(val);

  return prefix + (shouldFormat ? inspect(val, { depth: null, colors: true }) : val);
}

const logger = createLogger({
  level: 'info',
  format: format.combine(
    format.timestamp(),
    format.errors({ stack: true }),
    format.colorize(),
    format.printf(info => {
      const msg = formatWithInspect(info.message);
      const splatArgs = info[Symbol.for('splat')] || [];
      const rest = splatArgs.map(data => formatWithInspect(data)).join(' ');

      return `${info.timestamp} - ${info.level}: ${msg} ${rest}`;
    })
  ),
  transports: [new transports.Console()]
});

logger.info({ one: 1, two: 2, three: 3 });
logger.info(chalk.blue('[TEST]:'), { one: 1, two: 2, three: 3 }, [4, 5, 6]);
logger.info(chalk.blue('[TEST]:'), null, undefined, 'one', 2, { 3: 3, 4: '4' });
logger.info(chalk.blue('[TEST]:'), chalk.yellow('Bombastic'), () => {}, /foo/);
logger.error(chalk.blue('[ERR]:'), new Error('Error number 1'));
logger.error(new Error('Error number 2'));

There are many things to handle, some of which

• An Object-like value as the first argument
• Several arguments of mixed values
• Strings with ANSI escape codes, e.g. using chalk
• Esoteric values like Function and RegEx
• An Error as a first argument or anywhere after that
• Should still work fine alongside other formatters

Current bugs with this solution

• Passing an Error as the 1st argument does not print the Stack Trace
  • This is because info.message is just a string and the stack tract is in the stack property
• Passing an Object with a message property as the 1st argument only printsmessage, discarding any other properties
  • Same reason as the one above
• Passing an Error as the 2nd argument somehow concatenates the error message on top of info.message (which is usually the value of the 1st argument), resulting in seeing the error message twice
  • Tracked in https://github.com/winstonjs/winston/issues/1660
  • This is actually part of the README:

    NOTE: any { message } property in a meta object provided will automatically be concatenated to any msg already provided: For example the below will concatenate ‘world’ onto ‘hello’:

Playing around with the errors formatter didn’t help.

Positive enhancements

• Logging primitive values now gets prettified
• Logging several Object-like values now adds a newline between them
• Logging an Array is now prettified instead of looking like an Object with indices keys

---

Edit:

We can handle the errors formatting but it’s hacky:

function formatWithInspect(val) {
+ if (val instanceof Error) {
+   return '';
+ }

  const prefix = isPrimitive(val) ? '' : '\n';
  const shouldFormat = typeof val !== 'string' || !hasAnsi(val);

  return prefix + (shouldFormat ? inspect(val, { depth: null, colors: true }) : val);
}

...
    format.printf((info) => {
      const msg = formatWithInspect(info.message);
      const splatArgs = info[Symbol.for('splat')] || [];
      const rest = splatArgs.map((data) => formatWithInspect(data)).join(' ');
+    const stackTrace = info.stack ? `\n${info.stack}` : '';

      return `${info.timestamp} - ${info.level}: ${msg} ${rest}${stackTrace}`;
    })
...

This works for me. combineMessageAndSplat that combines message and splat using util.format

const winston = require("winston");
const util    = require('util');

const combineMessageAndSplat = () => {
    return {transform: (info, opts) => {
      //combine message and args if any
      info.message =  util.format(info.message, ...info[Symbol.for('splat')]  ||  [] )
      return info;
    }
  }
}

const logger = winston.createLogger({
  format:
    winston.format.combine(
      combineMessageAndSplat(),
      winston.format.simple()
    )
});

logger.add(new winston.transports.Console({
    level: 'info'
  })
);

logger.info("string");          // info: string
logger.info({a:1,b:[{c:[1]}]}); // info: { a: 1, b: [ { c: [Array] } ] }
logger.info("1","2",{a:1});     // info: 1 2 { a: 1 }
logger.info([{},""]);           // info: [ {}, '' ]
logger.error(new Error());      // error: Error ...    at Object.<anonymous> 

@indexzero Is this under your radar? I think this is a major breaking change. It actually prevents from moving from 2.x to 3.x as it requires us to change every log entry

I wanted a solution that supports %d, %o etc, but still defaults to including any rest arguments, so that logger.info('hello %d %j', 42, {a:3}, 'some', 'more', 'arguments') is rendered like this:

hello 42 {"a": 3} some more arguments

My solution for this ended up using the splat symbol but manually invoking util.format() directly from printf, which by default includes any rest arguments:

const {format} = require('util');
const winston = require('winston');
const {combine, timestamp, printf} = winston.format;
const SPLAT = Symbol.for('splat');

const transport = new winston.transports.Console({
    format: combine(
        timestamp(),
        printf(({timestamp, level, message, [SPLAT]: args = []}) =>
            `${timestamp} - ${level}: ${format(message, ...args)}`)
    )
})

If you don’t want printf you could of course instead add a transform that simply expands the args into info.message, and then format the end result the way you like:

format: combine(
  {
    transform(info) {
      const {[SPLAT]: args = [], message} = info;

      info.message = format(message, ...args);

      return info;
    }
  },
  simple()
)  

The problem with using format.splat() is that it consumes the matching arguments but seems to throw away the rest. By invoking util.format() myself I can override that behaviour.

Temporary workaround:

const wrapper = ( original ) => {
    return (...args) => original(args.join(" "));
};

winstonLogger.error = wrapper(winstonLogger.error);
winstonLogger.warn = wrapper(winstonLogger.warn);
winstonLogger.info = wrapper(winstonLogger.info);
winstonLogger.verbose = wrapper(winstonLogger.verbose);
winstonLogger.debug = wrapper(winstonLogger.debug);
winstonLogger.silly = wrapper(winstonLogger.silly);

I’ve solved it using something along these lines:

const { version } = require('../package');

const { createLogger, format, transports } = require('winston');
const { combine, timestamp, colorize, label, printf, align } = format;
const { SPLAT } = require('triple-beam');
const { isObject } = require('lodash');

function formatObject(param) {
  if (isObject(param)) {
    return JSON.stringify(param);
  }
  return param;
}

// Ignore log messages if they have { private: true }
const all = format((info) => {
  const splat = info[SPLAT] || [];
  const message = formatObject(info.message);
  const rest = splat.map(formatObject).join(' ');
  info.message = `${message} ${rest}`;
  return info;
});

const customLogger = createLogger({
  format: combine(
    all(),
    label({ label: version }),
    timestamp(),
    colorize(),
    align(),
    printf(info => `${info.timestamp} [${info.label}] ${info.level}: ${formatObject(info.message)}`)
  ),
  transports: [new transports.Console()]
});

So after some more investigation, I found that you need the splat formatter in order for multiple arguments to be printed. I thought that was just for argument interpolation (i.e. stuff with %s etc. in it), but it seems you need it just to do logger.info("something", value).

But this is still being a bit weird for me - I’m getting something that looks like JSON in the output with a key “meta”, even though I am not using a JSON format:

logger.info('Test: %s', 1, 2, 3, 4);

Produces:

info: Test: 1 {"meta":[2,3,4]}

Even the example in examples doesn’t produce what it says it will:

https://github.com/winstonjs/winston/blob/master/examples/interpolation.js#L20-L21

info: test message first, second {"meta":{"number":123}}

i am exploring winston to use in my project, now wondering is it worth taking the risk as this issue is open for more than 2 years. for me this seems like a basic function for any logging framework

When I try to log with arguments I get a weird output var s = "Hello" log.info("asdasda", s)

Getting the output

{"0":"H","1":"e","2":"l","3":"l","4":"o","service":"XXXX","level":"info","message":"asdasda","timestamp":"2019-04-15 13:58:51"}

I used the normal quick start code

Also waiting for proper way to emulate console.log(...args) in winston…

Really upsetting that they decided to make a breaking change this large and STILL have not mentioned it in the migration guide or the documentation.

Regardless I wanted to share my solution which I found quite compact and follows how node js implements console.log using util.format

const winstonLogger= createLogger(...);

const writeLogType = (logLevel) => {
    return function () {
        const args = Array.from(arguments);
        winstonLogger[logLevel](util.format(...args));
    };
};

const logger = {
    silly: writeLogType('silly'),
    debug: writeLogType('debug'),
    verbose: writeLogType('verbose'),
    info: writeLogType('info'),
    warn: writeLogType('warn'),
    error: writeLogType('error'),
};

At this point I have lost faith in winston project. I cant believe this issue is not embraced at all. I have switched from winston to pino to bunyan and back to winston and to winston 2. Winston is able to provide very important functionalities the other two cannot, however the disability to log multiple parameters and error is downright unacceptable. With pino, you cannot define a stackdriver service context and transform. With bunyan, you cannot transform the logs as well. With winston you cannot log more than 1 parameter. I am having a hard time believing these are all our ‘modern’ logger options in 2022.

To leave my bits I have put together the following winston configuration to accommodate both errors and multiple parameters in the logs. Thanks to BananaAcid’s reply above

const winston = require('winston');
const util = require('util');


const enumerateErrorFormat = winston.format(info => {
    if (info.message instanceof Error) {
      info.message = Object.assign({
        message: info.message.message,
        stack: info.message.stack
      }, info.message);
    }

    if (info instanceof Error) {
      return Object.assign({
        message: info.message,
        stack: info.stack
      }, info);
    }

    return info;
});

const logger = winston.createLogger({
    level: 'silly',
    format: winston.format.combine(
        enumerateErrorFormat(),
        {
            transform: (info) => {
                const args = [info.message, ...(info[Symbol.for('splat')] || [])];
                info.message = args;

                const msg = args.map(arg => {
                    if (typeof arg == 'object')
                        return util.inspect(arg, {compact: true, depth: Infinity});
                    return arg;
                }).join(' ');

                info[Symbol.for('message')] = `${info[Symbol.for('level')]}: ${msg}${info.stack ? ' ' + info.stack : ''}`;

                return info;
            }
        }
    )
});

logger.add(new winston.transports.Console())
logger.add(new winston.transports.File({filename: './logs.txt.'}));

logger.silly('hello silly', 1234, 'my condolence', {ahmet:1, meh:[{ahmet:1, meh:'alo'},{ahmet:1, meh:'alo'}]}, [{ahmet:1, meh:'alo'},{ahmet:1, meh:'alo'}]);
logger.debug('hello debug', () => console.log(1+2));
logger.info('hello info');
logger.warn('hello warn');
logger.error('hello error');
logger.error(new Error('error 1'), 123, new Error('error 2'));

it works for me using info[Symbol.for('splat')]

const logger = winston.createLogger({
    level: 'debug',
    transports: [
        ...
    ],
    format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.printf((info: any) => {
            const timestamp = info.timestamp.trim();
            const level = info.level;
            const message = (info.message || '').trim();
            const args = info[Symbol.for('splat')];
            const strArgs = (args || []).map((arg: any) => {
                return util.inspect(arg, {
                    colors: true
                });
            }).join(' ');
            return `[${timestamp}] ${level} ${message} ${strArgs}`;
        })
    )
});

Same issue, any update regarding this one? I love Winston, but it drives me crazy when I cannot print all arguments passed to the logger, which I can do with console.log().

@indexzero Was wondering if you were still planning to address this at some point?

Thanks to who posted the suggestions above. Damn I’ve thrown away one day just to integrate Winston 3 on my project 😕

Mine is a variation of @alexilyaev great suggestions:

const { omit } = require('lodash');
const hasAnsi = require('has-ansi');

function isPrimitive(val) {
  return val === null || (typeof val !== 'object' && typeof val !== 'function');
}
function formatWithInspect(val) {
  if (val instanceof Error) {
    return '';
  }

  const shouldFormat = typeof val !== 'string' && !hasAnsi(val);
  const formattedVal = shouldFormat
    ? inspect(val, { depth: null, colors: true })
    : val;

  return isPrimitive(val) ? formattedVal : `\n${formattedVal}`;
}

// Handles all the different log formats for console
function getDomainWinstonLoggerFormat(format) {
  return format.combine(
    format.timestamp(),
    format.errors({ stack: true }),
    format.colorize(),
    format.printf((info) => {
      const stackTrace = info.stack ? `\n${info.stack}` : '';

      // handle single object
      if (!info.message) {
        const obj = omit(info, ['level', 'timestamp', Symbol.for('level')]);
        return `${info.timestamp} - ${info.level}: ${formatWithInspect(obj)}${stackTrace}`;
      }

      const splatArgs = info[Symbol.for('splat')] || [];
      const rest = splatArgs.map(data => formatWithInspect(data)).join('');
      const msg = formatWithInspect(info.message);

      return `${info.timestamp} - ${info.level}: ${msg}${rest}${stackTrace}`;
    }),
  );
}

for logs like:

logger.info({
    joe: 'blow',
  });
  logger.info('Single String');
  logger.info('With Func ', () => {}, /foo/);
  logger.info('String One ', 'String Two');
  logger.info('String One ', 'String Two ', 'String Three');
  logger.info('Single Object ', {
    test: 123,
  });
  logger.info(
    'Multiple Objects ',
    {
      test: 123,
    },
    {
      martin: 5555,
    },
  );
  logger.error('Error: ', new Error('Boom!'));

It outputs like this - which is good for all my scenarios:

Hi there, huge Bumper and show stopper, trying to migrate to the 3.X, probably will keep the 2.x for a while.

A bit disappointed 😦

Related to:
https://github.com/winstonjs/winston/issues/1377

There’s just too many things that don’t work the same.

I had to conform to console.* methods, orientating on all above, and …

• default console methods (they colorize by default) for chrome-dev-tools
• electrons terminal console output (also colored by default)
• writing to a file

But: The file output should show object details.

So I ended up with:

// make File and FileList parseable // from: https://stackoverflow.com/a/51939522/1644202
File.prototype.toObject = function () {
    return Object({
        name: String(this.name),
        path: String(this.path),
        lastModified: parseInt(this.lastModified),
        lastModifiedDate: String(this.lastModifiedDate),
        size: parseInt(this.size),
        type: String(this.type)
    });
};

FileList.prototype.toArray = function () {
    return Array.from(this).map(function (file) {
        return file.toObject()
    });
};

// this fixes: winston console transport to use the original console functions and all the colorization/folding/etc that comes with it
const Transport = require('winston-transport');
class WebDeveloperConsole extends Transport {
    constructor(opts) {
        super(opts);
    }

    log(info, callback) {
        (window.console[info.level] || window.console.log).apply(window.console, [info.timestamp, ...info.message]);
        callback();
    }
};

// Electron app console output
class AppConsole extends Transport {
    constructor(opts) {
        super(opts);

        const { remote } = require('electron');
        this.electronConsole = remote.getGlobal('console');
    }

    log(info, callback) {
        (this.electronConsole[info.level] || this.electronConsole.log).apply(this.electronConsole, [info.timestamp, ...info.message]);
        callback();
    }
};

const util = require('util');
const {
    createLogger,
    transports,
    format
} = require('winston');

let logger = createLogger({
    level: 'trace',
    levels: {
        error: 0,
        warn: 1,
        info: 2,
        //http: 3,   no console.* methods
        //verbose: 4,
        debug: 3,
        trace: 4
    },

    format: format.combine(
        format.prettyPrint(),
        format.timestamp({
            format: 'DD-MM-YYYY hh:mm:ss A'
        }),

        {
            transform(info) {
                const { timestamp, message } = info;
                const level = info[Symbol.for('level')];
                const args = [message, ...(info[Symbol.for('splat')] || [])];  // join the args back into one arr
                info.message = args;  // for all custom transports (mainly the console ones)

                let msg = args.map(e => {
                    if (e.toString() == '[object FileList]')
                        return util.inspect(e.toArray(), true, 10);
                    else if (e.toString() == '[object File]')
                        return util.inspect(e.toObject(), true, 10);
                    else if (e.toString() == '[object Object]') {
                        return util.inspect(e, true, 5);
                    }
                    else if (e instanceof Error)
                        return e.stack
                    else
                        return e;
                }).join(' ');

                info[Symbol.for('message')] = `${timestamp} - ${level}: ${msg}`; // for inbuild transport / file-transport

                return info;
            }
        },
    ),
    transports: [
        //new transports.Console(),
        new WebDeveloperConsole(),
        new AppConsole(),
        ...
    ],
    ...
});

I still don’t understand how to output multiple values in Winston.

I just wanted to replace console.log('Hello', var1, '!') with logger.log('Hello', var1, '!').

To be honest, trying to use Winston always lead to a lot of time wasted and surprising problems with logging.

I want to share my winston setup:

const util = require('util');
const { createLogger, format, transports } = require('winston');
const { combine, colorize, timestamp, printf, padLevels} = format;

const myFormat = printf(({ level, message, label, timestamp, ...rest }) => {
	const splat = rest[Symbol.for('splat')];
	const strArgs = splat ? splat.map((s) => util.formatWithOptions({ colors: true, depth: 10 }, s)).join(' ') : '';
	return `${timestamp}  ${level}  ${util.formatWithOptions({ colors: true, depth: 10}, message)} ${strArgs}`;
});

const logger = createLogger({
	level: process.env.NODE_ENV === 'production' ? 'info' : 'debug',
	format: combine(
		colorize(),
		timestamp({
			format: 'YYYY-M-DD HH:mm:ss',
		}),
		padLevels(),
		myFormat
	),
	transports: [new transports.Console()],
});

logger.info('test info');
logger.error('test error');
logger.debug('test debug');

Here is a common workaround to allow for multiple parameters: https://github.com/rooseveltframework/roosevelt/blob/master/lib/tools/logger.js#L29

Meanwhile, I workaround this issue with the following code: Please note that I didn’t spend so much time on it so please test it carefully.

import { createLogger, format, transports } from "winston";
import { TransformableInfo } from "logform";

const prepareSplats = format((info: TransformableInfo): TransformableInfo => {
  const formatRegExp = /%[scdjifoO%]/g; // this line was copied from logform
  const splatSymbol = Symbol.for("splat") as unknown as string;

  const msg = info.message; // this line was copied from logform
  let splat = info[splatSymbol] || info.splat; // this line was copied from logform
  const tokens = msg && msg.match && msg.match(formatRegExp); // this line was copied from logform

  if (!tokens && (splat?.length)) {
    if (!(splat.length === 1 && typeof splat[0] === "object")) {
      splat = splat.map((v, index) => {
        return { [`arg_${index}`]: v };
      });
    }
  }

  return {
    ...info,
    [splatSymbol]: splat,
  };
});

export const log = createLogger({
  defaultMeta: { service: "your-service-name" },
  transports: [
    new transports.Console({
      level: "info",
      format: format.combine(
        format.timestamp({ format: "YYYY-MM-DD HH:mm:ss.SSS" }),
        format.ms(),
        format.errors({ stack: false }),
        prepareSplats(),
        format.splat(),
        format.json()
      ),
    }),
  ],
});

Is the only solution to use Pino or something other than Winston?

Well, patching Winston yourself as described in this thread is a viable solution. It is disappointing that something so major has to be fixed this way, but the framework is extensible enough to fix this way without forking, so there’s that.

I would like to chime in and request this feature to be added to the core Winston. Currently, I’m using the custom formatter with splat to achieve this functionality, which honestly feels very hacky. It would be nice to have functionality that matches console.log

Hey I’m starting with Winston, never used v2, so I’m on v3.2.1

I was trying to simply do:

import winston, { format } from 'winston';
winston.format(format.combine(format.splat(), format.simple()));

winston.info('buildFastify dataPath %s', opts.dataPath);

And hoping the string interpolation works; but nope.

{"level":"info","message":"buildFastify dataPath %s"}

When I was expecting

{"level":"info","message":"buildFastify dataPath /My/Data/Path"}

This issue is the same thing somehow? Or I’m forced to use the logger.log('info', .....) function instead?

Edit

Event trying this doesn’t work.

  winston.log('info', 'buildFastify dataPath %s', opts.dataPath);

output:

{"level":"info","message":"buildFastify dataPath %s"}

This is what worked for me:

const { format, createLogger, transports } = require('winston');
const jsonStringify = require('fast-safe-stringify');

const logLikeFormat = {
  transform(info) {
    const { timestamp, label, message } = info;
    const level = info[Symbol.for('level')];
    const args = info[Symbol.for('splat')];
    const strArgs = args.map(jsonStringify).join(' ');
    info[Symbol.for('message')] = `${timestamp} [${label}] ${level}: ${message} ${strArgs}`;
    return info;
  }
};

const debugFormat = {
  transform(info) {
    console.log(info);
    return info;
  }
};

const logger = createLogger({
  format: format.combine(
    // debugFormat, // uncomment to see the internal log structure
    format.timestamp(),
    format.label({ label: 'myLabel' }),
    logLikeFormat,
    // debugFormat, // uncomment to see the internal log structure
  ),
  transports: [
    new transports.Console()
  ]
});


logger.info('foo', 'bar', 1, [2, 3], true, { name: 'John' });

which results in: 2019-07-04T21:30:08.455Z [myLabel] info: foo "bar" 1 [2,3] true {"name":"John"}

Basically format.combine sets a pipeline for an info object. For each format function, transform is called and the final log message should be written to info[Symbol.for('message')] hope this helps