Null formController

[grzesiek2010]

ODK Collect version

v2022.3.0

Android version

9, 10, 11 (maybe other too)

Problem description

https://console.firebase.google.com/u/1/project/api-project-322300403941/crashlytics/app/android:org.odk.collect.android/issues/4e09834954ffc3ee419ef8f9d316d2ed?versions=v2022.3.0%20(4477)&time=last-seven-days&types=crash&sessionEventKey=62EAAD7202EE000131F54D37A810577A_1706145731068221603

Fatal Exception: java.lang.NullPointerException: Attempt to invoke virtual method 'int org.odk.collect.android.javarosawrapper.FormController.getEvent()' on a null object reference
       at org.odk.collect.android.activities.FormEntryActivity.onScreenRefresh(FormEntryActivity.java:1398)
       at org.odk.collect.android.formentry.FormIndexAnimationHandler.handle(FormIndexAnimationHandler.kt:23)
       at org.odk.collect.android.activities.FormEntryActivity.lambda$setupViewModels$7(FormEntryActivity.java:470)
       at org.odk.collect.android.activities.FormEntryActivity.$r8$lambda$T1V91JgXeCj2xNxpJOqRFsZ76xg(FormEntryActivity.java)
       at org.odk.collect.android.activities.FormEntryActivity$$InternalSyntheticLambda$1$c215df7b263d2a4690ddbf172f65e5f56e8023672153174df88d6c10c303a1fb$3.onChanged(FormEntryActivity.java:4)
       at androidx.lifecycle.LiveData.considerNotify(LiveData.java:133)
       at androidx.lifecycle.LiveData.dispatchingValue(LiveData.java:146)
       at androidx.lifecycle.LiveData$ObserverWrapper.activeStateChanged(LiveData.java:468)
       at androidx.lifecycle.LiveData$LifecycleBoundObserver.onStateChanged(LiveData.java:425)
       at androidx.lifecycle.LifecycleRegistry$ObserverWithState.dispatchEvent(LifecycleRegistry.java:354)
       at androidx.lifecycle.LifecycleRegistry.forwardPass(LifecycleRegistry.java:265)
       at androidx.lifecycle.LifecycleRegistry.sync(LifecycleRegistry.java:307)
       at androidx.lifecycle.LifecycleRegistry.moveToState(LifecycleRegistry.java:148)
       at androidx.lifecycle.LifecycleRegistry.handleLifecycleEvent(LifecycleRegistry.java:134)
       at androidx.lifecycle.ReportFragment.dispatch(ReportFragment.java:68)
       at androidx.lifecycle.ReportFragment$LifecycleCallbacks.onActivityPostStarted(ReportFragment.java:187)
       at android.app.Activity.dispatchActivityPostStarted(Activity.java:1396)
       at android.app.Activity.performStart(Activity.java:8268)
       at android.app.ActivityThread.handleStartActivity(ActivityThread.java:3861)
       at android.app.servertransaction.TransactionExecutor.performLifecycleSequence(TransactionExecutor.java:221)
       at android.app.servertransaction.TransactionExecutor.cycleToPath(TransactionExecutor.java:201)
       at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:173)
       at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
       at android.app.ClientTransactionHandler.executeTransaction(ClientTransactionHandler.java:63)
       at android.app.ActivityThread.handleRelaunchActivityLocally(ActivityThread.java:6006)
       at android.app.ActivityThread.access$3400(ActivityThread.java:301)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2335)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loop(Looper.java:246)

[grzesiek2010]

So far I have't been able to reproduce the issue but I'm going to share my thoughts so maybe it will help someone else or I will be able to find something new during describing it.

The crash is caused by null form controller which we take from Collect.getInstance().getFormController(). FormEntryActivity#onScreenRefresh where the crash takes place is called from FormIndexAnimationHandler#handle and FormIndexAnimationHandler#handle is called when FormEntryViewModel#currentIndex is updated.

The only way of updating FormEntryViewModel#currentIndex is calling FormEntryViewModel#updateIndex. The method does not take any parameters but it always updates FormEntryViewModel#currentIndex using formController.getFormIndex() see:

    private void updateIndex() {
        currentIndex.setValue(formController.getFormIndex());
    }

That would mean formController in FormEntryViewModel was NOT NULL (otherwise we would get that crash earlier in FormEntryViewModel#updateIndex) but formController stored in the application class that we access by calling Collect.getInstance().getFormController() was NULL. It would be very strange...

There is one more strange thing... in logs we see that the sequence of events is like: FormEntryActivity#onScreenRefresh <- FormIndexAnimationHandler#handle as I mentioned the only place where we call FormIndexAnimationHandler#handle is a livedata which we only update calling FormEntryViewModel#updateIndex but that FormEntryViewModel#updateIndex is never visible in logs.

Those two strange things make me think that maybe the value in livedata is not updated by us but it's a restored state (we do not consume it). Maybe it's possible somehow that formController in the application class was cleared (or not set yet) but the view model keeps currentIndex and calls update automatically before we setup formController again?

[seadowg]

Those two strange things make me think that maybe the value in livedata is not updated by us but it's a restored state (we do not consume it). Maybe it's possible somehow that formController in the application class was cleared (or not set yet) but the view model keeps currentIndex and calls update automatically before we setup formController again?

Totally agree with this - but, also unsure of how! ViewModels are retained on rotation, so in that case there would be data retained (as the same LiveDataobject would be in play). However, we'd expect the single FormController to still be present in that scenario. Currently, the only thing I can think of, is that there is a way for the line that sets formController to null to be called during some kind of Activity reload where the ViewModel is retained. I need to dig deeper to work out how/if that could happen though.

[grzesiek2010]

The issue was not fixed entirely:

1. We display a dialog and don't know what the root cause is
2. The crash caused by the same toot cause is now visible in a different place: https://console.firebase.google.com/u/1/project/api-project-322300403941/crashlytics/app/android:org.odk.collect.android/issues/840ed61ef4be2a68153d081636ffb8b9?time=last-seven-days&versions=v2022.3.2%20(4485)&types=crash&sessionEventKey=62FC8F5800740001364161D35EAAB21B_1711182400205551772

I'm going to reopen it so that we can continue our conversations/investigation in the same thread. I'll just change the title.

[grzesiek2010]

Thanks to the new logs I can add something more here...

It looks like the issue takes place when a user have two (or more) open forms at the same time. It's not possible to do that from the app directly (from the list of forms) but it is doable if you have multiple shortcuts or you start form filling from external apps (this issue might be related but it's definitely not the only case: https://github.com/getodk/collect/issues/5246)

In the logs you can see that one form is saved and closed but it looks like another one is open. In the logs I also do not see (maybe just in some of them) that a user goes through BlankFormListActivity, it's almost always directly FormEntryActivity so it also indicates that activity is started directly from shortcuts or external apps.

[grzesiek2010]

This should confirm if what I said above is true https://github.com/getodk/collect/pull/5255

[grzesiek2010]

Ok we have new logs here: https://console.firebase.google.com/u/1/project/api-project-322300403941/crashlytics/app/android:org.odk.collect.android/issues/c842c92cb47ec7174307eeb16145c52c?time=last-seven-days&versions=v2022.3.4%20(4496)&types=error&sessionEventKey=630E012802A500011FE48C6644669D8F_1716090298388784704 It can't be more cryptic just look at the logs:

 0 | Tue Aug 30 2022 14:23:04 GMT+0200 (Central European Summer Time) | session_start
 1 | Tue Aug 30 2022 14:23:05 GMT+0200 (Central European Summer Time) | screen_view
 2 | Tue Aug 30 2022 14:23:07 GMT+0200 (Central European Summer Time) | screen_view
 3 | Tue Aug 30 2022 14:23:08 GMT+0200 (Central European Summer Time) | W/null: onCreate f2555f7f3c781ce27d94dd8f00b516b0
 4 | Tue Aug 30 2022 14:23:09 GMT+0200 (Central European Summer Time) | W/null: Setting formController from null to null
 5 | Tue Aug 30 2022 14:23:09 GMT+0200 (Central European Summer Time) | W/null: onStart f2555f7f3c781ce27d94dd8f00b516b0
 6 | Tue Aug 30 2022 14:23:09 GMT+0200 (Central European Summer Time) | W/null: onResume f2555f7f3c781ce27d94dd8f00b516b0
 7 | Tue Aug 30 2022 14:23:09 GMT+0200 (Central European Summer Time) | screen_view
 8 | Tue Aug 30 2022 14:23:11 GMT+0200 (Central European Summer Time) | W/null: onPause f2555f7f3c781ce27d94dd8f00b516b0
 9 | Tue Aug 30 2022 14:23:11 GMT+0200 (Central European Summer Time) | screen_view
10 | Tue Aug 30 2022 14:23:13 GMT+0200 (Central European Summer Time) | W/null: Setting formController from null to null
11 | Tue Aug 30 2022 14:23:13 GMT+0200 (Central European Summer Time) | W/null: onResume f2555f7f3c781ce27d94dd8f00b516b0
12 | Tue Aug 30 2022 14:23:13 GMT+0200 (Central European Summer Time) | screen_view
13 | Tue Aug 30 2022 14:23:15 GMT+0200 (Central European Summer Time) | W/null: Setting formController from null to not null
14 | Tue Aug 30 2022 14:24:29 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@6613a54
15 | Tue Aug 30 2022 14:24:29 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@8239dfd
16 | Tue Aug 30 2022 14:24:29 GMT+0200 (Central European Summer Time) | W/null: Form saved and closed
17 | Tue Aug 30 2022 14:24:30 GMT+0200 (Central European Summer Time) | W/null: onPause f2555f7f3c781ce27d94dd8f00b516b0
18 | Tue Aug 30 2022 14:24:30 GMT+0200 (Central European Summer Time) | screen_view
19 | Tue Aug 30 2022 14:24:30 GMT+0200 (Central European Summer Time) | W/null: onDestroy f2555f7f3c781ce27d94dd8f00b516b0
20 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | screen_view
21 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | W/null: onCreate f2555f7f3c781ce27d94dd8f00b516b0
22 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | W/null: Setting formController from not null to null
23 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | W/null: onStart f2555f7f3c781ce27d94dd8f00b516b0
24 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | W/null: onResume f2555f7f3c781ce27d94dd8f00b516b0
25 | Tue Aug 30 2022 14:24:31 GMT+0200 (Central European Summer Time) | screen_view
26 | Tue Aug 30 2022 14:24:33 GMT+0200 (Central European Summer Time) | W/null: Setting formController from null to not null
27 | Tue Aug 30 2022 14:25:47 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@1a189d5
28 | Tue Aug 30 2022 14:25:47 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@984c5ea
29 | Tue Aug 30 2022 14:25:47 GMT+0200 (Central European Summer Time) | W/null: Form saved and closed
30 | Tue Aug 30 2022 14:25:47 GMT+0200 (Central European Summer Time) | W/null: onPause f2555f7f3c781ce27d94dd8f00b516b0
31 | Tue Aug 30 2022 14:25:47 GMT+0200 (Central European Summer Time) | screen_view
32 | Tue Aug 30 2022 14:25:48 GMT+0200 (Central European Summer Time) | W/null: onDestroy f2555f7f3c781ce27d94dd8f00b516b0
33 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | screen_view
34 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | W/null: onCreate f2555f7f3c781ce27d94dd8f00b516b0
35 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | W/null: Setting formController from not null to null
36 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | W/null: onStart f2555f7f3c781ce27d94dd8f00b516b0
37 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | W/null: onResume f2555f7f3c781ce27d94dd8f00b516b0
38 | Tue Aug 30 2022 14:25:49 GMT+0200 (Central European Summer Time) | screen_view
39 | Tue Aug 30 2022 14:25:51 GMT+0200 (Central European Summer Time) | W/null: Setting formController from null to not null
40 | Tue Aug 30 2022 14:26:46 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@df34c64
41 | Tue Aug 30 2022 14:26:46 GMT+0200 (Central European Summer Time) | W/null: Closing database handler:org.odk.collect.android.externaldata.ExternalSQLiteOpenHelper@b362ecd
42 | Tue Aug 30 2022 14:26:46 GMT+0200 (Central European Summer Time) | W/null: Form saved and closed
43 | Tue Aug 30 2022 14:26:47 GMT+0200 (Central European Summer Time) | W/null: onPause f2555f7f3c781ce27d94dd8f00b516b0
44 | Tue Aug 30 2022 14:26:47 GMT+0200 (Central European Summer Time) | W/null: onDestroy f2555f7f3c781ce27d94dd8f00b516b0
45 | Tue Aug 30 2022 14:26:47 GMT+0200 (Central European Summer Time) | W/null: onCreate f2555f7f3c781ce27d94dd8f00b516b0
46 | Tue Aug 30 2022 14:26:47 GMT+0200 (Central European Summer Time) | W/null: Setting formController from not null to null
47 | Tue Aug 30 2022 14:26:47 GMT+0200 (Central European Summer Time) | W/null: onStart f2555f7f3c781ce27d94dd8f00b516b0

I will translate it to something more readable:

1. ODK Collect is started
2. The user goes to the list of forms and starts Form A
3. The form is filled and saved and the user is moved to the main menu
4. The user repeats steps 2 and 3 filling the same form
5. The user repeats steps 2 and 3 filling the same form once again... but here something weird happens... instead of moving to the main menu after saving the form, FormEntryActivity#onCreate is called immediately after FormEntryActivity#onDestroy and we end up in that state with null form controller.

I have no idea how that could happen. We protect users from multiclicking and opening the same form twice so I don't think it's the case...

[grzesiek2010]

@seadowg If you have anything to share please do. I'm not going to spend more time on it soon because I've run out of ideas... My plan is to:

1. Wait for merging https://github.com/getodk/collect/pull/5254 since it might be somehow related
2. Wait for removing shared form controller object (this pr I believe https://github.com/getodk/collect/pull/5267)
3. Investigate starting multiple FormEntryActivities (for example using shortcuts) what doesn't work well now and also might be a source of many problems.

Once we do all of that we can get back to this issue.

[seadowg]

@grzesiek2010 is this still happening? It looks we're not seeing any of the crases/logs any longer.

[grzesiek2010]

I think we haven't done everything yet to fix different kinds of problems with the null form controller but yes those crashes are not that common now so we can close the issue and get back to it if needed in the future.