Mvvmcross: `System.NullReferenceException` in `MvvmCross.MvxAndroidLog..cctor()`

[ElteHupkes]

🐛 Bug Report

This error is showing up more and more often in our AppCenter logs, and I've experienced it myself on more than one occasion when opening the app after having it in the background for a while. Likely this it happens during a restore from a suspended state. I'm suspecting there is another problem at the root of this, because as far as I can tell MvxAndroidLog is only ever used to log warnings or errors.

The crash occurs immediately during launch of the app, with the stack trace:

System.TypeInitializationException: The type initializer for 'MvvmCross.MvxAndroidLog' threw an exception.
  at MvvmCross.Base.MvxDelegateExtensions.Raise[T] (System.EventHandler`1[TEventArgs] eventHandler, System.Object sender, T value) <0xc5db3688 + 0x0004c> in <9d4f9435ec2e4f689ff8f7c93cbc23d4>:0
  at MvvmCross.Droid.Support.V4.EventSource.MvxEventSourceFragment.OnCreate (Android.OS.Bundle savedInstanceState) <0xc4d5ca10 + 0x00067> in <31c494f50f7540ce98d0d38a64d16c2e>:0
  at MvvmCross.Droid.Support.V4.MvxFragment.OnCreate (Android.OS.Bundle savedInstanceState) <0xc4d57a44 + 0x0000f> in <31c494f50f7540ce98d0d38a64d16c2e>:0
  at Android.Support.V4.App.Fragment.n_OnCreate_Landroid_os_Bundle_ (System.IntPtr jnienv, System.IntPtr native__this, System.IntPtr native_savedInstanceState) <0xc590ff4c + 0x00067> in <d11ad82551744865b825d307f93a6e4b>:0
  at (wrapper dynamic-method) System.Object.49(intptr,intptr,intptr)
--- End of inner exception stack trace ---
  System.NullReferenceException: Object reference not set to an instance of an object
    at MvvmCross.Mvx.Resolve[TService] () <0xc5d53f48 + 0x00034> in <9d4f9435ec2e4f689ff8f7c93cbc23d4>:0
    at MvvmCross.MvxAndroidLog..cctor () <0xc4d55f94 + 0x0002b> in <31c494f50f7540ce98d0d38a64d16c2e>:0

So I suspect the following happens:

• Android attempts to restore some kind of fragment state
• There is something to log or warn about this restore
• MvxAndroidLog is loaded and the static constructor throws an error because the resolve for the log provider fails.

Expected behavior

Debatable. Given the moment that MvxAndroidLog is typically invoked it's arguably quite likely that IMvxLogProvider is not yet available when it is. There would either need to be a fallback to something that does log, otherwise a crash with the message that is logged would be more useful than this NPE.

Reproduction steps

I haven't been able to come up with a convenient repro yet. Triggering MvxAndroidLog to do anything before Setup is complete should be sufficient, but since these classes are internal it's not trivial to do. In my particular case leaving the app alone long enough for it to be suspended and then reopening reproduces it often, but not always. This may or may not happen for any app using fragments - as mentioned, I think there is a different problem going on, which doesn't get logged because the logger crashes...

My main beef here is the MvxAndroidLog classes optimistically assuming that the log provider will be available, which given the moment of its invocation isn't a given.

Configuration

Version: 6.1.2

Platform:

• [ ] :iphone: iOS
• [ x ] :robot: Android
• [ ] :checkered_flag: WPF
• [ ] :earth_americas: UWP
• [ ] :apple: MacOS
• [ ] :tv: tvOS
• [ ] :monkey: Xamarin.Forms

[EGoverde]

I can reproduce this issue with an app containing a viewpager, putting it to the background, then filling the memory of the device using another app and returning to the app (which will reinitialize).

Somehow only a specific build target had this issue, which had 'AotAssemblies' set to true. Once I removed that value the issue disappeared for me.

[ElteHupkes]

Ah, I actually think it only happens here with AOT compiled assemblies also. Let's see if I can figure out what's going on using that information.

[ElteHupkes]

I can confirm that it only happens with AOT enabled. The performance improvement with AOT is so staggering that I'm not considering disabling that though.

I tried to find the underlying error by registering an alternative logger in Fragment.OnCreate() when it was missing, but that approach is a dead end, because I no longer think there is an underlying error, and MvxAndroidLog doesn't really appear to be called before EnsureSetupInitialized(). Instead I think AOT compilation actually results in the type initializer for MvxAndroidLog being executed as soon as MvxBindingFragmentAdapter.HandleCreateCalled() is executed, even though the type is never used. What's even more curious is that this only seems to happen when the class is restored from state. I can reproduce this behavior by putting something like this in a Fragment's OnCreate:

Console.Out.WriteLine("Start of OnCreate");
if ("some string".Contains("nope")) {
    MyStaticClass.SomeMethod();
}

Where MyStaticClass has a constructor with another log statement. When you initially load the fragment, that log statement is never executed. Flooding the phone's memory and then returning to the app results in:

I/MonoDroid: MyStaticClass static constructor
I/MonoDroid: Start of OnCreate

Completely weird, and probably an AOT compilation bug rather than an MvvmCross bug. All that being said, this error could still be prevented by making MvxAndroidLog.Instance lazy rather than being initialized in the static constructor.

I also have a workaround for this particular case: By putting this.EnsureSetupInitialized() as the first statement in OnCreate of your MvxFragment subclass you make sure that the log provider is present before any the callbacks methods where MvxAndroidLog is referenced are executed.

[orestesgaolin]

I also have a workaround for this particular case: By putting this.EnsureSetupInitialized() as the first statement in OnCreate of your MvxFragment subclass you make sure that the log provider is present before any the callbacks methods where MvxAndroidLog is referenced are executed.

I tried to apply your solution in a following way in my BaseActivity, but I still get the TypeInitializationException while returning to the app from background.

public abstract class BaseActivity<T> : MvxAppCompatActivity<T> where T: BaseViewModel
{
    protected abstract int LayoutId { get; }

    protected override void OnCreate(Bundle bundle)
    {
        base.OnCreate(bundle);
        var setup = MvxAndroidSetupSingleton.EnsureSingletonAvailable(ApplicationContext);
        setup.EnsureInitialized();
        SetContentView(LayoutId);
    }
}

The performance improvement when using AOT is so significant that I cannot accept turning it off but on the other hand this problem is also extremely irritating (especially on low-end phones).

[ElteHupkes]

@orestesgaolin From what I can gather from searching for it the MvxAndroidLog isn't used anywhere in MvxAppCompatActivity.OnCreate() so I'm guessing that's not where your problem is. I could be wrong of course. For me it only happens in fragments, which use it in a create callback here. Again, it's not actually used anywhere, just referenced, which triggers the type initializer with AOT.

That being said, this reference happens in the OnCreate method of the fragment, so the workaround needs to be placed before that. This is what the OnCreate of my fragment looks like:

public override void OnCreate(Bundle savedInstanceState)
{
    // Workaround for AOT crash.
    // See https://github.com/MvvmCross/MvvmCross/issues/3115#issuecomment-429814767
    this.EnsureSetupInitialized();
    base.OnCreate(savedInstanceState);
}

i.e. I'm calling this.EnsureSetupInitialized() _before_ calling base.

[ElteHupkes]

By the way for whomever needs help getting their application suspended, I've found Android Toolbelt to be helpful (also available in the Play Store but this one you can just drop into an emulator). It just fills up your memory. At some point Android starts suspending apps and you'll see memory jump up again, that's when you can continue testing. There is no way to keep a debugger attached for this scenario obviously.

[ElteHupkes]

@martijn00 What was the particular reason for this issue being closed? Was something implemented to mitigate this or is the workaround deemed sufficient? I don't particularly care one way or another, it's just unclear to me.

[Cheesebaron]

@ElteHupkes there is a PR referenced + over a year old. If you still see the issue, speak up.

[ElteHupkes]

@Cheesebaron That's what I thought initially, but the referenced PR is for another project. I'm not currently seeing this because I have implemented the workaround, but I have no reason to assume it wouldn't otherwise still be a problem. The reason why this happens with AOT only is still a complete mystery to me so it _may_ have been solved if something changed there. Otherwise the easiest place to solve it is MvvmCross (for AOT compilation I wouldn't even know where to start looking), maybe I can create a PR later this week.