1564218 - Intermittent test failure in glean-ac

Status: RESOLVED FIXED

(Data Platform and Tools :: Glean: SDK, defect, P3)

Description

[Michael Droettboom [:mdroettboom]]

SUITE: mozilla.components.service.glean.storages.EventsStorageEngineTest
  TEST: getSnapshot() correctly clears the stores
    [Robolectric] mozilla.components.service.glean.storages.EventsStorageEngineTest.getSnapshot() correctly clears the stores: sdk=28; resources=legacy
    [Robolectric] NOTICE: legacy resources mode is deprecated; see http://robolectric.org/migrating/#migrating-to-40
    I/AssetManager: no overlays.list file found
    I/MonitoringInstr: Instrumentation started!
    I/MonitoringInstr: Setting context classloader to 'org.robolectric.internal.bytecode.SandboxClassLoader@5b8d7829', Original: 'org.robolectric.internal.bytecode.SandboxClassLoader@5b8d7829'
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 1
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 1
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 0
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 0
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 0
    I [glean/Glean] Metrics enabled: true
    I [glean/Glean] Registering pings for mozilla.components.service.glean.GleanMetrics.Pings
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 1
    W/SQLiteConnectionPool: A SQLiteConnection object for database ':memory:' was leaked!  Please fix your application to end transactions in progress properly and to close the database when it is no longer needed.
    W/SQLiteConnectionPool: A SQLiteConnection object for database ':memory:' was leaked!  Please fix your application to end transactions in progress properly and to close the database when it is no longer needed.
    W/SQLiteConnectionPool: A SQLiteConnection object for database ':memory:' was leaked!  Please fix your application to end transactions in progress properly and to close the database when it is no longer needed.
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    W/SQLiteConnectionPool: A SQLiteConnection object for database ':memory:' was leaked!  Please fix your application to end transactions in progress properly and to close the database when it is no longer needed.
    D/SQLiteCursor: received count(*) from native_fill_window: 1
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 0
    I/CursorWindowStats: Created a new Cursor. # Open Cursors=1 (# cursors opened by this proc=1)
    D/SQLiteCursor: received count(*) from native_fill_window: 0
  FAILURE

java.lang.AssertionError: expected:<1> but was:<2>
	at org.junit.Assert.fail(Assert.java:88)
	at org.junit.Assert.failNotEquals(Assert.java:834)
	at org.junit.Assert.assertEquals(Assert.java:118)
	at org.junit.Assert.assertEquals(Assert.java:144)
	at mozilla.components.service.glean.storages.EventsStorageEngineTest.getSnapshot() correctly clears the stores(EventsStorageEngineTest.kt:187)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.robolectric.RobolectricTestRunner$HelperTestRunner$1.evaluate(RobolectricTestRunner.java:601)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.robolectric.internal.SandboxTestRunner$2.evaluate(SandboxTestRunner.java:260)
	at org.robolectric.internal.SandboxTestRunner.runChild(SandboxTestRunner.java:130)
	at org.robolectric.internal.SandboxTestRunner.runChild(SandboxTestRunner.java:42)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.robolectric.internal.SandboxTestRunner$1.evaluate(SandboxTestRunner.java:84)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
	at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
	at sun.reflect.GeneratedMethodAccessor77.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
	at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:118)
	at sun.reflect.GeneratedMethodAccessor76.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:175)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:157)
	at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:748)

Comment 1

[Jan-Erik Rediger [:janerik]]

Would you have a chance to look what's causing this?

Comment 2

[Travis Long [:travis_]]

Yes, if not this week then first of next week for sure

Comment 3

[Travis Long [:travis_]]

I just took a look at what may cause this and it's pretty obscure. The @Before setup for the test explicitly calls EventsStorageEngine.clearAllStores() which should delete the files in the directory right before this test runs, and this test only calls record() once so there should only ever be a single file in the directory when this test runs.

The only thing I can think of that might have an influence here, is that the test WorkManager is being initialized twice, once in resetGlean and once directly in the @Before function. There are a couple of other places in the Glean tests where this is the case so I'm working out a PR to fix it up, but I'm not convinced this is the solution.

Comment 4

[Travis Long [:travis_]]

Attachment: GitHub Pull Request

This PR removes the duplicate calls to WorkManagerTestInitHelper.initializeTestWorkManager(context) that remained after this line was added to resetGlean.

Comment 5

[Travis Long [:travis_]]

Untaking this and leaving in the intake for triage next week.

Comment 6

[Travis Long [:travis_]]

Attachment: Log output

This seems to still be a [thing](https://tools.taskcluster.net/groups/BqqrvaVGTq2L5CsL2vJf3w)

It looks like this test is pretty careful about resetting things before the test is run, so we may need to try something like what I had to do with experiments tests and retrieve the initial value and subtract to do something like:  

`assertEquals(1, currentValue - initialValue)`

Comment 7

[Travis Long [:travis_]]

Another failure: https://tools.taskcluster.net/groups/ZNwzvQBBTsmbGyCQkKhKkA ->
https://taskcluster-artifacts.net/UG2LMUJqRV6zruYkfJhXiQ/0/public/logs/live_backing.log

Comment 8

[Travis Long [:travis_]]

Yet another instance of this occurring here

Comment 10

[Travis Long [:travis_]]

Another report of this from Jon: https://github.com/mozilla-mobile/android-components/issues/3977#issuecomment-528365411

Comment 11

[Travis Long [:travis_]]

Closing this since we haven't had any new reports in 8 months.