Closed Bug 824067 Opened 12 years ago Closed 6 years ago

Intermittent testPasswordEncrypt | Error invoking method - java.lang.reflect.InvocationTargetException

Categories

(Firefox for Android Graveyard :: General, defect, P3)

Product:
Firefox for Android Graveyard
Component:
General
Platform:
ARM
Android
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: emorley, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled][leave open])

Attachments

(1 file)

enable testPasswordEncrypt
3.30 KB, patch
wesj
: review+
Details | Diff | Splinter Review 
Android no-ionmonkey Tegra 250 mozilla-inbound opt test robocop on 2012-12-20 20:49:28 PST for push bcb3c5c91c28

slave: tegra-132

https://tbpl.mozilla.org/php/getParsedLog.php?id=18153624&tree=Mozilla-Inbound

{
1 INFO TEST-START | testPasswordEncrypt
2 INFO TEST-PASS | testPasswordEncrypt | Found a content resolver - android.app.ContextImpl$ApplicationContentResolver@484bb9b8 should not equal null
3 INFO TEST-PASS | testPasswordEncrypt | Insert returned correct uri - content://org.mozilla.fennec.db.passwords/passwords/1?profilePath=%2Fmnt%2Fsdcard%2Ftests%2Fprofile should equal content://org.mozilla.fennec.db.passwords/passwords/1?profilePath=%2Fmnt%2Fsdcard%2Ftests%2Fprofile
4 INFO TEST-UNEXPECTED-FAIL | testPasswordEncrypt | Error invoking method - java.lang.reflect.InvocationTargetException
Exception caught during test!
junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testPasswordEncrypt | Error invoking method - java.lang.reflect.InvocationTargetException
	at junit.framework.Assert.fail(Assert.java:47)
	at org.mozilla.fennec.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:107)
	at org.mozilla.fennec.FennecMochitestAssert.ok(FennecMochitestAssert.java:136)
	at org.mozilla.fennec.tests.testPasswordEncrypt.testPasswordEncrypt(testPasswordEncrypt.java:121)
	at java.lang.reflect.Method.invokeNative(Native Method)
	at java.lang.reflect.Method.invoke(Method.java:521)
	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:122)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at junit.framework.TestResult$1.protect(TestResult.java:106)
	at junit.framework.TestResult.runProtected(TestResult.java:124)
	at junit.framework.TestResult.run(TestResult.java:109)
	at junit.framework.TestCase.run(TestCase.java:118)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
5 INFO TEST-UNEXPECTED-FAIL | testPasswordEncrypt | Exception caught - junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testPasswordEncrypt | Error invoking method - java.lang.reflect.InvocationTargetException
}
Looks like this is caused by bug 823705....I don't see how yet.
(In reply to Geoff Brown [:gbrown] (PTO Dec 21-31) from comment #3)
> Looks like this is caused by bug 823705....I don't see how yet.

Yeah that's the only thing I can see.
Blocks: 823705
With custom logging, I found that the exception causing the failure is:

12-28 20:37:18.901  3517  3525 W System.err: java.lang.reflect.InvocationTargetException
12-28 20:37:18.921  3517  3525 W System.err: 	at org.mozilla.gecko.NSSBridge.decrypt(NSSBridge.java:46)
12-28 20:37:18.921  3517  3525 W System.err: 	at java.lang.reflect.Method.invokeNative(Native Method)
12-28 20:37:18.921  3517  3525 W System.err: 	at java.lang.reflect.Method.invoke(Method.java:521)
12-28 20:37:18.921  3517  3525 W System.err: 	at org.mozilla.fennec.tests.testPasswordEncrypt.testPasswordEncrypt(testPasswordEncrypt.java:68)
12-28 20:37:18.921  3517  3525 W System.err: 	at java.lang.reflect.Method.invokeNative(Native Method)
12-28 20:37:18.921  3517  3525 W System.err: 	at java.lang.reflect.Method.invoke(Method.java:521)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
12-28 20:37:18.921  3517  3525 W System.err: 	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:125)
12-28 20:37:18.921  3517  3525 W System.err: 	at junit.framework.TestCase.runBare(TestCase.java:127)
12-28 20:37:18.921  3517  3525 W System.err: 	at junit.framework.TestResult$1.protect(TestResult.java:106)
12-28 20:37:18.921  3517  3525 W System.err: 	at junit.framework.TestResult.runProtected(TestResult.java:124)
12-28 20:37:18.921  3517  3525 W System.err: 	at junit.framework.TestResult.run(TestResult.java:109)
12-28 20:37:18.921  3517  3525 W System.err: 	at junit.framework.TestCase.run(TestCase.java:118)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
12-28 20:37:18.921  3517  3525 W System.err: 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
12-28 20:37:18.921  3517  3525 W System.err: Caused by: java.lang.Exception: PK11SDR_Decrypt returned error -12285: Unable to find the certificate or key necessary for authentication.
12-28 20:37:18.921  3517  3525 W System.err: 	at org.mozilla.gecko.NSSBridge.nativeDecrypt(Native Method)
12-28 20:37:18.921  3517  3525 W System.err: 	... 19 more
(In reply to Geoff Brown [:gbrown] (PTO Dec 21-31) from comment #53)
> With custom logging, I found that the exception causing the failure is:

Slightly offtopic, but is this logging that we could (/should) be running by default? :-)
I am not sure how to fix this. 

wesj -- any ideas? If not, we should probably disable this test for now.
Flags: needinfo?(wjohnston)
I'm going to try pushing this to try and see if we can get any extra info about the exception. If you want to disable it in the mean time, that's fine. Master password seems to be working fine in my nightly builds.
Flags: needinfo?(wjohnston)
The error being thrown in native code is:

java.lang.Exception: PK11SDR_Decrypt returned error -12285: Unable to find the certificate or key necessary for authentication.
http://mxr.mozilla.org/mozilla-central/source/mozglue/android/NSSBridge.cpp#213

(from : https://tbpl.mozilla.org/php/getParsedLog.php?id=18413484&tree=Try&full=1#error0 )

I wonder if we're running really early and somehow despite calling NSS_Initialize here:
http://mxr.mozilla.org/mozilla-central/source/mozglue/android/NSSBridge.cpp#154
the keys and db aren't being set up correctly (maybe we made something async that wasn't previously?) Brian sits near by and volunteered to come look with me when he's clear of some b2g blockers.
Test disabled while we figure out what's happening: https://hg.mozilla.org/integration/mozilla-inbound/rev/7f2728cfad82
Whiteboard: [test disabled][leave open]
(In reply to Geoff Brown [:gbrown] from comment #76)
> Test disabled while we figure out what's happening:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/7f2728cfad82

Thank you :-)
I talked to brian about this. He was suspicious this was an old intermittent that was made worse by the upgrade. I don't think we actually used to see many failures in this test (correct me if I'm wrong). He told me to assign it to him and he'd look once this b2g work has settled down a bit.
Assignee: nobody → bsmith
> > Test disabled while we figure out what's happening:
> > https://hg.mozilla.org/integration/mozilla-inbound/rev/7f2728cfad82


We want to perform tests, to find the out what triggered the test.

But before we did that, we wanted to confirm that we indeed still experience that failure, it the test gets reenabled.

But apparently we don't?

In this try build:
https://tbpl.mozilla.org/?tree=Try&rev=eded7fc2daea

I had reenabled the test, and in 15 test cycles, we never got a testPasswordEncrypt failure. 13 cycles were green, and two cycles were orange with other failures.
It seems like Kai is working on this, so I'm changing the assigned-to field to him. Feel free to assign it back to me if you stop working on it.

Wes wrote (in email):
> In the wild this code is run in second process
> (through the PasswordProvider service). When we test the password
> provider (in testPasswordProvider) I assume that still happens. These
> tests just test the NSS Bridge explicitly though. So they're likely
> running in the same process as Gecko.

What is the "NSS bridge", exactly?

> There's no threading in the PasswordProvider as well, but when these
> tests are running, we're starting Gecko. In fact, we have this
> blockForGeckoReady call at the top that ensures that we've basically
> loaded browser.xul and done some initial setup (started loading a
> page I think). That's all definitely happening in a separate thread.
> 
> Any advice on how to better handle multiple threads here?

If you are running in the Gecko process, you must not call NSS_Init* or NSS_Shutdown yourself; instead you must have PSM do it. And, that means you must something like this (either in JS or C++) on the main thread before you ever use NSS:

    nsresult rv;
    nsCOMPtr<nsISupports> dummyUsedToEnsureNSSIsInitialized
      = do_GetService("@mozilla.org/psm;1", &rv);
    NS_ENSURE_SUCCESS(rv, rv);

And, also, if your NSS-using code runs off the main thread, then you should run that code within a subclass of CryptoTask (security/manager/ssl/src/CryptoTask.h).

Cheers,
Brian
Assignee: bsmith → kaie
No, I'm not working on it, assigning back.

Wan-Teh had asked me to find out if this is a bug in NSS or not, and it looks it it's not, that's all I wanted to achieve.
Assignee: kaie → bsmith
This patch removes the call to loadNSSLibs and re-enables the test. It passes try just fine: https://tbpl.mozilla.org/?tree=Try&rev=e6937e9943ac.

The test waits for Gecko:Ready anyway, and that's well after Fennec has loaded NSS, so I think any explicit call to loadNSSLibs is redundant.

There are bigger issues raised in Comment 87, and I don't want to see those glossed over, but I would like to get this test enabled as soon as possible: We could [leave open] this bug for follow-up or spin off another bug. Thoughts?
Attachment #713018 - Flags: review?(wjohnston)
Attachment #713018 - Flags: feedback?(bsmith)
I am unsure what "Gecko:Ready" precisely signifies. In particular, I'm not sure it is guaranteed anywhere that NSS has been started up before Gecko:Ready.

What you're proposing sounds reasonable if we file the follow-up bug for fixing the potential race against NSS shutdown due to the lack of use of the CryptoTask/nsNSSShutdownObject constructs.
(In reply to Brian Smith (:bsmith) from comment #90)
> I am unsure what "Gecko:Ready" precisely signifies. In particular, I'm not
> sure it is guaranteed anywhere that NSS has been started up before
> Gecko:Ready.

Gecko:Ready happens sometime after the GeckoThread.run() method calls GeckoAppShell.runGecko(), which happens sometime after the call to GeckoLoader.loadNSSLibs() in GeckoThread.initGeckoEnvironment(). So the NSS libs are guaranteed to have been loaded before Gecko:Ready is fired.
Attachment #713018 - Flags: review?(wjohnston) → review+
It's not failing consistently any more, but it's still failing. Disabled again: https://hg.mozilla.org/integration/mozilla-inbound/rev/cef766712c20
Whiteboard: [test disabled][leave open]
Attachment #713018 - Flags: feedback?(bsmith)
Assignee: brian → nobody
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Mass-closing old bugs I filed that have not had recent activity/no longer affect me.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: