add opinionated reporting module

lib/sproc/core.rb

@@ -15,7 +15,8 @@ module ShellType
     ].freeze
   end
 
-  # The possible states of this subprocess
+  # The available execution states of a the subprocess
+  # running within an SProc instance.
   module ExecutionState
     NOT_STARTED = 0
     RUNNING = 1
@@ -73,42 +74,6 @@ def initialize(type: ShellType::NONE, stdout_callback: nil,
       @env = env
     end
 
-    # Return the execution state of this SubProcess. Note that it is not
-    # identical with the life-cycle of the underlying ProcessStatus object
-    #
-    # @return current ExecutionState
-    def execution_state
-      return ExecutionState::NOT_STARTED if @execution_thread.nil?
-
-      # Count this SubProcess as running as long as the thread
-      # that executes it is alive (this includes book keeping
-      # chores within this class as well)
-      return ExecutionState::RUNNING if @execution_thread.alive?
-
-      status = task_info[:process_status]
-
-      # an execution thread that has run but not generated a task_info
-      # means that we tried to start a process but failed
-      return ExecutionState::FAILED_TO_START if status.nil?
-
-      # a process can terminate for different reasons:
-      # - its done
-      # - an uncaught exception-
-      # - an uncaught signal
-
-      # this should take care of uncaught signals
-      return ExecutionState::ABORTED if status.signaled?
-
-      # If the process completed (either successfully or not)
-      return ExecutionState::COMPLETED if status.exited?
-
-      # We don't currently handle a process that has been stopped...
-      raise NotImplementedError("Unhandled process 'stopped' status!") if status.stopped?
-
-      # We should never come here
-      raise RuntimeError("Unhandled process status: #{status.inspect}")
-    end
-
     # Start the sub-process and block until it has completed.
     #
     #
@@ -147,6 +112,48 @@ def wait_on_completion
       task_info
     end
 
+    # Return the execution state of this SubProcess. Note that it is not
+    # identical with the life-cycle of the underlying ProcessStatus object
+    #
+    # @return current ExecutionState
+    def execution_state
+      return ExecutionState::NOT_STARTED if @execution_thread.nil?
+
+      # Count this SubProcess as running as long as the thread
+      # that executes it is alive (this includes book keeping
+      # chores within this class as well)
+      return ExecutionState::RUNNING if @execution_thread.alive?
+
+      status = task_info[:process_status]
+
+      # an execution thread that has run but not generated a task_info
+      # means that we tried to start a process but failed
+      return ExecutionState::FAILED_TO_START if status.nil?
+
+      # a process can terminate for different reasons:
+      # - its done
+      # - an uncaught exception-
+      # - an uncaught signal
+
+      # this should take care of uncaught signals
+      return ExecutionState::ABORTED if status.signaled?
+
+      # If the process completed (either successfully or not)
+      return ExecutionState::COMPLETED if status.exited?
+
+      # We don't currently handle a process that has been stopped...
+      raise NotImplementedError("Unhandled process 'stopped' status!") if status.stopped?
+
+      # We should never come here
+      raise RuntimeError("Unhandled process status: #{status.inspect}")
+    end
+
+    # @return the TaskInfo representing this SubProcess, nil if
+    #         process has not started
+    def task_info
+      @runner.task_info
+    end
+
     # blocks until all processes in the given array are completed/aborted.
     #
     # the implementation polls each process after each given poll interval
@@ -211,12 +218,6 @@ def self.wait_or_back_to_back(running_proc, polling_interval = 100)
       all_proc
     end
 
-    # @return the TaskInfo representing this SubProcess, nil if
-    #         process has not started
-    def task_info
-      @runner.task_info
-    end
-
     # return processes that are no longer running
     def self.get_finished(running_proc)
       running_proc.select do |p|
@@ -228,6 +229,8 @@ def self.get_finished(running_proc)
 
     private
 
+    # a helper method that supports both synch/async execution
+    # depending on the supplied args
     def exec(synch, env, cmd, *args, **opts)
       raise 'Subprocess already running!' unless @execution_thread.nil? || !@execution_thread.alive?
 

lib/sproc/reporter.rb

@@ -0,0 +1,196 @@
+require_relative 'core'
+
+# This module is written to provide sub-process
+# execution with some human readable logging of process start/stop/errors
+#
+# It wraps SProc instances and execution with calls to logging methods
+# that tries to make the resulting log user friendly
+module SProc
+  module Reporting
+    class << self
+      attr_accessor :logger
+    end
+
+    def logger
+      Reporting.logger
+    end
+
+    # Run a process synchronuously via the native shell and log
+    # output suitable for a build log
+    #
+    # @param cmd_name   a String containing a descriptive
+    #                        name for what the process will do.
+    # @param cmd, args, opts see SProc.exec_sync
+    #
+    # @return                the SProc instance containing the completed process
+    def report_sync(cmd_name, cmd, *args, **opts)
+      p = create_proc_and_log(cmd_name,
+                              ShellType::NONE, :exec_sync,
+                              cmd, args, opts)
+      report_completed(p)
+      p
+    end
+
+    # Run a process asynchronuously via the native shell and log
+    # output suitable for a build log
+    #
+    # @param cmd_name   a String containing a descriptive
+    #                        name for what the process will do.
+    # @param cmd, args, opts see SProc.exec_sync
+    #
+    # @return                the created SProc instance
+    def report_async(cmd_name, cmd, *args, **opts)
+      create_proc_and_log(cmd_name,
+                          ShellType::NONE, :exec_async,
+                          cmd, args, opts)
+    end
+
+    # Run a process asynchronuously via the Bash shell and log
+    # output suitable for a build log
+    #
+    # @param cmd_name   a String containing a descriptive
+    #                        name for what the process will do.
+    # @param cmd, args, opts see SProc.exec_sync
+    #
+    # @return                the created SProc instance
+    def report_async_within_bash(cmd_name, cmd, *args, **opts)
+      create_proc_and_log(cmd_name,
+                          ShellType::BASH, :exec_async,
+                          cmd, args, opts)
+    end
+
+    # Log output from a completed/aborted process
+    #
+    # @param process   the SProc instance that has run
+    # @return          true/false corresponding to process success
+    def report_completed(process)
+      friendly_name = if @log_friendly_name_map&.key?(process)
+                  "#{@log_friendly_name_map[process]}"
+                else
+                  'Process'
+                end
+      started_ok = true
+      case process.execution_state
+      when ExecutionState::COMPLETED
+        process.exit_zero? && log_completed_ok(friendly_name, process.task_info)
+        !process.exit_zero? && log_completed_err(friendly_name, process.task_info)
+      when ExecutionState::ABORTED
+        log_aborted(friendly_name, process.task_info)
+        started_ok = false
+      when ExecutionState::FAILED_TO_START
+        log_failed_start(friendly_name, process.task_info)
+        started_ok = false
+      else
+        log_unexpected(friendly_name, process.task_info)
+      end
+      started_ok && process.exit_zero?
+    end
+
+    private
+
+    def create_proc_and_log(cmd_name, type, method, cmd, args, opts)
+      log_start(cmd_name, type, method, cmd, args, **opts)
+      p = SProc.new(type: type).send(method, cmd, args, **opts)
+      @log_friendly_name_map ||= {}
+      @log_friendly_name_map[p] = cmd_name
+      p
+    end
+
+    def log_method_result_ok(friendly_name, delta)
+      logger.info do
+        "#{friendly_name} completed successfully after #{delta.round(3)}s"
+      end
+    end
+
+    def log_method_result_error(friendly_name_method, delta, exc)
+      logger.error do
+        "#{friendly_name_method} aborted by #{exc.class} after #{delta.round(3)}s\n"\
+        "Exception info: #{exc.message}"
+      end
+
+      logger.debug do
+        exc.backtrace.to_s
+      end
+    end
+
+    def log_start(cmd_name, type, method, cmd, *args, **opts)
+      logger.info do
+        async_str = method == :exec_async ? 'asynchronuously' : 'synchronuously'
+        type_str = type == ShellType::NONE ? 'without shell' : 'within the bash shell'
+        "'#{cmd_name}' executing #{async_str} #{type_str}..."
+      end
+      logger.debug do
+        msg = String.new("Starting #{cmd}")
+        msg << " with args: #{args.flatten.inspect}" unless args.nil? || args.empty?
+        msg << " and opts: #{opts.inspect}" unless opts.nil? || opts.empty?
+        msg
+      end
+    end
+
+    def log_one_dll(regex, cmd_str, time)
+      m = regex.match(cmd_str)
+      s = m.nil? ? cmd_str : m[1]
+      max = 45
+      s = s.length > max ? s.slice(0..max - 1) : s.ljust(max)
+      logger.info { "#{s} took #{time.round(3)}s." }
+    end
+
+    def log_aborted(friendly_name, p_info)
+      logger.error do
+        "'#{friendly_name}' aborted!\n"\
+        "When running: #{p_info[:cmd_str]}\n"\
+        "#{merge_proc_output(p_info)}"\
+        "#{p_info[:process_status] unless p_info[:process_status].nil?}"
+      end
+    end
+
+    def log_failed_start(friendly_name, p_info)
+      logger.error do
+        "'#{friendly_name}' not run!\n"\
+        "Could not start process using: #{p_info[:cmd_str]}\n"\
+        "#{merge_proc_output(p_info)}"
+      end
+    end
+
+    def log_completed_ok(friendly_name, p_info)
+      logger.info do
+        "'#{friendly_name}' completed successfully after #{p_info[:wall_time].round(3)}s"
+      end
+      logger.debug do
+        "Cmd: #{p_info[:cmd_str]}"
+      end
+    end
+
+    def log_completed_err(friendly_name, p_info)
+      logger.error do
+        "'#{friendly_name}' completed with exit code "\
+        "#{p_info[:process_status].exitstatus}\n"\
+        "When running: #{p_info[:cmd_str]}\n"\
+        "after #{p_info[:wall_time].round(3)}s\n"\
+        "#{merge_proc_output(p_info)}"
+      end
+    end
+
+    def log_unexpected(friendly_name, p_info)
+      logger.error do
+        "'#{friendly_name}' caused unexpected error!"\
+        ' Trying to display info on a running process'\
+        "(#{p_info[:cmd_str]})"
+      end
+    end
+
+    # @return String with sections for each non-empty output stream
+    #                and exception messages
+    def merge_proc_output(p_info)
+      inf_str = %i[stdout stderr].collect do |sym|
+        next('') if p_info[sym].empty?
+
+        "--- #{sym} ---\n#{p_info[sym]}"
+      end.join("\n")
+
+      exc = p_info[:exception]
+      inf_str << "--- exception ---\n#{exc}\n" unless exc.nil?
+      inf_str
+    end
+  end
+end

sproc.gemspec

@@ -1,39 +1,40 @@
 # frozen_string_literal: true
 
-require_relative "lib/sproc/version"
+require_relative 'lib/sproc/version'
 
 Gem::Specification.new do |spec|
-  spec.name          = "sproc"
+  spec.name          = 'sproc'
   spec.version       = SProc::VERSION
-  spec.authors       = ["Anders Rillbert"]
-  spec.email         = ["[email protected]"]
+  spec.authors       = ['Anders Rillbert']
+  spec.email         = ['[email protected]']
 
-  spec.summary       = "Run subprocess asynch/synch."
-  spec.description   = "Run subprocess asynch/synch."
-  spec.homepage      = "https://github.com/rillbert/sproc"
-  spec.license       = "MIT"
-  spec.required_ruby_version = Gem::Requirement.new(">= 2.7.0")
+  spec.summary       = 'Spawn commands as asynch/synch subprocesses.'
+  spec.description   = 'Easier invokation of asynch/synch commands with '\
+                       'a reasonable easy and flexible interface for processing stdout and stderr'
+  spec.homepage      = 'https://github.com/rillbert/sproc'
+  spec.license       = 'MIT'
+  spec.required_ruby_version = Gem::Requirement.new('>= 2.7.0')
 
-  spec.metadata["allowed_push_host"] = "https://rubygems.org"
+  spec.metadata['allowed_push_host'] = 'https://rubygems.org'
 
-  spec.metadata["homepage_uri"] = spec.homepage
-  spec.metadata["source_code_uri"] = spec.homepage
-  spec.metadata["changelog_uri"] = spec.homepage
+  spec.metadata['homepage_uri'] = spec.homepage
+  spec.metadata['source_code_uri'] = spec.homepage
+  spec.metadata['changelog_uri'] = spec.homepage
 
   # Specify which files should be added to the gem when it is released.
   # The `git ls-files -z` loads the files in the RubyGem that have been added into git.
   spec.files = Dir.chdir(File.expand_path(__dir__)) do
     `git ls-files -z`.split("\x0").reject { |f| f.match(%r{\A(?:test|spec|features)/}) }
   end
-  spec.bindir        = "exe"
+  spec.bindir        = 'exe'
   spec.executables   = spec.files.grep(%r{\Aexe/}) { |f| File.basename(f) }
-  spec.require_paths = ["lib"]
+  spec.require_paths = ['lib']
 
   # Developer dependencies
-  spec.add_development_dependency "minitest", "~> 5.1"
+  spec.add_development_dependency 'minitest', '~> 5.1'
 
   # Uncomment to register a new dependency of your gem
-#  spec.add_dependency "example-gem", "~> 1.0"
+  #  spec.add_dependency "example-gem", "~> 1.0"
 
   # For more information and examples about making a new gem, checkout our
   # guide at: https://bundler.io/guides/creating_gem.html