1302601 - Permaorange (test) Halting on failure while running ['python2.7', 'mach', '--log-no-times', 'gradle', 'app:testAutomationDebugUnitTest']

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=3454637&repo=autoland

https://queue.taskcluster.net/v1/task/EJ-VOFkOSqSo8VBjq7IK4Q/runs/0/artifacts/public%2Flogs%2Flive_backing.log

Apparently something on autoland didn't like something being merged to it.

Comment 1

[Phil Ringnalda (:philor)]

Hidden on all trunk trees, in anticipation of that getting merged back around and spreading the burn everywhere else.

Comment 2

[Sebastian Kaspari (:sebastian; :pocmo)]

https://public-artifacts.taskcluster.net/EJ-VOFkOSqSo8VBjq7IK4Q/0/public/android/unittest/automationDebug/index.html

2 failures:
* BrowserProviderHistoryTest. testHistoryExpirationNormalOld
* BrowserProviderHistoryTest. testHistoryVisitAggregates

Comment 3

[Sebastian Kaspari (:sebastian; :pocmo)]

I see those failures locally too.

@grisha: Do you have time looking into why this is happening? Did we change anything regarding history?

Comment 4

[:Grisha Kruglov]

(In reply to Sebastian Kaspari (:sebastian) from comment #3)
> I see those failures locally too.
> 
> @grisha: Do you have time looking into why this is happening? Did we change
> anything regarding history?

I don't believe anything changed. Seeing those failures locally as well. I'll investigate.

Comment 5

[:Grisha Kruglov]

This is the commit that breaks the tests, from the recently landed Bug 1293710:

https://hg.mozilla.org/mozilla-central/diff/20809b09b2ff/mobile/android/tests/background/junit4/src/org/mozilla/gecko/db/BrowserProviderHistoryVisitsTestBase.java#l1.60

Comment 6

[:Grisha Kruglov]

Attachment: Bug 1302601 - Fix broken tests - poor method override

Review commit: https://reviewboard.mozilla.org/r/80864/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/80864/

Comment 7

[:Grisha Kruglov]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=506c8ac43b3a

Comment 8

[Andrzej Hunt :ahunt]

Comment on attachment 8794378 [details]
Bug 1302601 - Fix broken tests - poor method override

https://reviewboard.mozilla.org/r/80864/#review79524

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b451b91d4b46
Fix broken tests - poor method override r=ahunt

Comment 10

[Iris Hsiao [:ihsiao]]

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

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/82908a457460

Comment 12

[Ryan VanderMeulen [:RyanVM]]

This is still failing on Trunk and Aurora.
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-searchStr=tc(test)&exclusion_profile=false

Comment 13

[:Grisha Kruglov]

Test failures I'm seeing now are different, seem to now resolve around managing SQL connections.

testGetRecentHistoryVisitsForGUID

java.lang.RuntimeException: java.util.concurrent.ExecutionException: java.lang.IllegalStateException: Illegal connection pointer 1. Current pointers for thread Thread[pool-571-thread-1,5,main] []
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.execute(ShadowSQLiteConnection.java:469)
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.prepareStatement(ShadowSQLiteConnection.java:388)
	at org.robolectric.shadows.ShadowSQLiteConnection.nativePrepareStatement(ShadowSQLiteConnection.java:79)
	at android.database.sqlite.SQLiteConnection.nativePrepareStatement(SQLiteConnection.java)
	at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:889)
	at android.database.sqlite.SQLiteConnection.execute(SQLiteConnection.java:548)
	at android.database.sqlite.SQLiteSession.beginTransactionUnchecked(SQLiteSession.java:323)
	at android.database.sqlite.SQLiteSession.beginTransaction(SQLiteSession.java:298)
	at android.database.sqlite.SQLiteDatabase.beginTransaction(SQLiteDatabase.java:505)
	at android.database.sqlite.SQLiteDatabase.beginTransaction(SQLiteDatabase.java:416)
	at org.mozilla.gecko.db.AbstractTransactionalProvider.beginWrite(AbstractTransactionalProvider.java:121)
	at org.mozilla.gecko.db.BrowserProvider.insertHistory(BrowserProvider.java:1595)
	at org.mozilla.gecko.db.BrowserProvider.insertInTransaction(BrowserProvider.java:624)
	at org.mozilla.gecko.db.AbstractTransactionalProvider.insert(AbstractTransactionalProvider.java:210)
	at org.robolectric.shadows.ShadowContentProviderClient.insert(ShadowContentProviderClient.java:67)
	at android.content.ContentProviderClient.insert(ContentProviderClient.java)
	at org.mozilla.gecko.sync.repositories.android.VisitsHelperTest.testGetRecentHistoryVisitsForGUID(VisitsHelperTest.java:70)


Another failure of the same test, different stack trace:
testGetRecentHistoryVisitsForGUID

android.database.sqlite.SQLiteCantOpenDatabaseException: Cannot open SQLite connection
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.getSqliteException(ShadowSQLiteConnection.java:481)
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.execute(ShadowSQLiteConnection.java:464)
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.open(ShadowSQLiteConnection.java:365)
	at org.robolectric.shadows.ShadowSQLiteConnection.nativeOpen(ShadowSQLiteConnection.java:73)
	at android.database.sqlite.SQLiteConnection.nativeOpen(SQLiteConnection.java)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:209)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)
	at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
	at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:806)
	at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:791)
	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:694)
	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:1142)
	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:267)
	at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)
	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)
	at org.mozilla.gecko.db.AbstractPerProfileDatabaseProvider.getWritableDatabase(AbstractPerProfileDatabaseProvider.java:61)
	at org.mozilla.gecko.db.AbstractTransactionalProvider.insert(AbstractTransactionalProvider.java:207)
	at org.robolectric.shadows.ShadowContentProviderClient.insert(ShadowContentProviderClient.java:67)
	at android.content.ContentProviderClient.insert(ContentProviderClient.java)
	at org.mozilla.gecko.sync.repositories.android.VisitsHelperTest.testGetRecentHistoryVisitsForGUID(VisitsHelperTest.java:70)


testDatabaseIsQueriesForNormalRequestsWithNetworkSkipped

android.database.sqlite.SQLiteCantOpenDatabaseException: Cannot open SQLite connection
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.getSqliteException(ShadowSQLiteConnection.java:481)
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.execute(ShadowSQLiteConnection.java:464)
	at org.robolectric.shadows.ShadowSQLiteConnection$Connections.open(ShadowSQLiteConnection.java:365)
	at org.robolectric.shadows.ShadowSQLiteConnection.nativeOpen(ShadowSQLiteConnection.java:73)
	at android.database.sqlite.SQLiteConnection.nativeOpen(SQLiteConnection.java)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:209)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)
	at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
	at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:806)
	at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:791)
	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:694)
	at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:234)
	at android.database.sqlite.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:187)
	at org.mozilla.gecko.db.AbstractPerProfileDatabaseProvider.getReadableDatabase(AbstractPerProfileDatabaseProvider.java:43)
	at org.mozilla.gecko.db.BrowserProvider.query(BrowserProvider.java:1228)
	at org.robolectric.shadows.ShadowContentResolver.query(ShadowContentResolver.java:156)
	at android.content.ContentResolver.query(ContentResolver.java)
	at org.mozilla.gecko.db.LocalBrowserDB.getFaviconURLFromPageURL(LocalBrowserDB.java:1247)
	at org.mozilla.gecko.icons.loader.LegacyLoader.loadBitmapFromDatabase(LegacyLoader.java:61)
	at org.mozilla.gecko.icons.loader.TestLegacyLoader.testDatabaseIsQueriesForNormalRequestsWithNetworkSkipped(TestLegacyLoader.java:42)

Comment 14

[Andrzej Hunt :ahunt]

(In reply to :Grisha Kruglov from comment #13)
> Test failures I'm seeing now are different, seem to now resolve around
> managing SQL connections.
> 
> testGetRecentHistoryVisitsForGUID

I found that if I disable TestLegacyLoader.* locally, testGetRecentHistoryVisitsForGUID starts working again.

I've managed to hackily get TestLegacyLoader.* working (with testGetRecentHistoryVisitsForGUID also succeeding) by manually forcing GeckoProfile initilisation as part of the test, but I don't really understand why it isn't working by default yet.

I.e. adding the following to each test in TestLegacyLoader makes things work:
       File profileDir = dirContainingProfile.newFolder();
       GeckoProfile profile = GeckoProfile.get(RuntimeEnvironment.application.getApplicationContext(), "profileName", profileDir);
       BrowserDB db = BrowserDB.from(profile);

Comment 15

[:Grisha Kruglov]

Narrowing this down further, TestLegacyLoader#testDatabaseIsQueriesForNormalRequestsWithNetworkSkipped is what trips everything else up, and more specifically it seems to be this call:
final IconResponse response = loader.load(request);

Comment 16

[Andrzej Hunt :ahunt]

(In reply to :Grisha Kruglov from comment #15)
> Narrowing this down further,
> TestLegacyLoader#testDatabaseIsQueriesForNormalRequestsWithNetworkSkipped is
> what trips everything else up, and more specifically it seems to be this
> call:
> final IconResponse response = loader.load(request);

The difference between this test and other tests is:
- Other tests-
- Create new BrowserProvider
- Query using one of the BrowserContractHelper.***_URI
-- These are built using PARAM_PROFILE == Constants.DEFAULT_PROFILE == "default"
-- We pass this URI to BrowserProvider, and we end up opening a DB based on the URI in AbstractTransactionalProvider
-- So we open a DB for the given profile name
-- Which calls AbstractTransactionDatabaseProivder.getWritableDatabase (or Readable...), which opens a db path based on the profile name.

- LegacyLoader -
- Calls into Favicon code
- Which grabs BrowserDB directly from GeckoProfile
-- But GeckoProfile hasn't been initialised
-- So we have a null profile
-- Which LocalBrowserDB can't handle

I.e. LegacyLoader depends on GeckoProfile being initialised correctly (not a valid assumption in a test). We would either have to convert this test to a robocop test, or ensure GeckoProfile is initialised (which the first 2 lines of my code in comment #14 would do), or read the expected data via a ContentProvider (which I think would miss the point of this test), or rewrite LegacyLoader to read from the ContentProvider using a URI instead of trying to access BrowserDB.

Comment 17

[:Grisha Kruglov]

(In reply to Andrzej Hunt :ahunt from comment #16)
> - LegacyLoader -
> - Calls into Favicon code
> - Which grabs BrowserDB directly from GeckoProfile
> -- But GeckoProfile hasn't been initialised
> -- So we have a null profile
> -- Which LocalBrowserDB can't handle
> 
> I.e. LegacyLoader depends on GeckoProfile being initialised correctly (not a
> valid assumption in a test). We would either have to convert this test to a
> robocop test, or ensure GeckoProfile is initialised (which the first 2 lines
> of my code in comment #14 would do), or read the expected data via a
> ContentProvider (which I think would miss the point of this test), or
> rewrite LegacyLoader to read from the ContentProvider using a URI instead of
> trying to access BrowserDB.

I don't think we have a "null profile" in this case. You can see that when this test runs, a "default" GeckoProfile gets initialized (see GeckoProfile#initFromArgs) and cached (see https://dxr.mozilla.org/mozilla-central/source/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoProfile.java#250).

As such, it makes sense that you can run TestLegacyLoader tests in isolation using Android Studio without any hiccups.

I imagine that if you modify your GeckoProfile initialization snippet from Comment 14 with profile name="default", you will have the exact same problems.

I wonder if "resetting" the GeckoProfile singleton will help at all before the tests are run.

Comment 18

[:Grisha Kruglov]

Indeed, if I poke at GeckoProfile.sProfileCache via reflections right before that loader.load call in testDatabaseIsQueriesForNormalRequestsWithNetworkSkipped, I see that when running tests locally there are already 2 profiles present in the profile cache, and one of them is a "default" profile.

Comment 19

[:Grisha Kruglov]

Couldn't push a patch for a review against this bug, so I filed a follow-up Bug 1305615.