Xamarin Android App Seems to Start Up in the Middle of a Bluetooth Callback Even After Being Removed

Question

I have a Xamarin app build with the latest versions of Xamarin as of when this is being posted.

This app uses a bluetooth plugin, but I am not sure that is relevant.

One of the first things that is done in this app is to initialize a Logging component. The first thing that is output in the logger is the date and time of log creation each time the app starts. The next thing is the version of the app using another component.

That is all done in the ConfigureServices method in the App.xaml.cs file. I use the normal dependency injection provided by Microsoft.

I also have a Start method in my App.xaml.cs file.

The bluetooth component is started up in the Start method that includes a callback for when the bluetooth state changes.

For Android the ConfigureServices is called first in the Android MainActivity file in the OnCreate method. It is not async so I would expect it to complete before anything else would happen.

A few lines later the Start method of App.xaml.cs is called. This is async and is awaited.

When everything is working normally, I can see in the logs that the log file is created, then the Version is output from when the Logger is created and then after a few other things it calls my method that starts trying to communicate with my bluetooth device.

The first thing I should always see at the very stop of the log is:

Log Startup - 2023-03-06 07:28 AM
(3/6/2023 - 7:28:11 AM) [ 0: Information ]Current Version: 2.0.xx

This happens on most phones. The problem I am having is that on only some phones (all Samsung as far as I can tell), the first thing in the log is this:

Log Startup - 2023-03-05 07:39 PM
(3/5/2023 - 7:39:19 PM) [ 0: Information ]Starting Reinitialize:

Starting Reinitialize is a method that should be called when a bluetooth device is connected. At this point in the startup supposedly the bluetooth setup hasn't even really happened yet, so this does not make any sense.

To make matters even more interesting, this will happen even if the user completely removes the app from the phone, reinstalls the app and then deletes the app cache and data so they are both 0.

It is as if the app is starting right in the middle of an async or bluetooth callback even though the app was removed from the phone. I don't know how that is even possible.

I added the output of the stack trace from inside the Reinitialize method.

On a phone that everything is working here is the log with stack trace:

Log Startup - 2023-03-06 07:28 AM
(3/6/2023 - 7:28:11 AM) [ 0: Information ]Current Version: 2.0.21
(3/6/2023 - 7:28:12 AM) [ 0: Debug       ]Setting setup source. Old hash: ; New hash: 1946124341
(3/6/2023 - 7:28:13 AM) [ 0: Debug       ]Waiting on animation...
(3/6/2023 - 7:28:14 AM) [ 0: Debug       ]JWT token expires at 3/3/2023 3:09:54 PM and it is currently 3/6/2023 2:28:14 PM
(3/6/2023 - 7:28:14 AM) [ 0: Information ]Attempting to log in user using stored credentials
(3/6/2023 - 7:28:15 AM) [ 0: Debug       ]Animation complete. Waiting on startup task...
(3/6/2023 - 7:28:16 AM) [ 0: Information ]User logged in
(3/6/2023 - 7:28:16 AM) [ 0: Information ]User logged in using stored credentials
(3/6/2023 - 7:28:16 AM) [ 0: Debug       ]Configuring FLURL
(3/6/2023 - 7:28:16 AM) [ 0: Debug       ]Attempting to connect to the previously known device, if there is one.
(3/6/2023 - 7:28:16 AM) [ 0: Debug       ]Bluetooth device connected. 00000000-0000-0000-0000-c93acebc5355
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Updating MTU size to 237 after requesting 255.
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Setting task complete so that things can continue.
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Firing external connected subscription
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Application started up.
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]JWT token expires at 3/8/2023 2:28:15 PM and it is currently 3/6/2023 2:28:17 PM
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Initializing user licenses.
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]JWT token expires at 3/8/2023 2:28:15 PM and it is currently 3/6/2023 2:28:17 PM
(3/6/2023 - 7:28:17 AM) [ 0: Debug       ]Tuner was connected. Reinitializing tuner.
(3/6/2023 - 7:28:17 AM) [ 0: Information ]Starting Reinitialize: 
  at System.Environment.get_StackTrace () [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/corlib/System/Environment.cs:316 
  at DynoJet.Device.Harley.PV4.Reinitialize () [0x0000f] in /Users/tpitman/Projects/Mindfire/Dynojet/Dynojet-PV4/Source/DynoJet.Device.Harley/PV4.cs:640 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine] (TStateMachine& stateMachine) [0x0002c] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:316 
  at DynoJet.Device.Harley.PV4.Reinitialize () [0x00000] in <26ab81599ca14679b2a2e6698b7d4ff4>:0 
  at DynoJet.App+<>c__DisplayClass25_0.b__6 (DynoJet.Device.Bluetooth.ConnectionArgs state) [0x0039a] in /Users/tpitman/Projects/Mindfire/Dynojet/Dynojet-PV4/Source/DynoJet/DynoJet/App.xaml.cs:355 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.InvokeMoveNext (System.Object stateMachine) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:1092 
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00071] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:968 
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:910 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run () [0x00024] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:1073 
  at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction (System.Action action, System.Boolean allowInlining, System.Threading.Tasks.Task& currentTask) [0x0001a] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/TaskContinuation.cs:676 
  at System.Threading.Tasks.Task.FinishContinuations () [0x00052] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:3165 
  at System.Threading.Tasks.Task.FinishStageThree () [0x0003c] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2222 
  at System.Threading.Tasks.Task`1[TResult].TrySetResult (TResult result) [0x0004f] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:422 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[TResult].SetResult (TResult result) [0x0003d] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:608 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[TResult].SetResult (System.Threading.Tasks.Task`1[TResult] completedTask) [0x00010] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:636 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult () [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:378 
  at DynoJet.Analytics.Service.AnalyticsService.MakeAssociation (System.String deviceGuid, System.Nullable`1[T] vehicleRegistrationId) [0x000f1] in /Users/tpitman/Projects/Mindfire/Dynojet/Dynojet-PV4/Source/DynoJet.Analytics.Service/AnalyticsService.cs:48 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.InvokeMoveNext (System.Object stateMachine) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:1092 
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00071] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:968 
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:910 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run () [0x00024] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/runtime/compilerservices/AsyncMethodBuilder.cs:1073 
  at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction (System.Action action, System.Boolean allowInlining, System.Threading.Tasks.Task& currentTask) [0x0001a] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/TaskContinuation.cs:676 
  at System.Threading.Tasks.Task.FinishContinuations () [0x00052] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:3165 
  at System.Threading.Tasks.Task.FinishStageThree () [0x0003c] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2222 
  at System.Threading.Tasks.Task`1[TResult].TrySetResult (TResult result) [0x0004f] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:422 
  at System.Threading.Tasks.TaskCompletionSource`1[TResult].TrySetResult (TResult result) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corefx/src/Common/src/CoreLib/System/Threading/Tasks/TaskCompletionSource.cs:274 
  at DynoJet.ApplicationService+<>c__DisplayClass6_0.b__1 (System.Threading.Tasks.Task task) [0x0000d] in /Users/tpitman/Projects/Mindfire/Dynojet/Dynojet-PV4/Source/DynoJet/DynoJet/ApplicationService.cs:32 
  at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke () [0x00024] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/TaskContinuation.cs:61 
  at System.Threading.Tasks.Task.Execute () [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2319 
  at System.Threading.Tasks.Task.ExecutionContextCallback (System.Object obj) [0x00006] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2463 
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00071] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:968 
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/executioncontext.cs:910 
  at System.Threading.Tasks.Task.ExecuteWithThreadLocal (System.Threading.Tasks.Task& currentTaskSlot) [0x00034] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/corlib/corert/Task.cs:72 
  at System.Threading.Tasks.Task.ExecuteEntry (System.Boolean bPreventDoubleExecution) [0x0004a] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2385 
  at System.Threading.Tasks.Task.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem () [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/external/corert/src/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:2334 
  at System.Threading.ThreadPoolWorkQueue.Dispatch () [0x00074] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/threadpool.cs:899 
  at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback () [0x00000] in /Users/builder/jenkins/workspace/archive-mono/2020-02/android/release/mcs/class/referencesource/mscorlib/system/threading/threadpool.cs:1261

As you can see lots of things happen before Reinitialize is ever called and the call stack is pretty big.

On a phone that is doing the weird startup as if it is starting in the middle of thing even after being removed, here is the log with the stack output of the same Reinitialize method:

Log Startup - 2023-03-05 07:39 PM
(3/5/2023 - 7:39:19 PM) [ 0: Information ]Starting Reinitialize: 
  at System.Environment.get_StackTrace () [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at DynoJet.Device.Harley.PV4.Reinitialize () [0x00000] in :0 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine] (TStateMachine& stateMachine) [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at DynoJet.Device.Harley.PV4.Reinitialize () [0x00000] in :0 
  at DynoJet.App+<>c__DisplayClass25_0.b__6 (DynoJet.Device.Bluetooth.ConnectionArgs state) [0x00000] in :0 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.InvokeMoveNext (System.Object stateMachine) [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run () [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Threading.Tasks.AwaitTaskContinuation.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem () [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Threading.ThreadPoolWorkQueue.Dispatch () [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0 
  at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback () [0x00000] in <7c78984e9f0e44b3b1e1a5d30389bb5b>:0

Notice how all of the normal startup is totally skipped and the Reinitialize stack trace is very short as if it is starting right in the middle of something.

I have one user who this happens to on a Samsung Note 20. Their son also has the same exact model of Samsung Note 20 and this does NOT happen on his son's phone.

I have not been able to reproduce the issue on any of my Samsung phones, but I do have more than one user in the field with this issue.

Can someone please explain to me what is going on and how to fix it?

I could try to add some hacking check to see if certain things have happened in the app at the point Reinitialize is being called and if those things haven't happened, just abort, but I am hoping someone can explain what is actually happening so I can fix the root cause or somehow change that behavior on these phones that it happens on.