Null formController #5241

grzesiek2010 · 2022-08-05T10:46:26Z

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)

The text was updated successfully, but these errors were encountered:

grzesiek2010 · 2022-08-05T11:17:18Z

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 · 2022-08-05T11:35:16Z

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 · 2022-08-17T12:21:19Z

The issue was not fixed entirely:

We display a dialog and don't know what the root cause is
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 · 2022-08-17T12:29:45Z

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: #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 · 2022-08-17T13:13:36Z

This should confirm if what I said above is true #5255

grzesiek2010 · 2022-08-30T17:11:15Z

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:

ODK Collect is started
The user goes to the list of forms and starts Form A
The form is filled and saved and the user is moved to the main menu
The user repeats steps 2 and 3 filling the same form
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 · 2022-09-01T16:08:20Z

@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:

Wait for merging Fixed starting form filling twice #5254 since it might be somehow related
Wait for removing shared form controller object (this pr I believe Allow multiple forms to be filled at once from shortcuts #5267)
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 · 2023-03-13T07:10:10Z

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

grzesiek2010 · 2023-03-14T16:52:02Z

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.

grzesiek2010 added the needs reproduction label Aug 5, 2022

seadowg mentioned this issue Aug 5, 2022

Add logging around suspicious FormEntryActivity code #5243

Merged

3 tasks

seadowg added this to the Hotfix milestone Aug 9, 2022

seadowg mentioned this issue Aug 9, 2022

Show error when mysterious reload crash would happen #5244

Merged

3 tasks

seadowg closed this as completed in #5244 Aug 10, 2022

seadowg removed this from the Hotfix milestone Aug 12, 2022

grzesiek2010 reopened this Aug 17, 2022

grzesiek2010 changed the title ~~NullPointerException: Attempt to invoke virtual method 'int org.odk.collect.android.javarosawrapper.FormController.getEvent()' on a null object reference~~ Null formController Aug 17, 2022

seadowg added the acknowledged label Oct 5, 2022

seadowg added this to the v2022.5 milestone Oct 5, 2022

grzesiek2010 modified the milestones: v2023.1, v2023.2 Feb 21, 2023

seadowg added the needs discussion label Mar 13, 2023

grzesiek2010 closed this as completed Mar 14, 2023

seadowg added this to ODK Collect Mar 20, 2023

github-project-automation bot moved this to icebox in ODK Collect Mar 20, 2023

seadowg moved this from icebox to done in ODK Collect Mar 20, 2023

grzesiek2010 removed this from the v2023.2 milestone Mar 23, 2023

seadowg mentioned this issue Jun 20, 2023

Remove lifecycle logging from FormFillingActivity #5637

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Null formController #5241

Null formController #5241

grzesiek2010 commented Aug 5, 2022

grzesiek2010 commented Aug 5, 2022 •

edited

Loading

seadowg commented Aug 5, 2022

grzesiek2010 commented Aug 17, 2022

grzesiek2010 commented Aug 17, 2022 •

edited

Loading

grzesiek2010 commented Aug 17, 2022

grzesiek2010 commented Aug 30, 2022 •

edited

Loading

grzesiek2010 commented Sep 1, 2022

seadowg commented Mar 13, 2023

grzesiek2010 commented Mar 14, 2023

Null formController #5241

Null formController #5241

Comments

grzesiek2010 commented Aug 5, 2022

ODK Collect version

Android version

Problem description

grzesiek2010 commented Aug 5, 2022 • edited Loading

seadowg commented Aug 5, 2022

grzesiek2010 commented Aug 17, 2022

grzesiek2010 commented Aug 17, 2022 • edited Loading

grzesiek2010 commented Aug 17, 2022

grzesiek2010 commented Aug 30, 2022 • edited Loading

grzesiek2010 commented Sep 1, 2022

seadowg commented Mar 13, 2023

grzesiek2010 commented Mar 14, 2023

grzesiek2010 commented Aug 5, 2022 •

edited

Loading

grzesiek2010 commented Aug 17, 2022 •

edited

Loading

grzesiek2010 commented Aug 30, 2022 •

edited

Loading