diff --git a/CK-Monitoring.sln b/CK-Monitoring.sln index aeea4ad..a60333f 100644 --- a/CK-Monitoring.sln +++ b/CK-Monitoring.sln @@ -1,7 +1,7 @@  Microsoft Visual Studio Solution File, Format Version 12.00 # Visual Studio 15 -VisualStudioVersion = 15.0.26403.7 +VisualStudioVersion = 15.0.26730.3 MinimumVisualStudioVersion = 10.0.40219.1 Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Solution Items", "Solution Items", "{C51E8D11-FC45-4D5B-85DC-68A7EEB83601}" ProjectSection(SolutionItems) = preProject @@ -17,11 +17,14 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Tests", "Tests", "{1E041F87 EndProject Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "CK.Monitoring", "CK.Monitoring\CK.Monitoring.csproj", "{4A4EAEFF-2A8B-4308-A178-3FFEE94CC009}" EndProject -Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "CK.Monitoring.Tests", "Tests\CK.Monitoring.Tests\CK.Monitoring.Tests.csproj", "{D9AC45A9-A7F9-4070-8AB4-50D76C688912}" +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "CK.Monitoring.Tests", "Tests\CK.Monitoring.Tests\CK.Monitoring.Tests.csproj", "{D9AC45A9-A7F9-4070-8AB4-50D76C688912}" EndProject Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "CodeCakeBuilder", "CodeCakeBuilder\CodeCakeBuilder.csproj", "{FD4817B6-3CD7-4E74-AA10-7CA95FDFCF2D}" EndProject Global + GlobalSection(Performance) = preSolution + HasPerformanceSessions = true + EndGlobalSection GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU Release|Any CPU = Release|Any CPU @@ -46,4 +49,7 @@ Global GlobalSection(NestedProjects) = preSolution {D9AC45A9-A7F9-4070-8AB4-50D76C688912} = {1E041F87-872B-43D0-B107-2D998F7AEE38} EndGlobalSection + GlobalSection(ExtensibilityGlobals) = postSolution + SolutionGuid = {0AA77C05-08ED-458A-A69D-43B7D4CD5324} + EndGlobalSection EndGlobal diff --git a/CK.Monitoring/DispatcherSink.cs b/CK.Monitoring/DispatcherSink.cs index dc21a39..c26be90 100644 --- a/CK.Monitoring/DispatcherSink.cs +++ b/CK.Monitoring/DispatcherSink.cs @@ -1,4 +1,4 @@ -using CK.Core; +using CK.Core; using System; using System.Collections.Concurrent; using System.Collections.Generic; @@ -17,6 +17,8 @@ internal class DispatcherSink : IGrandOutputSink readonly List _handlers; readonly long _deltaExternalTicks; readonly Action _externalOnTimer; + readonly object _confTrigger; + readonly Action _initialRegister; GrandOutputConfiguration[] _newConf; TimeSpan _timerDuration; @@ -26,11 +28,13 @@ internal class DispatcherSink : IGrandOutputSink volatile int _stopFlag; volatile bool _forceClose; - public DispatcherSink( TimeSpan timerDuration, TimeSpan externalTimerDuration, Action externalTimer ) + public DispatcherSink( Action initialRegister, TimeSpan timerDuration, TimeSpan externalTimerDuration, Action externalTimer ) { + _initialRegister = initialRegister; _queue = new BlockingCollection(); _handlers = new List(); _task = new Task( Process, TaskCreationOptions.LongRunning ); + _confTrigger = new object(); _timerDuration = timerDuration; _deltaTicks = timerDuration.Ticks; _deltaExternalTicks = externalTimerDuration.Ticks; @@ -56,51 +60,26 @@ public TimeSpan TimerDuration void Process() { - int nbEvent = 0; - IActivityMonitor monitor = new SystemActivityMonitor( applyAutoConfigurations: false, topic: GetType().FullName ); + var monitor = new ActivityMonitor( applyAutoConfigurations: false ); + // Simple pooling for initial configuration. + GrandOutputConfiguration[] newConf = _newConf; + while( newConf == null ) + { + Thread.Sleep( 0 ); + newConf = _newConf; + } + _initialRegister( monitor ); + monitor.SetTopic( GetType().FullName ); + DoConfigure( monitor, newConf ); while( !_queue.IsCompleted && !_forceClose ) { bool hasEvent = _queue.TryTake( out GrandOutputEventInfo e, millisecondsTimeout: 100 ); - var newConf = _newConf; - if( newConf != null && newConf.Length > 0 ) - { - Util.InterlockedSet( ref _newConf, t => t.Skip( newConf.Length ).ToArray() ); - var c = newConf[newConf.Length - 1]; - TimerDuration = c.TimerDuration; - List toKeep = new List(); - for( int iConf = 0; iConf < c.Handlers.Count; ++iConf ) - { - for( int iHandler = 0; iHandler < _handlers.Count; ++iHandler ) - { - if( _handlers[iHandler].ApplyConfiguration( monitor, c.Handlers[iConf] ) ) - { - c.Handlers.RemoveAt( iConf-- ); - toKeep.Add( _handlers[iHandler] ); - _handlers.RemoveAt( iHandler ); - break; - } - } - } - foreach( var h in _handlers ) - { - SafeActivateOrDeactivate( monitor, h, false ); - } - _handlers.Clear(); - _handlers.AddRange( toKeep ); - foreach( var conf in c.Handlers ) - { - var h = GrandOutput.CreateHandler( conf ); - if( SafeActivateOrDeactivate( monitor, h, true ) ) - { - _handlers.Add( h ); - } - } - } + newConf = _newConf; + if( newConf.Length > 0 ) DoConfigure( monitor, newConf ); List faulty = null; #region Process event if any. if( hasEvent ) { - ++nbEvent; foreach( var h in _handlers ) { try @@ -109,7 +88,9 @@ void Process() } catch( Exception ex ) { - monitor.SendLine( LogLevel.Error, h.GetType().FullName + ".Handle", ex ); + var msg = $"{h.GetType().FullName}.Handle() crashed."; + ActivityMonitor.CriticalErrorCollector.Add( ex, msg ); + monitor.SendLine( LogLevel.Fatal, msg, ex ); if( faulty == null ) faulty = new List(); faulty.Add( h ); } @@ -128,7 +109,9 @@ void Process() } catch( Exception ex ) { - monitor.SendLine( LogLevel.Error, h.GetType().FullName + ".OnTimer", ex ); + var msg = $"{h.GetType().FullName}.OnTimer() crashed."; + ActivityMonitor.CriticalErrorCollector.Add( ex, msg ); + monitor.SendLine( LogLevel.Fatal, msg, ex ); if( faulty == null ) faulty = new List(); faulty.Add( h ); } @@ -155,6 +138,71 @@ void Process() monitor.MonitorEnd(); } + private void DoConfigure( IActivityMonitor monitor, GrandOutputConfiguration[] newConf ) + { + Util.InterlockedSet( ref _newConf, t => t.Skip( newConf.Length ).ToArray() ); + var c = newConf[newConf.Length - 1]; + TimerDuration = c.TimerDuration; + List toKeep = new List(); + for( int iConf = 0; iConf < c.Handlers.Count; ++iConf ) + { + for( int iHandler = 0; iHandler < _handlers.Count; ++iHandler ) + { + try + { + if( _handlers[iHandler].ApplyConfiguration( monitor, c.Handlers[iConf] ) ) + { + // Existing _handlers[iHandler] accepted the new c.Handlers[iConf]. + c.Handlers.RemoveAt( iConf-- ); + toKeep.Add( _handlers[iHandler] ); + _handlers.RemoveAt( iHandler ); + break; + } + } + catch( Exception ex ) + { + var h = _handlers[iHandler]; + // Existing _handlers[iHandler] crashed with the proposed c.Handlers[iConf]. + var msg = $"Existing {h.GetType().FullName} crashed with the configuration {c.Handlers[iConf].GetType().FullName}."; + ActivityMonitor.CriticalErrorCollector.Add( ex, msg ); + monitor.SendLine( LogLevel.Fatal, msg, ex ); + // Since the handler can be compromised, we skip it from any subsequent + // attempt to reconfigure it and deactivate it. + _handlers.RemoveAt( iHandler-- ); + SafeActivateOrDeactivate( monitor, h, false ); + } + } + } + // Deactivate and get rid of remaining handlers. + foreach( var h in _handlers ) + { + SafeActivateOrDeactivate( monitor, h, false ); + } + _handlers.Clear(); + // Restores reconfigured handlers. + _handlers.AddRange( toKeep ); + // Creates and activates new handlers. + foreach( var conf in c.Handlers ) + { + try + { + var h = GrandOutput.CreateHandler( conf ); + if( SafeActivateOrDeactivate( monitor, h, true ) ) + { + _handlers.Add( h ); + } + } + catch( Exception ex ) + { + var msg = $"While creating handler for {conf.GetType().FullName}."; + ActivityMonitor.CriticalErrorCollector.Add( ex, msg ); + monitor.SendLine( LogLevel.Fatal, msg, ex ); + } + } + lock( _confTrigger ) + Monitor.PulseAll( _confTrigger ); + } + bool SafeActivateOrDeactivate( IActivityMonitor monitor, IGrandOutputHandler h, bool activate ) { try @@ -164,12 +212,21 @@ bool SafeActivateOrDeactivate( IActivityMonitor monitor, IGrandOutputHandler h, } catch( Exception ex ) { - monitor.SendLine( LogLevel.Error, h.GetType().FullName, ex ); + var msg = $"Handler {h.GetType().FullName} crashed during {(activate?"activation":"de-activation")}."; + ActivityMonitor.CriticalErrorCollector.Add( ex, msg ); + monitor.SendLine( LogLevel.Fatal, msg, ex ); return false; } return true; } + /// + /// Starts stopping this sink, returning true iif this call + /// actually stopped it. + /// + /// + /// True if this call stopped this sink, false if it has been already been stopped by another thread. + /// public bool Stop() { if( Interlocked.Exchange( ref _stopFlag, 1 ) == 0 ) @@ -191,10 +248,19 @@ public void Finalize( int millisecondsBeforeForceClose ) public void Handle( GrandOutputEventInfo logEvent ) => _queue.Add( logEvent ); - public void ApplyConfiguration( GrandOutputConfiguration configuration ) + public void ApplyConfiguration( GrandOutputConfiguration configuration, bool waitForApplication ) { Debug.Assert( configuration.InternalClone ); Util.InterlockedAdd( ref _newConf, configuration ); + if( waitForApplication ) + { + lock( _confTrigger ) + { + GrandOutputConfiguration[] newConf; + while( _stopFlag == 0 && (newConf = _newConf) != null && newConf.Contains( configuration ) ) + Monitor.Wait( _confTrigger ); + } + } } } } diff --git a/CK.Monitoring/GrandOutput.cs b/CK.Monitoring/GrandOutput.cs index 52c9519..a3ba475 100644 --- a/CK.Monitoring/GrandOutput.cs +++ b/CK.Monitoring/GrandOutput.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; @@ -20,10 +20,20 @@ public sealed partial class GrandOutput : IDisposable { readonly List> _clients; readonly DispatcherSink _sink; + readonly object _externalLogLock; + DateTimeStamp _externalLogLastTime; + int _handleCriticalErrors; + static GrandOutput _default; static readonly object _defaultLock = new object(); + /// + /// The tag that marks all external log entry sent when + /// is true. + /// + public static CKTrait CriticalErrorTag = ActivityMonitor.Tags.Context.FindOrCreate( "CriticalError" ); + /// /// Gets the default for the current Application Domain. /// Note that must have been called, otherwise this static property is null @@ -55,19 +65,19 @@ static public GrandOutput EnsureActiveDefault( GrandOutputConfiguration configur { lock( _defaultLock ) { - if (_default == null) + if( _default == null ) { SystemActivityMonitor.EnsureStaticInitialization(); - if (configuration == null) + if( configuration == null ) { configuration = new GrandOutputConfiguration() - .AddHandler( new Handlers.TextFileConfiguration() { Path = "Text" }); + .AddHandler( new Handlers.TextFileConfiguration() { Path = "Text" } ); configuration.InternalClone = true; } - _default = new GrandOutput(configuration); + _default = new GrandOutput( configuration, true ); ActivityMonitor.AutoConfiguration += AutoRegisterDefault; } - else if(configuration != null) _default.ApplyConfiguration(configuration); + else if( configuration != null ) _default.ApplyConfiguration( configuration ); } return _default; } @@ -82,15 +92,20 @@ static void AutoRegisterDefault( IActivityMonitor m ) /// This is thread safe and can be called at any moment. /// /// The configuration to apply. - public void ApplyConfiguration(GrandOutputConfiguration configuration) + /// + /// True to block until this configuration has been applied. + /// Note that another (new) configuration may have already replaced the given configuration + /// once this call ends. + /// + public void ApplyConfiguration( GrandOutputConfiguration configuration, bool waitForApplication = false ) { - if (configuration == null) throw new ArgumentNullException(nameof(configuration)); - if (!configuration.InternalClone) + if( configuration == null ) throw new ArgumentNullException( nameof( configuration ) ); + if( !configuration.InternalClone ) { configuration = configuration.Clone(); configuration.InternalClone = true; } - _sink.ApplyConfiguration(configuration); + _sink.ApplyConfiguration( configuration, waitForApplication ); } /// @@ -99,25 +114,32 @@ public void ApplyConfiguration(GrandOutputConfiguration configuration) /// assembly and namespace as their configuration objects and named the /// same without the "Configuration" suffix. /// - static public Func CreateHandler = config => - { - string name = config.GetType().GetTypeInfo().FullName; - if (!name.EndsWith("Configuration")) throw new CKException($"Configuration handler type name must end with 'Configuration': {name}."); - name = config.GetType().AssemblyQualifiedName.Replace("Configuration,", ","); - Type t = Type.GetType(name, throwOnError: true); - return (IGrandOutputHandler)Activator.CreateInstance(t, new[] { config }); - }; + static public Func CreateHandler = config => + { + string name = config.GetType().GetTypeInfo().FullName; + if( !name.EndsWith( "Configuration" ) ) throw new CKException( $"Configuration handler type name must end with 'Configuration': {name}." ); + name = config.GetType().AssemblyQualifiedName.Replace( "Configuration,", "," ); + Type t = Type.GetType( name, throwOnError: true ); + return (IGrandOutputHandler)Activator.CreateInstance( t, new[] { config } ); + }; /// /// Initializes a new . /// /// The configuration. - public GrandOutput( GrandOutputConfiguration config ) + /// True to handle critical errors. + public GrandOutput( GrandOutputConfiguration config, bool handleCriticalErrors = false ) { - if (config == null) throw new ArgumentNullException(nameof(config)); + if( config == null ) throw new ArgumentNullException( nameof( config ) ); + // Creates the client list first. _clients = new List>(); - _sink = new DispatcherSink(config.TimerDuration, TimeSpan.FromMinutes(5), DoGarbageDeadClients ); - ApplyConfiguration(config); + // Starts the pump thread. Its monitor will be registered + // in this GrandOutput. + _sink = new DispatcherSink( m => DoEnsureGrandOutputClient( m ), config.TimerDuration, TimeSpan.FromMinutes( 5 ), DoGarbageDeadClients ); + _externalLogLock = new object(); + _externalLogLastTime = DateTimeStamp.MinValue; + HandleCriticalErrors = handleCriticalErrors; + ApplyConfiguration( config, waitForApplication: true ); } /// @@ -130,36 +152,143 @@ public GrandOutput( GrandOutputConfiguration config ) /// A newly created client or the already existing one. public GrandOutputClient EnsureGrandOutputClient( IActivityMonitor monitor ) { - if( IsDisposed ) throw new ObjectDisposedException( nameof(GrandOutput) ); - if( monitor == null ) throw new ArgumentNullException( nameof(monitor) ); + if( IsDisposed ) throw new ObjectDisposedException( nameof( GrandOutput ) ); + if( monitor == null ) throw new ArgumentNullException( nameof( monitor ) ); + return DoEnsureGrandOutputClient( monitor ); + } + + GrandOutputClient DoEnsureGrandOutputClient( IActivityMonitor monitor ) + { Func reg = () => + { + var c = new GrandOutputClient( this ); + lock( _clients ) { - var c = new GrandOutputClient( this ); - lock( _clients ) - { - if( IsDisposed ) c = null; - else _clients.Add( new WeakReference( c ) ); - } - return c; - }; + if( IsDisposed ) c = null; + else _clients.Add( new WeakReference( c ) ); + } + return c; + }; return monitor.Output.RegisterUniqueClient( b => b.Central == this, reg ); } + /// + /// Gets or sets the filter for ExternalLog methods. + /// Defaults to : .Line + /// is used. + /// + public LogLevelFilter ExternalLogFilter { get; set; } + + /// + /// Logs an entry from any contextless source. + /// The monitor target has as its . + /// + /// + /// We consider that as long has the log level has bit set, the + /// decision has already being taken and here we do our job: dispatching of the log. + /// But for logs that do not claim to have been filtered, we challenge the . + /// + /// Log level. + /// String message. + /// Optional exception. + /// Optional tags (that must belong to ). + public void ExternalLog( LogLevel level, string message, Exception ex = null, CKTrait tags = null ) + { + LogLevelFilter filter = ExternalLogFilter; + if( filter == LogLevelFilter.None ) filter = ActivityMonitor.DefaultFilter.Line; + if( (level & LogLevel.IsFiltered) == 0 ) + { + if( (int)filter > (int)(level & LogLevel.Mask) ) return; + } + DateTimeStamp prevLogTime; + DateTimeStamp logTime; + lock( _externalLogLock ) + { + prevLogTime = _externalLogLastTime; + _externalLogLastTime = logTime = new DateTimeStamp( _externalLogLastTime, DateTime.UtcNow ); + } + var e = LogEntry.CreateMulticastLog( + Guid.Empty, + LogEntryType.Line, + prevLogTime, + depth: 0, + text: string.IsNullOrEmpty( message ) ? ActivityMonitor.NoLogText : message, + t: logTime, + level: level, + fileName: null, + lineNumber: 0, + tags: tags, + ex: ex != null ? CKExceptionData.CreateFrom( ex ) : null ); + _sink.Handle( new GrandOutputEventInfo( e, String.Empty ) ); + } + + /// + /// Logs an entry from any contextless source. + /// The monitor target has as its . + /// + /// + /// We consider that as long has the log level has bit set, the + /// decision has already being taken and here we do our job: dispatching of the log. + /// But for logs that do not claim to have been filtered, we challenge the . + /// + /// Log level. + /// String message. + /// Optional tags (that must belong to ). + public void ExternalLog( LogLevel level, string message, CKTrait tags ) => ExternalLog( level, message, null, tags ); + /// /// Gets the sink. /// public IGrandOutputSink Sink => _sink; + /// + /// Gets or sets whether this GrandOutput subscribes to + /// events and sends them by calling + /// with a tag. + /// Defaults to true for the GrandOutput, false otherwise. + /// + public bool HandleCriticalErrors + { + get { return _handleCriticalErrors != 0; } + set + { + if( value ) + { + if( Interlocked.Exchange( ref _handleCriticalErrors, 1 ) == 0 ) + { + ActivityMonitor.CriticalErrorCollector.OnErrorFromBackgroundThreads += CriticalErrorCollector_OnErrorFromBackgroundThreads; + } + } + else + { + if( Interlocked.Exchange( ref _handleCriticalErrors, 0 ) == 1 ) + { + ActivityMonitor.CriticalErrorCollector.OnErrorFromBackgroundThreads -= CriticalErrorCollector_OnErrorFromBackgroundThreads; + } + } + } + } + + void CriticalErrorCollector_OnErrorFromBackgroundThreads( object sender, CriticalErrorCollector.ErrorEventArgs e ) + { + int c = e.LoggingErrors.Count; + while( --c >= 0 ) + { + var err = e.LoggingErrors[c]; + ExternalLog( LogLevel.Fatal, err.Comment, err.Exception, CriticalErrorTag ); + } + } + void DoGarbageDeadClients() { - lock (_clients) + lock( _clients ) { - for (int i = 0; i < _clients.Count; ++i) + for( int i = 0; i < _clients.Count; ++i ) { GrandOutputClient cw; - if (!_clients[i].TryGetTarget(out cw) || !cw.IsBoundToMonitor) + if( !_clients[i].TryGetTarget( out cw ) || !cw.IsBoundToMonitor ) { - _clients.RemoveAt(i--); + _clients.RemoveAt( i-- ); } } } @@ -175,13 +304,12 @@ void DoGarbageDeadClients() /// Closes this . /// If this is the default one that is disposed, is set to null. /// - /// Monitor that will be used. Must not be null. /// Maximal time to wait. - public void Dispose( IActivityMonitor monitor, int millisecondsBeforeForceClose = Timeout.Infinite ) + public void Dispose( int millisecondsBeforeForceClose = Timeout.Infinite ) { - if( monitor == null ) throw new ArgumentNullException( nameof( monitor ) ); if( _sink.Stop() ) { + HandleCriticalErrors = false; lock( _defaultLock ) { if( _default == this ) @@ -206,13 +334,12 @@ public void Dispose( IActivityMonitor monitor, int millisecondsBeforeForceClose } /// - /// Calls with a - /// and (new SystemActivityMonitor(applyAutoConfigurations: false, topic: null )). + /// Calls with . /// If this is the default one that is disposed, is set to null. /// public void Dispose() { - Dispose(new SystemActivityMonitor(applyAutoConfigurations: false, topic: null ), Timeout.Infinite ); + Dispose( Timeout.Infinite ); } diff --git a/CK.Monitoring/Handlers/BinaryFile.cs b/CK.Monitoring/Handlers/BinaryFile.cs index bc3db51..e737348 100644 --- a/CK.Monitoring/Handlers/BinaryFile.cs +++ b/CK.Monitoring/Handlers/BinaryFile.cs @@ -17,10 +17,10 @@ public class BinaryFile : IGrandOutputHandler /// Initializes a new bound to its . /// /// The configuration. - public BinaryFile(BinaryFileConfiguration config) + public BinaryFile( BinaryFileConfiguration config ) { - if (config == null) throw new ArgumentNullException("config"); - _file = new MonitorBinaryFileOutput(config.Path, config.MaxCountPerFile, config.UseGzipCompression); + if( config == null ) throw new ArgumentNullException( "config" ); + _file = new MonitorBinaryFileOutput( config.Path, config.MaxCountPerFile, config.UseGzipCompression ); _config = config; } @@ -28,11 +28,11 @@ public BinaryFile(BinaryFileConfiguration config) /// Initialization of the handler: computes the path. /// /// - public bool Activate(IActivityMonitor m) + public bool Activate( IActivityMonitor m ) { - using (m.OpenGroup(LogLevel.Trace, $"Initializing BinaryFile handler (MaxCountPerFile = {_file.MaxCountPerFile}).", null)) + using( m.OpenGroup( LogLevel.Trace, $"Initializing BinaryFile handler (MaxCountPerFile = {_file.MaxCountPerFile}).", null ) ) { - return _file.Initialize(m); + return _file.Initialize( m ); } } @@ -40,16 +40,16 @@ public bool Activate(IActivityMonitor m) /// Writes a log entry. /// /// The log entry. - public void Handle(GrandOutputEventInfo logEvent) + public void Handle( GrandOutputEventInfo logEvent ) { - _file.Write(logEvent.Entry); + _file.Write( logEvent.Entry ); } /// /// Does nothing since files are automatically managed (relies on ). /// /// Indicative timer duration. - public void OnTimer(TimeSpan timerSpan) + public void OnTimer( TimeSpan timerSpan ) { } @@ -59,14 +59,14 @@ public void OnTimer(TimeSpan timerSpan) /// The monitor to use. /// Configuration to apply. /// True if the configuration applied. - public bool ApplyConfiguration(IActivityMonitor m, IHandlerConfiguration c) + public bool ApplyConfiguration( IActivityMonitor m, IHandlerConfiguration c ) { BinaryFileConfiguration cF = c as BinaryFileConfiguration; - if (cF == null || cF.Path != _config.Path) return false; - if( _config.UseGzipCompression != cF.UseGzipCompression) + if( cF == null || cF.Path != _config.Path ) return false; + if( _config.UseGzipCompression != cF.UseGzipCompression ) { _file.Close(); - _file = new MonitorBinaryFileOutput(_config.Path, _config.MaxCountPerFile, _config.UseGzipCompression); + _file = new MonitorBinaryFileOutput( _config.Path, _config.MaxCountPerFile, _config.UseGzipCompression ); } else _file.MaxCountPerFile = cF.MaxCountPerFile; _config = cF; @@ -77,9 +77,9 @@ public bool ApplyConfiguration(IActivityMonitor m, IHandlerConfiguration c) /// Closes the file if it is opened. /// /// The monitor to use to track activity. - public void Deactivate(IActivityMonitor m) + public void Deactivate( IActivityMonitor m ) { - m.SendLine(LogLevel.Info, "Closing file for BinaryFile handler.", null); + m.SendLine( LogLevel.Info, "Closing file for BinaryFile handler.", null ); _file.Close(); } diff --git a/CK.Monitoring/Handlers/TextFile.cs b/CK.Monitoring/Handlers/TextFile.cs index 0864b44..e787e2b 100644 --- a/CK.Monitoring/Handlers/TextFile.cs +++ b/CK.Monitoring/Handlers/TextFile.cs @@ -16,6 +16,7 @@ public sealed class TextFile : IGrandOutputHandler { readonly MonitorTextFileOutput _file; TextFileConfiguration _config; + int _countFlush; /// /// Initializes a new based on a . @@ -23,9 +24,10 @@ public sealed class TextFile : IGrandOutputHandler /// The configuration. public TextFile( TextFileConfiguration config ) { - if( config == null ) throw new ArgumentNullException( nameof(config) ); + if( config == null ) throw new ArgumentNullException( nameof( config ) ); _config = config; _file = new MonitorTextFileOutput( config.Path, config.MaxCountPerFile, false ); + _countFlush = _config.AutoFlushRate; } /// @@ -53,22 +55,33 @@ public void Handle( GrandOutputEventInfo logEvent ) /// Does nothing since files are automatically managed (relies on ). /// /// Indicative timer duration. - public void OnTimer(TimeSpan timerSpan) + public void OnTimer( TimeSpan timerSpan ) { + // Don't really care of the overflow here. + if( --_countFlush == 0 ) + { + _file.Flush(); + _countFlush = _config.AutoFlushRate; + } } /// /// Attempts to apply configuration if possible. + /// The key is the : the + /// must be a with the exact same path + /// for this reconfiguration to be applied. /// /// The monitor to use. /// Configuration to apply. /// True if the configuration applied. - public bool ApplyConfiguration(IActivityMonitor m, IHandlerConfiguration c) + public bool ApplyConfiguration( IActivityMonitor m, IHandlerConfiguration c ) { TextFileConfiguration cF = c as TextFileConfiguration; - if (cF == null || cF.Path != _config.Path) return false; + if( cF == null || cF.Path != _config.Path ) return false; _config = cF; _file.MaxCountPerFile = cF.MaxCountPerFile; + _file.Flush(); + _countFlush = _config.AutoFlushRate; return true; } diff --git a/CK.Monitoring/Handlers/TextFileConfiguration.cs b/CK.Monitoring/Handlers/TextFileConfiguration.cs index f8ce45c..6bb582f 100644 --- a/CK.Monitoring/Handlers/TextFileConfiguration.cs +++ b/CK.Monitoring/Handlers/TextFileConfiguration.cs @@ -1,10 +1,20 @@ -namespace CK.Monitoring.Handlers +namespace CK.Monitoring.Handlers { /// /// Configuration object for . /// public class TextFileConfiguration : FileConfigurationBase { + /// + /// Gets or sets the rate of the auto flush to be able to read + /// the temporary currrent file content. + /// This is a multiple of + /// and defaults to 6 (default GrandOutputConfiguration timer duration being 500 milliseconds, this + /// flushes the text approximately every 3 seconds). + /// Setting this to zero disables the timed-base flush. + /// + public int AutoFlushRate { get; set; } = 6; + /// /// Clones this configuration. /// @@ -14,7 +24,8 @@ public override IHandlerConfiguration Clone() return new TextFileConfiguration() { Path = Path, - MaxCountPerFile = MaxCountPerFile + MaxCountPerFile = MaxCountPerFile, + AutoFlushRate = AutoFlushRate }; } } diff --git a/CK.Monitoring/IGrandOutputHandler.cs b/CK.Monitoring/IGrandOutputHandler.cs index 993b773..cbec111 100644 --- a/CK.Monitoring/IGrandOutputHandler.cs +++ b/CK.Monitoring/IGrandOutputHandler.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.Linq; using System.Text; @@ -9,6 +9,8 @@ namespace CK.Monitoring { /// /// Handler interface. + /// Object implementing this interface must expose a public constructor that accepts + /// a configuration object. /// public interface IGrandOutputHandler : IGrandOutputSink { @@ -18,7 +20,7 @@ public interface IGrandOutputHandler : IGrandOutputSink /// /// The monitor to use. /// True on success, false on error (this handler will not be added). - bool Activate(IActivityMonitor m); + bool Activate( IActivityMonitor m ); /// /// Called on a regular basis. @@ -29,18 +31,21 @@ public interface IGrandOutputHandler : IGrandOutputSink /// /// Attempts to apply configuration if possible. + /// The handler must check the type of the given configuration and any key configuration + /// before accepting it and reconfigures it (in such case, true must be returned). + /// If this handler considers that this new configuration does not apply to itself, it must return false. /// /// The monitor to use. /// Configuration to apply. /// True if the configuration applied. - bool ApplyConfiguration(IActivityMonitor m, IHandlerConfiguration c); + bool ApplyConfiguration( IActivityMonitor m, IHandlerConfiguration c ); /// /// Closes this handler. /// This is called after the handler has been removed. /// /// The monitor to use. - void Deactivate(IActivityMonitor m); + void Deactivate( IActivityMonitor m ); } } diff --git a/CK.Monitoring/MonitorTextFileOutput.cs b/CK.Monitoring/MonitorTextFileOutput.cs index 0575342..7144bc5 100644 --- a/CK.Monitoring/MonitorTextFileOutput.cs +++ b/CK.Monitoring/MonitorTextFileOutput.cs @@ -1,12 +1,5 @@ -using System; -using System.Collections.Generic; -using System.IO; -using System.Threading; using CK.Core; -using System.Text; -using CK.Text; -using System.Diagnostics; -using System.Linq; +using System.IO; namespace CK.Monitoring { @@ -17,13 +10,9 @@ namespace CK.Monitoring /// public class MonitorTextFileOutput : MonitorFileOutputBase { - readonly StringBuilder _builder; - readonly Dictionary _monitorNames; + readonly MulticastLogEntryTextBuilder _builder; StreamWriter _writer; - Guid _currentMonitorId; - string _currentMonitorName; - DateTime _lastLogTime; - int _nameLen; + bool _canFlush; /// /// Initializes a new file for : the final file name is based on with a ".ckmon" extension. @@ -35,8 +24,7 @@ public class MonitorTextFileOutput : MonitorFileOutputBase public MonitorTextFileOutput( string configuredPath, int maxCountPerFile, bool useGzipCompression ) : base( configuredPath, ".txt" + (useGzipCompression ? ".gzip" : string.Empty), maxCountPerFile, useGzipCompression ) { - _builder = new StringBuilder(); - _monitorNames = new Dictionary(); + _builder = new MulticastLogEntryTextBuilder(); } /// @@ -46,116 +34,22 @@ public MonitorTextFileOutput( string configuredPath, int maxCountPerFile, bool u public void Write( IMulticastLogEntry e ) { BeforeWriteEntry(); - AppendEntry(e); - _writer.Write(_builder.ToString()); + _builder.AppendEntry( e ); + _writer.Write( _builder.Builder.ToString() ); + _canFlush = true; + _builder.Builder.Clear(); AfterWriteEntry(); - _builder.Clear(); } - void AppendEntry(IMulticastLogEntry e) + /// + /// Flushes the file content if needed. + /// + public void Flush() { - Debug.Assert(DateTimeStamp.MaxValue.ToString().Length == 32, - "DateTimeStamp FileNameUniqueTimeUtcFormat and the uniquifier: max => 32 characters long."); - Debug.Assert(Guid.NewGuid().ToString().Length == 36, - "Guid => 18 characters long."); - - _builder.Append(' ', _nameLen + 32); - _builder.Append("| ", e.Text != null ? e.GroupDepth : e.GroupDepth - 1); - string prefix = _builder.ToString(); - _builder.Clear(); - // MonitorId (if needed) on one line. - if (_currentMonitorId == e.MonitorId) - { - _builder.Append(' ', _nameLen + 1); - } - else - { - _currentMonitorId = e.MonitorId; - if (!_monitorNames.TryGetValue(_currentMonitorId, out _currentMonitorName)) - { - _currentMonitorName = _monitorNames.Count.ToString("X" + _nameLen); - int len = _currentMonitorName.Length; - if (_nameLen < len) - { - prefix = " " + prefix; - _nameLen = len; - } - _monitorNames.Add(_currentMonitorId, _currentMonitorName); - _builder.Append(_currentMonitorName) - .Append("~~~~") - .Append(' ', 28) - .Append("~~ Monitor: ") - .AppendLine(_currentMonitorId.ToString()); - _builder.Append(' ', _nameLen + 1); - } - else - { - _builder.Append(_currentMonitorName).Append('~'); - _builder.Append(' ', _nameLen - _currentMonitorName.Length); - } - } - // Log time prefixes the first line only. - TimeSpan delta = e.LogTime.TimeUtc - _lastLogTime; - if (delta >= TimeSpan.FromMinutes(1)) - { - string logTime = e.LogTime.TimeUtc.ToString(FileUtil.FileNameUniqueTimeUtcFormat); - _builder.Append(' '); - _builder.Append(logTime); - _builder.Append(' '); - _lastLogTime = e.LogTime.TimeUtc; - } - else - { - _builder.Append(' ', 17); - _builder.Append('+'); - _builder.Append(delta.ToString(@"ss\.fffffff")); - _builder.Append(' '); - } - - // Level is one char. - char level; - switch (e.LogLevel & LogLevel.Mask) - { - case LogLevel.Debug: level = 'd'; break; - case LogLevel.Trace: level = ' '; break; - case LogLevel.Info: level = 'i'; break; - case LogLevel.Warn: level = 'W'; break; - case LogLevel.Error: level = 'E'; break; - default: level = 'F'; break; - } - _builder.Append(level); - _builder.Append(' '); - _builder.Append("| ", e.Text != null ? e.GroupDepth : e.GroupDepth - 1); - - if (e.Text != null) - { - if (e.LogType == LogEntryType.OpenGroup) _builder.Append("> "); - prefix += " "; - _builder.AppendMultiLine(prefix, e.Text, false).AppendLine(); - if (e.Exception != null) - { - e.Exception.ToStringBuilder(_builder, prefix); - } - } - else + if( _canFlush ) { - Debug.Assert(e.Conclusions != null); - _builder.Append("< "); - if (e.Conclusions.Count > 0) - { - _builder.Append(" | ").Append(e.Conclusions.Count).Append(" conclusion"); - if (e.Conclusions.Count > 1) _builder.Append('s'); - _builder.Append(':').AppendLine(); - prefix += " | "; - foreach (var c in e.Conclusions) - { - _builder.AppendMultiLine(prefix, c.Text, true).AppendLine(); - } - } - else - { - _builder.AppendLine(); - } + _writer.Flush(); + _canFlush = false; } } @@ -167,10 +61,7 @@ protected override Stream OpenNewFile() { Stream s = base.OpenNewFile(); _writer = new StreamWriter( s ); - _currentMonitorId = Guid.Empty; - _monitorNames.Clear(); - _nameLen = 0; - _lastLogTime = DateTime.MinValue; + _builder.Reset(); return s; } @@ -182,6 +73,7 @@ protected override void CloseCurrentFile() _writer.Flush(); _writer.Dispose(); _writer = null; + _canFlush = false; base.CloseCurrentFile(); } } diff --git a/CK.Monitoring/MulticastLogEntryTextBuilder.cs b/CK.Monitoring/MulticastLogEntryTextBuilder.cs new file mode 100644 index 0000000..505c6b9 --- /dev/null +++ b/CK.Monitoring/MulticastLogEntryTextBuilder.cs @@ -0,0 +1,175 @@ +using CK.Core; +using CK.Text; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Text; + +namespace CK.Monitoring +{ + /// + /// Writes to a . + /// This object is not thread-safe. If it must be used in a concurrent manner, + /// a lock should protect it. + /// + public class MulticastLogEntryTextBuilder + { + readonly StringBuilder _prefixBuilder; + readonly StringBuilder _builder; + readonly Dictionary _monitorNames; + Guid _currentMonitorId; + string _currentMonitorName; + DateTime _lastLogTime; + int _nameLen; + + /// + /// Initializes a new instance of . + /// + /// The initial string builder to use. + public MulticastLogEntryTextBuilder( StringBuilder b = null ) + { + _prefixBuilder = new StringBuilder(); + _builder = new StringBuilder(); + _monitorNames = new Dictionary(); + } + + /// + /// Gets the . + /// + public StringBuilder Builder => _builder; + + /// + /// Appends a formatted entry to the . + /// + /// The + public void AppendEntry( IMulticastLogEntry e ) + { + Debug.Assert( DateTimeStamp.MaxValue.ToString().Length == 32, + "DateTimeStamp FileNameUniqueTimeUtcFormat and the uniquifier: max => 32 characters long." ); + Debug.Assert( Guid.NewGuid().ToString().Length == 36, + "Guid => 18 characters long." ); + + _prefixBuilder.Append( ' ', _nameLen + 32 ); + _prefixBuilder.Append( "| ", e.Text != null ? e.GroupDepth : e.GroupDepth - 1 ); + string prefix = _prefixBuilder.ToString(); + _prefixBuilder.Clear(); + // MonitorId (if needed) on one line. + if( e.MonitorId == Guid.Empty ) + { + _builder.Append('-').Append( ' ', _nameLen ); + } + else if( _currentMonitorId == e.MonitorId ) + { + _builder.Append( ' ', _nameLen + 1 ); + } + else + { + _currentMonitorId = e.MonitorId; + if( !_monitorNames.TryGetValue( _currentMonitorId, out _currentMonitorName ) ) + { + _currentMonitorName = _monitorNames.Count.ToString( "X" + _nameLen ); + int len = _currentMonitorName.Length; + if( _nameLen < len ) + { + prefix = " " + prefix; + _nameLen = len; + } + _monitorNames.Add( _currentMonitorId, _currentMonitorName ); + _builder.Append( _currentMonitorName ) + .Append( "~~~~" ) + .Append( ' ', 28 ) + .Append( "~~ Monitor: " ) + .AppendLine( _currentMonitorId.ToString() ); + _builder.Append( ' ', _nameLen + 1 ); + } + else + { + _builder.Append( _currentMonitorName ).Append( '~' ); + _builder.Append( ' ', _nameLen - _currentMonitorName.Length ); + } + } + // Log time prefixes the first line only. + TimeSpan delta = e.LogTime.TimeUtc - _lastLogTime; + if( delta >= TimeSpan.FromMinutes( 1 ) ) + { + string logTime = e.LogTime.TimeUtc.ToString( FileUtil.FileNameUniqueTimeUtcFormat ); + _builder.Append( ' ' ); + _builder.Append( logTime ); + _builder.Append( ' ' ); + _lastLogTime = e.LogTime.TimeUtc; + } + else + { + _builder.Append( ' ', 17 ); + _builder.Append( '+' ); + _builder.Append( delta.ToString( @"ss\.fffffff" ) ); + _builder.Append( ' ' ); + } + + // Level is one char. + char level; + switch( e.LogLevel & LogLevel.Mask ) + { + case LogLevel.Debug: level = 'd'; break; + case LogLevel.Trace: level = ' '; break; + case LogLevel.Info: level = 'i'; break; + case LogLevel.Warn: level = 'W'; break; + case LogLevel.Error: level = 'E'; break; + default: level = 'F'; break; + } + _builder.Append( level ); + _builder.Append( ' ' ); + _builder.Append( "| ", e.Text != null ? e.GroupDepth : e.GroupDepth - 1 ); + + if( e.Text != null ) + { + if( e.LogType == LogEntryType.OpenGroup ) _builder.Append( "> " ); + prefix += " "; + _builder.AppendMultiLine( prefix, e.Text, false ).AppendLine(); + if( e.Exception != null ) + { + e.Exception.ToStringBuilder( _builder, prefix ); + } + } + else + { + Debug.Assert( e.Conclusions != null ); + _builder.Append( "< " ); + if( e.Conclusions.Count > 0 ) + { + _builder.Append( " | " ).Append( e.Conclusions.Count ).Append( " conclusion" ); + if( e.Conclusions.Count > 1 ) _builder.Append( 's' ); + _builder.Append( ':' ).AppendLine(); + prefix += " | "; + foreach( var c in e.Conclusions ) + { + _builder.AppendMultiLine( prefix, c.Text, true ).AppendLine(); + } + } + else + { + _builder.AppendLine(); + } + } + } + + /// + /// Clears the and resets internal states (like monitor's numbering). + /// + public void Reset() + { + _builder.Clear(); + _currentMonitorId = Guid.Empty; + _monitorNames.Clear(); + _nameLen = 0; + _lastLogTime = DateTime.MinValue; + } + + /// + /// Overridden to return the 's ToString(). + /// + /// The builder's current text. + public override string ToString() => _builder.ToString(); + + } +} diff --git a/Tests/CK.Monitoring.Tests/CriticalErrorsTests.cs b/Tests/CK.Monitoring.Tests/CriticalErrorsTests.cs new file mode 100644 index 0000000..58524ec --- /dev/null +++ b/Tests/CK.Monitoring.Tests/CriticalErrorsTests.cs @@ -0,0 +1,111 @@ +using System; +using System.Collections.Generic; +using System.IO; +using System.Linq; +using System.Xml.Linq; +using CK.Core; +using NUnit.Framework; +using System.Threading.Tasks; +using FluentAssertions; +using System.Threading; + +namespace CK.Monitoring.Tests +{ + [TestFixture] + public class CriticalErrorsTests + { + [SetUp] + public void InitializePath() => TestHelper.InitalizePaths(); + + [Test] + public void HandleCriticalErrors_quick_test() + { + string folder = TestHelper.PrepareLogFolder( "CriticalErrorsQuickTest" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "CriticalErrorsQuickTest" }; + var config = new GrandOutputConfiguration().AddHandler( textConf ); + using( GrandOutput g = new GrandOutput( config ) ) + { + g.HandleCriticalErrors.Should().BeFalse(); + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "NOSHOW" ), null ); + ActivityMonitor.CriticalErrorCollector.WaitOnErrorFromBackgroundThreadsPending(); + g.HandleCriticalErrors = true; + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "SHOW 1" ), null ); + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "SHOW 2" ), "...with comment..." ); + ActivityMonitor.CriticalErrorCollector.WaitOnErrorFromBackgroundThreadsPending(); + g.HandleCriticalErrors = false; + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "NOSHOW" ), null ); + ActivityMonitor.CriticalErrorCollector.WaitOnErrorFromBackgroundThreadsPending(); + } + string textLogged = File.ReadAllText( Directory.EnumerateFiles( folder ).Single() ); + textLogged.Should() + .Contain( "SHOW 1" ) + .And.Contain( "SHOW 2" ) + .And.Contain( "...with comment..." ) + .And.NotContain( "NOSHOW" ); + } + + public class BuggySinkConfiguration : IHandlerConfiguration + { + public IHandlerConfiguration Clone() => new BuggySinkConfiguration(); + } + + public class BuggySinkHandler : IGrandOutputHandler + { + public BuggySinkHandler( BuggySinkConfiguration conf ) + { + } + + public bool Activate( IActivityMonitor m ) => true; + + public bool ApplyConfiguration( IActivityMonitor m, IHandlerConfiguration c ) + { + return c is BuggySinkConfiguration; + } + + public void Deactivate( IActivityMonitor m ) + { + } + + public void Handle( GrandOutputEventInfo logEvent ) + { + throw new Exception( "From inside BuggySinkHandler" ); + } + + public void OnTimer( TimeSpan timerSpan ) + { + } + } + + public class KExistePasConfiguration : IHandlerConfiguration + { + public IHandlerConfiguration Clone() => new KExistePasConfiguration(); + } + + [Test] + public void CriticalErrors_handle_sink_creation_error() + { + string folder = TestHelper.PrepareLogFolder( "CriticalErrorsSinkCreationError" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "CriticalErrorsSinkCreationError" }; + var config = new GrandOutputConfiguration() + .AddHandler( textConf ) + .AddHandler( new KExistePasConfiguration() ); + using( GrandOutput g = new GrandOutput( config, true ) ) + { + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "SHOW 1" ), null ); + ActivityMonitor.CriticalErrorCollector.WaitOnErrorFromBackgroundThreadsPending(); + ActivityMonitor.CriticalErrorCollector.Add( new Exception( "SHOW 2" ), "...with comment..." ); + ActivityMonitor.CriticalErrorCollector.WaitOnErrorFromBackgroundThreadsPending(); + } + string textLogged = File.ReadAllText( Directory.EnumerateFiles( folder ).Single() ); + textLogged.Should() + .Contain( "SHOW 1" ) + .And.Contain( "SHOW 2" ) + .And.Contain( "...with comment..." ) + .And.Contain( "While creating handler for CK.Monitoring.Tests.CriticalErrorsTests+KExistePasConfiguration." ); + } + + + } +} diff --git a/Tests/CK.Monitoring.Tests/GrandOutputTests.cs b/Tests/CK.Monitoring.Tests/GrandOutputTests.cs index a5c27c5..83000fa 100644 --- a/Tests/CK.Monitoring.Tests/GrandOutputTests.cs +++ b/Tests/CK.Monitoring.Tests/GrandOutputTests.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Diagnostics; using System.IO; using System.Linq; @@ -98,10 +98,13 @@ public void CKMon_binary_files_can_be_GZip_compressed() var map = mlr.GetActivityMap(); - map.Monitors.Should().HaveCount( 3 ); - map.Monitors[0].ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); - map.Monitors[1].ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); - map.Monitors[2].ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); + map.Monitors.Should().HaveCount( 4 ); + // The DispatcherSink monitor define its Topic: CK.Monitoring.DispatcherSink + // Others do not have any topic. + var notDispatcherSinkMonitors = map.Monitors.Where( m => !m.AllTags.Any( t => t.Key == ActivityMonitor.Tags.MonitorTopicChanged ) ); + notDispatcherSinkMonitors.ElementAt( 0 ).ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); + notDispatcherSinkMonitors.ElementAt( 1 ).ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); + notDispatcherSinkMonitors.ElementAt( 2 ).ReadFirstPage( 6000 ).Entries.Should().HaveCount( 5415 ); } static IActivityMonitor CreateMonitorAndRegisterGrandOutput( string topic, GrandOutput go ) @@ -118,40 +121,89 @@ public class SlowSinkHandlerConfiguration : IHandlerConfiguration public IHandlerConfiguration Clone() => new SlowSinkHandlerConfiguration() { Delay = Delay }; } + public class SlowSinkHandler : IGrandOutputHandler { int _delay; + public static volatile int ActivatedDelay; public SlowSinkHandler( SlowSinkHandlerConfiguration c ) { + _delay = c.Delay; } public bool Activate( IActivityMonitor m ) { + ActivatedDelay = _delay; return true; } public bool ApplyConfiguration( IActivityMonitor m, IHandlerConfiguration c ) { - _delay = ((SlowSinkHandlerConfiguration)c).Delay; - return true; + var conf = c as SlowSinkHandlerConfiguration; + if( conf != null ) + { + _delay = conf.Delay; + ActivatedDelay = _delay; + return true; + } + return false; } public void Deactivate( IActivityMonitor m ) { + ActivatedDelay = -1; } - public void Handle( GrandOutputEventInfo logEvent ) => Thread.Sleep( _delay ); + public void Handle( GrandOutputEventInfo logEvent ) + { + _delay.Should().BeGreaterOrEqualTo( 0 ); + _delay.Should().BeLessThan( 1000 ); + Thread.Sleep( _delay ); + } public void OnTimer( TimeSpan timerSpan ) { } } - - [Test] - public void disposing_GrandOutput_waits_for_termination() + public void ApplyConfiguration_can_wait() + { + var c100 = new GrandOutputConfiguration() + .AddHandler( new SlowSinkHandlerConfiguration() { Delay = 100 } ); + var c0 = new GrandOutputConfiguration() + .AddHandler( new SlowSinkHandlerConfiguration() { Delay = 0 } ); + SlowSinkHandler.ActivatedDelay = -1; + using( var g = new GrandOutput( c100 ) ) + { + SlowSinkHandler.ActivatedDelay.Should().Be( 100 ); + // Without waiting, we must be able to find an apply that + // did not succeed in at least 11 tries. + int i; + for( i = 0; i <= 10; ++i ) + { + SlowSinkHandler.ActivatedDelay = -1; + g.ApplyConfiguration( c0, waitForApplication: false ); + if( SlowSinkHandler.ActivatedDelay == -1 ) break; + } + i.Should().BeLessThan( 10 ); + // With wait for application: + // ...Artificially adding multiple configurations with 0 delay. + for( i = 0; i <= 10; ++i ) g.ApplyConfiguration( c0, waitForApplication: false ); + // ...Applying 100 is effective. + g.ApplyConfiguration( c100, waitForApplication: true ); + SlowSinkHandler.ActivatedDelay.Should().Be( 100 ); + // ...Artificially adding multiple configurations with 100 delay. + for( i = 0; i <= 10; ++i ) g.ApplyConfiguration( c100, waitForApplication: false ); + // ...Applying 0 is effective. + g.ApplyConfiguration( c0, waitForApplication: true ); + SlowSinkHandler.ActivatedDelay.Should().Be( 0 ); + } + } + + [TestCase( 1 )] + public void disposing_GrandOutput_waits_for_termination( int loop ) { string logPath = TestHelper.PrepareLogFolder( "Termination" ); var c = new GrandOutputConfiguration() @@ -162,22 +214,22 @@ public void disposing_GrandOutput_waits_for_termination() { var m = new ActivityMonitor( applyAutoConfigurations: false ); g.EnsureGrandOutputClient( m ); - DumpMonitor1082Entries( m, 300 ); + DumpMonitor1082Entries( m, loop ); } // All tempoary files have been closed. var fileNames = Directory.EnumerateFiles( logPath ).ToList(); fileNames.Should().NotContain( s => s.EndsWith( ".tmp" ) ); - // The 300 "~~~~~FINAL TRACE~~~~~" appear in text logs. + // The {loop} "~~~~~FINAL TRACE~~~~~" appear in text logs. fileNames .Where( n => n.EndsWith( ".txt" ) ) .Select( n => File.ReadAllText( n ) ) .Select( t => Regex.Matches( t, "~~~~~FINAL TRACE~~~~~" ).Count ) .Sum() - .Should().Be( 300 ); + .Should().Be( loop ); } - [Test] - public void disposing_GrandOutput_deactivate_handlers_even_when_disposing_fast_but_logs_are_lost() + [TestCase(1)] + public void disposing_GrandOutput_deactivate_handlers_even_when_disposing_fast_but_logs_are_lost( int loop ) { string logPath = TestHelper.PrepareLogFolder( "TerminationLost" ); var c = new GrandOutputConfiguration() @@ -187,19 +239,19 @@ public void disposing_GrandOutput_deactivate_handlers_even_when_disposing_fast_b { var m = new ActivityMonitor( applyAutoConfigurations: false ); g.EnsureGrandOutputClient( m ); - DumpMonitor1082Entries( m, 300 ); - g.Dispose( TestHelper.ConsoleMonitor, 0 ); + DumpMonitor1082Entries( m, loop ); + g.Dispose( 0 ); } // All tempoary files have been closed. var fileNames = Directory.EnumerateFiles( logPath ).ToList(); fileNames.Should().NotContain( s => s.EndsWith( ".tmp" ) ); - // There is less that the normal 300 "~~~~~FINAL TRACE~~~~~" in text logs. + // There is less that the normal {loop} "~~~~~FINAL TRACE~~~~~" in text logs. fileNames .Where( n => n.EndsWith( ".txt" ) ) .Select( n => File.ReadAllText( n ) ) .Select( t => Regex.Matches( t, "~~~~~FINAL TRACE~~~~~" ).Count ) .Sum() - .Should().BeLessThan( 300 ); + .Should().BeLessThan( loop ); } static void DumpMonitor1082Entries( IActivityMonitor monitor, int count ) diff --git a/Tests/CK.Monitoring.Tests/Persistence/MultiFileReaderTests.cs b/Tests/CK.Monitoring.Tests/Persistence/MultiFileReaderTests.cs index ddca24e..cd15ae0 100644 --- a/Tests/CK.Monitoring.Tests/Persistence/MultiFileReaderTests.cs +++ b/Tests/CK.Monitoring.Tests/Persistence/MultiFileReaderTests.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; @@ -10,6 +10,7 @@ using NUnit.Framework; using FluentAssertions; using System.Threading; +using CK.Text; namespace CK.Monitoring.Tests.Persistence { @@ -31,21 +32,26 @@ public void artificially_generated_missing_log_entries_are_detected() var m = new ActivityMonitor( false ); g.EnsureGrandOutputClient( m ); m.Trace( "NoShow-1" ); - g.ApplyConfiguration( emptyConfig ); + g.ApplyConfiguration( emptyConfig, true ); m.Trace( "NoShow-2" ); - Thread.Sleep( 300 ); - g.ApplyConfiguration( binaryConfig ); - Thread.Sleep( 300 ); + // We must let the trace to be handled by the previous configuration: + // entries are not processed before a change of the config since + // we want to apply the new configuration as soon as possible. + Thread.Sleep( emptyConfig.TimerDuration + emptyConfig.TimerDuration ); + g.ApplyConfiguration( binaryConfig, true ); m.Trace( "Show-1" ); - Thread.Sleep( 300 ); - g.ApplyConfiguration( emptyConfig ); - Thread.Sleep( 300 ); + Thread.Sleep( emptyConfig.TimerDuration + emptyConfig.TimerDuration ); + g.ApplyConfiguration( emptyConfig, true ); m.Trace( "NoShow-3" ); } var replayed = new ActivityMonitor( false ); var c = replayed.Output.RegisterClient( new StupidStringClient() ); TestHelper.ReplayLogs( new DirectoryInfo( folder ), true, mon => replayed, TestHelper.ConsoleMonitor ); - c.Entries.Select( e => e.Text ).ShouldBeEquivalentTo( new[] { "", "Show-1" }, o => o.WithStrictOrdering() ); + var entries = c.Entries.Select( e => e.Text ).Concatenate( "|" ); + // We may have "|Initializing..." followe by "|Show-1" or the opposite. + + entries.Should().Contain( "|Initializing BinaryFile handler (MaxCountPerFile = 20000)." ) + .And.Contain( "|Show-1" ); } @@ -103,20 +109,18 @@ private static void DuplicateTestWith6Entries( int nbEntries1, int nbEntries2, b reader.Add( files ); var map = reader.GetActivityMap(); map.ValidFiles.All( rawFile => rawFile.IsValidFile ).Should().BeTrue( "All files are correctly closed with the final 0 byte and no exception occurred while reading them." ); + map.Monitors.Should().HaveCount( 2 ); - var readMonitor = map.Monitors.Single(); + var allEntries1 = map.Monitors[0].ReadAllEntries().ToList(); + var allEntries2 = map.Monitors[1].ReadAllEntries().ToList(); - List allEntries = new List(); - using( var pageReader = readMonitor.ReadFirstPage( pageReadLength ) ) - { - do - { - allEntries.AddRange( pageReader.Entries ); - } - while( pageReader.ForwardPage() > 0 ); - } - allEntries.Select( e => e.Entry.Text ).ShouldBeEquivalentTo( - new[] { "Trace 1", "OpenTrace 1", "Trace 1.1", "Trace 1.2", null, "Trace 2" }, o => o.WithStrictOrdering() ); + var allEntries = allEntries1.Any( e => e.Entry.Text == "Topic: CK.Monitoring.DispatcherSink" ) + ? allEntries2 + : allEntries1; + + allEntries.Select( e => e.Entry.Text ) + .SequenceEqual( new[] { "Trace 1", "OpenTrace 1", "Trace 1.1", "Trace 1.2", null, "Trace 2" } ) + .Should().BeTrue(); } } diff --git a/Tests/CK.Monitoring.Tests/Properties/launchSettings.json b/Tests/CK.Monitoring.Tests/Properties/launchSettings.json index 83980da..1beb3a0 100644 --- a/Tests/CK.Monitoring.Tests/Properties/launchSettings.json +++ b/Tests/CK.Monitoring.Tests/Properties/launchSettings.json @@ -1,4 +1,4 @@ -{ +{ "profiles": { "NUnit GUI": { "commandName": "Executable", @@ -6,4 +6,4 @@ "commandLineArgs": "bin\\Release\\net451\\CK.Monitoring.Tests.dll" } } -} \ No newline at end of file +} diff --git a/Tests/CK.Monitoring.Tests/TestHelper.cs b/Tests/CK.Monitoring.Tests/TestHelper.cs index d7b29cf..6f23ae8 100644 --- a/Tests/CK.Monitoring.Tests/TestHelper.cs +++ b/Tests/CK.Monitoring.Tests/TestHelper.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.IO; using System.Linq; @@ -9,7 +9,6 @@ namespace CK.Monitoring.Tests { - static class TestHelper { static string _solutionFolder; @@ -37,6 +36,15 @@ public static bool LogsToConsole } } + public static string FileReadAllText( string path ) + { + using( Stream s = new FileStream( path, FileMode.Open, FileAccess.Read, FileShare.ReadWrite, 4096, FileOptions.SequentialScan ) ) + using( StreamReader r = new StreamReader( s ) ) + { + return r.ReadToEnd(); + } + } + public static string SolutionFolder { get diff --git a/Tests/CK.Monitoring.Tests/TextFileTests.cs b/Tests/CK.Monitoring.Tests/TextFileTests.cs index 2643f37..540a56f 100644 --- a/Tests/CK.Monitoring.Tests/TextFileTests.cs +++ b/Tests/CK.Monitoring.Tests/TextFileTests.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; using System.IO; using System.Linq; @@ -7,6 +7,7 @@ using NUnit.Framework; using System.Threading.Tasks; using FluentAssertions; +using System.Threading; namespace CK.Monitoring.Tests { @@ -16,6 +17,7 @@ public class TextFileTests static readonly Exception _exceptionWithInner; static readonly Exception _exceptionWithInnerLoader; + #region static initialization of exceptions static TextFileTests() { _exceptionWithInner = ThrowExceptionWithInner( false ); @@ -45,10 +47,136 @@ static Exception ThrowLoaderException() catch( Exception ex ) { e = ex; } return e; } + #endregion [SetUp] public void InitializePath() => TestHelper.InitalizePaths(); + [Test] + public void text_file_auto_flush_and_reconfiguration() + { + string folder = TestHelper.PrepareLogFolder( "AutoFlush" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "AutoFlush" }; + textConf.AutoFlushRate.Should().Be( 6, "Default AutoFlushRate configuration." ); + + var config = new GrandOutputConfiguration().AddHandler( textConf ); + config.TimerDuration.Should().Be( TimeSpan.FromMilliseconds( 500 ), "Default timer congiguration." ); + + using( GrandOutput g = new GrandOutput( config ) ) + { + var m = new ActivityMonitor( false ); + g.EnsureGrandOutputClient( m ); + Thread.Sleep( 5 ); + m.Info( "Must wait 3 seconds..." ); + Thread.Sleep( 700 ); + string tempFile = Directory.EnumerateFiles( folder ).Single(); + TestHelper.FileReadAllText( tempFile ).Should().BeEmpty(); + Thread.Sleep( 3000 ); + TestHelper.FileReadAllText( tempFile ).Should().Contain( "Must wait 3 seconds..." ); + + textConf.AutoFlushRate = 1; + m.Info( "Reconfiguration triggers a flush..." ); + Thread.Sleep( 10 ); + g.ApplyConfiguration( new GrandOutputConfiguration().AddHandler( textConf ), waitForApplication: true ); + TestHelper.FileReadAllText( tempFile ).Should().Contain( "Reconfiguration triggers a flush..." ); + m.Info( "Wait only approx 500ms..." ); + Thread.Sleep( 700 ); + string final = TestHelper.FileReadAllText( tempFile ); + final.Should().Contain( "Wait only approx 500ms" ); + } + } + + [Test] + public void external_logs_quick_test() + { + string folder = TestHelper.PrepareLogFolder( "ExternalLogsQuickTest" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "ExternalLogsQuickTest" }; + var config = new GrandOutputConfiguration().AddHandler( textConf ); + using( GrandOutput g = new GrandOutput( config ) ) + { + Task.Run( () => g.ExternalLog( LogLevel.Info, "Async started." ) ).Wait(); + var m = new ActivityMonitor( false ); + g.EnsureGrandOutputClient( m ); + m.Info( "Normal monitor starts." ); + Task t = Task.Run( () => + { + for( int i = 0; i < 10; ++i ) g.ExternalLog( LogLevel.Info, $"Async n°{i}." ); + } ); + m.MonitorEnd( "This is the end." ); + t.Wait(); + } + string textLogged = File.ReadAllText( Directory.EnumerateFiles( folder ).Single() ); + textLogged.Should() + .Contain( "Normal monitor starts." ) + .And.Contain( "Async started." ) + .And.Contain( "Async n°0." ) + .And.Contain( "Async n°9." ) + .And.Contain( "This is the end." ); + } + + [Test] + public void external_logs_stress_test() + { + string folder = TestHelper.PrepareLogFolder( "ExternalLogsStressTest" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "ExternalLogsStressTest" }; + var config = new GrandOutputConfiguration().AddHandler( textConf ); + int taskCount = 20; + int logCount = 10; + using( GrandOutput g = new GrandOutput( config ) ) + { + var tasks = Enumerable.Range( 0, taskCount ).Select( c => Task.Run( () => + { + for( int i = 0; i < logCount; ++i ) + { + Thread.Sleep( 2 ); + g.ExternalLog( LogLevel.Info, $"{c} n°{i}." ); + } + } ) ).ToArray(); + Task.WaitAll( tasks ); + } + string textLogged = File.ReadAllText( Directory.EnumerateFiles( folder ).Single() ); + for( int c = 0; c < taskCount; ++c ) + for( int i = 0; i < logCount; ++i ) + textLogged.Should() + .Contain( $"{c} n°{i}." ); + } + + [Test] + public void external_logs_filtering() + { + string folder = TestHelper.PrepareLogFolder( "ExternalLogsFiltering" ); + + var textConf = new Handlers.TextFileConfiguration() { Path = "ExternalLogsFiltering" }; + var config = new GrandOutputConfiguration().AddHandler( textConf ); + ActivityMonitor.DefaultFilter.Line.Should().Be( LogLevelFilter.Trace ); + using( GrandOutput g = new GrandOutput( config ) ) + { + g.ExternalLog( LogLevel.Debug, "NOSHOW" ); + g.ExternalLog( LogLevel.Trace, "SHOW 0" ); + g.ExternalLogFilter = LogLevelFilter.Debug; + g.ExternalLog( LogLevel.Debug, "SHOW 1" ); + g.ExternalLogFilter = LogLevelFilter.Error; + g.ExternalLog( LogLevel.Warn, "NOSHOW" ); + g.ExternalLog( LogLevel.Error, "SHOW 2" ); + g.ExternalLog( LogLevel.Fatal, "SHOW 3" ); + g.ExternalLog( LogLevel.Trace|LogLevel.IsFiltered, "SHOW 4" ); + g.ExternalLogFilter = LogLevelFilter.None; + g.ExternalLog( LogLevel.Debug, "NOSHOW" ); + g.ExternalLog( LogLevel.Trace, "SHOW 4" ); + } + string textLogged = File.ReadAllText( Directory.EnumerateFiles( folder ).Single() ); + textLogged.Should() + .Contain( "SHOW 0" ) + .And.Contain( "SHOW 1" ) + .And.Contain( "SHOW 2" ) + .And.Contain( "SHOW 3" ) + .And.Contain( "SHOW 4" ) + .And.NotContain( "NOSHOW" ); + } + [Explicit] [Test] public void dumping_text_file_with_multiple_monitors()