Components.utils.evalInSandbox is interrupted by SQLite executeAsync callback

UNCONFIRMED
Unassigned

Status

()

UNCONFIRMED
6 years ago
6 years ago

People

(Reporter: godmar, Unassigned)

Tracking

14 Branch
x86_64
Linux
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Reporter)

Description

6 years ago
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.
(Reporter)

Comment 1

6 years ago
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.
Component: Untriaged → Event Handling
Product: Firefox → Core
Not event handling, but not sure which component.
Component: Event Handling → General

Comment 3

6 years ago
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.
(Reporter)

Comment 4

6 years ago
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>
(Reporter)

Comment 5

6 years ago
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

6 years ago
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

6 years ago
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.
(Reporter)

Comment 8

6 years ago
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

6 years ago
logStringMessage posts a runnable to the event loop, correct instead of logging immediately, correct.
And no, the JS->C++ layer is synchronous.
(Reporter)

Comment 11

6 years ago
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.
If you want to get that, that would be swell. A breakpoint on mozilla::storage::CompletionNotifier::Run should be what you're looking for.
You need to log in before you can comment on or make changes to this bug.