1026263 - Error writing default prefs during packaged web app installation

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Web Apps (PWAs), defect, P1)

Description

[Richard Newman [:rnewman]]

D/GeckoWebapps(16543): About to download file:///storage/emulated/0/Android/data/com.firefox.marketplace.p8344165ef13eb4d5ef5dc57154f97795/files/Download/application.zip
E/GeckoConsole(16543): [apps] App installation successful for 2048
I/DeviceManagement(17575): PackageUpdateReceiver: vvv Package added: [com.firefox.marketplace.p8344165ef13eb4d5ef5dc57154f97795]
I/DeviceManagement(17575): WorkflowService: Start local workflow: class=[com.htc.cs.dm.workflow.PackageUpdateWorkflow] args=[Bundle[{packageName=com.firefox.marketplace.p8344165ef13eb4d5ef5dc57154f97795, operation=1}]]
I/DeviceManagement(17575): WorkflowService: Starting workflow service
D/GeckoWebapps(16543): onProgress: 53113/53113
I/DeviceManagement(17575): WorkflowService: Executing workflow: workflow=[com.htc.cs.dm.workflow.PackageUpdateWorkflow@41b0fcc0] args=[Bundle[mParcelledData.dataSize=196]]
I/DeviceManagement(17575): PackageUpdateWorkflow: ==================================================
I/DeviceManagement(17575): PackageUpdateWorkflow: Package update: package=com.firefox.marketplace.p8344165ef13eb4d5ef5dc57154f97795, operation=ADD
I/DeviceManagement(17575): PackageUpdateWorkflow: ==================================================
D/GeckoWebapps(16543): Saving /data/data/org.mozilla.fennec_rnewman/files/mozilla/webapps/webapps.json
E/ExternalAccountType( 1343): Unsupported attribute readOnly
D/GeckoWebapps(16543): File hash computed: a1fc24b95adeca31bedc621ac44cf0c7
D/GeckoWebapps(16543): getAppLocalIdByStoreId:https://marketplace.firefox.com#d77a62a6-3128-471d-9f97-845d9772be04
D/GeckoWebapps(16543): _onDownloadPackage
D/GeckoWebapps(16543): Saving /data/data/org.mozilla.fennec_rnewman/files/mozilla/webapps/{36db18ef-279e-4177-b7d3-64d32bb75f53}/manifest.webapp
D/GeckoWebapps(16543): Saving /data/data/org.mozilla.fennec_rnewman/files/mozilla/webapps/webapps.json
D/GeckoWebapps(16543): updateAppHandlers: old=null new=[object Object]
D/GeckoWebapps(16543): Saving /data/data/org.mozilla.fennec_rnewman/files/mozilla/webapps/webapps.json
D/GeckoWebappManager(16543): Error writing default prefs: Unix error 2 during operation open on file /data/data/org.mozilla.fennec_rnewman/files/mozilla/luc2u36i.webapp0/default-prefs.js.tmp (No such file or directory)

Comment 1

[Martyn Haigh (:mhaigh)]

Any idea how to reproduce this?

Comment 2

[Richard Newman [:rnewman]]

Steps I took (I don't know how easy it is to repro!):

* Launch Nightly.
* Tap the marketplace link.
* Search for ":packaged".
* Install 2048.
* Watch the log.

Comment 3

[Myk Melez [:myk] [@mykmelez]]

rnewman: can you still reproduce?  I can't do so on the latest Nightly build.

Comment 4

[Richard Newman [:rnewman]]

I have a strong suspicion that this is a race condition with profile directory creation -- webapp profiles are built differently. So I doubt it's a reproducible bug, just one we have to read the code and think about.

Comment 5

[Myk Melez [:myk] [@mykmelez]]

Hmm, ok.  Upon APK installation, the code paths vary depending on whether you press Done to return to Fennec or Open to launch the app from the install dialog.  The former triggers InstallListener.onReceive, while the latter triggers WebappImpl.onCreate.

But either way, the next relevant call is to InstallHelper.startInstall, which calls InstallHelper.install.  And that triggers this trio of call chains (where "…" identifies an event-dispatched call):

1. > GeckoProfile.get (which returns a GeckoProfile instance);
2. > GeckoProfile.getDir > GeckoProfile.forceCreate > GeckoProfile.createProfileDir > java.io.File.mkdirs (which should create the profile directory synchronously);
3. … "Webapps:AutoInstall" … WebappManager.autoInstall > DOMApplicationRegistry.doInstallPackage … "webapps-ask-install" … WebappManager.askInstall > DOMApplicationRegistry.confirmInstall > WebappManager._postInstall > WebappManager.writeDefaultPrefs > WebappManager._writeData (which tries to write data to a file in the directory).

The statement that fails with "No such file or directory" is this one in _writeData:

  OS.File.writeAtomic(aFile.path, array, { tmpPath: aFile.path + ".tmp" }).then(null, function onError(reason) {
    debug("Error writing default prefs: " + reason);
  });

But the profile directory should definitely have been created by then.  And the temp file, which is what the error message actually cites, shouldn't need to exist, as writeAtomic should create it.

GeckoProfile logs some messages, so we could confirm its behavior to some extent by looking earlier in the log, if you happen to still have a more complete version of it.  Specifically, it should include the debug message "Created new profile dir."

Otherwise, I suppose there's a chance that writeAtomic could have a bug, although it seems unlikely.

Requesting needinfo from Yoric and Marco, who have experience with OS.File, for their insight into that possibility.

Comment 6

[Marco Castelluccio [:marco]]

It's strange indeed, IIRC writeAtomic creates files using O_TRUNC and O_WRONLY so it shouldn't fail if the parent directory exists.

forceCreate, before calling createProfileDir, tries to find an already existing profile dir with findProfileDir. Is it possible that a profile dir is being found, without checking if it really exists?

Comment 7

[David Teller [:Yoric] - still alive but not very active]

Indeed, this error message clearly points out to the directory not existing. Who creates the directory? Is it in the same process/thread?

Comment 8

[Myk Melez [:myk] [@mykmelez]]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo") from comment #7)
> Who creates the directory? Is it in the same process/thread?

GeckoProfile.createProfileDir creates the directory:

  http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/GeckoProfile.java#596

It's in the same process, and I think (unsure) that it's in the same thread.

Comment 9

[Myk Melez [:myk] [@mykmelez]]

rnewman: would you happen to have a more complete log lying about, by any chance?  GeckoProfile should log "Created new profile dir." before GeckoWebapps logs "About to download…", and I'm curious if it did that in your case.

I'm also wondering what version of Android (and which device) you have, as I could imagine this somehow being affected by an underlying change to the order of execution of the ActivityResultHandler for the install intent <http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/webapp/EventListener.java?rev=c44f8dcd20df#190> and the activity that observes installation <http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/webapp/InstallListener.java>.

Comment 10

[Richard Newman [:rnewman]]

(In reply to Myk Melez [:myk] [@mykmelez] from comment #9)
> rnewman: would you happen to have a more complete log lying about, by any
> chance?  GeckoProfile should log "Created new profile dir." before
> GeckoWebapps logs "About to download…", and I'm curious if it did that in
> your case.

I don't, I'm afraid.

> I'm also wondering what version of Android (and which device) you have

This was most likely an HTC One M7 running KitKat.



> It's in the same process, and I think (unsure) that it's in the same thread.

Along the lines of Comment 5:

webapp.InstallHelper.startInstall()
  => runnable on background thread
    install(String, JSONObject)
       GeckoProfile.getDir
         GeckoProfile.forceCreate
           GeckoProfile.createProfileDir

so the creation is happening on the background thread.

startInstall is indeed called from WebappImpl.onCreate and also from InstallListener.

But in theory this could also be WebappImpl.showSplash, which will call getDir on the main thread. GeckoProfile is thread-safe, so that shouldn't be a concern, and I didn't launch the app, so I don't think we need to worry there.


But all this should be academic; I'm puzzled how Gecko could even have the full profile path before the directory is created, because (as you note) GeckoProfile makes the directory tree before writing it to profiles.ini or returning the value to the caller. It should not be possible for a caller of getDir to receive a directory that doesn't exist.

That makes me think that this error 2 is not due to a missing profile directory, but due to a permissions error, an error inside the atomic write (moving the temp file to its final destination), or somesuch.


> forceCreate, before calling createProfileDir, tries to find an already existing profile dir with
> findProfileDir. Is it possible that a profile dir is being found, without checking if it really exists?

findProfileDir reads from profiles.ini.

The only reason why that would be wrong is if something deleted the directory after it was created -- we only write to profiles.ini if we successfully create the directory.

Comment 11

[Marco Castelluccio [:marco]]

(In reply to Richard Newman [:rnewman] from comment #10)
> But all this should be academic; I'm puzzled how Gecko could even have the
> full profile path before the directory is created, because (as you note)
> GeckoProfile makes the directory tree before writing it to profiles.ini or
> returning the value to the caller. It should not be possible for a caller of
> getDir to receive a directory that doesn't exist.
> 
> That makes me think that this error 2 is not due to a missing profile
> directory, but due to a permissions error, an error inside the atomic write
> (moving the temp file to its final destination), or somesuch.

The error in your log "Error writing default prefs: Unix error 2 during operation open on file /data/data/org.mozilla.fennec_rnewman/files/mozilla/luc2u36i.webapp0/default-prefs.js.tmp (No such file or directory)" says that it's happened during the open operation (not during write or move), because OS.File creates errors using the name of the operation it is currently executing.

writeAtomic should throw a "permission denied" error (errno 13) in case of permission errors.

I've deduced this by quickly looking at the OS.File code, so you may want Yoric to confirm.

If I'm not mistaken, the only line where this exception could've been thrown is: http://mxr.mozilla.org/mozilla-central/source/toolkit/components/osfile/modules/osfile_shared_front.jsm?rev=f6e46d1fc903#463

Comment 12

[Myk Melez [:myk] [@mykmelez]]

Attachment: patch v1: set orientation default pref on firstrun

It still isn't clear to me why the profile directory doesn't exist post-install, but it isn't actually necessary to create a default prefs file in it, since that file doesn't get converted into actual prefs until firstrun, by which time we might as well simply set the orientation pref like we set a bunch of other default prefs on firstrun.

The only twist is that the orientation pref's value depends on a manifest property, so we have to load the manifest before setting it.  But we do that already on firstrun, right after setting the other default prefs, so it's trivial to wait until we load the manifest before setting orientation.

While testing this fix, I noticed that Line Runner, which specifies a landscape orientation, starts in the wrong orientation on firstrun.  But that's unrelated to this change, since it happens even without it (and on every run, not just firstrun).  I filed that issue as bug 1052298.

Comment 13

[Wesley Johnston (:wesj)]

Comment on attachment 8471419 [details] [diff] [review]
patch v1: set orientation default pref on firstrun

Review of attachment 8471419 [details] [diff] [review]:
-----------------------------------------------------------------

I like it.

Comment 14

[Myk Melez [:myk] [@mykmelez]]

https://hg.mozilla.org/integration/fx-team/rev/cfda006cc65f

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/cfda006cc65f