Add minimal logging of UnitOfWork activity

* Add logger to IOC container when LCM_TransactionLogPath
  environment variable is defined.
* Use logging to add breadcrumbs to trace UOW calls.
* This is a first step to try and track down some intermittent
  failures in FieldWorks unit tests.

Author: jasonleenaylor

src/SIL.LCModel/FileTransactionLogger.cs

@@ -0,0 +1,48 @@
+using System;
+using System.Diagnostics;
+using System.IO;
+using System.Text;
+
+namespace SIL.LCModel
+{
+   internal class FileTransactionLogger : ITransactionLogger, IDisposable
+   {
+	   private object m_lock = new object();
+	   private FileStream m_stream;
+	   
+	   internal FileTransactionLogger(string filePath)
+	   {
+		   m_stream = File.Open(filePath, FileMode.Append, FileAccess.Write, FileShare.Read);
+	   }
+
+	   ~FileTransactionLogger()
+	   {
+		   Dispose(false);
+	   }
+
+	   public void AddBreadCrumb(string description)
+	   {
+		   lock (m_lock)
+		   {
+			   m_stream.WriteAsync(Encoding.UTF8.GetBytes((description + Environment.NewLine).ToCharArray()), 0,
+				   description.Length + 1);
+		   }
+	   }
+
+	   protected virtual void Dispose(bool disposing)
+		{
+			Debug.WriteLineIf(!disposing, "****** Missing Dispose() call for " + GetType() + ". *******");
+			lock (m_stream)
+			{
+				m_stream?.Flush();
+				m_stream?.Dispose();
+			}
+		}
+
+		public void Dispose()
+	   {
+		   Dispose(true);
+		   GC.SuppressFinalize(this);
+		}
+   }
+}

src/SIL.LCModel/IOC/LcmServiceLocatorFactory.cs

@@ -5,6 +5,7 @@
 using System;
 using System.Collections.Generic;
 using System.Diagnostics;
+using System.IO;
 using System.Runtime.InteropServices;
 using CommonServiceLocator;
 using SIL.LCModel.Application;
@@ -16,6 +17,7 @@
 using SIL.LCModel.DomainServices.DataMigration;
 using SIL.LCModel.Infrastructure;
 using SIL.LCModel.Infrastructure.Impl;
+using SIL.Reporting;
 using StructureMap;
 using StructureMap.Pipeline;
 
@@ -56,6 +58,13 @@ internal LcmServiceLocatorFactory(BackendProviderType backendProviderType, ILcmU
 		/// ------------------------------------------------------------------------------------
 		public IServiceProvider CreateServiceLocator()
 		{
+			ITransactionLogger logger = null;
+
+			var logPath = Environment.GetEnvironmentVariable("LCM_TransactionLogPath");
+			if (!string.IsNullOrEmpty(logPath))
+			{
+				logger = new FileTransactionLogger(Path.Combine(logPath, $"lcm_transaction.{DateTime.Now.Ticks}.log"));
+			}
 			// NOTE: When creating an object through IServiceLocator.GetInstance the caller has
 			// to call Dispose() on the newly created object, unless it's a singleton
 			// (registered with LifecycleIs(new SingletonLifecycle())) in which case
@@ -108,12 +117,6 @@ public IServiceProvider CreateServiceLocator()
 				.For<IdentityMap>()
 				.LifecycleIs(new SingletonLifecycle())
 				.Use<IdentityMap>();
-			// No. This makes a second instance of IdentityMap,
-			// which is probably not desirable.
-			//registry
-			//	.For<ICmObjectIdFactory>()
-			//	.LifecycleIs(new SingletonLifecycle())
-			//	.Use<IdentityMap>();
 			// Register IdentityMap's other interface.
 			registry
 				.For<ICmObjectIdFactory>()
@@ -184,7 +187,7 @@ public IServiceProvider CreateServiceLocator()
 			registry
 				.For<IUndoStackManager>()
 				.Use(c => (IUndoStackManager)c.GetInstance<IUnitOfWorkService>());
-
+			registry.For<ITransactionLogger>().Use(() => logger);
 			// Add generated factories.
 			AddFactories(registry);
 

src/SIL.LCModel/ITransactionLogger.cs

@@ -0,0 +1,7 @@
+namespace SIL.LCModel
+{
+   internal interface ITransactionLogger
+   {
+	   void AddBreadCrumb(string description);
+   }
+}

src/SIL.LCModel/Infrastructure/Impl/UnitOfWorkService.cs

@@ -12,6 +12,7 @@
 using SIL.LCModel.Core.Cellar;
 using SIL.LCModel.Core.KernelInterfaces;
 using SIL.LCModel.Utils;
+using SIL.Reporting;
 using Timer = System.Timers.Timer;
 
 namespace SIL.LCModel.Infrastructure.Impl
@@ -26,7 +27,7 @@ namespace SIL.LCModel.Infrastructure.Impl
 	/// via the 'PropChanged' method of the IVwNotifyChange interface.
 	/// In this implementation, the LCM ISILDataAccess implementation farms out this
 	/// notification function to this class.
-	/// IVwNotifyChange implementations are not to use this notificatin mechanism
+	/// IVwNotifyChange implementations are not to use this notification mechanism
 	/// to make additional data changes. That is done using the second set of Mediator clients.
 	///
 	/// The second set of Mediator clients is between CmObjects.
@@ -35,7 +36,7 @@ namespace SIL.LCModel.Infrastructure.Impl
 	/// of properties on other CmObjects.
 	///
 	/// With this twofold Mediator mechanism,
-	/// the IVwNotifyChange system can stay with its purpose of refeshing UI display,
+	/// the IVwNotifyChange system can stay with its purpose of refreshing UI display,
 	/// while the second system can take care of side effect data changes.
 	/// </summary>
 	/// <remarks>
@@ -103,6 +104,7 @@ internal enum BusinessTransactionState
 		private readonly IDataStorer m_dataStorer;
 		private readonly IdentityMap m_identityMap;
 		private readonly ILcmUI m_ui;
+		private readonly ITransactionLogger m_logger;
 		internal ICmObjectRepositoryInternal ObjectRepository
 		{
 			get;
@@ -151,7 +153,7 @@ internal BusinessTransactionState CurrentProcessingState {
 		/// <summary>
 		/// Constructor.
 		/// </summary>
-		internal UnitOfWorkService(IDataStorer dataStorer, IdentityMap identityMap, ICmObjectRepositoryInternal objectRepository, ILcmUI ui)
+		internal UnitOfWorkService(IDataStorer dataStorer, IdentityMap identityMap, ICmObjectRepositoryInternal objectRepository, ILcmUI ui, ITransactionLogger logger)
 		{
 			if (dataStorer == null) throw new ArgumentNullException("dataStorer");
 			if (identityMap == null) throw new ArgumentNullException("identityMap");
@@ -160,6 +162,7 @@ internal UnitOfWorkService(IDataStorer dataStorer, IdentityMap identityMap, ICmO
 
 			m_dataStorer = dataStorer;
 			m_identityMap = identityMap;
+			m_logger = logger;
 			ObjectRepository = objectRepository;
 			m_ui = ui;
 			CurrentProcessingState = BusinessTransactionState.ReadyForBeginTask;
@@ -216,6 +219,7 @@ private void Dispose(bool fDisposing)
 				m_saveTimer.Dispose();
 			}
 			IsDisposed = true;
+			m_logger?.AddBreadCrumb("UOW Disposed.");
 		}
 		#endregion
 
@@ -247,7 +251,7 @@ void SaveOnIdle(object sender, ElapsedEventArgs e)
 				// If it is less than 2s since the user did something don't save to smooth performance (unless the user has been busy as a beaver for more than 5 minutes)
 				if (now - m_ui.LastActivityTime < TimeSpan.FromSeconds(2.0) && now < (m_lastSave + TimeSpan.FromMinutes(5)))
 					return;
-
+				m_logger.AddBreadCrumb("Saving from SaveOnIdle");
 				SaveInternal();
 			}
 		}
@@ -282,6 +286,7 @@ public void Save()
 
 		private void SaveInternal()
 		{
+			m_logger?.AddBreadCrumb("Attempting Save.");
 			// don't allow reentrant calls.
 			if (m_fInSaveInternal)
 				return;
@@ -309,6 +314,7 @@ private void SaveInternal()
 						if (stack.CanUndo())
 							undoable = true;
 					}
+					m_logger?.AddBreadCrumb($"Raising save event: New:{newbies.Count} Changed:{dirtballs.Count} Deleted:{goners.Count}");
 					RaiseSave(undoable);
 				}
 
@@ -324,6 +330,7 @@ private void SaveInternal()
 					return; // Don't try to save the changes we just reverted!
 				}
 
+				m_logger?.AddBreadCrumb("Committing");
 				// let the BEP determine if a commit should occur or not
 				if (!m_dataStorer.Commit(realNewbies, dirtballs, goners))
 				{
@@ -520,7 +527,7 @@ internal void SendPropChangedNotifications(IEnumerable<ChangeInformation> change
 			ChangeInformation[] changes = subscribers.Length == 0 ? changesEnum.Where(ci => ci.HasNotifier).ToArray() : changesEnum.ToArray();
 			if (changes.Length == 0)
 				return;
-
+			m_logger?.AddBreadCrumb($"Sending prop changed notifications. Changes:{changes.Length} Subscribers: {subscribers.Length}");
 			m_ui.SynchronizeInvoke.Invoke(() =>
 			{
 				foreach (IVwNotifyChange sub in subscribers)