Repository navigation
logging may send entries in incorrect order #2014
Description
Activity
Should we switch to
async.mapSeries?I don't think the problem is with
async.map. In my test-case,entriesis 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.writewas 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.writewas 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.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 towrite. 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.hrtimeis 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
insertIdas a way of ordering events with the same timestamp. This is supposed to be anEventIdvalue which is supposed to be a globally unique way of identifying an event across a network of services.
PR forthcoming.
@danoscarmike this probably also belongs on https://github.com/GoogleCloudPlatform/google-cloud-node/projects/5.
- added a commit that references this issue
on Mar 13, 2017 - added 2 commits that reference this issue
on Feb 24, 2026 - added a commit that references this issue
on Mar 11, 2026 - added a commit that references this issue
on Mar 18, 2026
Two successive calls to
Log.prototype.writeshould 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_: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 fromassignDefaultResource.