Appcenter-sdk-dotnet: SQLite exception sending crashes in UWP

[asierpn]

Description

I've enabled the Crashes SDK in our UWP project, our tests in debug and release with sideloading were succesfull, but after publishing a new version in Windows Store we have started to see this exception in HockeyApp:

Date/Time: 2019-10-29T19:59:23.1704098Z
OS Version: Windows 10.0.18362.418
Report Version: 104

Exception Type: System.AggregateException
Crashed Thread: 13

Application Specific Information:
A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (Corrupt)

Here is the stack trace of the exception
stacktrace.txt

The TrackEvent API of the Analytics SDK is working fine.

Repro Steps

1. Enable App Center Crashes and Analytics in UWP project
2. Call Crashes.TrackError passing a handled exception and some additional properties
3. Publish in Microsoft Store and execute this version

[annakocheshkova]

Hi there, thank you for the report! Do you have any information about the specific types of devices this issue happens on or any environment info?

[asierpn]

We are publishing a new version in Microsoft Store with an option to manually force an exception to try to reproduce the issue.

At this moment this has happened only to one user yesterday using an HP ProDesk 400 G3 from Windows 10.0.18362.418, the SDK version is 2.5.0. The UWP project targets 18362 with minimum version 17763. The AppCenter nuget package is installed in a UWP class library project.

There is 58 crash logs of the same issue and same user with 5 minutes of difference between them.

[annakocheshkova]

Am I correct is this 1.5.0 (not 2.5.0)? Any particular reason you are not updating to the newer versions?

[asierpn]

Oops, sorry for the mistake, it's version 2.5.0

[asierpn]

We have tried to reproduce the issue on other computers and it seems that the issue is only happening on a concrete computer, I've physical access to this computer as it is an internal computer, is there any check we can do on its file system to determine the cause of this exception?

[guperrot]

Do you have a dependency on SQLite? If yes what package are you using with what version? It might be a conflict with the one we depend on from the SDK.

[guperrot]

Another question, what is the inner exception type and message? only the stacktrace was provided or the aggregate exception, but an aggregate exception has at least one inner exception with a more meaningful exception type and message.

[asierpn]

Do you have a dependency on SQLite? If yes what package are you using with what version? It might be a conflict with the one we depend on from the SDK.

We are using Microsoft.Azure.Mobile.Client.SQLiteStore 3.1.0 which has a dependency of SQLitePCLRaw.bundle_green 1.1.2.

The issue is only happening in one device while this version is installed in more than one hundred devices, we will try to re-install the app in that device, I suspect that there is something wrong in the file system.

[asierpn]

Another question, what is the inner exception type and message? only the stacktrace was provided or the aggregate exception, but an aggregate exception has at least one inner exception with a more meaningful exception type and message.

I get the stacktrace from HockeyApp, I will change the exception description to log the last inner exception in the next version of our app.

[guperrot]

So the raw stack trace does not show the intermediate types?

Does the raw view shows System.AggregateException then immediately SQLite.PreparedSqlLiteInsertCommand.ExecuteNonQuery(Object[]) + 0x17d or are there intermediate information you have not shared yet?

[asierpn]

No, I've shared with you the full stack trace

Date/Time: 2019-10-31T20:51:54.0956464Z
OS Version: Windows 10.0.18362.418
Report Version: 104

Exception Type: System.AggregateException
Crashed Thread: 12

Application Specific Information:
A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (Corrupt)

Exception Stack:
unknown location
SQLite.PreparedSqlLiteInsertCommand.ExecuteNonQuery(Object[]) + 0x17d
SQLite.SQLiteConnection.Insert(Object, String, Type) + 0x32c
...

[guperrot]

If you have access to this computer, any chance you can try to get a better stack trace from there? One that would show the real exception type and message. Like attaching VS debugger to the process to see the logs or use the modified build from https://github.com/microsoft/appcenter-sdk-dotnet/issues/1184#issuecomment-550274566.

[guperrot]

(On a side note it's not a crash, it's a silent unobserved exception not causing a crash, HA is subscribing to those by default and report them as a crash and can be very noisy, we changed that in App Center so that it's not a default behavior to report those and we have the concept of errors which are not crashes in App Center with Crashes.TrackError, which is now supported in UWP since v2.5.0).

[asierpn]

I will publish a new version today which will log a detailed inner exception description. It's good to know that this exception is not a crash. Thanks also for the clarification of the difference between error and crash in App Center.

[asierpn]

I'm publishing a new version which will log the detailed inner exception message and stacktrace, but after doing some tests seems that hockeyapp is logging correctly the inner exception message (Corrupt) and stacktrace of this exception.

[guperrot]

Hum now I am confused. You seem to have control on how the unobserved exception is logged to HA while my comment was about an automatic mode in HA SDK so I might have said something inaccurate.

Can you share the details of how you capture this exception and how you forward to HA with custom processing?

Also thanks in advance for sharing the new detailed stack trace once you have it.

[asierpn]

We capture the exceptions with try{}catch{} and we pass them to a LoggingService which in UWP writes the exception to HA:

HockeyClient.Current.TrackException(ex, properties);

We've modified the description of the exception in HA doing this:

      HockeyClient.Current.Configure("ddddddddddddddddddddddddd")
                            .SetExceptionDescriptionLoader((Exception ex) =>
                            {
                              if (ex.InnerException == null)
                              {
                                return string.Format("Message: {0}\r\nUser: {1}\r\nMachine:{2}\r\nStackTrace: {3}",
                                  ex.Message,
                                  App.UserProfile?.UserPrincipalName,
                                  hostName,
                                  ex.StackTrace);
                              }
                              else
                              {
                                var innerException = ex;
                                while (innerException.InnerException != null)
                                  innerException = ex.InnerException;
                                return string.Format("Message: {0}\r\nUser: {1}\r\nMachine:{2}\r\nStackTrace: {3}\r\nInner Message: {4}\r\nInner StackTrace: {5}",
                                  ex.Message,
                                  App.UserProfile?.UserPrincipalName,
                                  hostName,
                                  ex.StackTrace,
                                  innerException.Message,
                                  innerException.StackTrace);
                              }
                            });

Yesterday there was an issue with Microsoft Store, I'm publishing now the new version with this code to see the inner exception details.

We cannot debug easily on the affected machine because it's a production machine which at this moment is used 24/7

[guperrot]

(Oh I see so it would not be any different after migrating to App Center Crashes.TrackError API (except api name), we released the UWP implementation for that one in version 2.5.0).

So yeah it was definitely not a crash if you were capturing it, unless you re-throw it after? Are you calling that in https://docs.microsoft.com/en-us/dotnet/api/system.threading.tasks.taskscheduler.unobservedtaskexception?view=dotnet-uwp-10.0 callback?

Anyway, we will wait for the stack trace.

[asierpn]

@guperrot, you are in true, it is a crash, I usually call TrackError from try{}catch{} code block, but in this case the exception is not raised from our code and we are not handling the UnobservedTaskException event so it's HA who is suscribing to those and logging it, I apologize for my error. On the other hand the stacktrace logged originally by HA is the stacktrace of the inner exception, our manual log of the most inner exception's stacktrace is exactly the same:

description.txt

[guperrot]

Hi, UnobservedTaskException are not causing crashes though, those are unhandled errors that HA can report automatically (but on AppCenter we stopped doing that automatically and let you subscribe to the event if you really need to report those as it contains a lot of noise and you might want to filter), but the app should continue running after those.

Regarding the stack trace we are back to square 1 where we don't see the reason why it fails in SQLite. I think we will need to change our own try/catch behavior in that class as it's never supposed to throw in the first place on any error (there are try/catch blocks there but they seem to be not working).

[guperrot]

Ok the message of the exception is actually legit "Corrupt", that part confused me but it looks like a real message as shown in https://forums.xamarin.com/discussion/23979/sqlite-database-corrupt. We always access sqlite in a sequential way so that cannot be the cause of corruption.

It looks like we need a failover to delete corrupted databases and start over, we already have that cleanup code in Android and iOS SDKs.

Also to confirm unhandled unobserved exceptions do not crash the app (no exit):

I caused the code to throw a fake exception in the same method and test logging it:

diff --git a/Apps/Contoso.UWP.Puppet/App.xaml.cs b/Apps/Contoso.UWP.Puppet/App.xaml.cs
index f1d25cce..47d2a738 100644
--- a/Apps/Contoso.UWP.Puppet/App.xaml.cs
+++ b/Apps/Contoso.UWP.Puppet/App.xaml.cs
@@ -13,6 +13,7 @@ using Windows.UI.Xaml.Controls;
 using Windows.UI.Xaml.Navigation;
 using Microsoft.AppCenter.Analytics;
 using Microsoft.AppCenter.Crashes;
+using System.Threading.Tasks;

 namespace Contoso.UWP.Puppet
 {
@@ -27,6 +28,10 @@ namespace Contoso.UWP.Puppet
         /// </summary>
         public App()
         {
+            TaskScheduler.UnobservedTaskException += (object sender, UnobservedTaskExceptionEventArgs args) =>
+            {
+                AppCenterLog.Error("AppCenterPuppet", "Unobserved exception observed=" + args.Observed, args.Exception);
+            };
             CoreApplication.EnablePrelaunch(true);
             InitializeComponent();
             Suspending += OnSuspending;
diff --git a/SDK/AppCenter/Microsoft.AppCenter.Windows.Shared/Storage/Storage.cs b/SDK/AppCenter/Microsoft.AppCenter.Windows.Shared/Storage/Storage.cs
index aff340db..2df51e75 100644
--- a/SDK/AppCenter/Microsoft.AppCenter.Windows.Shared/Storage/Storage.cs
+++ b/SDK/AppCenter/Microsoft.AppCenter.Windows.Shared/Storage/Storage.cs
@@ -91,6 +91,7 @@ namespace Microsoft.AppCenter.Storage
                 var logJsonString = LogSerializer.Serialize(log);
                 var logEntry = new LogEntry { Channel = channelName, Log = logJsonString };
                 _storageAdapter.InsertAsync(logEntry).GetAwaiter().GetResult();
+                Task.Run(() => throw new Exception("Corrupt")).GetAwaiter().GetResult();
             });
         }

@@ -275,7 +276,7 @@ namespace Microsoft.AppCenter.Storage
             _pendingDbIdentifierGroups.Add(GetFullIdentifier(channelName, batchId), ids);
             AppCenterLog.Debug(AppCenterLog.LogTag, message);
         }
-
+
         private async Task InitializeDatabaseAsync()
         {
             try
@@ -392,6 +393,8 @@ namespace Microsoft.AppCenter.Storage
                     // Can't throw exceptions here because it will cause the FlushQueue to stop
                     // processing, but if the task faults, the exception will be thrown again
                     // because the original creator of this task will await it too.
+                    GC.Collect();
+                    GC.WaitForPendingFinalizers();
                 }
             }
         }

And got something really close:

2019-11-11 15:52:16.749 [AppCenterPuppet] ERROR: Unobserved exception observed=False
System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (Corrupt) ---> System.Exception: Corrupt
   at Microsoft.AppCenter.Storage.Storage.<>c.<PutLog>b__11_1()
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.AppCenter.Storage.Storage.<>c__DisplayClass11_0.<PutLog>b__0()
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AppCenter.Storage.Storage.<FlushQueueAsync>d__27.MoveNext()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Exception: Corrupt
   at Microsoft.AppCenter.Storage.Storage.<>c.<PutLog>b__11_1()
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.AppCenter.Storage.Storage.<>c__DisplayClass11_0.<PutLog>b__0()
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AppCenter.Storage.Storage.<FlushQueueAsync>d__27.MoveNext()<---

So I see 2 actions on our side:

• Don't throw unobserved exceptions from our SDK.
• Delete corrupted databases automatically and log an error with AppCenterLog.

[asierpn]

Great, that makes sense

[guperrot]

Version 2.6.2 fixes the behavior of SQLite exceptions so that they are no longer unobserved. In addition corrupted databases will be deleted and re-created.

[myokeeh]

Specifically for those using Microsoft.Azure.Mobile.Client and Microsoft.Azure.Mobile.Client.SQLiteStore, version 4.2.0 released today fixes this.