logging-winston: use custom serialization

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

Curious... seems to be passing for me.

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.

Let me stare at the code for a bit.

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?

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)'

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?

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?

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.

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.

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

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

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.

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

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

🎖 Teamwork! 🏆

logging-winston: metadata serialization

feat: Enable tracing via OpenTelemetry. (#2218)

Navigation Menu

Repository navigation

logging-winston: use custom serialization #2218

4 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

logging-winston: use custom serialization #2218

Description

Activity

ofrobots commented on Apr 20, 2017

stephenplusplus commented on Apr 20, 2017

ofrobots commented on Apr 20, 2017

ofrobots commented on Apr 20, 2017

stephenplusplus commented on Apr 20, 2017

ofrobots commented on Apr 20, 2017

stephenplusplus commented on Apr 20, 2017

ofrobots commented on Apr 20, 2017

stephenplusplus commented on Apr 20, 2017

ofrobots commented on Apr 20, 2017

4 remaining items

ofrobots commented on Apr 21, 2017

stephenplusplus commented on Apr 21, 2017

ofrobots commented on Apr 21, 2017

stephenplusplus commented on Apr 21, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions