Playground – Part 3: Catch it, trace it, log it and upload it

This article is part of a series called Playground:

• Playground – Part 1: A Xamarin.Forms Microsoft.Extended journey
• Playground – Part 2: Settings with Options pattern
• Playground – Part 3: Catch it, trace it, log it and upload it (this one)

In the previous article, we implemented our settings layer. In this one, we’ll add some logging capabilities to our Playground.

As Shiny comes with its own logging system built in, I was wondering if official Microsoft.Extensions.Logging packages could add some more value or not.

Actually, not so much as it adds a lot more package dependencies for almost the same job offered by Shiny.Core’s logging system.

Also, if Shiny’s ILogger interface offers the opportunity to save some more key/value parameters while tracking events and exceptions, it’s not available into the extension one AFAIK.

So, if we’ll use a built-in feature, why this article? Because I want more 🙂

First of all, we just configured settings, now it’s time to use it to initialize AppCenter.

Then, what I’d like would be getting an attached log file to any AppCenter error (managed exceptions or not), so I could read what the user was about to do just before the exception. I mean not only the exception trace itself but any locally tracked event before it just occurred. I’m saying locally because I don’t want to track everything the user does to AppCenter Events, but I want it all only in case of exception. This way, it would help me to understand what’s the behavior ending to this exception, because you know, sometimes exceptions are not absolutely crystal clear… and most of all, it would be so helpful to get a reproduction scenario attached to AppCenter error entries! Something more useful than just this famous scenario:

• “hey, it doesn’t work!”
  • “ok, what did you do?”
• “I can’t remember!”
  • “hum, okay thanks…”

Well, to be honest, AppCenter share some useful info already to understand what happened. But I told you, I want more!

Finally, there are things to do about catching, we’ll see.

So let’s code!

Do not install the Shiny’s AppCenter integration nuget package as we’ll create our own logger.

Create a Logging folder.

Then we’ll create our own file logger which will log everything into a file obviously, but limited to a max line number. We make it line limited to prevent from unlimited growing and because we really don’t care about what event happened this morning during breakfast, when the exception just occurred this evening. I need last X lines for each exception, not all day log for all exceptions!

Ok so it’s limited to 1000 lines max let’s admit, but, I want it to continue logging new entries even if we reached the limit 🙂 We’re not talking about rolling files here, but lines replacement. When the limit has been reached, I want it to drop the first one (the older line) and add the new coming one, like my tv box timeshifting feature.

To do that, create a LimitedFileLogger.cs file into the Logging folder, with this content:

    public class LimitedFileLogger : ILogger
    {
        private readonly object _syncLock = new object();
        private readonly string _filePath;
        private readonly int _maxLines;

        public LimitedFileLogger(IOptions<FileLoggerSettings> fileLoggerSettings, IFileSystem fileSystem)
        {
#if DEBUG
            _filePath = Path.Combine(fileSystem.Public.FullName, fileLoggerSettings.Value.LogFileName);
#else
            _filePath = Path.Combine(fileSystem.AppData.FullName, fileLoggerSettings.Value.LogFileName);
#endif
            _maxLines = fileLoggerSettings.Value.LogFileMaxLines;
        }

        public void Write(Exception exception, params (string Key, string Value)[] parameters)
        {
            var message = $@"[{DateTime.Now:MM/d/yyyy hh:mm:ss tt}] {exception}";

            Write(message);
        }


        public void Write(string eventName, string description, params (string Key, string Value)[] parameters)
        {
            var message = $@"[{DateTime.Now:MM/d/yyyy hh:mm:ss tt}] {eventName}";
            if (!string.IsNullOrWhiteSpace(description))
                message += $" - {description}";

            Write(message);
        }

        private void Write(string message)
        {
            lock (_syncLock)
            {
                if (!File.Exists(_filePath))
                {
                    File.AppendAllText(_filePath, message);
                    return;
                }

                var logEntries = File.ReadAllLines(_filePath).ToList();

                logEntries.Add(message);

                while (logEntries.Count > _maxLines)
                    logEntries.RemoveAt(0);

                File.WriteAllLines(_filePath, logEntries);
            }
        }
    }

Our file logger needs 2 parameters:

• _filePath: the path to the log file
• _maxLines: the line number from  where we’ll start to replace lines

Both of it are read directly or not from an IOptions<FileLoggerSettings> injected instance.

Alright! you get it? Here we are! We’ll use our settings layer to configure our file logger. So now we’ll update all our appsettings.{environment}.json to something like:

{
  "Logging": {
    "AppCenterSettings": {
      "Secret": "ios={Your iOS App secret here};android={Your Android App secret here};",
      "TrackCrashes": true,
      "TrackEvents": false
    },
    "FileLoggerSettings": {
      "LogFileName": "log.txt",
      "LogFileMaxLines": 1000
    }
  },
  "SomeAppSettings": {
    "Key1": "ios=Debug_iOS_value1;android=Debug_Android_value1;uwp=Debug_UWP_value1",
    "Key2": 0,
    "Key3": true
  }
}

As you can see, things has changed. I introduced a Logging parent section, with our previous AppCenterSettings sub-section in to it and of course a brand new FileLoggerSettings section with its needed parameters. Don’t forget to repeat this operation into each environment appsettings files.

With this new json structure and sections, change your SettingsModule content to make it look like:

public class SettingsModule : ShinyModule
{
    public override void Register(IServiceCollection services)
    {
        // AppSettings (loaded from embedded json settings files to readonly properties)
        var stream = Assembly.GetAssembly(typeof(App)).GetManifestResourceStream($"{typeof(App).Namespace}.Settings.AppSettings.SettingsFiles.appsettings.json");
        if (stream != null)
        {
            var config = new ConfigurationBuilder()
                .AddJsonStream(stream)
                .Build();

            // Add all settings sections here
            services.Configure<AppCenterSettings>(config.GetSection($"Logging:{nameof(AppCenterSettings)}"), options => options.BindNonPublicProperties = true);
            services.Configure<FileLoggerSettings>(config.GetSection($"Logging:{nameof(FileLoggerSettings)}"), options => options.BindNonPublicProperties = true);
            services.AddOptions<SomeAppSettings>()
                .Bind(config.GetSection(nameof(SomeAppSettings)), options => options.BindNonPublicProperties = true)
                .ValidateDataAnnotations();
        }

        // UserSettings (sync with device preferences)
        services.AddOptions<UserAccountSettings>();
        services.AddOptions<UserProfileSettings>();

        // SessionSettings (kept in-memory during app lifetime)
        services.AddOptions<SomeSessionSettings>();
        services.AddOptions<SomeOtherSessionSettings>();
    }
}

The interesting part here is just that we updated AppCenterSettings binding to take care of the new section hierarchy with a simple Logging:, and introduced the FileLoggerSettings section binding:

services.Configure<AppCenterSettings>(config.GetSection($"Logging:{nameof(AppCenterSettings)}"), options => options.BindNonPublicProperties = true);
services.Configure<FileLoggerSettings>(config.GetSection($"Logging:{nameof(FileLoggerSettings)}"), options => options.BindNonPublicProperties = true);

Back to the LimitedFileLogger class, everything else is about writing into the file, plus the replacement logic.

The #if DEBUG thing is here to let me access the log file from my device while in debug mode. The path is constructed with the help of Shiny’s IFileSystem injected instance.

Now we get a log file tracking last 1000 lines of events and exceptions, we’ll create our AppCenterLogger.

Create an AppCenterLogger.cs file into the Logging folder, and make it look like:

    public class AppCenterLogger : ILogger
    {
        private readonly string _filePath;
        private readonly string _fileName;

        public AppCenterLogger(IOptions<AppCenterSettings> appCenterSettings, IOptions<FileLoggerSettings> fileLoggerSettings, IFileSystem fileSystem)
        {
#if DEBUG
            _filePath = Path.Combine(fileSystem.Public.FullName, fileLoggerSettings.Value.LogFileName);
#else
            _filePath = Path.Combine(fileSystem.AppData.FullName, fileLoggerSettings.Value.LogFileName);
#endif
            _fileName = fileLoggerSettings.Value.LogFileName;

            var list = new List<Type>(2);
            if (appCenterSettings.Value.TrackCrashes)
                list.Add(typeof(Crashes));

            if (appCenterSettings.Value.TrackEvents)
                list.Add(typeof(Analytics));

            AppCenter.Start(appCenterSettings.Value.Secret, list.ToArray());

            Crashes.GetErrorAttachments = GetErrorAttachments;
        }

        private IEnumerable<ErrorAttachmentLog> GetErrorAttachments(ErrorReport report)
        {
            var attachments = new List<ErrorAttachmentLog>();
            var attachment = GetErrorAttachment();
            if (attachment != null)
                attachments.Add(attachment);

            return attachments;
        }

        private ErrorAttachmentLog GetErrorAttachment()
        {
            ErrorAttachmentLog attachment = null;
            try
            {
                if (File.Exists(_filePath))
                {
                    var logBytes = File.ReadAllBytes(_filePath);
                    attachment = ErrorAttachmentLog.AttachmentWithBinary(logBytes, _fileName, "text/plain");
                }
            }
            catch (Exception ex)
            {
                attachment = ErrorAttachmentLog.AttachmentWithText($"Reading log file thrown error: {ex}", _fileName);
            }

            return attachment;
        }

        public void Write(Exception exception, params (string Key, string Value)[] parameters)
        {
            var attachment = GetErrorAttachment();
            Crashes.TrackError(exception, parameters?.ToDictionary(), attachment);
        }

        public void Write(string eventName, string description, params (string Key, string Value)[] parameters)
        {
            Analytics.TrackEvent($"[{eventName}] {description}", parameters.ToDictionary());
        }
    }

As we just did for our LimitedFileLogger, we inject needed options settings (AppCenter and FileLogger) and the IFileSystem again.

We construct the resulting _filePath value, then activate AppCenter’s Crashes and Analytics features, depending on the appsettings config. Please don’t forget to paste your AppCenter secret into your appsettings files, as it’s used here to start it all.

Finally, about the log file logic itself, we load it as an attachment each time we get an unhandled exception with Crashes.GetErrorAttachments = GetErrorAttachments;, or a handled one while calling Write(Exception exception ...).

Here we get our AppCenter logger, tracking errors with the attached log file.

The last thing we need to do is registering both loggers so that Shiny will call its Write methods each time we call the Log.Write static method from anywhere (OMG I just said static).

Well, actually, there’s another thing to do before registering, because there’s a pitfall with the registration method itself: it ask us for a crash and event activation boolean (activation by code) and we don’t want to do that as we don’t know it during registration. These activation informations are stored into appsettings json files and available directly into our AppCenterLogger with its IOptions<AppCenterSettings> injection.

To workaround this, please create an IExtendedLogger interface into the Logging folder, with this content:

public interface IExtendedLogger : ILogger
{
    bool IsCrashEnabled { get; }

    bool IsEventsEnabled { get; }
}

Then change your AppCenterLogger to:

    public class AppCenterLogger : IExtendedLogger
    {
        private readonly string _filePath;
        private readonly string _fileName;

        public AppCenterLogger(IOptions<AppCenterSettings> appCenterSettings, IOptions<FileLoggerSettings> fileLoggerSettings, IFileSystem fileSystem)
        {
#if DEBUG
            _filePath = Path.Combine(fileSystem.Public.FullName, fileLoggerSettings.Value.LogFileName);
#else
            _filePath = Path.Combine(fileSystem.AppData.FullName, fileLoggerSettings.Value.LogFileName);
#endif
            _fileName = fileLoggerSettings.Value.LogFileName;

            var list = new List<Type>(2);
            if (appCenterSettings.Value.TrackCrashes)
            {
                list.Add(typeof(Crashes));
                IsCrashEnabled = true;
            }

            if (appCenterSettings.Value.TrackEvents)
            {
                list.Add(typeof(Analytics));
                IsEventsEnabled = true;
            }

            AppCenter.Start(appCenterSettings.Value.Secret, list.ToArray());

            Crashes.GetErrorAttachments = GetErrorAttachments;
        }

        public bool IsCrashEnabled { get; }
        public bool IsEventsEnabled { get; }

        private IEnumerable<ErrorAttachmentLog> GetErrorAttachments(ErrorReport report)
        {
            var attachments = new List<ErrorAttachmentLog>();
            var attachment = GetErrorAttachment();
            if (attachment != null)
                attachments.Add(attachment);

            return attachments;
        }

        private ErrorAttachmentLog GetErrorAttachment()
        {
            ErrorAttachmentLog attachment = null;
            try
            {
                if (File.Exists(_filePath))
                {
                    var logBytes = File.ReadAllBytes(_filePath);
                    attachment = ErrorAttachmentLog.AttachmentWithBinary(logBytes, _fileName, "text/plain");
                }
            }
            catch (Exception ex)
            {
                attachment = ErrorAttachmentLog.AttachmentWithText($"Reading log file thrown error: {ex}", _fileName);
            }

            return attachment;
        }

        public void Write(Exception exception, params (string Key, string Value)[] parameters)
        {
            var attachment = GetErrorAttachment();
            Crashes.TrackError(exception, parameters?.ToDictionary(), attachment);
        }

        public void Write(string eventName, string description, params (string Key, string Value)[] parameters)
        {
            Analytics.TrackEvent($"[{eventName}] {description}", parameters.ToDictionary());
        }
    }

Now that IExtendedLogger interface expose the current activations of AppCenterLogger, we can register it.

To do that, create a LoggingModule into your Modules folder like so:

    public class LoggingModule : ShinyModule
    {
        public override void Register(IServiceCollection services)
        {
#if DEBUG
            services.AddSingleton<ILogger, DebugLogger>();
            services.AddSingleton<ILogger, ConsoleLogger>();
#endif
            services.AddSingleton<ILogger, LimitedFileLogger>();
            services.AddSingleton<ILogger, AppCenterLogger>();
        }

        public override void OnContainerReady(IServiceProvider services)
        {
            var loggers = services.GetServices<ILogger>();
            foreach (var logger in loggers)
            {
                Log.AddLogger(logger, 
                    (logger as IExtendedLogger)?.IsCrashEnabled ?? true,
                    (logger as IExtendedLogger)?.IsEventsEnabled ?? true);
            }
        }
    }

What we’re doing here is quite simple:

• we register every logger we need into our DI container
• once the container is ready, we resolve it all and register each of it into the Shiny logging system

Now everything is in place about logging, so if you log some events and then log an exception, you should see the exception entry from your AppCenter dashboard with a log file attachement 🙂

The last thing I would configure after logging, is global catching.

I hate unhandled exceptions meaning app crashing!

So I need to be sure everything is caught and logged everywhere, even if I don’t explicitly try catch it! Lazy time!

Global catching could be addressed by several ways:

1. One of it is provided by AsyncErrorHandler fody package, which will add the try catch things for you, everywhere we get some async task code.

Changing this:

public class SomeClass
{
    public async Task SomeTask(string someString)
    {
        await someService.SomeTask(someString);
    }
}

to this:

public class SomeClass
{
    public async Task SomeTask(string someString)
    {
        try 
        {
            await someService.SomeTask(someString);
        }
        catch (Exception exception)
        {
            AsyncErrorHandler.HandleException(exception);
        } 
    }
}

where AsyncErrorHandler.HandleException should be defined like so:

public static class AsyncErrorHandler
{
    public static void HandleException(Exception exception)
    {
        Log.Write(exception);
    }
}

Except the AsyncErrorHandler.HandleException you’ll have to write somewhere by yourself, the try cach boilerplate will be added for you at build time by weaving.

That means that even if you don’t try catch an awaitable task, it will be done for you and exceptions will be centralized to the HandleException static method.

2. Another way would be using the built in RX Default Exception Handler

Combined with Shiny, we just have to create a StartupTask like so:

public class GlobalExceptionHandler : IObserver<Exception>, IShinyStartupTask
{
    private readonly IMaterialDialog _dialogs;
    public GlobalExceptionHandler(IMaterialDialog dialogs) => _dialogs = dialogs;


    public void Start() => RxApp.DefaultExceptionHandler = this;
    public void OnCompleted() { }
    public void OnError(Exception error) { }


    public async void OnNext(Exception ex)
    {
        Log.Write(ex);
        await _dialogs.AlertAsync(ex.ToString(), "ERROR");
    }
}

and register it from our Startup class:

services.AddSingleton<GlobalExceptionHandler>();

What’s interesting with this solution is that it prevent you from adding another package dependency and as you can see we can inject things through the constructor, like a dialog service.

public partial class MainPageViewModel : ViewModelBase
{
    public MainPageViewModel(BaseServices baseServices)
        : base(baseServices)
    {
        Title = "Hello from Xamarin.Forms, Shiny, Prism & ReactiveUI!";

        Log.Write("TestEvent", "TestDescription");
        try
        {
            Crashes.GenerateTestCrash();
        }
        catch (System.Exception ex)
        {
            Log.Write(ex, ("testKey", "testValue"));
        }
    }
}

Here is our Logging layer implemented!

Next article will talk about consuming data, the resilient way, using Apizr. But before that, I’ll start another series focused on Apizr itself.

Playground source code is available on GitHub.

As the playground project is constantly moving and growing, be sure to select the corresponding tag, then the commit number and finally the Browse files button to explore the blog post matching version.

JeremyBP

Specialized since 2013 in cross-platform applications development for iOS, Android and Windows, using technologies such as Microsoft Xamarin and Microsoft Azure. Initially focused, since 2005, on development, then administration of Customer Relationship Management systems, mainly around solutions such as Microsoft SharePoint and Microsoft Dynamics CRM.