Use serilog for logging.

Perspex.Base/Perspex.Base.csproj

@@ -65,6 +65,10 @@
     <Compile Include="Threading\PerspexScheduler.cs" />
   </ItemGroup>
   <ItemGroup>
+    <Reference Include="Serilog, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\portable-net45+win+wpa81+wp80+MonoAndroid10+MonoTouch10\Serilog.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
     <Reference Include="Splat, Version=1.6.2.0, Culture=neutral, processorArchitecture=MSIL">
       <HintPath>..\packages\Splat.1.6.2\lib\Portable-net45+win+wpa81+wp80\Splat.dll</HintPath>
       <Private>True</Private>

Perspex.Base/PerspexObject.cs

@@ -7,7 +7,8 @@
 namespace Perspex
 {
     using Perspex.Reactive;
-    using Splat;
+    using Serilog;
+    using Serilog.Core.Enrichers;
     using System;
     using System.Collections.Generic;
     using System.ComponentModel;
@@ -64,7 +65,7 @@ namespace Perspex
     /// <remarks>
     /// This class is analogous to DependencyObject in WPF.
     /// </remarks>
-    public class PerspexObject : INotifyPropertyChanged, IEnableLogger
+    public class PerspexObject : INotifyPropertyChanged
     {
         /// <summary>
         /// The registered properties by type.
@@ -88,11 +89,23 @@ namespace Perspex
         /// </summary>
         private PropertyChangedEventHandler inpcChanged;
 
+        /// <summary>
+        /// A serilog logger for logging property events.
+        /// </summary>
+        private ILogger propertyLog;
+
         /// <summary>
         /// Initializes a new instance of the <see cref="PerspexObject"/> class.
         /// </summary>
         public PerspexObject()
         {
+            this.propertyLog = Log.ForContext(new[]
+            {
+                new PropertyEnricher("Area", "Property"),
+                new PropertyEnricher("SourceContext", this.GetType()),
+                new PropertyEnricher("Id", this.GetHashCode()),
+            });
+
             foreach (var property in this.GetRegisteredProperties())
             {
                 var e = new PerspexPropertyChangedEventArgs(
@@ -515,14 +528,12 @@ namespace Perspex
                 v = this.CreatePriorityValue(property);
                 this.values.Add(property, v);
             }
-            
-            this.Log().Debug(
-                "Set local value of {0}.{1} (#{2:x8}) to {3}",
-                this.GetType().Name,
-                property.Name,
-                this.GetHashCode(),
-                value);
 
+            this.propertyLog.Verbose(
+                "Set {Property} to {$Value} with priority {Priority}", 
+                property, 
+                value,
+                priority);
             v.SetDirectValue(value, (int)priority);
         }
 
@@ -569,12 +580,11 @@ namespace Perspex
                 this.values.Add(property, v);
             }
 
-            this.Log().Debug(
-                "Bound value of {0}.{1} (#{2:x8}) to {3}",
-                this.GetType().Name,
-                property.Name,
-                this.GetHashCode(),
-                description != null ? description.Description : "[Anonymous]");
+            this.propertyLog.Verbose(
+                "Bound {Property} to {Binding} with priority {Priority}", 
+                property, 
+                source,
+                priority);
 
             return v.Add(source, (int)priority);
         }
@@ -699,13 +709,12 @@ namespace Perspex
                 {
                     this.RaisePropertyChanged(property, oldValue, newValue, (BindingPriority)result.ValuePriority);
 
-                    this.Log().Debug(
-                        "Value of {0}.{1} (#{2:x8}) changed from {3} to {4}",
-                        this.GetType().Name,
-                        property.Name,
-                        this.GetHashCode(),
+                    this.propertyLog.Verbose(
+                        "{Property} changed from {$Old} to {$Value} with priority {Priority}",
+                        property,
                         oldValue,
-                        newValue);
+                        newValue,
+                        (BindingPriority)result.ValuePriority);
                 }
             });
 

Perspex.Base/packages.config

@@ -5,5 +5,6 @@
   <package id="Rx-Linq" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-Main" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-PlatformServices" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
+  <package id="Serilog" version="1.5.5" targetFramework="portable45-net45+win8" userInstalled="true" />
   <package id="Splat" version="1.6.2" targetFramework="portable45-net45+win8" userInstalled="true" />
 </packages>

Perspex.Controls/Perspex.Controls.csproj

@@ -127,6 +127,10 @@
     <Compile Include="Properties\AssemblyInfo.cs" />
   </ItemGroup>
   <ItemGroup>
+    <Reference Include="Serilog, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\portable-net45+win+wpa81+wp80+MonoAndroid10+MonoTouch10\Serilog.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
     <Reference Include="Splat, Version=1.6.2.0, Culture=neutral, processorArchitecture=MSIL">
       <HintPath>..\packages\Splat.1.6.2\lib\Portable-net45+win+wpa81+wp80\Splat.dll</HintPath>
       <Private>True</Private>

Perspex.Controls/Primitives/TemplatedControl.cs

@@ -13,7 +13,8 @@ namespace Perspex.Controls.Primitives
     using Perspex.Media;
     using Perspex.Styling;
     using Perspex.VisualTree;
-    using Splat;
+    using Serilog;
+    using Serilog.Core.Enrichers;
 
     public class TemplatedControl : Control, ITemplatedControl
     {
@@ -46,6 +47,8 @@ namespace Perspex.Controls.Primitives
 
         private bool templateApplied;
 
+        private ILogger templateLog;
+
         static TemplatedControl()
         {
             TemplateProperty.Changed.Subscribe(e =>
@@ -56,6 +59,16 @@ namespace Perspex.Controls.Primitives
             });
         }
 
+        public TemplatedControl()
+        {
+            this.templateLog = Log.ForContext(new[]
+            {
+                new PropertyEnricher("Area", "Template"),
+                new PropertyEnricher("SourceContext", this.GetType()),
+                new PropertyEnricher("Id", this.GetHashCode()),
+            });
+        }
+
         public Brush Background
         {
             get { return this.GetValue(BackgroundProperty); }
@@ -122,10 +135,7 @@ namespace Perspex.Controls.Primitives
 
                 if (this.Template != null)
                 {
-                    this.Log().Debug(
-                        "Creating template for {0} (#{1:x8})",
-                        this.GetType().Name,
-                        this.GetHashCode());
+                    this.templateLog.Verbose("Creating control template");
 
                     var child = this.Template.Build(this);
                     this.SetTemplatedParent(child);

Perspex.Controls/packages.config

@@ -5,5 +5,6 @@
   <package id="Rx-Linq" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-Main" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-PlatformServices" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
+  <package id="Serilog" version="1.5.5" targetFramework="portable45-net45+win8" userInstalled="true" />
   <package id="Splat" version="1.6.2" targetFramework="portable45-net45+win8" userInstalled="true" />
 </packages>

Perspex.Layout/LayoutManager.cs

@@ -11,6 +11,9 @@ namespace Perspex.Layout
     using System.Reactive.Subjects;
     using NGenerics.DataStructures.General;
     using Perspex.VisualTree;
+    using Serilog;
+    using Serilog.Core.Enrichers;
+    using System.Reactive.Disposables;
 
     /// <summary>
     /// Manages measuring and arranging of controls.
@@ -53,11 +56,28 @@ namespace Perspex.Layout
         /// </summary>
         private Heap<Item> toArrange = new Heap<Item>(HeapType.Minimum);
 
+        /// <summary>
+        /// Prevents re-entrancy.
+        /// </summary>
+        private bool running;
+
+        /// <summary>
+        /// The logger to use.
+        /// </summary>
+        private ILogger log;
+
         /// <summary>
         /// Initializes a new instance of the <see cref="LayoutManager"/> class.
         /// </summary>
         public LayoutManager()
         {
+            this.log = Log.ForContext(new[]
+            {
+                new PropertyEnricher("Area", "Layout"),
+                new PropertyEnricher("SourceContext", this.GetType()),
+                new PropertyEnricher("Id", this.GetHashCode()),
+            });
+
             this.layoutNeeded = new Subject<Unit>();
             this.layoutCompleted = new Subject<Unit>();
         }
@@ -102,25 +122,45 @@ namespace Perspex.Layout
         /// </summary>
         public void ExecuteLayoutPass()
         {
-            this.LayoutQueued = false;
+            if (this.running)
+            {
+                return;
+            }
 
-            for (int i = 0; i < MaxTries; ++i)
+            using (Disposable.Create(() => this.running = false))
             {
-                if (this.measureNeeded)
-                {
-                    this.ExecuteMeasure();
-                    this.measureNeeded = false;
-                }
+                this.running = true;
+                this.LayoutQueued = false;
 
-                this.ExecuteArrange();
+                this.log.Information(
+                    "Started layout pass. To measure: {Measure} To arrange: {Arrange}",
+                    this.toMeasure.Count,
+                    this.toArrange.Count);
 
-                if (this.toMeasure.Count == 0)
+                var stopwatch = new System.Diagnostics.Stopwatch();
+                stopwatch.Start();
+
+                for (int i = 0; i < MaxTries; ++i)
                 {
-                    break;
+                    if (this.measureNeeded)
+                    {
+                        this.ExecuteMeasure();
+                        this.measureNeeded = false;
+                    }
+
+                    this.ExecuteArrange();
+
+                    if (this.toMeasure.Count == 0)
+                    {
+                        break;
+                    }
                 }
-            }
 
-            this.layoutCompleted.OnNext(Unit.Default);
+                stopwatch.Stop();
+                this.log.Information("Layout pass finised in {Time}", stopwatch.Elapsed);
+
+                this.layoutCompleted.OnNext(Unit.Default);
+            }
         }
 
         /// <summary>

Perspex.Layout/Layoutable.cs

@@ -9,7 +9,8 @@ namespace Perspex.Layout
     using System;
     using System.Linq;
     using Perspex.VisualTree;
-    using Splat;
+    using Serilog;
+    using Serilog.Core.Enrichers;
 
     public enum HorizontalAlignment
     {
@@ -27,7 +28,7 @@ namespace Perspex.Layout
         Bottom,
     }
 
-    public class Layoutable : Visual, ILayoutable, IEnableLogger
+    public class Layoutable : Visual, ILayoutable
     {
         public static readonly PerspexProperty<double> WidthProperty =
             PerspexProperty.Register<Layoutable, double>("Width", double.NaN);
@@ -63,6 +64,8 @@ namespace Perspex.Layout
 
         private Rect? previousArrange;
 
+        private ILogger layoutLog;
+
         static Layoutable()
         {
             Layoutable.AffectsMeasure(Visual.IsVisibleProperty);
@@ -77,6 +80,16 @@ namespace Perspex.Layout
             Layoutable.AffectsMeasure(Layoutable.VerticalAlignmentProperty);
         }
 
+        public Layoutable()
+        {
+            this.layoutLog = Log.ForContext(new[]
+            {
+                new PropertyEnricher("Area", "Layout"),
+                new PropertyEnricher("SourceContext", this.GetType()),
+                new PropertyEnricher("Id", this.GetHashCode()),
+            });
+        }
+
         public double Width
         {
             get { return this.GetValue(WidthProperty); }
@@ -192,11 +205,7 @@ namespace Perspex.Layout
                 this.DesiredSize = desiredSize;
                 this.previousMeasure = availableSize;
 
-                this.Log().Debug(
-                    "Measure of {0} (#{1:x8}) requested {2} ",
-                    this.GetType().Name,
-                    this.GetHashCode(),
-                    this.DesiredSize);
+                this.layoutLog.Verbose("Measure requested {DesiredSize}", this.DesiredSize);
             }
         }
 
@@ -218,11 +227,7 @@ namespace Perspex.Layout
 
             if (force || !this.IsArrangeValid || this.previousArrange != rect)
             {
-                this.Log().Debug(
-                    "Arrange of {0} (#{1:x8}) gave {2} ",
-                    this.GetType().Name,
-                    this.GetHashCode(),
-                    rect);
+                this.layoutLog.Verbose("Arrange to {Rect} ", rect);
 
                 this.IsArrangeValid = true;
                 this.ArrangeCore(rect);
@@ -236,10 +241,7 @@ namespace Perspex.Layout
 
             if (this.IsMeasureValid)
             {
-                this.Log().Debug(
-                    "Invalidated measure of {0} (#{1:x8})",
-                    this.GetType().Name,
-                    this.GetHashCode());
+                this.layoutLog.Verbose("Invalidated measure");
             }
 
             this.IsMeasureValid = false;
@@ -268,10 +270,7 @@ namespace Perspex.Layout
 
             if (this.IsArrangeValid)
             {
-                this.Log().Debug(
-                    "Invalidated arrange of {0} (#{1:x8})",
-                    this.GetType().Name,
-                    this.GetHashCode());
+                this.layoutLog.Verbose("Arrange measure");
             }
 
             this.IsArrangeValid = false;

Perspex.Layout/Perspex.Layout.csproj

@@ -64,6 +64,10 @@
     <Compile Include="Properties\AssemblyInfo.cs" />
   </ItemGroup>
   <ItemGroup>
+    <Reference Include="Serilog, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\portable-net45+win+wpa81+wp80+MonoAndroid10+MonoTouch10\Serilog.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
     <Reference Include="Splat, Version=1.6.2.0, Culture=neutral, processorArchitecture=MSIL">
       <HintPath>..\packages\Splat.1.6.2\lib\Portable-net45+win+wpa81+wp80\Splat.dll</HintPath>
       <Private>True</Private>

Perspex.Layout/packages.config

@@ -5,5 +5,6 @@
   <package id="Rx-Linq" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-Main" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-PlatformServices" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
+  <package id="Serilog" version="1.5.5" targetFramework="portable45-net45+win8" userInstalled="true" />
   <package id="Splat" version="1.6.2" targetFramework="portable45-net45+win8" userInstalled="true" />
 </packages>

Perspex.SceneGraph/Perspex.SceneGraph.csproj

@@ -107,6 +107,10 @@
     <Compile Include="VisualTree\VisualExtensions.cs" />
   </ItemGroup>
   <ItemGroup>
+    <Reference Include="Serilog, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\portable-net45+win+wpa81+wp80+MonoAndroid10+MonoTouch10\Serilog.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
     <Reference Include="Splat, Version=1.6.2.0, Culture=neutral, processorArchitecture=MSIL">
       <HintPath>..\packages\Splat.1.6.2\lib\Portable-net45+win+wpa81+wp80\Splat.dll</HintPath>
       <Private>True</Private>

Perspex.SceneGraph/Visual.cs

@@ -17,7 +17,8 @@ namespace Perspex
     using Perspex.Platform;
     using Perspex.Rendering;
     using Perspex.VisualTree;
-    using Splat;
+    using Serilog;
+    using Serilog.Core.Enrichers;
 
     public class Visual : Animatable, IVisual
     {
@@ -46,6 +47,8 @@ namespace Perspex
 
         private Visual visualParent;
 
+        private ILogger visualLogger;
+
         static Visual()
         {
             AffectsRender(IsVisibleProperty);
@@ -55,6 +58,13 @@ namespace Perspex
 
         public Visual()
         {
+            this.visualLogger = Log.ForContext(new[]
+            {
+                new PropertyEnricher("Area", "Visual"),
+                new PropertyEnricher("SourceContext", this.GetType()),
+                new PropertyEnricher("Id", this.GetHashCode()),
+            });
+
             this.visualChildren = new PerspexList<IVisual>();
             this.visualChildren.CollectionChanged += this.VisualChildrenChanged;
         }
@@ -307,10 +317,7 @@ namespace Perspex
 
         private void NotifyAttachedToVisualTree(IRenderRoot root)
         {
-            this.Log().Debug(
-                "Attached {0} (#{1:x8}) to visual tree",
-                this.GetType().Name,
-                this.GetHashCode());
+            this.visualLogger.Verbose("Attached to visual tree");
 
             this.OnAttachedToVisualTree(root);
 
@@ -325,10 +332,7 @@ namespace Perspex
 
         private void NotifyDetachedFromVisualTree(IRenderRoot oldRoot)
         {
-            this.Log().Debug(
-                "Detached {0} (#{1:x8}) from visual tree",
-                this.GetType().Name,
-                this.GetHashCode());
+            this.visualLogger.Verbose("Detached from visual tree");
 
             this.OnDetachedFromVisualTree(oldRoot);
 

Perspex.SceneGraph/packages.config

@@ -5,5 +5,6 @@
   <package id="Rx-Linq" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-Main" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
   <package id="Rx-PlatformServices" version="2.2.5" targetFramework="portable-net45+win8" userInstalled="true" />
+  <package id="Serilog" version="1.5.5" targetFramework="portable45-net45+win8" userInstalled="true" />
   <package id="Splat" version="1.6.2" targetFramework="portable45-net45+win8" userInstalled="true" />
 </packages>

TestApplication/Program.cs

@@ -17,24 +17,12 @@ using Perspex.Gtk;
 #endif
 using ReactiveUI;
 using Splat;
+using Serilog;
+using Serilog.Filters;
+using Serilog.Events;
 
 namespace TestApplication
 {
-    class TestLogger : ILogger
-    {
-        public LogLevel Level
-        {
-            get;
-            set;
-        }
-
-        public void Write(string message, LogLevel logLevel)
-        {
-            if ((int)logLevel < (int)Level) return;
-            System.Diagnostics.Debug.WriteLine(message);
-        }
-    }
-
     class Item
     {
         public string Name { get; set; }
@@ -106,9 +94,11 @@ namespace TestApplication
 
         static void Main(string[] args)
         {
-            //LogManager.Enable(new TestLogger());
-            //LogManager.Instance.LogLayoutMessages = true;
-            //LogManager.Instance.LogPropertyMessages = true;
+            Log.Logger = new LoggerConfiguration()
+                .Filter.ByIncludingOnly(Matching.WithProperty("Area", "Layout"))
+                .MinimumLevel.Verbose()
+                .WriteTo.Trace(outputTemplate: "[{Id:X8}] [{SourceContext}] {Message}")
+                .CreateLogger();
 
             // The version of ReactiveUI currently included is for WPF and so expects a WPF
             // dispatcher. This makes sure it's initialized.

TestApplication/TestApplication.csproj

@@ -38,6 +38,14 @@
       <SpecificVersion>False</SpecificVersion>
       <HintPath>..\packages\reactiveui-core.6.4.0.1\lib\Net45\ReactiveUI.dll</HintPath>
     </Reference>
+    <Reference Include="Serilog, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\net45\Serilog.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
+    <Reference Include="Serilog.FullNetFx, Version=1.5.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10, processorArchitecture=MSIL">
+      <HintPath>..\packages\Serilog.1.5.5\lib\net45\Serilog.FullNetFx.dll</HintPath>
+      <Private>True</Private>
+    </Reference>
     <Reference Include="Splat, Version=1.6.2.0, Culture=neutral, processorArchitecture=MSIL">
       <HintPath>..\packages\Splat.1.6.2\lib\Net45\Splat.dll</HintPath>
       <Private>True</Private>

TestApplication/packages.config

@@ -8,6 +8,7 @@
   <package id="Rx-Main" version="2.2.5" targetFramework="net45" userInstalled="true" />
   <package id="Rx-PlatformServices" version="2.2.5" targetFramework="net45" userInstalled="true" />
   <package id="Rx-XAML" version="2.2.5" targetFramework="net45" userInstalled="true" />
+  <package id="Serilog" version="1.5.5" targetFramework="net45" userInstalled="true" />
   <package id="SharpDX" version="2.6.3" targetFramework="net45" userInstalled="true" />
   <package id="SharpDX.Direct2D1" version="2.6.3" targetFramework="net45" userInstalled="true" />
   <package id="SharpDX.DXGI" version="2.6.3" targetFramework="net45" userInstalled="true" />