Open Bug 1848398 Opened 1 year ago Updated 1 year ago

test_ext_webRequest_style_cache.js fails on Android, due to cache miss of SharedStyleSheetCache

Categories

(Core :: CSS Parsing and Computation, defect)

defect

Tracking

()

People

(Reporter: robwu, Unassigned, NeedInfo)

References

Details

Attachments

(3 files)

test_ext_webRequest_style_cache.js fails on Android. I took a closer look, and it looks like the style cache is not hit despite the logs suggesting it to be populated.

When I compare the output of a run on desktop vs Android (see below for instructions), I see that the CSS file is cached as expected at the first load,

[Child 12345: Main Thread]: D/nsCSSLoader SharedStyleSheetCache::InsertIfNeeded
[Child 12345: Main Thread]: D/nsCSSLoader Putting style sheet in shared cache: http://example.com/data/file_stylesheet_cache.css

... but that the cache hit behavior is different at the second load. The following log fragments demonstrate this clearly (the cache hit/miss log originate from this part of the source code of Loader::CreateSheet).

Good (Desktop):

INFO "Loading second page to check the caching behavior"
[Child 12345: Main Thread]: D/nsCSSLoader css::Loader::LoadSheet(aURL, aObserver) api call
[Child 12345: Main Thread]: D/nsCSSLoader   Non-document sheet uri: 'http://example.com/data/file_stylesheet_cache.css'
[Child 12345: Main Thread]: D/nsCSSLoader css::Loader::CreateSheet(http://example.com/data/file_stylesheet_cache.css)
[Child 12345: Main Thread]: D/nsCSSLoader KeyEquals(http://example.com/data/file_stylesheet_cache.css)
[Child 12345: Main Thread]: D/nsCSSLoader   Hit cache with state: Complete

Bad (Android):

INFO "Loading second page to check the caching behavior"
[Child 12345: Main Thread]: D/nsCSSLoader css::Loader::LoadSheet(aURL, aObserver) api call
[Child 12345: Main Thread]: D/nsCSSLoader   Non-document sheet uri: 'http://example.com/data/file_stylesheet_cache.css'
[Child 12345: Main Thread]: D/nsCSSLoader css::Loader::CreateSheet(http://example.com/data/file_stylesheet_cache.css)
[Child 12345: Main Thread]: D/nsCSSLoader KeyEquals(http://example.com/data/file_stylesheet_cache.css)
[Child 12345: Main Thread]: D/nsCSSLoader   Needs parser

("Need parser" means that the cache was missed)

Desktop (for comparison)

  • Command:
    MOZ_LOG=nsCSSLoader:5,sync ./mach test toolkit/components/extensions/test/xpcshell/test_ext_webRequest_style_cache.js --verbose --log-mach-verbose --tag=remote-webextensions
  • Log: see stdout.

Android

  • Setup to prepare the build: Create .mozconfig-android with the output of ./mach bootstrap (documentation).
  • Setup of MOZ_LOG (generic documentation: GeckoView automation):
    1. Create org.mozilla.geckoview.test_runner-geckoview-config.yaml with the following content:
      env:
        MOZ_LOG: nsCSSLoader:5,sync
      
    2. Push the file to the device with adb push org.mozilla.geckoview.test_runner-geckoview-config.yaml /data/local/tmp/
  • Command:
    MOZCONFIG=.mozconfig-android ./mach test toolkit/components/extensions/test/xpcshell/test_ext_webRequest_style_cache.js --verbose --log-mach-verbose --tag=remote-webextensions
  • Log: adb logcat
    • Note: run adb logcat before running the test. Due to bug 1844829 there is tons of logspam; see that bug for a grep command to filter the output.

Example of good log, from a test run on desktop.

Minimal post-processing of the log file:

  • Stripped timestamp prefixes.
  • Replaced child process ID with 12345.

Example of bad log, from a test run on Android ( emulator - ./mach android-emulator ).

Post-processing of the log file:

  • Stripped timestamp / adb log prefixes.
  • Replaced child process ID with 12345.
  • Removed lots of logspam from bug 1844829.
  • Removed even more unrelated log lines that are not relevant in the comparison with desktop.
  • Converted INFO/FAIL/PASS JSON "action" messages to the format as seen on desktop.

This log shows the nsCSSLoader + INFO/PASS/FAIL parts of the test.

Due to the post-processing this can compared easily with the desktop variant with diff.

To help with debugging:

  • Add comments and explicit test assertion messages that explains the
    test expectation in the webRequest listener.

  • Add info() calls to clearly mark the stage of the test.

  • Add explicit test support for opening a ContentPage in a specific
    process, and open a new ContentPage in that process. This is done
    instead of the current logic (=navigate ContentPage to new
    destination), to rule out document destruction as a cause of the
    stylesheet cache destruction.

Despite these measures, the test is still failing on Android.

The test was introduced in bug 1599160. In comment 3 I added an improved version of the test to rule out some failure causes, but the test still fails on Android.

The cause of the failure is independent of extensions, because the actual trigger for the failure is an unexpected cache miss at https://searchfox.org/mozilla-central/rev/77dd6aa3810610949a5ff925e24de2f8c11377fd/layout/style/Loader.cpp#961,969,984,998

Therefore I'm moving this bug to that component for further triage. See the initial report for reproduction steps and analysis, and comment 1 and comment 2 for formatted log messages.

Component: Android → CSS Parsing and Computation
Product: WebExtensions → Core
Blocks: 1680132

The severity field is not set for this bug.
:jfkthame, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(jfkthame)

Does android, the cp.loadURL call have different navigation / bfcache behavior than desktop here? Does making the bfcache behavior the same fix the test?

What it seems to me is that the first page dies, then we clear the sheet from the cache, and the second page doesn't find it by the time we get to load it.

Flags: needinfo?(rob)

(In reply to Emilio Cobos Álvarez (:emilio) from comment #6)

Does android, the cp.loadURL call have different navigation / bfcache behavior than desktop here? Does making the bfcache behavior the same fix the test?

I suspected navigation & bfcache, but ruled that out as the cause, by keeping the page open while opening a new page. I have attached these changes in the updated test (attached in comment 3 - https://phabricator.services.mozilla.com/D186043) and the issue is still reproduced.

What it seems to me is that the first page dies, then we clear the sheet from the cache, and the second page doesn't find it by the time we get to load it.

In the updated test, the first page is not closed, yet the issue still happens. Due to the difference in observed logs (comment 1 vs comment 2), a next step could be to look at the conditions at https://searchfox.org/mozilla-central/rev/77dd6aa3810610949a5ff925e24de2f8c11377fd/layout/style/Loader.cpp#961,969,984,998 and see what triggers the difference in behavior.

Flags: needinfo?(rob)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: