Can not log variables that are null or undefined

[dagerikhl]

Hello! I'm having an issue with logging variables if I expect them to sometimes be null or undefined.

I am using a custom formatter, but disabling this does not fix the problem.

Error when console.log()-ing the error:

TypeError: Cannot read property 'message' of undefined
    at DerivedLogger.(anonymous function) [as debug] (<...>\node_modules\winston\lib\winston\create-logger.js:43:26)

And from my logger logging its own error,:

15:52:25 error: Cannot read property 'message' of undefined

Steps to reproduce

1. Call a winston logger with an undefined variable or object, e.g. logger.debug(null); or let myVar = undefined; logger.info(myVar);.

Expected behaviour

1. Winston logs the error according to all the formats applied to it.
2. Execution continues.

Actual behaviour

1. Winston logs a Cannot read property 'message' of null/undefined error.
2. Execution halts.

System info

• Windows 10
• NodeJS v. 8.9.1
• npm v. 5.6.0
• winston v. 3.0.0-rc1

[DABH]

Sorry, does this also happen with the latest rc (3.0.0-rc5)? If so, any chance you can show us how your logger and transports are setup/defined?

[indexzero]

@DABH instincts are correct – this appears to be a duplicate of #1224, which was fixed in [email protected] (see: #1224 (comment))

... please let us know if the problem persists after upgrading.

[dagerikhl]

Updating winston to 3.0.0-rc5 does in fact fix the error, or rather: make another error in my own code apparent. Updating just made the error go silent, because errors happening within my formatter code was not printed (see below).

So there was en error with rc1, but it's fixed now, thanks!

This is also made apparent by the fact that format.json() is now working with logger.debug(null);.

(Sorry @indexzero, didn't find that issue before posting!)

My error

In case anyone else comes across the same error. Rookie mistake, I know, but see "Something odd" below for why I didn't catch this.

The error I had in my code was calling:

Object.keys(info.message);

when info.message could be null without null-checking it.

Something odd

This however, did not log any errors, which is odd, and made the mistake hard to spot and fix. My code is definitively wrong, but shouldn't this log an error, at least to the console? This might also be something to do with how Object.keys() is impl., and not winston.

Specifically, when calling logger.debug(null); this code produces no errors and stops execution:

const myFormat = format.printf((info) => {
    console.log(info.message);
    let t = Object.keys(info.message);
    return info.message;
}

And outputs to console:

null

While this code produces an error (as one would expect) and stops execution:

const myFormat = format.printf((info) => {
    console.log(info.message);
    let t = Object.keys(null);
    return info.message;
}

With this output to console:

D:\Git\Private\DdSG_Server\logger.js:8
   let t = Object.keys(null);
                  ^

TypeError: Cannot convert undefined or null to object
   at Function.keys (<anonymous>)
   at Printf.format.printf [as template] (<...>\logger.js:8:20)
   at Printf.transform (<...>\node_modules\logform\printf.js:15:26)
   at Format.cascaded [as transform] (<...>\node_modules\logform\combine.js:34:24)
   at DerivedLogger._transform (<...>\node_modules\winston\lib\winston\logger.js:229:25)
   at DerivedLogger.Transform._read (_stream_transform.js:186:10)
   at DerivedLogger.Transform._write (_stream_transform.js:174:12)
   at doWrite (_stream_writable.js:387:12)
   at writeOrBuffer (_stream_writable.js:373:5)
   at DerivedLogger.Writable.write (_stream_writable.js:290:11)

Setup

For completeness, here's my logger setup (logger.js.):

const winston = require('winston');

const format = winston.format;

const myFormat = format.printf((info) => {
    const timestamp = (new Date()).toLocaleTimeString();

    let parsedMessage;
    if (/*info.message && <ADDED NOW>*/typeof info.message !== 'string' && Object.keys(info.message).length > 1) {
        parsedMessage = `\n${JSON.stringify({ ...info.message }, null, 2)}`;
    } else if (typeof info.message !== 'string') {
        parsedMessage = `${JSON.stringify(info.message)}`;
    } else {
        parsedMessage = info.message;
    }

    let logMessage = `${timestamp} ${info.level}: ${parsedMessage}`;

    return logMessage;
});

const logger = winston.createLogger({
    level: 'info',
    format: format.combine(format.colorize(), myFormat),
    transports: [
        new winston.transports.Console({
            level: 'silly'
        }),
        new winston.transports.File({
            filename: 'error.log',
            level: 'error'
        }),
        new winston.transports.File({
            filename: 'combined.log'
        })
    ]
});

global.logger = logger;

[indexzero]

@dagerikhl thanks for the detailed repro – what you've described is #1261, which is one of the last "show stopper" important bugs for us to fix before the May 29th release for 3.0.0 proper. If you have thoughts on the best way to handle user generated errors within formats commenting on #1261 is the best place. Thanks again!

[dagerikhl]

Wow, I'm really nailing it with the searches! Thanks for clearing that up, and thanks for the help. If I think of some way to handle it, I'll be sure to comment.