Closed Bug 1622610 Opened 4 years ago Closed 4 years ago

Raptor webextension fails to load on Moto G5 due to NS_ERROR_FILE_ACCESS_DENIED

Categories

(Testing :: Raptor, defect, P2)

Version 3
defect

Tracking

(firefox77 fixed)

RESOLVED FIXED
mozilla77
Tracking Status
firefox77 --- fixed

People

(Reporter: whimboo, Assigned: bc)

References

Details

Sometimes the Raptor web extension cannot be loaded because a file access denied error for the Raptor extension manifest file. Here an excerpt from the adb logcat file:

https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ak8V_SWZQ5iTtdCwqjxKKA/runs/0/artifacts/public/test_info/logcat-ZY3223CQ8P.log

03-14 18:09:09.315 10213 10229 I GeckoConsole: 1584209349314 addons.xpi-utils WARN addMetadata: Add-on raptor@mozilla.org is invalid: Error: Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)(resource://gre/modules/Extension.jsm:559:20) JS Stack trace: readJSON/</<@Extension.jsm:559:20

Not sure what that means for the device and if it has some general problems. Maybe that is related to bug 1622447?

Bob or Geoff, have you seen anything like that before?

Flags: needinfo?(gbrown)
Flags: needinfo?(bob)
Summary: Raptor webextension fails to load on Moto G5 due to → Raptor webextension fails to load on Moto G5 due to NS_ERROR_FILE_ACCESS_DENIED

Note, that we could turn-on addon logging for a try build to get further information.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #1)

Note, that we could turn-on addon logging for a try build to get further information.

Please. That file should have been on the sdcard which doesn't have the ability to change file permissions. I don't know that I trust the error message in that some times I've seen permission errors for non-existent files. In your try run can you use ADBDevice.ls to do a recursive ls -R on /sdcard/raptor and /sdcard/tests?

It is strange to see access denied on /sdcard -- I wouldn't think that possible.

If NS_ERROR_FILE_ACCESS_DENIED actually arises from a file permission issue, I might suspect it means:

  • /sdcard isn't (fully?) mounted yet -- not waiting for boot completion and filesystem ready?
  • the file hasn't been (fully) written yet: is it possible the browser is launched before the profile is completely written?
  • the file does not exist (comment 2)

But I'm also wondering if NS_ERROR_FILE_ACCESS_DENIED is actually indicating some Gecko condition rather than the file permission issue that the error message suggests. From https://searchfox.org/mozilla-central/rev/d69ec052bed8700af7a283e37b60b4af22734930/toolkit/components/extensions/Extension.jsm#559 I see NS_ERROR_FILE_ACCESS_DENIED was reported by NetUtils.asyncFetch, but haven't looked in asyncFetch.

Flags: needinfo?(gbrown)

Oh, there is a whole stack:

03-14 18:09:09.315 10213 10229 I GeckoConsole: 1584209349314	addons.xpi-utils	WARN	addMetadata: Add-on raptor@mozilla.org is invalid: Error: Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)(resource://gre/modules/Extension.jsm:559:20) JS Stack trace: readJSON/</<@Extension.jsm:559:20
03-14 18:09:09.315 10213 10229 I GeckoConsole: onStopRequest@NetUtil.jsm:128:18
03-14 18:09:09.315 10213 10229 I GeckoConsole: awaitPromise@XPIProvider.jsm:226:15
03-14 18:09:09.315 10213 10229 I GeckoConsole: syncLoadManifest@XPIInstall.jsm:754:22
03-14 18:09:09.315 10213 10229 I GeckoConsole: addMetadata@XPIDatabase.jsm:2783:32
03-14 18:09:09.315 10213 10229 I GeckoConsole: processFileChanges@XPIDatabase.jsm:3218:26
03-14 18:09:09.315 10213 10229 I GeckoConsole: checkForChanges@XPIProvider.jsm:2941:55
03-14 18:09:09.315 10213 10229 I GeckoConsole: startup@XPIProvider.jsm:2395:12
03-14 18:09:09.315 10213 10229 I GeckoConsole: callProvider@AddonManager.jsm:215:31
03-14 18:09:09.315 10213 10229 I GeckoConsole: _startProvider@AddonManager.jsm:587:17
03-14 18:09:09.315 10213 10229 I GeckoConsole: startup@AddonManager.jsm:811:14
03-14 18:09:09.315 10213 10229 I GeckoConsole: startup@AddonManager.jsm:3482:26
03-14 18:09:09.315 10213 10229 I GeckoConsole: observe@addonManager.js:87:29

Let me know when you've had a chance to do the try run with the extension logging. and I'll take another look.

Flags: needinfo?(bob)

The try build shows an error which is actually bug 1624077. I will trigger more jobs in the hope to see the one as covered by this bug.

See Also: → 1624077

I was not able to reproduce this bug anymore. Lets wait for a bit and check regularly if it might have happened again on central/autoland.

This blocks bug 1627867 now.

Here a recent failure:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=297475789&repo=autoland&lineNumber=2728

04-14 06:33:04.066 11190 11206 D GeckoViewConsole: onEvent GeckoView:WebExtension:List null
04-14 06:33:04.094 11190 11206 I Gecko   : Extension error: Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED) resource://gre/modules/Extension.jsm:567 :: readJSON/</<@resource://gre/modules/Extension.jsm:567:20
04-14 06:33:04.094 11190 11206 I Gecko   : onStopRequest@resource://gre/modules/NetUtil.jsm:128:18
04-14 06:33:04.094 11190 11206 I Gecko   : 
04-14 06:33:04.094 11190 11206 E GeckoConsole: [JavaScript Error: "Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)" {file: "resource://gre/modules/Extension.jsm" line: 567}]
04-14 06:33:04.094 11190 11206 E GeckoConsole: readJSON/</<@resource://gre/modules/Extension.jsm:567:20
04-14 06:33:04.094 11190 11206 E GeckoConsole: onStopRequest@resource://gre/modules/NetUtil.jsm:128:18
04-14 06:33:04.096 11190 11206 I GeckoConsole: 1586845984095	addons.xpi	WARN	Exception running bootstrap method startup on raptor@mozilla.org: Error: Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)(resource://gre/modules/Extension.jsm:567:20) JS Stack trace: readJSON/</<@Extension.jsm:567:20
04-14 06:33:04.096 11190 11206 I GeckoConsole: onStopRequest@NetUtil.jsm:128:18
04-14 06:33:04.148 11190 11206 D GeckoViewConsole: onEvent GeckoView:ActionDelegate:Attached {"extensionId":"raptor@mozilla.org"}
04-14 06:33:04.149 11190 11206 D GeckoViewConsole: Could not find extension with id=raptor@mozilla.org
Blocks: 1627867
No longer blocks: 1609295

In a lot of cases the last log entry in the logcat is:

04-14 12:17:30.038 11851 11870 I WebExtensions: [raptor-runnerjs] pageload test finished

That comes from:

https://searchfox.org/mozilla-central/rev/2cd2d511c0d94a34fb7fa3b746f54170ee759e35/testing/raptor/webext/raptor/runner.js#705

That is followed-up in the normal log with:

[task 2020-04-14T12:17:35.213Z] 12:17:30     INFO -  raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 15, u'subtest_unit': u'ms', u'name': u'raptor-tp6m-bbc-geckoview-cold', u'lower_is_better': True, u'measurements': {u'dcf': [2893], u'fcp': [2022], u'fnbpaint': [1853], u'loadtime': [4561]}, u'browser_cycle': u'12', u'subtest_lower_is_better': True, u'cold': True, u'browser': u'GeckoView Example 77.0a1 20200414102036', u'type': u'pageload', u'page': u'https://www.bbc.com/news/business-47245877', u'unit': u'ms', u'alert_threshold': 2}
[task 2020-04-14T12:17:35.213Z] 12:17:30     INFO -  perftest-results-handler Info: received results in RaptorResultsHandler.add
[task 2020-04-14T12:17:35.213Z] 12:17:30     INFO -  raptor-control-server Info: received webext_status: Not closing last Tab: 10001
[task 2020-04-14T12:17:35.213Z] 12:17:30     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2020-04-14T12:17:35.213Z] 12:17:30     INFO -  raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
[task 2020-04-14T12:17:35.213Z] 12:17:31     INFO -  adb shell_output: adb -s ZY322BV893 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-14T12:17:35.213Z] 12:17:31     INFO -  raptor-webext-android Info: begin browser cycle 13 of 15 for test raptor-tp6m-bbc-geckoview-cold

It means that Raptor kills geckoview_example. After that we start geckoview_example again:

[task 2020-04-14T12:20:08.812Z] 12:17:47     INFO -  adb launch_application: am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.MAIN -d about:blank
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  adb shell_output: adb -s ZY322BV893 wait-for-device shell am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.MAIN -d about:blank, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.MAIN dat=about:blank cmp=org.mozilla.geckoview_example/.GeckoViewActivity }
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  Status: ok
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  Activity: org.mozilla.geckoview_example/.GeckoViewActivity
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  ThisTime: 691
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  TotalTime: 691
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  WaitTime: 701
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  Complete
[task 2020-04-14T12:20:08.812Z] 12:17:48     INFO -  adb shell_output: adb -s ZY322BV893 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 12119
[task 2020-04-14T12:20:08.812Z] 12:20:07     INFO -  adb shell_output: adb -s ZY322BV893 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:

Then nothing happens for about 2:30 minutes, and Raptor kills the non-responding geckoview_example process. Checking the logcat the file access denied error appears:

04-14 12:17:49.936 12119 12135 E GeckoConsole: [JavaScript Error: "Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)" {file: "resource://gre/modules/Extension.jsm" line: 567}]

Bob, any further idea what this could be or how to debug that?

Flags: needinfo?(bob)

It shouldn't be anything to do with file permissions on the sdcard. I see that we call ADBDevice.stop_application and then almost immediately attempt to start the app. There is no wait in the code to wait for the process to exit. The sdcard is FAT and perhaps that is causing the access denied if a previous process is still accessing the file. My guess is after starting the app, running the test and stopping the app, a GC or other device housekeeping code is running that may slow the shutdown. My first thought would be to insert a loop waiting for process_exist to return False. Can you reproduce this on try reasonably easily? I would modify stop_application and verify the fix there if possible.

Flags: needinfo?(bob)
Blocks: 1622447

Thanks Bob. I don't have time to check that before early next week. Greg or Florin, would one of you be able to check that earlier?

Flags: needinfo?(gmierz2)
Flags: needinfo?(fstrugariu)
Blocks: 1624077

Yup, here's a try run with a patch that contains the modifications that :bc proposed: https://treeherder.mozilla.org/#/jobs?repo=try&revision=0e4c7daa943553d9ee475dd40f93a23418c4b53d

Flags: needinfo?(gmierz2)

Greg pushed another try build with an additional sleep of 45s between killing the app, and starting the next process:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b8db6882796bd46d7cc652dfb4a69d5967066ad2

So that last try push is interesting. In all the retriggers, there wasn't a single failure that was related to this issue (tp6m-6 is not caused by this, and tp6m-1 failures are timeouts caused by the 45s wait). As :bc mentioned above, this means that there is some process holding the file after the app is killed, or some house cleaning code is running.

Maybe we can print all the running activities via adb after the process has been quit, and after those 45s? I would like to see what has been changed. Mind triggering another try build for that?

Flags: needinfo?(gmierz2)

Hmm, I think I got lucky on the previous try run where I didn't get any failures - we're seeing the failures in the try link in C#18 now (with the 45s wait).

No longer blocks: 1622447
Flags: needinfo?(fstrugariu)

So I cannot see something specific in those logs what could keep hold on these files. Maybe I overlook something?

Greg, what about if we just use a different profile directory on the device too for each instance of Firefox? That should help us to get rid of those file access denied errors. If you agree, who could work on that?

Flags: needinfo?(gmierz2)

I wonder if putting the raptor profile on the sdcard might be an issue. It is FAT instead of ext4 or something else. I am working on a patch to better support Android 10+ which involves changing the default test root in ADBDevice to internal storage. I haven't focused on raptor but will include it in my testing to see if there is any difference.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #20)

So I cannot see something specific in those logs what could keep hold on these files. Maybe I overlook something?

Greg, what about if we just use a different profile directory on the device too for each instance of Firefox? That should help us to get rid of those file access denied errors. If you agree, who could work on that?

I agree, I made a small patch to check if that might work: https://treeherder.mozilla.org/#/jobs?repo=try&revision=50162ae1e5bde202eeb1fb1853d56435981c1245

If this doesn't fix it, then :bc's suggestion of moving away from the SD card would be the best next step.

Flags: needinfo?(gmierz2)

One other item to consider is if the updated adb.py will help even with the profile on the sdcard. I forgot I did include the raptor tests in my most recent try. It looks pretty good but I'm not sure if the g5 failures are common enough for us to see them in one push.

(In reply to Geoff Brown [:gbrown] from comment #3)

But I'm also wondering if NS_ERROR_FILE_ACCESS_DENIED is actually indicating some Gecko condition rather than the file permission issue that the error message suggests. From https://searchfox.org/mozilla-central/rev/d69ec052bed8700af7a283e37b60b4af22734930/toolkit/components/extensions/Extension.jsm#559 I see NS_ERROR_FILE_ACCESS_DENIED was reported by NetUtils.asyncFetch, but haven't looked in asyncFetch.

Has anyone narrowed down where NS_ERROR_FILE_ACCESS_DENIED originates from? If not, it's still possible that it only indicates some Gecko condition, which might be independent of the file system.

(In reply to Greg Mierzwinski [:sparky] from comment #22)

I agree, I made a small patch to check if that might work: https://treeherder.mozilla.org/#/jobs?repo=try&revision=50162ae1e5bde202eeb1fb1853d56435981c1245

If this doesn't fix it, then :bc's suggestion of moving away from the SD card would be the best next step.

Looks like this didn't work out. So moving it to the internal storage might be good to try. Greg, could you keep poking on it?

Depends on: 1632959

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #25)

(In reply to Greg Mierzwinski [:sparky] from comment #22)

I agree, I made a small patch to check if that might work: https://treeherder.mozilla.org/#/jobs?repo=try&revision=50162ae1e5bde202eeb1fb1853d56435981c1245

If this doesn't fix it, then :bc's suggestion of moving away from the SD card would be the best next step.

Looks like this didn't work out. So moving it to the internal storage might be good to try. Greg, could you keep poking on it?

I don't think moving to internal storage will change anything but it's worth a shot. I think the error is along the lines of what :gbrown mentioned, this seems like it's related to something in geckoview.

See Also: → 1535365

Oh, the extensions process would make sense. Given that this was backed out 45 minutes ago, lets see how this changes our Raptor tests. I will check again on Monday.

See also bug 1632959, which might be the candidate here. Lets see if the work Bob is doing on bug 1632959 will fix it right away.

See Also: → 1632959

I reproduced NS_ERROR_FILE_ACCESS_DENIED with Addons debugging and MOZ_LOG=nsPipe:5 in
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299372275&repo=try&lineNumber=1960
See the logcat, where you can see ACCESS_DENIED=0x80520015 in some of the nsPipe calls.

04-25 05:41:37.077  7922  7938 I GeckoConsole: 1587793297076	addons.xpi-utils	DEBUG	Finished async read of XPI database, parsing...
04-25 05:41:37.080  7922  7938 I GeckoConsole: 1587793297080	addons.xpi-utils	DEBUG	Successfully read XPI database
04-25 05:41:37.082  7922  7938 I GeckoConsole: 1587793297082	addons.xpi-utils	DEBUG	New add-on raptor@mozilla.org installed in app-profile
04-25 05:41:37.274  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe III AsyncWait [this=0x86b2ed60]
04-25 05:41:37.274  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe OOO WriteSegments [this=0x859ca048 count=16384]
04-25 05:41:37.274  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe OOO appended new segment
04-25 05:41:37.274  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe OOO rolling back write cursor 0 bytes
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe OOO CloseWithStatus [this=0x859ca048 reason=80520015]
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe PPP nsPipe::OnPipeException [reason=80520015 output-only=1]
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe nsPipeInputStream::OnInputException [this=0x86b2ed60 reason=80520015]
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe nsPipeOutputStream::OnOutputException [this=0x859ca048 reason=80520015]
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe OOO CloseWithStatus [this=0x859ca048 reason=80470002]
04-25 05:41:37.275  7922  7991 I Gecko   : [(null) 7922: Unnamed thread 0x86b8aa80]: D/nsPipe PPP nsPipe::OnPipeException [reason=80470002 output-only=1]
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe III CloseWithStatus [this=0x86b2ed60 reason=80520015]
04-25 05:41:37.277  7922  7938 I Gecko   : ZZZ NetUtil onStopRequest 2152857621
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe OOO CloseWithStatus [this=0x859fcf98 reason=80470002]
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe PPP nsPipe::OnPipeException [reason=80470002 output-only=1]
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe nsPipeInputStream::OnInputException [this=0x86b2ec40 reason=80470002]
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe nsPipeOutputStream::OnOutputException [this=0x859fcf98 reason=80470002]
04-25 05:41:37.277  7922  7938 I Gecko   : [(null) 7922: Main Thread]: D/nsPipe III CloseWithStatus [this=0x86b2ed60 reason=80470002]
04-25 05:41:37.279  7922  7938 I GeckoConsole: 1587793297278	addons.xpi-utils	WARN	addMetadata: Add-on raptor@mozilla.org is invalid: Error: Error while loading 'file:///storage/emulated/0/raptor/profile/extensions/raptor@mozilla.org/manifest.json' (NS_ERROR_FILE_ACCESS_DENIED)(resource://gre/modules/Extension.jsm:569:20) JS Stack trace: readJSON/</<@Extension.jsm:569:20
04-25 05:41:37.279  7922  7938 I GeckoConsole: onStopRequest@NetUtil.jsm:129:18
04-25 05:41:37.279  7922  7938 I GeckoConsole: awaitPromise@XPIProvider.jsm:226:15
04-25 05:41:37.279  7922  7938 I GeckoConsole: syncLoadManifest@XPIInstall.jsm:752:22
04-25 05:41:37.279  7922  7938 I GeckoConsole: addMetadata@XPIDatabase.jsm:2787:32
04-25 05:41:37.279  7922  7938 I GeckoConsole: processFileChanges@XPIDatabase.jsm:3223:26
04-25 05:41:37.279  7922  7938 I GeckoConsole: checkForChanges@XPIProvider.jsm:2957:55
04-25 05:41:37.279  7922  7938 I GeckoConsole: startup@XPIProvider.jsm:2417:12
04-25 05:41:37.279  7922  7938 I GeckoConsole: callProvider@AddonManager.jsm:212:31
04-25 05:41:37.279  7922  7938 I GeckoConsole: _startProvider@AddonManager.jsm:584:17
04-25 05:41:37.279  7922  7938 I GeckoConsole: startup@AddonManager.jsm:808:14
04-25 05:41:37.279  7922  7938 I GeckoConsole: startup@AddonManager.jsm:3479:26
04-25 05:41:37.279  7922  7938 I GeckoConsole: observe@addonManager.js:87:29

I don't know this code / haven't analyzed the logs / don't know what it means.

Since the patch on bug 1632959 landed yesterday we haven't seen this failure anymore! I think this is great news, and I will re-check on Monday. If it's completely gone we can close this bug then.

There was no more such a failure since Bob's patch on bug 1632959 landed. I call this fixed. Thanks a lot!

Assignee: nobody → bob
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
No longer blocks: 1624077
You need to log in before you can comment on or make changes to this bug.