logger crashes on moment.js object ( TypeError: config._d.getTime is not a function )

[carchrae]

Related issues

arguably, this is a bug with moment.js - but i'm not certain who should fix :
moment/moment#5011

[REQUIRED] Version info

node: 12 and 14

firebase-functions: 3.14.1

firebase-tools: 9.14.0

firebase-admin: 9.9.0

moment: 2.29.1

[REQUIRED] Test case

const functions = require('firebase-functions').logger;
const moment = require('moment');

console.log('this works', { m : moment() } );
console.log('this works too!', JSON.stringify({ m: moment() } ));

logger.info('wat!  this blows up!', { m : moment() } );
logger.info('but this works!', moment());

[REQUIRED] Steps to reproduce

simply run the test case

[REQUIRED] Expected behavior

logger should allow logging of moment object.

[REQUIRED] Actual behavior

note: this happens locally as well as when deployed

TypeError: config._d.getTime is not a function
    at new Moment (/workspace/node_modules/moment/moment.js:258:58)
    at Object.clone (/workspace/node_modules/moment/moment.js:3756:16)
    at Object.toISOString (/workspace/node_modules/moment/moment.js:3916:28)
    at Object.toJSON (/workspace/node_modules/moment/moment.js:4247:38)
    at JSON.stringify (<anonymous>)
    at write (/workspace/node_modules/firebase-functions/lib/logger.js:39:84)
    at Object.info (/workspace/node_modules/firebase-functions/lib/logger.js:81:5) 

Were you able to successfully deploy your functions?

yes

[google-oss-bot]

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

[carchrae]

fwiw, i suspect the problem is with removeCircular somehow destroying the moment object:

firebase-functions/src/logger.ts

Line 33 in 4028acc

function removeCircular(obj: any, refs: any[] = []): any {

[carchrae]

btw a workaround is to simply never try to log a moment object. eg, always call moment.format() or moment.toDate()

[i14h]

thanks @carchrae for reporting this. @joehan can you please take a look into this?

[joehan]

Digging into this a bit, I think I see the issue. In removeCircular, we loop through all properties of the object and overwrite ones containing circular references with the string '[circular]'. For moment(), this ends up overwriting_d. JSON.stringify() calls moment().toJSON, which (after chaining through a few other functions), eventually tries to call _d.getTime. Since this has been overwritteb, this breaks

Gonna write up a quick fix to make this not break horribly, but in general this code is not well suited for complex objects that contain functions. To anyone else running into this issue or similar ones, I think @carchrae's solution of always calling moment.format() or moment.toDate() is still a good practice.

[carchrae]

i appreciate not wanting to mess things up for currently deployed applications that rely on removeCircular. would be be a horrid idea to allow removeCircular to be disabled or customised? imho people logging objects with circular references are asking for trouble in the first place ;) - tho i appreciate util.inspect used to do something similar and i guess this is what you're trying to maintain.

the sad part for me, in terms of dev experience, is this blew a bunch of time. the other logging tools i used had no problem with moment - but i suspect they don't even try to handle circular refs.

one fix, with some performance cost is to wrap all calls to logger with something that transforms the object with JSON.parse(JSON.stringify(o)) - maybe that could that be used as a fallback too, or in some 'slow-but-more-robust' logger mode?

fwiw, there should absolutely be more care taken when logging in production (so many wasted cycles go there), but when debugging something i was just trying to dump state and got the strange error.

[mdinos]

Perhaps tangentially related, the logger doesn't seem to handle plain old Date objects either:

@carchrae's suggestion of JSON.parse(JSON.stringify(o)) seems to do the trick as a workaround:

[fahu]

This bug seems to be introduced with v3.14. I used to log moment objects in version 3.13 and all worked fine. With version 3.14.1 it produces the above mentioned issue.

[joehan]

Hey all, I think this should be fixed after the PR is merged + released. This will go out in 3.15.0 - if you still face this issue after that point, please let me know!