Dependency-Injection-based logging cannot log all the things

[jonpryor]

(Logging! How does it work?!)

(I'm not sure where this error should actually live, and any fix likely spans multiple repo's, so…)

Problems with .UseLogging(…):

1. It executes "late" in app startup, and thus cannot control ILogger messages generated before .UseLogging(…) itself is executed.

2. It does not support messages from the LogExtensionPoint.Log<T>() extension method: https://github.com/unoplatform/Uno.Core/blob/c499a9947d9447bcaa627d1db872fb7837f64157/src/Uno.Core.Extensions.Logging.Singleton/LogExtensionPoint.cs#L56

   The .Log() extension method is also used within Uno itself, meaning these messages are not shown when only .UseLogging(…) is used. Consider:

   https://github.com/unoplatform/uno/blob/3523a6f482cd691d7d5b9a7758607e77e6def7fc/src/Uno.UI.Dispatching/Native/NativeDispatcher.cs#L146

   dispatcher.Log().Error("NativeDispatcher unhandled exception", exception);

3. Given (1) and (2), in order to see all ILogger-based messages, then (at present) both App.InitializeLogging() and .UseLogging(…) MUST be used.

This setup is Not Good: the default unoapp templates either use (1) (with dotnet new unoapp -preset "recommended") or (2) (with dotnet new unoapp [-di False]). Which means that it currently is not possible to observe all ILogger messages.

Solution?

If we want to capture all ILogger messages, from all contexts, then one of the following two things needs to happen:

1. The default templates need to be updated so that both .UseLogging(…) and App.InitializeLogging() are always used, or

2. .UseLogging(…) needs to be optional, with App.InitializeLogging() (a) present in all templates, and (b) "plays nicely" with Dependency-Injection based ILogger acquisition.

Background

While investigating Uno Chefs + $(PublishTrimmed)=true not showing favorited recipes: unoplatform/uno#20533 (comment)

…I noticed that a _logger.LogError() statement was executing but not printing anything: https://github.com/unoplatform/uno.chefs/blob/899cd9b98704bce3493b0abe7f2931ad08a9e8a0/Chefs/Client/Mock/BaseMockEndpoint.cs#L13-L17

Which brings forth an interesting question: Logging, how does it work?

I fear the answer is "not well".

Investigation

There are (at least?) two separate "initialize logging" systems within uno.templates:

1. The Dependency-Injecction oriented infrastructure which uses .UseLogging(…).

   This is used with e.g. dotnet new unoapp -preset "recommended".
   https://github.com/unoplatform/uno.templates/blob/8988cac5efc444de0afeb400da1da24620b5c083/src/Uno.Templates/content/unoapp/MyExtensionsApp.1/App.recommended.cs#L81-L112

2. The non-DI supporting App.InitializeLogging():

   This is used with e.g. dotnet new unoapp -preset "recommended" -http "none" -di False -log "none" -nav "blank".

   https://github.com/unoplatform/uno.templates/blob/8988cac5efc444de0afeb400da1da24620b5c083/src/Uno.Templates/content/unoapp/MyExtensionsApp.1/Platforms/Desktop/Program.cs#L10-L14
   https://github.com/unoplatform/uno.templates/blob/8988cac5efc444de0afeb400da1da24620b5c083/src/Uno.Templates/content/unoapp/MyExtensionsApp.1/App.blank.cs#L115-L182

They appear to log different things.

DI-based logging:

# dotnet new install Uno.Templates::6.5.0-dev.108
dotnet new unoapp -n unoapp_rec -preset "recommended"
cd unoapp_rec
dotnet build unoapp_rec/unoapp_rec.csproj -f net10.0-desktop
unoapp_rec/bin/Debug/net10.0-desktop/unoapp_rec

No messages are printed. (This is good, right? Hold that thought.)

Compare to non-DI based logging:

# dotnet new install Uno.Templates::6.5.0-dev.108
dotnet new unoapp -n unoapp_nodi -preset "recommended" -http "none" -di False -log "none" -nav "blank"
cd unoapp_nodi
dotnet build unoapp_nodi/unoapp_nodi.csproj -f net10.0-desktop
./unoapp_nodi/bin/Debug/net10.0-desktop/unoapp_nodi

No changes to the template, and the non-DI app does show error messages!

warn: Uno.UI.Runtime.Skia.MacOS.MacOSWindowNative[0]
      Unable to find icon file […/unoapp_nodi/unoapp_nodi/bin/Debug/net10.0-desktop/Assets/Icons/iconStoreLogo.png] specified in the Package.appxmanifest file.
warn: Uno.UI.ResourceResolver[0]
      Couldn't statically resolve resource HD_ControlFillColorQuaternaryBrush
warn: Uno.UI.ResourceResolver[0]
      Couldn't statically resolve resource SystemChromeHighlightColor

What if we log an error message via ILogger?

Update App in both projects to log an error message

diff --git a/unoapp_rec/App.xaml.cs b/unoapp_rec/App.xaml.cs
index 6635d6b..a433af9 100644
--- a/unoapp_rec/App.xaml.cs
+++ b/unoapp_rec/App.xaml.cs
@@ -12,6 +12,7 @@ public partial class App : Application
     public App()
     {
         this.InitializeComponent();
+        this.Log().LogError("error message");
     }
 
     protected Window? MainWindow { get; private set; }

diff --git a/unoapp_nodi/App.xaml.cs b/unoapp_nodi/App.xaml.cs
index 6c77eb1..a330fe1 100644
--- a/unoapp_nodi/App.xaml.cs
+++ b/unoapp_nodi/App.xaml.cs
@@ -13,6 +13,7 @@ public partial class App : Application
     public App()
     {
         this.InitializeComponent();
+        this.Log().LogError("error message");
     }
 
     protected Window? MainWindow { get; private set; }

Rebuild, rerun, and…

The DI-based unoapp_rec does not log any messages.

The non-DI based unoapp_nodi does log messages:

fail: unoapp_nodi.App[0]
      error message
warn: Uno.UI.Runtime.Skia.MacOS.MacOSWindowNative[0]
      Unable to find icon file […/unoapp_nodi/unoapp_nodi/bin/Debug/net10.0-desktop/Assets/Icons/iconStoreLogo.png] specified in the Package.appxmanifest file.
warn: Uno.UI.ResourceResolver[0]
      Couldn't statically resolve resource HD_ControlFillColorQuaternaryBrush
warn: Uno.UI.ResourceResolver[0]
      Couldn't statically resolve resource SystemChromeHighlightColor

On another lark, what if we add the non-DI logging setup from unoapp_nodi to unoapp_rec?

diff --git a/unoapp_rec/App.xaml.cs b/unoapp_rec/App.xaml.cs
index 6635d6b..b1a06f0 100644
--- a/unoapp_rec/App.xaml.cs
+++ b/unoapp_rec/App.xaml.cs
@@ -12,6 +12,7 @@ public partial class App : Application
     public App()
     {
         this.InitializeComponent();
+        this.Log().LogError("error message from App constructor");
     }
 
     protected Window? MainWindow { get; private set; }
@@ -107,4 +108,74 @@ public partial class App : Application
             )
         );
     }
+
+    /// <summary>
+    /// Configures global Uno Platform logging
+    /// </summary>
+    public static void InitializeLogging()
+    {
+#if DEBUG
+        // Logging is disabled by default for release builds, as it incurs a significant
+        // initialization cost from Microsoft.Extensions.Logging setup. If startup performance
+        // is a concern for your application, keep this disabled. If you're running on the web or
+        // desktop targets, you can use URL or command line parameters to enable it.
+        //
+        // For more performance documentation: https://platform.uno/docs/articles/Uno-UI-Performance.html
+
+        var factory = LoggerFactory.Create(builder =>
+        {
+#if __WASM__
+            builder.AddProvider(new global::Uno.Extensions.Logging.WebAssembly.WebAssemblyConsoleLoggerProvider());
+#elif __IOS__
+            builder.AddProvider(new global::Uno.Extensions.Logging.OSLogLoggerProvider());
+
+            // Log to the Visual Studio Debug console
+            builder.AddConsole();
+#else
+            builder.AddConsole();
+#endif
+
+            // Exclude logs below this level
+            builder.SetMinimumLevel(LogLevel.Information);
+
+            // Default filters for Uno Platform namespaces
+            builder.AddFilter("Uno", LogLevel.Warning);
+            builder.AddFilter("Windows", LogLevel.Warning);
+            builder.AddFilter("Microsoft", LogLevel.Warning);
+
+            // Generic Xaml events
+            // builder.AddFilter("Microsoft.UI.Xaml", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.VisualStateGroup", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.StateTriggerBase", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.UIElement", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.FrameworkElement", LogLevel.Trace );
+
+            // Layouter specific messages
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls.Layouter", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls.Panel", LogLevel.Debug );
+
+            // builder.AddFilter("Windows.Storage", LogLevel.Debug );
+
+            // Binding related messages
+            // builder.AddFilter("Microsoft.UI.Xaml.Data", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Data", LogLevel.Debug );
+
+            // Binder memory references tracking
+            // builder.AddFilter("Uno.UI.DataBinding.BinderReferenceHolder", LogLevel.Debug );
+
+            // DevServer and HotReload related
+            // builder.AddFilter("Uno.UI.RemoteControl", LogLevel.Information);
+
+            // Debug JS interop
+            // builder.AddFilter("Uno.Foundation.WebAssemblyRuntime", LogLevel.Debug );
+        });
+
+        global::Uno.Extensions.LogExtensionPoint.AmbientLoggerFactory = factory;
+
+#if HAS_UNO
+        global::Uno.UI.Adapter.Microsoft.Extensions.Logging.LoggingAdapter.Initialize();
+#endif
+#endif
+    }
 }
diff --git a/unoapp_rec/Platforms/Desktop/Program.cs b/unoapp_rec/Platforms/Desktop/Program.cs
index d0122d3..ba97e48 100644
--- a/unoapp_rec/Platforms/Desktop/Program.cs
+++ b/unoapp_rec/Platforms/Desktop/Program.cs
@@ -7,7 +7,7 @@ internal class Program
     [STAThread]
     public static void Main(string[] args)
     {
-
+        App.InitializeLogging();
         var host = UnoPlatformHostBuilder.Create()
             .App(() => new App())
             .UseX11()

NOW we see log messages from unoapp_rec!

fail: unoapp_rec.App[0]
      error message from App constructor
warn: Uno.UI.Runtime.Skia.MacOS.MacOSWindowNative[0]
      Unable to find icon file […/unoapp_rec/unoapp_rec/bin/Debug/net10.0-desktop/Assets/Icons/iconStoreLogo.png] specified in the Package.appxmanifest file.
fail: Uno.UI.DataBinding.BindingPropertyHelper[0]
      The [SplashScreenContent] property getter does not exist on type [Uno.Toolkit.UI.ExtendedSplashScreen]

Next question: what about Dependency Injection?

New patch to App.xaml.cs. Summary of changes from the default template:

1. Use this.Log().Logerror() from both App constructor and App.OnLaunched()
2. Add new IMyService and MyService types, and register with services.AddSingleton<…>()
3. Lookup the service in (2) via Host.Services.GetRequiredService<IMyService>().

diff --git a/unoapp_rec/App.xaml.cs b/unoapp_rec/App.xaml.cs
index 6635d6b..2f57d01 100644
--- a/unoapp_rec/App.xaml.cs
+++ b/unoapp_rec/App.xaml.cs
@@ -12,6 +12,7 @@ public partial class App : Application
     public App()
     {
         this.InitializeComponent();
+        this.Log().LogError("error message from App constructor");
     }
 
     protected Window? MainWindow { get; private set; }
@@ -75,7 +76,7 @@ public partial class App : Application
                 .ConfigureServices((context, services) =>
                 {
                     // TODO: Register your services
-                    //services.AddSingleton<IMyService, MyService>();
+                    services.AddSingleton<IMyService, MyService>();
                 })
                 .UseNavigation(ReactiveViewModelMappings.ViewModelMappings, RegisterRoutes)
             );
@@ -87,6 +88,8 @@ public partial class App : Application
                 MainWindow.SetWindowIcon();
 
         Host = await builder.NavigateAsync<Shell>();
+        var service = Host.Services.GetRequiredService<IMyService>();
+        this.Log().LogError("error message from App.OnLaunched");
     }
 
     private static void RegisterRoutes(IViewRegistry views, IRouteRegistry routes)
@@ -107,4 +110,84 @@ public partial class App : Application
             )
         );
     }
+
+    /// <summary>
+    /// Configures global Uno Platform logging
+    /// </summary>
+    public static void InitializeLogging()
+    {
+#if DEBUG
+        // Logging is disabled by default for release builds, as it incurs a significant
+        // initialization cost from Microsoft.Extensions.Logging setup. If startup performance
+        // is a concern for your application, keep this disabled. If you're running on the web or
+        // desktop targets, you can use URL or command line parameters to enable it.
+        //
+        // For more performance documentation: https://platform.uno/docs/articles/Uno-UI-Performance.html
+
+        var factory = LoggerFactory.Create(builder =>
+        {
+#if __WASM__
+            builder.AddProvider(new global::Uno.Extensions.Logging.WebAssembly.WebAssemblyConsoleLoggerProvider());
+#elif __IOS__
+            builder.AddProvider(new global::Uno.Extensions.Logging.OSLogLoggerProvider());
+
+            // Log to the Visual Studio Debug console
+            builder.AddConsole();
+#else
+            builder.AddConsole();
+#endif
+
+            // Exclude logs below this level
+            builder.SetMinimumLevel(LogLevel.Information);
+
+            // Default filters for Uno Platform namespaces
+            builder.AddFilter("Uno", LogLevel.Warning);
+            builder.AddFilter("Windows", LogLevel.Warning);
+            builder.AddFilter("Microsoft", LogLevel.Warning);
+
+            // Generic Xaml events
+            // builder.AddFilter("Microsoft.UI.Xaml", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.VisualStateGroup", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.StateTriggerBase", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.UIElement", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.FrameworkElement", LogLevel.Trace );
+
+            // Layouter specific messages
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls.Layouter", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Controls.Panel", LogLevel.Debug );
+
+            // builder.AddFilter("Windows.Storage", LogLevel.Debug );
+
+            // Binding related messages
+            // builder.AddFilter("Microsoft.UI.Xaml.Data", LogLevel.Debug );
+            // builder.AddFilter("Microsoft.UI.Xaml.Data", LogLevel.Debug );
+
+            // Binder memory references tracking
+            // builder.AddFilter("Uno.UI.DataBinding.BinderReferenceHolder", LogLevel.Debug );
+
+            // DevServer and HotReload related
+            // builder.AddFilter("Uno.UI.RemoteControl", LogLevel.Information);
+
+            // Debug JS interop
+            // builder.AddFilter("Uno.Foundation.WebAssemblyRuntime", LogLevel.Debug );
+        });
+
+        global::Uno.Extensions.LogExtensionPoint.AmbientLoggerFactory = factory;
+
+#if HAS_UNO
+        global::Uno.UI.Adapter.Microsoft.Extensions.Logging.LoggingAdapter.Initialize();
+#endif
+#endif
+    }
+}
+
+interface IMyService;
+
+class MyService : IMyService
+{
+    public MyService(ILogger<MyService> logger)
+    {
+        logger.LogError("error message from from MyService!");
+    }
 }

If Program.cs does not call App.InitializeLogging(), app output is:

fail: unoapp_rec.MyService[0]
      error message from from MyService!

i.e. we get no messages from this.Log().LogError(…)!

If Program.cs does call App.InitializeLogging(), then app output is:

fail: unoapp_rec.App[0]
      error message from App constructor
warn: Uno.UI.Runtime.Skia.MacOS.MacOSWindowNative[0]
      Unable to find icon file […/unoapp_rec/unoapp_rec/bin/Debug/net10.0-desktop/Assets/Icons/iconStoreLogo.png] specified in the Package.appxmanifest file.
fail: Uno.UI.DataBinding.BindingPropertyHelper[0]
      The [SplashScreenContent] property getter does not exist on type [Uno.Toolkit.UI.ExtendedSplashScreen]
fail: unoapp_rec.MyService[0]
      error message from from MyService!
fail: unoapp_rec.App[0]
      error message from App.OnLaunched

If Program.cs does call App.InitializeLogging(), and we remove the .UseLogging(…) invocation from App.OnLaunched(), then app output is:

fail: unoapp_rec.App[0]
      error message from App constructor
warn: Uno.UI.Runtime.Skia.MacOS.MacOSWindowNative[0]
      Unable to find icon file […/unoapp_rec/unoapp_rec/bin/Debug/net10.0-desktop/Assets/Icons/iconStoreLogo.png] specified in the Package.appxmanifest file.
fail: Uno.UI.DataBinding.BindingPropertyHelper[0]
      The [SplashScreenContent] property getter does not exist on type [Uno.Toolkit.UI.ExtendedSplashScreen]
fail: unoapp_rec.App[0]
      error message from App.OnLaunched

i.e. we are missing the Dependency-Injection messages from MyService!

[jonpryor]

After discussing #3011 and unoplatform/uno.templates#1921 with @kazo0 and @nickrandolph…

First, verify that the NoDI-style logger initialization works with Serilog. Assuming it works:

1. Update fix: HostBuilder.Build() shares LogExtensionPoint.AmbientLoggerFactory #3011 so that .UseLogging() checks to see if LogExtensionPoint.AmbientLoggerFactory was used to replace the ILoggerFactory within HostBuilder.Build(). If it does, then log an error message describing what to do.
2. Update fix: Log All-The-Things! uno.templates#1921 to remove all use of .UseLogging() and use only App.InitializeLogging().