diff --git a/src/SIL.LCModel/FileTransactionLogger.cs b/src/SIL.LCModel/FileTransactionLogger.cs new file mode 100644 index 00000000..63090368 --- /dev/null +++ b/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_lock) + { + m_stream?.Flush(); + m_stream?.Dispose(); + } + } + + public void Dispose() + { + Dispose(true); + GC.SuppressFinalize(this); + } + } +} diff --git a/src/SIL.LCModel/IOC/LcmServiceLocatorFactory.cs b/src/SIL.LCModel/IOC/LcmServiceLocatorFactory.cs index f04fa79e..2290785a 100644 --- a/src/SIL.LCModel/IOC/LcmServiceLocatorFactory.cs +++ b/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() .LifecycleIs(new SingletonLifecycle()) .Use(); - // No. This makes a second instance of IdentityMap, - // which is probably not desirable. - //registry - // .For() - // .LifecycleIs(new SingletonLifecycle()) - // .Use(); // Register IdentityMap's other interface. registry .For() @@ -184,7 +187,7 @@ public IServiceProvider CreateServiceLocator() registry .For() .Use(c => (IUndoStackManager)c.GetInstance()); - + registry.For().Use(() => logger); // Add generated factories. AddFactories(registry); diff --git a/src/SIL.LCModel/ITransactionLogger.cs b/src/SIL.LCModel/ITransactionLogger.cs new file mode 100644 index 00000000..0031a88b --- /dev/null +++ b/src/SIL.LCModel/ITransactionLogger.cs @@ -0,0 +1,7 @@ +namespace SIL.LCModel +{ + internal interface ITransactionLogger + { + void AddBreadCrumb(string description); + } +} diff --git a/src/SIL.LCModel/Infrastructure/Impl/UnitOfWorkService.cs b/src/SIL.LCModel/Infrastructure/Impl/UnitOfWorkService.cs index d54ee933..16ab4b96 100644 --- a/src/SIL.LCModel/Infrastructure/Impl/UnitOfWorkService.cs +++ b/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. /// /// @@ -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 { /// /// Constructor. /// - 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 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)