From c48c970cf8400c03fc783edf6db0415b993ffa27 Mon Sep 17 00:00:00 2001
From: Mike Karlesky <michael@karlesky.net>
Date: Thu, 2 May 2024 13:56:56 -0400
Subject: [PATCH] =?UTF-8?q?=E2=99=BB=EF=B8=8F=20More=20better=20log=20file?=
 =?UTF-8?q?=20handling?=
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

- Slightly clearer code and comments
- Changed log file format to use narrower timestamp and heading
- Altered log file message layout to be clearer and remain well-formatted with multiline log message strings
---
 lib/ceedling/loginator.rb      | 43 +++++++++++++++++++++++++++-------
 lib/ceedling/system_wrapper.rb |  5 ++--
 2 files changed, 38 insertions(+), 10 deletions(-)

diff --git a/lib/ceedling/loginator.rb b/lib/ceedling/loginator.rb
index 4db964fb3..297bb681b 100644
--- a/lib/ceedling/loginator.rb
+++ b/lib/ceedling/loginator.rb
@@ -37,7 +37,7 @@ def set_logfile( log_filepath )
 
   # log() + out()
   # -----
-  # log() -> add "\n"
+  # log() -> string + "\n"
   # out() -> raw string to stream(s)
   #
   # Write the given string to an optional log file and to the console
@@ -73,11 +73,16 @@ def out(string, verbosity=Verbosity::NORMAL, label=LogLabels::AUTO, stream=nil)
     # Choose appropriate console stream
     stream = get_stream( verbosity, stream )
 
+    # Write to log as though Verbosity::DEBUG (no filtering at all) but without fun characters
     if @project_logging
+      file_str = string.dup() # Copy for safe inline modifications
+
       # Add labels
-      file_str = format( string.dup(), verbosity, label, false )
+      file_str = format( file_str, verbosity, label, false )
 
-      # Write to log as though Verbosity::DEBUG (no filtering at all) but without fun characters
+      # Note: In practice, file-based logging only works with trailing newlines (i.e. `log()` calls)
+      #       `out()` calls will be a little ugly in the log file, but these are typically only
+      #       used for console logging anyhow.
       logfile( sanitize( file_str, false ), extract_stream_name( stream ) )
     end
 
@@ -174,9 +179,9 @@ def sanitize(string, decorate)
 
   def extract_stream_name(stream)
     name = case (stream.fileno)
-      when 0 then '#<IO:$stdin>'
-      when 1 then '#<IO:$stdout>'
-      when 2 then '#<IO:$stderr>'
+      when 0 then '<IO:$stdin>'
+      when 1 then '<IO:$stdout>'
+      when 2 then '<IO:$stderr>'
       else stream.inspect
     end
     
@@ -184,8 +189,30 @@ def extract_stream_name(stream)
   end
 
 
-  def logfile(string, heading='')
-    output = "#{heading} | #{@system_wrapper.time_now}\n#{string.strip}\n"
+  def logfile(string, stream='')
+    # Ex: '#<IO:$stdout> May  1 22:20:41 2024 | '
+    header = "#{stream} #{@system_wrapper.time_now('%b %e %H:%M:%S %Y')} | "
+
+    # Split any multiline strings so we can align them with the header
+    lines = string.strip.split("\n")
+
+    # Build output string with the first (can be only) line
+    output = "#{header}#{lines[0]}\n"
+
+    # If additional lines in a multiline string, pad them on the left
+    # to align with the header
+    if lines.length > 1
+      lines[1..-1].each {|line| output += ((' ' * header.length) + line + "\n")}
+    end
+
+    # Example output:
+    #
+    # <IO:$stdout> May  1 22:20:40 2024 | Determining Artifacts to Be Built...
+    # <IO:$stdout> May  1 22:20:40 2024 | Building Objects
+    #                                     ----------------
+    # <IO:$stdout> May  1 22:20:40 2024 | Compiling TestUsartModel.c...
+    # <IO:$stdout> May  1 22:20:40 2024 | Compiling TestUsartModel::unity.c...
+    # <IO:$stdout> May  1 22:20:40 2024 | Compiling TestUsartModel::cmock.c...
 
     @file_wrapper.write( @log_filepath, output, 'a' )
   end
diff --git a/lib/ceedling/system_wrapper.rb b/lib/ceedling/system_wrapper.rb
index e31523f42..b80c5631e 100644
--- a/lib/ceedling/system_wrapper.rb
+++ b/lib/ceedling/system_wrapper.rb
@@ -55,8 +55,9 @@ def env_get(name)
     return ENV[name]
   end
 
-  def time_now
-    return Time.now.asctime
+  def time_now(format=nil)
+    return Time.now.asctime if format.nil?
+    return Time.now.strftime( format )
   end
 
   def shell_capture3(command:, boom:false)