Google-cloud-node: logging-winston: use custom serialization

[stephenplusplus]

Could you take a look at this system test that is failing?

• Build

 1) LoggingWinston log should properly write log entries:

      Uncaught AssertionError: '2017-04-13T13:18:30.003Z' === 'Thu Apr 13 2017 13:17:08 GMT+0000 (UTC)'
      + expected - actual

      -2017-04-13T13:18:30.003Z
      +Thu Apr 13 2017 13:17:08 GMT+0000 (UTC)

      at Object.testData.verify (system-test/logging-winston.js:63:18)
      at system-test/logging-winston.js:104:20
      at Array.forEach (native)
      at system-test/logging-winston.js:102:14
      at node_modules/@google-cloud/logging/src/index.js:314:14

[ofrobots]

Curious... seems to be passing for me.

[stephenplusplus]

Alright, you can close this if you can't find anything flaky about the test, then if the problem shows up again on CI, we'll just re-open.

[ofrobots]

Let me stare at the code for a bit.

[ofrobots]

I am really puzzled by this. The test is:

var testTimestamp = new Date();
//...
assert.strictEqual(
    entry.metadata.labels.testTimestamp,
    util.inspect(testTimestamp)
);

Even if it is a flake, I am quite puzzled how util.inspect(testTimestamp) managed to format it as Thu Apr 13 2017 13:17:08 GMT+0000 (UTC). util.inspect should use the ISO form.

Do you have objections to pre-emptively adding a debug print to catch some more info if it flakes again?

[stephenplusplus]

Looks like that's a new thing:

$ node
> process.version
'v4.8.2'
> util.inspect(new Date())
'Thu Apr 20 2017 12:30:34 GMT-0400 (Eastern Daylight Time)'

[ofrobots]

Okay, it makes a lot more sense now.

It is definitely a flake in that case. It seems that we are retrieving the log entries from previous system-test run. That is, a node 4 run is fetching the entries from a preceding node 6/7 run.

The delay is already set to 90 seconds, should we increase it?

[stephenplusplus]

I suppose so :( Does any source code need to be touched to make sure the behavior of the new util.inspect() is passed to the API, even in Node v4 envs, or no big deal?

[ofrobots]

The contract we have is that we will format metadata attached to winston log entries using util.inspect. Whatever behaviour util.inspect has with a given node version is the behaviour we should follow. So, no, I don't think source code needs to be touched.

[stephenplusplus]

I can see your point, but I worry that will set them up for the same confusion we just had when they inevitably upgrade Node or simply try to write an app that handles consistently-formed data from a log that has writers from multiple environments. Assuming Logging's job is to take input, stringify it, and send it to the API, it seems like a bug that we would do that differently depending on what version of Node is running.

The "contract" part is a bit more weighted now that we have gone 1.0 with Logging. If you don't think we should guarantee a consistent API message across multiple Node versions (which we could call a bug fix, as opposed to a breaking change), then go ahead and bump the delay of the system test and we'll see if we get better results.

[ofrobots]

logging-winston should follow winston conventions. Winston also formats data using util.inspect: https://github.com/winstonjs/winston#logging-with-metadata.

[stephenplusplus]

Sorry, thought your earlier link was to the Logging class. So, sure, LW can do what it pleases. I am still a bit curious for a reason why you wouldn't want your data to be consistent between Node versions. It's good to be consistent with Winston, but maybe Winston hasn't considered the difference that the new inspect introduced. Are you not concerned?

[ofrobots]

I think we have to trade-off when users get surprised:

1. When users decide to migrate between node major versions they might notice that their Date objects are formatted differently, for logging-winston, and everywhere else.
2. When users attach the stackdriver logging to their existing winston loggers, they might get surprised to notice that logging-winston is formatting dates differently than winston does locally.

Neither are exceptional options, but given that it is Node.js-core that changed behaviour, the former is a better option IMO.

[stephenplusplus]

Is this a change in util.inspect or the stringifying of Date? My proposal isn't to deviate from what winston does, but question if they should be encoding user input consistently, independent of Node version. You're more experienced with the library and process, so I'm trying to separate your concern for the problem vs. how we handle it. If it's not a problem that they are encoding differently depending on Node version, then I'll also drop my concern.

From my inexperienced view, it's not obvious to me that this is what a user would expect-- the user never asked for "util.inspect", they just asked for their data to be serialized. And I think they would expect the library to do it "one way".

[ofrobots]

Upon your prompting I looked further into the default behaviour of winston. It turns out that the docs are a lie. winston doesn't util.inspect by default – that's used only when prettyPrint option is specified.

$ nvm run 6 date.js
Running node v6.10.0 (npm v3.10.10)
info: hello ts=Thu Apr 20 2017 18:12:29 GMT-0700 (PDT)

$ nvm run 4 date.js
Running node v4.8.0 (npm v2.15.11)
info: hello ts=Thu Apr 20 2017 18:12:33 GMT-0700 (PDT)

With prettyPrint:

$ nvm run 6 date.js
Running node v6.10.0 (npm v3.10.10)
info: hello
{ ts: 2017-04-21T01:12:10.255Z }

$ nvm run 4 date.js
Running node v4.8.0 (npm v2.15.11)
info: hello
{ ts: Thu Apr 20 2017 18:12:20 GMT-0700 (PDT) }

The default behaviour in the Console transport is to coerce the Dates to a string: https://github.com/winstonjs/winston/blob/fcf04e1dece55ec1dd100e4a8a2cdcda91146e74/lib/winston/common.js#L358.

I am not sure if we should special case Date to paper over the Node version differences as it might end up being a rabbit hole of quite a few differences across other types too.

A better solution would be to make util.inspect optional (default: false) and let common-grpc do the serialization. This would be a semver major change, but we are still in the 0.x, so still doable.

WDYT?

[ofrobots]

BTW, here's the change in Node that changed the behaviour of util.inspect: https://github.com/nodejs/node/issues/4314

[stephenplusplus]

A better solution would be to make util.inspect optional (default: false) and let common-grpc do the serialization. This would be a semver major change, but we are still in the 0.x, so still doable.

That sounds good to me, and thank you for digging into this.

[ofrobots]

That sounds good to me, and thank you for digging into this.

Thank you for being a good advocate for consistent behaviour for users :).

[stephenplusplus]

🎖 Teamwork! 🏆