logging may send entries in incorrect order

Two successive calls to Log.prototype.write should preserve the order of the log entries, as written to the Logging service. I am noticing my log entries showing up out of order.

I think the problem is due to the async behaviour in Log.prototype.decorateEntries_:

Log.prototype.decorateEntries_ = function(entries, callback) {
  var self = this;

  async.map(entries, function(entry, callback) {
    if (!(entry instanceof Entry)) {
      entry = self.entry(entry);
    }

    var decoratedEntry = entry.toJSON();
    decoratedEntry.logName = self.formattedName_;

    self.metadata_.assignDefaultResource(decoratedEntry, function(err, entry) {
      // Ignore errors (the API will speak up if it has an issue).
      callback(null, entry || decoratedEntry);
    });
  }, callback);
};

Two successive calls to the above, within the timer resolution of JavaScript Date.now() (i.e. having the same timestamp), may get written to the network out of order depending on which log entry gets called back first from assignDefaultResource.

Should we switch to async.mapSeries?

I don't think the problem is with async.map. In my test-case, entries is always a single element array.

Ah, right. I misunderstood the first read over. So, probably better to capture the timestamp at the top of the function, and manually assign to all created entries within async.map?

I don't think it is related to the capture of the timestamp. Imagine two entries that are supposed to get the same timestamp because log.write was called successively twice. They should have the same timestamp.

It is the fetch of the default resource potentially from the network that adds non-determinism here. I think we will need to remove this non-determinism from the path somehow.

As a developer, I would not expect these to have the timestamp:

log.write('...', function() {})
log.write('...', function() {})

If log.write was completely sync, it's still possible to have different timestamps on two different lines of code. For cases that require that certainty, they should remove the uncertainty and manually assign the appropriate timestamp onto their entries. Please correct me if I'm missing something.

BTW, here's the test: https://github.com/GoogleCloudPlatform/google-cloud-node/pull/1997/files#diff-4becf23148fef29d25428567c8d33fc7.

In the example you posted, there is no notion of a timestamp. As a developer I wouldn't care how the logging library deals with things internally, I would just want my log entries to show up in the logging service in the correct order.

Given the coarse granularity of Date.now() in JavaScript, it is quite possible that those two successive lines, even if they are synchronous, would have the exact same timestamp.

Perhaps the solution here is to use a high resolution timer?

Given the coarse granularity of Date.now() in JavaScript, it is quite possible that those two successive lines, even if they are synchronous, would have the exact same timestamp.

I would not expect that. I would relate to it being inconvenient and unfortunate, but that is the language we're working with. There isn't a guarantee between any two lines of code that the timestamp will be the same, and I expect a developer of the language to be aware of that.

My suggestion above about capturing the timestamp at the head of the function would guarantee they show up in the right order. Doesn't that accomplish what we're going for?

I don't think capturing the timestamp at the head of the function as you propose would solve the problem of log entries showing up in the wrong order. But perhaps I am misunderstand what you are proposing.

Log.prototype.decorateEntries_ = function() {
  var now = Date.now()

  // first async call, things can start getting out of order,
  // but the timestamp was already captured
  async.map(...
}

Log.prototype.write = function() {
  // all sync executions
  this.decorateEntries_(...
}

log.write() // calls decorateEntries_ first, gets earlier timestamp
log.write() // calls decorateEntries_ second, gets later timestamp

Right, but there is no guarantee that 'earlier' timestamp is different from 'later' timestamp. It is quite likely it is going to be the same timestamp.

Let me ponder this over and see if there is a better solution.

Okay, it looks like I got tripped up again, and thought we were trying to ensure the ordering of calls to log.write() was preserved, and not trying to force different timestamps on each call to write. If we're not currently capturing a timestamp of enough specificity, that sounds like the easiest solution, but do please ponder!

After a bit of pondering and talking to various people, including the Logging API folks, I have some observations:

The Logging API service does not guarantee that the insertion order of log entries with the same timestamp will be preserved. This means that even if we got rid of the non-determinism in writing the log entries to the network, the service may reorder them anyway. In other words, fixing non-determinism doesn't help – we need to provide proper metadata on the entries themselves via timestamps or other mechanism to communicate sequential ordering to the Log service.
JavaScript Date only has a millisecond resolution. V8 implements this using using a higher resolution timer but this is not exposed to JavaScript.
process.hrtime is higher resolution, but it is relative to arbitrary epoch rather than Unix epoch. We need time relative to Unix epoch to use as the timestamp here. No other higher resolution timers relative to unix epoch are exposed by either Node or V8.
There are native modules in the ecosystem (e.g. microtime) that expose microsecond resolution. 1) I would loathe to add a native module as a dependency as that adds frictions for our users. 2) Microsecond resolution on the timer would reduce the probability of a collision on the timestamp, but they would still be possible.
The service does use insertId as a way of ordering events with the same timestamp. This is supposed to be an EventId value which is supposed to be a globally unique way of identifying an event across a network of services.

PR forthcoming.

Add insertId on log entries

@danoscarmike

@danoscarmike this probably also belongs on https://github.com/GoogleCloudPlatform/google-cloud-node/projects/5.

Add insertId on log entries

feat: Query Profile (#2014)

feat: add functionality for passing preconditions at the function lev…

fix(deps): update dependency @opentelemetry/semantic-conventions to ~…

feat: add functionality for passing preconditions at the function lev…

Navigation Menu

Repository navigation

logging may send entries in incorrect order #2014

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

logging may send entries in incorrect order #2014

Description

Activity

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 22, 2017

stephenplusplus commented on Feb 22, 2017

ofrobots commented on Feb 24, 2017

ofrobots commented on Feb 27, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions