Closed Bug 1214980 Opened 4 years ago Closed 4 years ago

Intermittent testDistribution | Exception caught - java.util.NoSuchElementException

Categories

(Firefox for Android :: Testing, defect)

ARM
Android
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 46
Tracking Status
firefox44 --- affected
firefox45 --- fixed
firefox46 --- fixed
fennec 44+ ---

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

09:38:51     INFO -  0 ERROR Exception caught during test! - java.util.NoSuchElementException
09:38:51     INFO -  	at java.util.Scanner.next(Scanner.java:1007)
09:38:51     INFO -  	at java.util.Scanner.next(Scanner.java:980)
09:38:51     INFO -  	at org.mozilla.gecko.util.FileUtils.getFileContents(FileUtils.java:91)
09:38:51     INFO -  	at org.mozilla.gecko.distribution.Distribution.getAndroidPreferences(Distribution.java:391)
09:38:51     INFO -  	at org.mozilla.gecko.preferences.DistroSharedPrefsImport.importPreferences(DistroSharedPrefsImport.java:28)
09:38:51     INFO -  	at org.mozilla.gecko.tests.testDistribution.initDistribution(testDistribution.java:290)
09:38:51     INFO -  	at org.mozilla.gecko.tests.testDistribution.testDistribution(testDistribution.java:140)
09:38:51     INFO -  	at java.lang.reflect.Method.invokeNative(Native Method)
09:38:51     INFO -  	at java.lang.reflect.Method.invoke(Method.java:525)
09:38:51     INFO -  	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
09:38:51     INFO -  	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
09:38:51     INFO -  	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192)
09:38:51     INFO -  	at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:132)
09:38:51     INFO -  	at junit.framework.TestCase.runBare(TestCase.java:134)
09:38:51     INFO -  	at junit.framework.TestResult$1.protect(TestResult.java:115)
09:38:51     INFO -  	at junit.framework.TestResult.runProtected(TestResult.java:133)
09:38:51     INFO -  	at junit.framework.TestResult.run(TestResult.java:118)
09:38:51     INFO -  	at junit.framework.TestCase.run(TestCase.java:124)
09:38:51     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:191)
09:38:51     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:176)
09:38:51     INFO -  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:554)
09:38:51     INFO -  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1701)


:mhaigh -- Do you understand what happened here?
Flags: needinfo?(martyn.haigh+bugzilla)
It looks like our FileUtils is borked [1]:
  scanner = new Scanner(file, "UTF-8");
  return scanner.useDelimiter("\\A").next();

We shouldn't call `Scanner.next` without calling `Scanner.hasNext` first.

The changeset that moved that came from the end of 2014, so unclear why this appeared two months ago:
  http://hg.mozilla.org/mozilla-central/rev/f9856f8ee44f

I'm not sure what the expected output is here if there are no tokens – maybe the empty String as the file is empty? Should it be null?

It's weird this is an intermittent issue though – if we fix the util, we might just be moving the problem elsewhere.

[1]: https://dxr.mozilla.org/mozilla-central/rev/974fe614d5299159dc16d98d97d76af653158d29/mobile/android/base/util/FileUtils.java#91
Flags: needinfo?(martyn.haigh+bugzilla)
I was thinking this was a regression from http://hg.mozilla.org/mozilla-central/rev/c043c708384c.
(In reply to Geoff Brown [:gbrown] from comment #15)
> I was thinking this was a regression from
> http://hg.mozilla.org/mozilla-central/rev/c043c708384c.

Looks like it! ty (& ty Margaret for getting me the same info simultaneously on irc :P)
Depends on: 1205335
That commit added the line that fails to testDistribution:
  DistroSharedPrefsImport.importPreferences(mActivity, dist);

DistroSharedPrefsImport is a new class added by that patch which calls:
 Distribution.getAndroidPreferences (added by the commit)
  FileUtils.getFileContents

Which throws because the Scanner has no tokens. Distribution.getAndroidPreferences tries to get the contents of `preferences.json`. So:
  * Why is preferences.json sometimes empty when read, causing the Scanner to throw?
  * Why was the addition of reading these preferences necessary in the first place?
(In reply to Michael Comella (:mcomella) from comment #17)
>   * Why was the addition of reading these preferences necessary in the first
> place?

It looks like the patch in bug 1205335 was made to allow distribution files to set SharedPreferences.
fwiw, if we were to take the quick and dirty route, having `FileUtils.getFileContents` return the empty String if the file was empty should suffice, at least for this use case:
  new JSONObject(FileUtils...)

I assume new JSONObject will create an empty Object with the empty String.
(In reply to Michael Comella (:mcomella) from comment #17)
>   * Why is preferences.json sometimes empty when read, causing the Scanner
> to throw?

Nick and Margaret, you reviewed the patch that landed this – it appears the Scanner [1] running on `preferences.json` [2] uses the delimiter of "\\A" (EOL?) and there are no tokens in the Scanner sometimes but not others when running in testDistribution (causing this intermittent). Any ideas why? I can't seem to find any instance of `preferences.json` outside of our code so I'm not sure if it's added as part of the test harness or not and if that's related.

[1]: http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/util/FileUtils.java?rev=11024b678090#91
[2]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/distribution/Distribution.java?rev=c043c708384c#384
Flags: needinfo?(nalexander)
Flags: needinfo?(margaret.leibovic)
I'm not going to continue working on this because my changes in bug 1209967 seem unrelated – I think we're close to fixing this however so flagging for triage.
tracking-fennec: --- → ?
(In reply to Michael Comella (:mcomella) from comment #20)
> (In reply to Michael Comella (:mcomella) from comment #17)
> >   * Why is preferences.json sometimes empty when read, causing the Scanner
> > to throw?
> 
> Nick and Margaret, you reviewed the patch that landed this – it appears the
> Scanner [1] running on `preferences.json` [2] uses the delimiter of "\\A"
> (EOL?) and there are no tokens in the Scanner sometimes but not others when
> running in testDistribution (causing this intermittent). Any ideas why? I
> can't seem to find any instance of `preferences.json` outside of our code so
> I'm not sure if it's added as part of the test harness or not and if that's
> related.

The preferences.json read in this test comes from the distribution in the mock ZIP file we include in test assets here:
http://mxr.mozilla.org/mozilla-central/find?text=&string=mock-package

Not sure why this would be empty sometimes...
Flags: needinfo?(margaret.leibovic)
tracking-fennec: ? → 44+
Sebastian, you've been in this code recently. Any ideas what could be going on here?
Flags: needinfo?(s.kaspari)
I don't know what is causing this yet: The code is looking okay and I haven't seen this failure happening locally. Today I had this test running in a loop on an emulator while having lunch. Not a single failure.
Flags: needinfo?(s.kaspari)
(In reply to Michael Comella (:mcomella) from comment #20)
> (In reply to Michael Comella (:mcomella) from comment #17)
> >   * Why is preferences.json sometimes empty when read, causing the Scanner
> > to throw?
> 
> Nick and Margaret, you reviewed the patch that landed this – it appears the
> Scanner [1] running on `preferences.json` [2] uses the delimiter of "\\A"
> (EOL?) and there are no tokens in the Scanner sometimes but not others when
> running in testDistribution (causing this intermittent). Any ideas why? I
> can't seem to find any instance of `preferences.json` outside of our code so
> I'm not sure if it's added as part of the test harness or not and if that's
> related.
> 
> [1]:
> http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/util/
> FileUtils.java?rev=11024b678090#91
> [2]:
> https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/
> distribution/Distribution.java?rev=c043c708384c#384

I tried to understand this but I see nothing unusual.  I can't explain this; I wonder if we're seeing some problem with file writes not actually making it to the disk before the subsequent read, either due to some OS-level guarantees we're mis-interpreting or due to a race condition of our own making.
Flags: needinfo?(nalexander)
We can recover if we catch the exception, wait, then retry: https://treeherder.mozilla.org/#/jobs?repo=try&revision=404c020a0e49. http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/695d41d7bda37a25351d32538a646db683479fe79a3650b803ef24de22a589409e78eaf6bacc0a419ce4b7b80cbcfa32a92e0711cb42f8c9f7cb3be7385dd9a0 has:

12-23 15:11:49.942  2015  2028 D Robocop : waiting for Distribution:Set:OK
12-23 15:11:49.982  2015  2028 D GeckoDistribution: Getting file from distribution.
12-23 15:11:50.022  2015  2029 D GeckoDistribution: Creating /data/data/org.mozilla.fennec/distribution
12-23 15:11:50.032  2015  2029 D GeckoDistribution: Creating /data/data/org.mozilla.fennec/distribution/extensions
12-23 15:11:50.052  2015  2028 D GeckoDistribution: Creating /data/data/org.mozilla.fennec/distribution/extensions
12-23 15:11:50.072  2015  2028 D GeckoDistribution: Creating /data/data/org.mozilla.fennec/distribution/searchplugins/common
12-23 15:11:50.092  2015  2028 D GeckoDistribution: Creating /data/data/org.mozilla.fennec/distribution/suggestedsites/locales/en-US
12-23 15:11:50.102  2015  2029 E GeckoDistribution: Unable to create directories: /data/data/org.mozilla.fennec/distribution/extensions
12-23 15:11:50.132  2015  2028 W GeckoTestDistribution: NoSuchElementException on first initDistribution -- retrying
12-23 15:11:53.142  2015  2028 D Robocop : waiting for Distribution:Set:OK
12-23 15:11:53.142  2015  2028 D GeckoDistribution: Getting file from distribution.

Anyone got a better idea?
Could we port this test to use Robolectric/Mockito junit tests (like bug 1232984)?

It seems like that would be a more appropriate framework for testing this distribution logic, especially if the source of this problem is the zip file we use to mock the APK.
Flags: needinfo?(s.kaspari)
(In reply to :Margaret Leibovic from comment #34)
> Could we port this test to use Robolectric/Mockito junit tests (like bug
> 1232984)?
> 
> It seems like that would be a more appropriate framework for testing this
> distribution logic, especially if the source of this problem is the zip file
> we use to mock the APK.

Yeah, that's a great idea. Let's try that. (Keeping NI to explore this)
(In reply to Geoff Brown [:gbrown] from comment #33)
> We can recover if we catch the exception, wait, then retry:
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=404c020a0e49.
> http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/
> 695d41d7bda37a25351d32538a646db683479fe79a3650b803ef24de22a589409e78eaf6bacc0
> a419ce4b7b80cbcfa32a92e0711cb42f8c9f7cb3be7385dd9a0 has:

This is interesting too. I wonder what has changed at the time we do the second (successful) try. If we'd know that we could just wait for "this".
Clearing NI: There's currently too much other stuff in the pipeline and having ongoing flags makes me care less about all of them. I still like the idea of writing a Robolectric/Mockito test for this.
Flags: needinfo?(s.kaspari)
Until we have a long-term, sane solution, let's just make it work.

We can leave this open or file a follow-up bug for comment 34.
Attachment #8706509 - Flags: review?(margaret.leibovic)
Attachment #8706509 - Flags: review?(margaret.leibovic) → review+
See Also: → 1239847
https://hg.mozilla.org/mozilla-central/rev/2504e6659015
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 46
You need to log in before you can comment on or make changes to this bug.