781828 - Components.utils.evalInSandbox is interrupted by SQLite executeAsync callback

Status: UNCONFIRMED

(Core :: General, defect)

Description

[Godmar Back]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.57 Safari/537.1

Steps to reproduce:

This is a concurrency issue so I'm providing a description only. 

Our extension calls 

write_to_log("BEFORE evalInSandbox")
Components.util.evalInSandbox("ENTERING evalInSandbox")
write_to_log("AFTER evalInSandbox")

In addition, we have a pending executeAsync() call.
Components.utils.evalInSandbox("


Actual results:

Intermittently, the executeAsync() completion callback is delivered after evalInSandbox has been called, but before the code inside the sandbox has been executed. That is:

BEFORE evalInSandbox
executeAsync.complete is called now!
ENTERING evalInSandbox
AFTER evalInSandbox


Expected results:

The executeAsync callback shouldn't be called until after evalInSandbox returns; that is, the call to evalInSandbox should appear synchronously from the caller's perspective:

BEFORE evalInSandbox
ENTERING evalInSandbox
AFTER evalInSandbox
(return from event handler)
executeAsync.complete can be called now!

In my opinion, the observed behavior creates an unexpected control flow - evalInSandbox should not allow the delivery of SQLite executeAsync callbacks. Observed in 14.0.1 on Ubuntu.

Comment 1

[Godmar Back]

ps: sorry about the stray "Components.util.evalInSandbox(" ... line in my post.

Also, while I have simplified the scenario somewhat, I do want to point out that our actual code that is being evaluated in Components.util.evalInSandbox does not interact with SQLite in any way. In fact, it doesn't call into any XPCOM components - it's simply evaluating a bunch of top-level declarations - that make up the definition of jQuery 1.4.2.  In fact, we see the SQLite callback coming in before the very first line of the eval'd code is run when we put a log statement there, as my simplified example shows.

Side note: fortunately, since our code already heavily uses a framework that allows us to express dependent activities using managed function queues, we could work around this (for us) unexpected behavior simply by introducing an additional dependency that is fulfilled when evalInSandbox returns.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Not event handling, but not sure which component.

Comment 3

[Josh Matthews [:jdm]]

What code does write_to_log execute? Is the evalInSandbox call you make in your example identical to the one you're using in your production code? Nothing in evalInSandbox's implementation looks to me like it should spin the event loop, and that's what causes executeAsync.complete to be triggered.

Comment 4

[Godmar Back]

write_to_log() uses logStringMessage() on a instance of @mozilla.org/consoleservice:
<pre>
    write : function (msg) {
        var consoleService = Components.classes["@mozilla.org/consoleservice;1"]
            .getService(Components.interfaces.nsIConsoleService);
        consoleService.logStringMessage(msg);
    },
</pre>

Comment 5

[Godmar Back]

I note that I could see the effects of the out-of-order execution without the log.write - in fact, that's how I stumbled upon this bug.  Adding the log.write just helped me pinpoint the control flow diversion to be at the entry of Sandbox.evaluate(), right before the very first line of sandboxed code was run.

You're right, as if you're triggering the event loop there.

Comment 6

[Josh Matthews [:jdm]]

I'm still suspicious of the code you're evaluating in the sandbox. Nothing in http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCComponents.cpp#3847 should be touching the event loop at all.

Comment 7

[Josh Matthews [:jdm]]

I mean, for one thing, logStringMessage itself is asynchronous, such that you can't reason well about it except in relation to events that are already present on the event loop and events you dispatch after calling logStringMessage.

Comment 8

[Godmar Back]

I don't know what you mean by 'logStringMessage' being asynchronous - are you saying it's implemented by posting a (future) event to print something?  The function's javascript binding is certainly synchronous. And, in any event, the behavior occurs without the write to the console at all. The code in the sandbox, again, is literally jQuery 1.4.2: http://code.jquery.com/jquery-1.4.2.js

I agree with your reading of XPCComponents.cpp, which is why I find this thing so mysterious.

Could it be, perhaps, that the call to nsXPCComponents_Utils::EvalInSandbox is itself executed as an event, that is, that there's a layer between the JavaScript binding and the C++ code?  It would need to post the 'evalInSandbox' event, crank the event loop at which point the executeAsync may come through.

Comment 9

[Josh Matthews [:jdm]]

logStringMessage posts a runnable to the event loop, correct instead of logging immediately, correct.

Comment 10

[Josh Matthews [:jdm]]

And no, the JS->C++ layer is synchronous.

Comment 11

[Godmar Back]

Well, I have no idea then (and no ideas where one would need to look, either, other than in my code which I've already done to the best of ability).  A possible debugging tool would be an extended stacktrace that shows the C-stack at the point in time the executeAsync callback fires. (The backtrace I obtained ended where the .complete callback was invoked).

As I pointed out, since our code (outside the sandbox, not in the sandbox) is heavily asynchronous, we already have a framework in place to deal with asynchronously-fulfilled dependencies, I can easily work around by adding a dependency that's fulfilled only after EvalInSandbox returns and that acts as a precondition for the action that fires in the executeAsync.

Comment 12

[Josh Matthews [:jdm]]

If you want to get that, that would be swell. A breakpoint on mozilla::storage::CompletionNotifier::Run should be what you're looking for.