Winston: `this._addDefaultMeta` is not a function

[errietta]

Please tell us about your environment:

• _winston version?_
  
  
  
  • [ ] winston@2
  
  
  • [x] winston@3
  
  
• _node -v outputs:_ 8.9.3
• _Operating System? Linux & Mac
• _Language?_ Es6

What is the problem?

Since the 3.2.0 release we are getting the following:

error: this._addDefaultMeta is not a function {"stack":"TypeError: this._addDefaultMeta is not a function\n    at APIClient.(anonymous function) [as logger] (/Users/erriettakostala/prototype1/server/node_modules/winston/lib/winston/create-logger.js:55:16)\n  

We're just calling log the same way as before.

  const logger = winston.createLogger({
    level: process.env.LOG_LEVEL || 'debug',
    format: process.env.NODE_ENV === 'production' ? winston.format.json() : winston.format.simple(),
    transports: [ new winston.transports.Console() ]
  })

logger.log({
  level: 'info',
  message: ''
});

What do you expect to happen instead?

The code to not crash :-)

[errietta]

So it might be our fault. I can only reproduce this if we do:

const log = logger.debug;
log('test');

logger.debug('test') is fine

[kibertoad]

Right, so it happens due to function not being bound to this in such use-case. Not sure if that is correct usage as there is no promise for any of logger functions to be stateless pure functions. It will also work if you do const log = logger.debug.bind(logger)

[tominek]

I am not sure in this case, as such a use case could be typical when using winston as custom logger. In my case I am using it as custom logger for SailsJS and until 3.2.0 everything was working fine :-/

My code:

const logger = createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: combine(timestamp(), format.json()),
  transports: [new transports.Console()],
})

module.exports.log = {
  custom: logger,
}

[kibertoad]

I guess we need to use arrow function there, it autobinds. Will try to come up with a PR for that ASAP.

[kibertoad]

Quick'n'straighforward attempt to fix seems to break stuff. More investigation needed.

You can see it here: https://github.com/kibertoad/winston/tree/fix/autobind-for-functions

If you have an idea why would that break child logger functionality, I would be glad to hear that.

[errietta]

is it because child does const logger = this; ?
(totally throwing stuff to the wall)

[indexzero]

Howdy folks – thanks for reporting this. I had noticed it in passing when writing an unrelated test for 3.2.0, but didn't realize it was a regression from 3.1.0.

The regression itself was introduced in #1483. Very thankful @soldair added test coverage for the scenario because fixing this would have introduced another regression without it <3.

1579 is an attempt to fix this issue. Currently it appears to be neutral from a performance perspective _(yay)_, but unfortunately not the most obvious, straight-forward, or otherwise "elegant" solution _(boo)_.

Given that https://github.com/winstonjs/winston/pull/1539 was overlooked for 3.2.0, if we can get some 👀👀👀from folks on #1579 and they are 👍then we should be in good shape to push out 3.2.1 tomorrow 💯✨🎉

[anton-bot]

Perhaps a related error that I am seeing:

Cannot read property '_addDefaultMeta' of undefined

[indexzero]

Yes. It is the same error. Thanks for reporting!

[ColinMorris83]

Am still getting similar issue after updating to 3.2.1. Am using NestJS and have a custom logger service which creates a logger and then assigns class properties to map against the logger methods.
e.g.
const logger = winston.createLogger(....);
this.log = logger.log;
this.error = logger.error;
this.warn = logger.warn;

etc.

When trying to log, get TypeError: this.write is not a function
Tried changing to
this.error = logger.error.bind(logger);

Which now will log without any error, but is then not logging the metadata.
e.g log.error('aaa', { abc: 'abc' }) will just output 'aaa' and nothing else.

[kibertoad]

@ColinMorris83 Could you create a PR with failing test in https://github.com/winstonjs/winston/blob/master/test/logger.test.js? (something similar to defaultMeta() autobinds correctly I would imagine)
I wonder how different is your case from the one covered by test (which works).

[ColinMorris83]

Hi @kibertoad,
I can create a failing test with the following, although it's not the same error I actually get when using it in Nest.
I added this to the bottom of logger.test.js

it('defaultMeta() autobinds correctly when using a class', () => {
    class LoggingService {
      constructor() {
        var logger = winston.createLogger({
          level: 'info',
          exitOnError: false,
          transports: []
        });
        this.info = logger.info;
      }
    }

    const service = new LoggingService();
    service.info('test');
  });

Which gives following:
1) Should support child loggers & defaultMeta
defaultMeta() autobinds correctly when using a class:
Uncaught TypeError: self._addDefaultMeta is not a function
at LoggingService.DerivedLogger.(anonymous function) [as info] (lib/winston/create-logger.js:39:371)
at Context.it (test/logger.test.js:1096:13)

Changing the line to this.info = logger.info.bind(logger); makes the test pass. However, then I think that will lead to next issue of metadata not outputting, but I'm not sure how to test for that in the unit test

[indexzero]

There are an almost endless number of permutations of this binding that can take place. The officially supported ones are:

1. A Logger instance.
2. None

e.g. for your failing test you could have either had LoggingService inherit from Logger e.g:

Use Object.create

it('defaultMeta() autobinds correctly when using a class', () => {
  var logger = winston.createLogger({
    level: 'info',
    exitOnError: false,
    transports: []
  });

  const service = Object.create(logger);
  service.info('test');
});

Properly bind this

it('defaultMeta() autobinds correctly when using a class', () => {
  class LoggingService {
    constructor() {
      var logger = winston.createLogger({
        level: 'info',
        exitOnError: false,
        transports: []
      });

      // Either bind to the logger
      this.info = logger.info.bind(logger);

      // Or pass through the arguments
      this.info = (...args) => logger.info(...args);
    }
  }

  const service = new LoggingService();
  service.info('test');
});

if your code was working previously it was an unintended side-effect of the larger regression not being resolved. This was a tricky thing to get right.

[ColinMorris83]

Thanks @indexzero
So if changing to bind to the logger like this:
this.info = logger.info.bind(logger);

After doing this the metadata does not get output, is that a bug or am I using it wrong.
e.g. in my case above it would have been:

service.info('test', { somemeta: 'something' });

[indexzero]

Understood. Perhaps I was wrong. The second technique will absolutely work:

it('defaultMeta() autobinds correctly when using a class', () => {
  class LoggingService {
    constructor() {
      var logger = winston.createLogger({
        level: 'info',
        exitOnError: false,
        transports: []
      });

      // Pass through the arguments
      this.info = (...args) => logger.info(...args);
    }
  }

  const service = new LoggingService();
  service.info('test');
});

[ColinMorris83]

Still have no metadata logged when using the pass through way too.
Perhaps it could be my format function needs updating, as when I console log the info object coming into it, it does not have a meta property.

const formatFunction = (info) => {
      const logMessage = `${info.timestamp} [${info.level}] ${(info.message ? info.message : '')}
      ${(info.meta && Object.keys(info.meta).length ? `\n${JSON.stringify(info.meta, null, 2)}` : '')}`;
      return logMessage.replace(/\n(?=\S)/g, '\n ');
    };

The info object is this:

{ somemeta: 'something',
  level: '\u001b[32mINFO\u001b[39m',
  message: 'App is running:',
  timestamp: '2019-01-30T14:17:46.850Z',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ { somemeta: 'something' } ] }

[indexzero]

I suspect this is unrelated if we are down to the level of debugging your format function.

[sapsaldog]

the worst thing related this issue is when you write data on databases by waterline ORM. I ended up giving up using mixing winston.js and sails.js,

sorry I've got the wrong number. :(

I should write this comment on another issue

[kibertoad]

@sapsaldog This sounds to me like something that sails.js should address, not winston.

[ColinMorris83]

I suspect this is unrelated if we are down to the level of debugging your format function.

Yep I think probably unrelated to the initial issue, although I suspect could be a bug introduced somewhere since on 3.1.0 the info object had a meta property, from 3.2.0 it's not there. I will try to find some time to see if it all works ok when using winston as a normal required module, taking the use of classes and NestJs out of the equation.

[indexzero]

Not a bug. By design. Breaking change from logform@1 to logform@2. See: https://github.com/winstonjs/logform/blob/master/CHANGELOG.md#new-splat-behavior

The behavior was inconsistent, opted to spread all properties. It you want to "unspread" use https://github.com/winstonjs/logform#metadata

[ColinMorris83]

Yep, just saw that stuff in the changelog, I'll take a look at the metadata docs you linked too. Thanks