diff --git a/imm/Imm.cs b/imm/Imm.cs index d20a359..2657d78 100644 --- a/imm/Imm.cs +++ b/imm/Imm.cs @@ -30,9 +30,9 @@ public interface Obj /// Obj Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 ); + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 ); } @@ -59,9 +59,9 @@ public interface Obj : Obj where T : Obj T Process( Func fn, string reason = "Processed", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 , + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 , [CallerArgumentExpression("fn")] string expStr = "" ); @@ -71,9 +71,9 @@ public interface Obj : Obj where T : Obj /// new T Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 ); + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 ); } @@ -186,9 +186,9 @@ public record class Versioned : Obj where T : Versioned public virtual T Process( Func fn, string reason = "Processed", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 , + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 , [CallerArgumentExpression("fn")] string expStr = "" ) { var current = (T)this; @@ -211,18 +211,18 @@ public record class Versioned : Obj where T : Versioned /// public virtual T Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 ) => Process( t => t, reason, memberName, filePath, lineNumber ); + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 ) => Process( t => t, reason, dbgName, dbgPath, dbgLine ); /// /// Implements Obj.Record by calling the virtual T Record. /// Obj Obj.Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 ) => this.Record( reason, memberName, filePath, lineNumber ); + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 ) => this.Record( reason, dbgName, dbgPath, dbgLine ); } @@ -244,9 +244,9 @@ public record class Recorded : Versioned where T : Recorded public virtual T Process( Func fn, string reason = "", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0, + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0, [CallerArgumentExpression("fn")] string expStr = "") { var current = (T)this; @@ -258,9 +258,9 @@ public record class Recorded : Versioned where T : Recorded { Version = current.Meta.Version + 1, Reason = reason, - MemberName = memberName, - FilePath = filePath, - LineNumber = lineNumber, + MemberName = dbgName, + FilePath = dbgPath, + LineNumber = dbgLine, Expression = expStr, OldObject = current }; @@ -272,11 +272,11 @@ public record class Recorded : Versioned where T : Recorded public new T Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0) + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0) { - return Process(t => t, reason, memberName, filePath, lineNumber ); + return Process(t => t, reason, dbgName, dbgPath, dbgLine ); } } @@ -294,27 +294,29 @@ public record class Timed : Recorded where T : Timed public Timed() { } protected Timed(Timed original) : base(original) { Meta = original.Meta; } + public override T Process( Func fn, string reason = "", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0, - [CallerArgumentExpression("fn")] string expression = "") + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0, + [CallerArgumentExpression( "fn" )] string dbgExpression = "" ) { var current = (T)this; - var next = fn(current); + var next = fn( current ); - if (ReferenceEquals(current, next)) return current; + if( ReferenceEquals( current, next ) ) + return current; var newMeta = new Metadata_Timed { Version = current.Meta.Version + 1, Reason = reason, - MemberName = memberName, - FilePath = filePath, - LineNumber = lineNumber, - Expression = expression, + MemberName = dbgName, + FilePath = dbgPath, + LineNumber = dbgLine, + Expression = dbgExpression, OldObject = current, CreatedAt = DateTime.UtcNow, TouchedAt = DateTime.UtcNow @@ -322,16 +324,34 @@ public record class Timed : Recorded where T : Timed var currentTimedMeta = current.Meta; var newVersion = next with { Meta = newMeta, OnChange = current.OnChange }; - newVersion.OnChange(current, newVersion); + newVersion.OnChange( current, newVersion ); return newVersion; } public new T Record( string reason = "Recorded", - [CallerMemberName] string memberName = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0) + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0) { - return Process(t => t, reason, memberName, filePath, lineNumber ); + return Process(t => t, reason, dbgName, dbgPath, dbgLine ); } } + +public static class TimedExt +{ + public static T Process( + ref T obj, + Func fn, + string reason = "", + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0, + [CallerArgumentExpression( "fn" )] string dbgExpression = "" + ) + where T : imm.Timed + { + obj = obj.Process( fn, reason, dbgName, dbgPath, dbgLine, dbgExpression ); + return obj; + } +} \ No newline at end of file diff --git a/imm/iu.cs b/imm/iu.cs index c1654b9..0b8473f 100644 --- a/imm/iu.cs +++ b/imm/iu.cs @@ -16,11 +16,11 @@ public static class iu public static T LightProcess( ref T obj, Func fn, - string reason = "Processed") + string reason = "Processed" ) where T : Versioned { - obj = obj.Process(fn, reason); - return obj; + obj = obj.Process( fn, reason ); + return obj; } /// @@ -33,15 +33,17 @@ public static class iu [CallerMemberName] string dbgName = "", [CallerFilePath] string dbgPath = "", [CallerLineNumber] int dbgLine = 0, - [CallerArgumentExpression("fn")] string dbgExpression = "") + [CallerArgumentExpression( "fn" )] string dbgExpression = "" ) where T : Recorded // Catches Recorded and Timed { // This will call the 'Timed' override if T is Timed, // or the 'Recorded' override if T is Recorded. - obj = obj.Process(fn, reason, dbgName, dbgPath, dbgLine, dbgExpression); + obj = obj.Process( fn, reason, dbgName, dbgPath, dbgLine, dbgExpression ); return obj; } + + // No specific Process needed for Timed, as it's caught by Recorded // and its Process override handles the timing. } \ No newline at end of file diff --git a/logging/Log.cs b/logging/Log.cs index 839a030..35e4eaa 100644 --- a/logging/Log.cs +++ b/logging/Log.cs @@ -27,7 +27,7 @@ ref: https://learn.microsoft.com/en-us/dotnet/csharp/whats-new/tutorials/interpo D O N E: -N O T D O I N G : +N O T  D O I N G : */ @@ -42,9 +42,9 @@ public record struct Value( T _val, string _exp = "" ) } static public Value Get( U v, - [CallerArgumentExpression("v")] - string dbgExp = "" - ) + [CallerArgumentExpression("v")] + string dbgExp = "" +) { return new( v, dbgExp ); } @@ -71,10 +71,10 @@ public struct SourceLoc public string ToLogString() => $"{_dbgFile}.{_dbgName}"; static public SourceLoc Record( - string reason = "", - [CallerMemberName] string dbgName = "", - [CallerFilePath] string dbgPath = "", - [CallerLineNumber] int dbgLine = 0 + string reason = "", + [CallerMemberName] string dbgName = "", + [CallerFilePath] string dbgPath = "", + [CallerLineNumber] int dbgLine = 0 ) { return new SourceLoc( reason, dbgName, dbgPath, dbgLine ); @@ -98,12 +98,12 @@ static public class log /* { - var start = new ThreadStart( StartGCWatcher ); + var start = new ThreadStart( StartGCWatcher ); - var thread = new Thread( start ); - thread.Priority = ThreadPriority.BelowNormal; - thread.Name = $"Logging"; - thread.Start(); + var thread = new Thread( start ); + thread.Priority = ThreadPriority.BelowNormal; + thread.Name = $"Logging"; + thread.Start(); } // */ @@ -120,12 +120,12 @@ static public class log /* { - var start = new ThreadStart( StartTracing ); + var start = new ThreadStart( StartTracing ); - var thread = new Thread( start ); - thread.Priority = ThreadPriority.BelowNormal; - thread.Name = $"Logging"; - thread.Start(); + var thread = new Thread( start ); + thread.Priority = ThreadPriority.BelowNormal; + thread.Name = $"Logging"; + thread.Start(); } // */ @@ -134,31 +134,26 @@ static public class log static void StartGCWatcher() { - while( s_threading != ThreadState.Running ) - { - Thread.Sleep( 10 ); - } - + // This wait is no longer needed with BlockingCollection, but kept for this component's logic + // It would be better to use a ManualResetEvent here if waiting is truly needed. + Thread.Sleep( 500 ); // Simple wait var processId = Process.GetCurrentProcess().Id; LogGC.PrintRuntimeGCEvents( processId ); } static void StartTracing() { - while( s_threading != ThreadState.Running ) - { - Thread.Sleep( 10 ); - } - + // See above comment + Thread.Sleep( 500 ); Tracing.TraceLogMonitor.Run(); } #endregion // CLR Logging static public Value Value( T val, - [CallerArgumentExpression("val")] - string dbgExp = "" - ) + [CallerArgumentExpression("val")] + string dbgExp = "" +) { return new( val, dbgExp ); } @@ -247,6 +242,7 @@ static public class log Obj = obj; } } + static LogEvent CreateLogEvent( LogType logType, string msg, string cat, object? obj, [CallerFilePath] string path = "", [CallerLineNumber] int line = -1, [CallerMemberName] string member = "", string exp = "" ) { var logEvent = new LogEvent( logType, msg, path, line, member, cat, exp, obj ); @@ -265,25 +261,19 @@ static public class log - static public void create( string filename, Endpoints endpoints ) - { - startup( filename, endpoints ); - } - static public void shutdown() { string msg = "==============================================================================\nLogfile shutdown at " + DateTime.Now.ToString(); - var evt = CreateLogEvent( LogType.Info, msg, "System", null ); - - s_events.Enqueue( evt ); + s_events.Add( evt ); // Use Add instead of Enqueue stop(); } - static internal ConcurrentQueue s_events = new ConcurrentQueue(); + // MODIFIED: Replaced ConcurrentQueue with BlockingCollection for a more robust producer-consumer pattern. + static readonly BlockingCollection s_events = new BlockingCollection( new ConcurrentQueue() ); - static private Thread s_thread = Thread.CurrentThread; + static private Thread? s_thread; static string s_cwd = Directory.GetCurrentDirectory(); static int s_cwdLength = s_cwd.Length; @@ -291,7 +281,7 @@ static public class log #region Util static public SourceLoc loc( [CallerMemberName] string dbgName = "", [CallerFilePath] string dbgPath = "", [CallerLineNumber] int dbgLine = -1 ) - => new SourceLoc( "", dbgName, dbgPath, dbgLine ); + => new SourceLoc( "", dbgName, dbgPath, dbgLine ); static public string whatFile( string path ) @@ -407,19 +397,6 @@ static public class log - static public void inf_valueo( string msg, Value v1, string cat = "" ) - { - } - - static public void info( string msg, A a, string cat = "", [CallerArgumentExpression( "a" )] string dbgExpA = "" ) - { - } - - static public void info( string msg, object a, object b, string cat = "", [CallerArgumentExpression( "a" )] string dbgExpA = "", [CallerArgumentExpression( "a" )] string dbgExpB = "" ) - { - } - - #endregion #region Helpers @@ -431,8 +408,8 @@ static public class log { var evt = new LogEvent( type, header, path, line, member, cat, dbgExpObj, obj ); { - - s_events.Enqueue( evt ); + // Use Add instead of Enqueue + s_events.Add( evt ); foreach( var pi in list ) { @@ -505,7 +482,8 @@ static public class log } else { - s_events.Enqueue( evt ); + // MODIFIED: Use Add instead of Enqueue for the BlockingCollection. + s_events.Add( evt ); } @@ -515,6 +493,7 @@ static public class log static Endpoints s_endpoints = Endpoints.Console; static int s_catWidth = 14; + static public bool IsLogging => s_thread != null && s_thread.IsAlive; static public void startup( string filename, Endpoints endpoints ) { @@ -525,15 +504,13 @@ static public class log lock( s_lock ) { - //We're already running, so just tell folks, and jump back - if( s_threading == ThreadState.Running ) + //We're already running if the thread is alive + if( s_thread != null && s_thread.IsAlive ) { log.info( $"Already running, so this is a NOP" ); + return; } - s_threading = ThreadState.Running; - - s_startTime = DateTime.Now; s_cwd = Directory.GetCurrentDirectory(); @@ -562,54 +539,29 @@ static public class log var beginLine = new LogEvent( LogType.Raw, $"Begin B E G I N ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); var timeLine = new LogEvent( LogType.Raw, $"D A T E {time.Year}/{time.Month.ToString( "00" )}/{time.Day.ToString( "00" )} T I M E {time.Hour.ToString( "00" )}:{time.Minute.ToString( "00" )}:{time.Second.ToString( "00" )}.{time.Millisecond.ToString( "000" )}{time.Microsecond.ToString( "000" )}", "", 0, "", "lib.time", "", null ); - - - //writeToAll( endLine ); - writeToAll( blankLine ); - writeToAll( blankLine ); - writeToAll( beginLine ); - writeToAll( blankLine ); - writeToAll( timeLine ); - writeToAll( blankLine ); - + // MODIFIED: All writes are now safely enqueued to be processed by the logger thread. + // This prevents the StreamWriter buffer corruption that caused null bytes. + s_events.Add( blankLine ); + s_events.Add( blankLine ); + s_events.Add( beginLine ); + s_events.Add( blankLine ); + s_events.Add( timeLine ); + s_events.Add( blankLine ); } LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup BEGIN", "", 0, "", "log.startup", "", null ); - writeToAll( msgStartupBegin ); + s_events.Add( msgStartupBegin ); LogEvent msgFilename = new LogEvent( LogType.Info, $"Logging in {filename}", "", 0, "", "log.startup", "", null ); - writeToAll( msgFilename ); + s_events.Add( msgFilename ); var optionsLine = new LogEvent( LogType.Info, $"Endpoints: {endpoints}", "", 0, "", "log.startup", "", null ); - writeToAll( optionsLine ); - + s_events.Add( optionsLine ); StartThread(); - - - //info( $"Logging in {filename}" ); - - LogGC.RegisterObjectId( s_lock ); - //Debug.Listeners.Add( this ); - - //var evt = CreateLogEvent( LogType.Info, $"startup", "System", null ); - - //s_events.Enqueue( evt ); - - /* - if( (endpoints & Endpoints.Console) == Endpoints.Console ) - { - addDelegate(WriteToConsole); - } - */ - - - //LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup END", "", 0, "", "lib.time", "", null ); - //writeToAll( msgStartupBegin ); - info( $"startup END", cat: "log.startup" ); } @@ -622,97 +574,64 @@ static public class log s_thread = new Thread( start ); s_thread.Priority = ThreadPriority.BelowNormal; s_thread.Name = $"Logging"; + s_thread.IsBackground = true; // Mark as background thread s_thread.Start(); } - private static void StopThread( ThreadState thread ) - { - log.info( $"Setting thread to {thread}"); - s_threading = thread; - int count = 0; - while( s_thread.IsAlive ) - { - Thread.Sleep( 0 ); - count++; - } - - Console.WriteLine( $"Waited {count} loops" ); - } - - public enum ThreadState - { - Invalid, - Running, - Paused, - Finished, - } - - static ThreadState s_threading = ThreadState.Invalid; + // REMOVED: ThreadState enum, StopThread, pauseThread, and unpauseThread methods. + // They are replaced by the simpler, safer lifecycle management of BlockingCollection. + // MODIFIED: Complete rewrite of the thread loop. + // This is now an efficient, blocking loop that consumes zero CPU while waiting for messages. + // It is also free of race conditions. static void threadLoop() { - Console.WriteLine( $"**********************************************************\n" ); - Console.WriteLine( $"Thread started" ); + Console.WriteLine( $"Logger thread started" ); - log.info( $"Thread started" ); - - while( s_threading != ThreadState.Running ) + try { - // TODO PERF Replace this with a semaphore/mutex - Thread.Sleep( 1 ); - } - - while( s_threading == ThreadState.Running ) - { - while( s_events.TryDequeue( out var evt ) ) + // This loop will block when the collection is empty and will + // automatically finish when s_events.CompleteAdding() is called from another thread. + foreach( var evt in s_events.GetConsumingEnumerable() ) { writeToAll( evt ); } - - // TODO PERF Replace this with a semaphore/mutex - Thread.Sleep( 1 ); + } + catch( Exception ex ) + { + Console.WriteLine( $"[CRITICAL] Logger thread crashed: {ex}" ); } - //var endLine = new LogEvent( LogType.Raw, $"End E N D ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); - var endLine = new LogEvent( LogType.Raw, $"Thread state {s_threading} ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); - writeToAll( endLine ); + Console.WriteLine( $"Logger thread has finished processing and is shutting down." ); } public static void stop() { - if( s_threading == ThreadState.Finished ) - return; + log.info( "Logger shutdown requested.", "log.system" ); - StopThread( ThreadState.Finished ); + // MODIFIED: This safely signals the consumer thread to finish. + s_events.CompleteAdding(); + + while( s_events.Count > 0 ) + { + // Wait for the queue to be fully processed. + Thread.Sleep( 10 ); + } + + // Wait for the thread to finish processing all remaining messages in the queue. + s_thread?.Join( 1000 ); + + s_thread = null; s_writer?.Close(); s_stream?.Close(); //s_errorWriter?.Close(); //s_errorStream?.Close(); - } - public static void pauseThread() - { - log.info("Pausing thread" ); - - s_threading = ThreadState.Paused; - - StopThread( ThreadState.Paused ); - } - - public static void unpauseThread() - { - s_threading = ThreadState.Running; - - StartThread(); - } - - - static public void addDelegate( Log_delegate cb ) { s_delegates.Add( cb ); @@ -1007,4 +926,4 @@ static public class log private static ArrayList s_delegates = new ArrayList(); -} +} \ No newline at end of file