From 7d98a5dbebcbe0d1c154977c0fe6d616952f8244 Mon Sep 17 00:00:00 2001 From: Atul Varma Date: Wed, 11 Jun 2008 18:58:30 -0700 Subject: [PATCH] Added a few log messages to hopefully make the debugging of generators easier. Also added an id component to generators, which is part of their name, to help distinguish between concurrent instances of the same generator function. The following debug output represents the new logging infomation: -- Async.Generator DEBUG runTestGenerator-0: self.cb generated at test_async_missing_yield.js:28 Async.Generator DEBUG secondGen-1: self.cb generated at test_async_missing_yield.js:20 Async.Generator DEBUG secondGen-1: done() called. Async.Generator DEBUG runTestGenerator-0: self.cb() called, resuming coroutine. Async.Generator DEBUG runTestGenerator-0: done() called. Async.Generator DEBUG secondGen-1: self.cb() called, resuming coroutine. Async.Generator DEBUG secondGen-1: done() called. Async.Generator ERROR Async method 'secondGen-1' is missing a 'yield' call (or called done() after being finalized) -- As you can see, I've added log messages whenever the Generator's 'cb' property is accessed--this is almost guaranteed to be very close to a 'yield' statement, and therefore provides us with a decently accurate idea of where the generator 'stopped'. We also log a message when the generator continues, and by doing so we get an idea of how the coroutines interleave. Another idea I had was to actually match calls to self.cb with calls to 'yield' to automatically detect e.g. two yields in a row (which will ordinarily result in a generator 'hanging'), a generator exiting while a self.cb still hasn't been called, but I'm not sure what kinds of reprecussions it may have. --- services/sync/modules/async.js | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/services/sync/modules/async.js b/services/sync/modules/async.js index ace09b9e5c1..e5134656133 100644 --- a/services/sync/modules/async.js +++ b/services/sync/modules/async.js @@ -48,6 +48,8 @@ Cu.import("resource://weave/util.js"); * Asynchronous generator helpers */ +let currentId = 0; + function AsyncException(initFrame, message) { this.message = message; this._trace = initFrame; @@ -74,6 +76,7 @@ function Generator(thisArg, method, onComplete, args) { Log4Moz.Level[Utils.prefs.getCharPref("log.logger.async")]; this._thisArg = thisArg; this._method = method; + this._id = currentId++; this.onComplete = onComplete; this._args = args; this._initFrame = Components.stack.caller; @@ -83,10 +86,14 @@ function Generator(thisArg, method, onComplete, args) { this._initFrame = this._initFrame.caller; } Generator.prototype = { - get name() { return this._method.name; }, + get name() { return this._method.name + "-" + this._id; }, get generator() { return this._generator; }, get cb() { + let caller = Components.stack.caller; + this._log.debug(this.name + + ": self.cb generated at " + + caller.filename + ":" + caller.lineNumber); let self = this, cb = function(data) { self.cont(data); }; cb.parentGenerator = this; return cb; @@ -126,6 +133,7 @@ Generator.prototype = { _handleException: function AsyncGen__handleException(e) { if (e instanceof StopIteration) { + this._log.debug(this.name + ": End of coroutine reached."); // skip to calling done() } else if (this.onComplete.parentGenerator instanceof Generator) { @@ -171,6 +179,7 @@ Generator.prototype = { }, cont: function AsyncGen_cont(data) { + this._log.debug(this.name + ": self.cb() called, resuming coroutine."); this._continued = true; try { this.generator.send(data); } catch (e) { @@ -199,6 +208,7 @@ Generator.prototype = { return; let self = this; let cb = function() { self._done(retval); }; + this._log.debug(this.name + ": done() called."); this._timer = Utils.makeTimerForCall(cb); },