994697 - [marionette-js-logger] switch to synchronous mode of operation supporting waiting for logged messages

Status: RESOLVED FIXED

(Testing Graveyard :: JSMarionette, defect)

Description

[Andrew Sutherland [:asuth] (he/him)]

marionette-js-logger was implemented before the synchronous marionette driver was created/adopted and currently does not really work with the synchronous driver.  Specifically, it receives logged messages via a websocket channel, but this fundamentally depends on the libuv event loop getting a chance to run and this does not happen with the synchronous driver.  sockit-to-me could theoretically yield while waiting, at least with new support added in node v0.12 a few days ago to support spawnSync, although that would likely undo a lot of the benefits of the synchronous API since it would make it harder to reason about what is going on and make it possible for horribly nested call stacks.

Here's what I proposed to :gaye on IRC:
10:19:59 AM - asuth: - host side sits there accumulating log entries into an array
10:20:11 AM - asuth: - client side has a command to executeScript() to the host and grab the current contents of the array, clearing it out
10:20:20 AM - asuth: - client then calls handleMessage / emits all that crap
10:20:33 AM - asuth: - client also has a variant that's waitForLogMessage()
10:20:49 AM - asuth: waitForLogMessage could either take a predicate that also gets to see all the log messages that show up
10:21:04 AM - asuth: or alternately the handleMessage/emit handlers could potentially call some other method on the logger to tell them they are all happy
10:21:47 AM - asuth: internally, waitForLogMessage just keeps calling to poll from the client, but using executeScriptAsync so that it won't return until at least one log entry is returned
10:22:00 AM - asuth: probably it would want to use a setTimeout or other event-loop turn mechanism so it doesn't go too crazy
10:22:08 AM - asuth: since observer notfications are synchronous

:gaye has signed off on this plan and in general with switching marionette-js-logger entirely to a synchronous mode of operation.  (So no keeping the websockets dependency around, etc.)  We can of course have the synchronous mode do asynchronous stuff by using setInterval/etc. without too much trouble.

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

Attachment: https://github.com/mozilla-b2g/marionette-js-logger/pull/8

This is pretty much good to go but there may need to be some changes as I connect it with my use-case a little more.  Asking for feedback to get it on the radar and since the core behaviour is unlikely to change.  Feel free to do a full review if you like :)

Comment 3

[Gareth Aye [:gaye] (back from PTO)]

Comment on attachment 8405320 [details] [review]
https://github.com/mozilla-b2g/marionette-js-logger/pull/8

Very nice! I have a few nits on GH, but I think this is [mostly] ready to go!

Comment 4

[Candice Serran (:cserran)]

asuth: is this bug still in progress? (need to update the milestone if it is)

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

Yes, this goes with the re-enable email tests thing.  Bumping.

Comment 6

[Gareth Aye [:gaye] (back from PTO)]

After much bitrot, this has finally landed on master https://github.com/mozilla-b2g/marionette-js-logger/commit/5f5888f0a2796154ec1a9678e0e8dd7751963505. Many thanks to :asuth who helped debug some of the fallout from when I botched a rebase from master onto his old branch.