1476627 - Concurrent content scripts: TelemetryStopwatch: key "WEBEXT_CONTENT_SCRIPT_INJECTION_MS" was already initialized

Status: NEW

(WebExtensions :: General, defect, P3)

Description

[Rob Wu [:robwu]]

Attachment: concurrentContentScript.zip

When a content script is running (and blocked),
and another content script is run (via tabs.executeScript),
or a stylesheet is modified (via the tabs.insertCSS/removeCSS),
then the second action does not wait for the first script to complete.

In contrast, when the content scripts are declared in the manifest file (in different keys), then the scripts are run sequentially as expected. Also, in Chromium, the behavior is that scripts are executed sequentially.

Besides reentrancy of JavaScript code, this also causes an issue with the WEBEXT_CONTENT_SCRIPT_INJECTION_MS telemetry probe - https://searchfox.org/mozilla-central/source/toolkit/components/extensions/ExtensionContent.jsm#486,496

Steps to reproduce:
1. Load attached extension.
2. At example.com, click on the extension button to run two scripts.
3. The first script shows an alert dialog - close this dialog.
3. Look at the global JS console.

Expected result:
First script started
First script ended
Second script runs.

Actual result:
First script started
Second script runs.
ERROR: TelemetryStopwatch: key "WEBEXT_CONTENT_SCRIPT_INJECTION_MS" was already initialized TelemetryStopwatch.jsm:352
ERROR: TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "WEBEXT_CONTENT_SCRIPT_INJECTION_MS", key: "null" TelemetryStopwatch.jsm:373
First script ended
ERROR: TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "WEBEXT_CONTENT_SCRIPT_INJECTION_MS", key: "null" TelemetryStopwatch.jsm:373


Note that the second script runs before the first script ends, and that no telemetry is recorded for either execution. This happens:
1. Content script 1 starts running and does not return yet (e.g. paused on debugger or modal dialog).
   -> TelemetryStopwatch.start #1

2. tabs.executeScript, tabs.insertCSS or tabs.removeCSS is executed.
   -> TelemetryStopwatch.start #2
   -> Because of #1, the pending timer (#1) is stopped and #2 is not started.

3. The call from the previous step finishes.
   -> TelemetryStopwatch.finish (is supposed to balance the timer from #2)
   -> Timer #2 not found because it was not started -> Error

4. The content script resumes (e.g. debugger resumed or modal dialog dismissed)
   -> TelemetryStopwatch.finish (should stop timer #1)
   -> Timer #1 not found because it was stopped -> Error


(Reproduced in Firefox 61.0.1 and Firefox Nightly)