logging may send entries in incorrect order

[ofrobots]

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.

[stephenplusplus]

Should we switch to async.mapSeries?

[ofrobots]

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

[stephenplusplus]

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?

[ofrobots]

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.

[stephenplusplus]

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.

[ofrobots]

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

[ofrobots]

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?

[stephenplusplus]

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?

[ofrobots]

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.

[stephenplusplus]

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

[ofrobots]

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.

[stephenplusplus]

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!