896109 - "requested profile directory missing" when accessing ContentProviders from Android background services tests

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Data Providers, defect)

Description

[Nick Alexander :nalexander [he/him]]

I'm seeing a lot of warnings like

W GeckoProfile(26936)         requested profile directory missing: null

when running the Android background services tests.  It's not clear that this is an issue, but it is new (introduced by Bug 871863).  These tests access the Fennec CPs exactly as Android Sync does, so it's likely this will appear with Sync accounts.

Comment 1

[Richard Newman [:rnewman]]

Is this happening for realz on Nightly now? qawanted, ASSEMBLE!

Comment 2

[Aaron Train [:aaronmt]]

Context? What breakage am I looking for? Over the weekend I gave the feature a whirl with Sync enabled and didn't see any major damage *thus far*.

Comment 3

[Richard Newman [:rnewman]]

(In reply to Aaron Train [:aaronmt] from comment #2)
> Context? What breakage am I looking for? Over the weekend I gave the feature
> a whirl with Sync enabled and didn't see any major damage *thus far*.

If Sync works -- that is, stuff is bidirectionally moving between mobile and desktop -- then that's great.

I'd be interested to know if something pops up in the logs during real-world usage, though.

Comment 4

[Richard Newman [:rnewman]]

This is happening *a lot* in Nightly during startup.

07-23 10:10:19.598 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:19.598 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:19.608 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:19.608 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:19.618 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:19.618 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:10:22.642 I/UpdateService(17693): next update will be at: Tue Jul 23 14:10:22 PDT 2013
07-23 10:10:22.652 I/UpdateService(17693): openning connection with url: https://aus2.mozilla.org/update/4/Fennec/25.0a1/20130723030205/Android_arm-eabi-gcc3/en-US/nightly/4.1.2/default/default/25.0a1/update.xml

and it also affects Sync:

07-23 10:09:46.653 I/FxSync  (17490): fennec :: GlobalSession :: Running next stage syncFormHistory (org.mozilla.gecko.sync.stage.FormHistoryServerSyncStage@4199aa98)...
07-23 10:09:47.094 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:09:47.094 D/FormHistoryProvider(17490): No profile provided, using 'default'
07-23 10:09:47.114 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:09:47.114 D/FormHistoryProvider(17490): No profile provided, using 'default'
07-23 10:09:47.114 W/GeckoProfile(17490): requested profile directory missing: null
07-23 10:09:47.114 D/FormHistoryProvider(17490): No profile provided, using 'default'
07-23 10:09:47.144 W/GeckoProfile(17490): requested profile directory missing: null

Fortunately the fallback logic seems to be working...

Comment 5

[Wesley Johnston (:wesj)]

Attachment: removelogging

This is just useless logging I think. We used to take a string here [1] and (if it wasn't an empty string) in setDir tell you if it wasn't valid (because... it seems odd that you explicitly requested a profile dir that doesn't exist). Now we convert that string to a File in a different place (so that the guest profile can pass in a File object instead).

I moved the logging back to where we take a string (that we know is non-null/empty) and try to make a file from it. Like it was before.

I would say we don't need this at all, but currently there's some strangeness in GeckoProfile where, if you pass in a name and an invalid profileDir string, we'll ignore the dir you passed in entirely and make one where we want (one with the correct salted name, next to profiles.ini). So logging that we couldn't find what you asked for is at least some indication of what's happened.

[1] http://hg.mozilla.org/mozilla-central/diff/20ccaa1b374a/mobile/android/base/GeckoProfile.java

Comment 6

[Wesley Johnston (:wesj)]

Attachment: Patch

Sending to finkle because he loves GeckoProfile so much.

Comment 7

[Wesley Johnston (:wesj)]

Attachment: Patch

Grr. Wrong patch. Looking at this more, I'd be happy to kill this logging though...

Comment 8

[Richard Newman [:rnewman]]

Any update on this, Wes?

Comment 9

[Wesley Johnston (:wesj)]

I started to land it, and then wondered about these places where we're seeing it all the time. Are these callers not able to cache the GeckoProfile instance and reuse it? Maybe its good to have this in here until that's fixed....?

Comment 10

[Richard Newman [:rnewman]]

(In reply to Wesley Johnston (:wesj) from comment #9)
> I started to land it, and then wondered about these places where we're
> seeing it all the time. Are these callers not able to cache the GeckoProfile
> instance and reuse it? Maybe its good to have this in here until that's
> fixed....?

The callers definitely can't: they're on the other side of a ContentResolver.

If you're suggesting that the ContentProviders should hold on to a GeckoProfile reference for the lifespan of the process... is it valid for GeckoProfile to be the second-most long-lived class in the application, way longer than GeckoApp/GeckoAppShell? (In other words: it had better not hold on to any objects...)

If so, then yeah, file a bug to add caching.

Comment 11

[Geoff Brown [:gbrown]]

Can we do something soon, please? 

The warning really floods the logcat in some tests. 

I checked on testBrowserProvider and GeckoProfile seemed to be working fine. mProfileDir for the default profile was set to /mnt/sdcard/tests/profile, as I would expect. Calls to https://hg.mozilla.org/mozilla-central/annotate/eabe3f50b083/mobile/android/base/GeckoProfile.java#l61 received a android.test.IsolatedContext, so isGeckoApp==false, so we fall through to https://hg.mozilla.org/mozilla-central/annotate/eabe3f50b083/mobile/android/base/GeckoProfile.java#l87 and https://hg.mozilla.org/mozilla-central/annotate/eabe3f50b083/mobile/android/base/GeckoProfile.java#l96, explaining dir==null.

Comment 12

[Aaron Train [:aaronmt]]

I still see this with FxAccounts usage (literally during a Sync), I don't get a null though, just '...is missing'

W/GeckoProfile(23242): Requested profile directory missing.

Comment 13

[Richard Newman [:rnewman]]

(In reply to Aaron Train [:aaronmt] from comment #12)
> I don't get a null though, just '...is missing'

We just changed that string as part of Bug 953993.

Comment 14

[Geoff Brown [:gbrown]]

This is still flooding test logs:

https://tbpl.mozilla.org/php/getParsedLog.php?id=34213393&full=1&branch=b2g-inbound#error0

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/b2g-inbound/sha512/f1123246342938d8e63569aedea1f8ea8b6347e1c115eeb747efb13cb74d9f3cc71d50b56f500a407929577ded942386682f4c24640541d1a4b7ca056eb0b9d6

Comment 15

[Nick Alexander :nalexander [he/him]]

This is ridiculous:

https://tbpl.mozilla.org/php/getParsedLog.php?id=34506179&full=1&branch=fx-team

Comment 16

[Wesley Johnston (:wesj)]

I haven't had time to look at this any deeper. Landed the log moving:

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

Comment 17

[Ryan VanderMeulen [:RyanVM]]

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