diff --git a/lib/sproc/core.rb b/lib/sproc/core.rb index f1a0ddd..5863628 100644 --- a/lib/sproc/core.rb +++ b/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? diff --git a/lib/sproc/reporter.rb b/lib/sproc/reporter.rb new file mode 100644 index 0000000..d7c32be --- /dev/null +++ b/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 diff --git a/sproc.gemspec b/sproc.gemspec index de056ea..778933c 100644 --- a/sproc.gemspec +++ b/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 = ["anders.rillbert@kutso.se"] + spec.authors = ['Anders Rillbert'] + spec.email = ['anders.rillbert@kutso.se'] - 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 diff --git a/test/reporter_test.rb b/test/reporter_test.rb new file mode 100644 index 0000000..9c5a4a8 --- /dev/null +++ b/test/reporter_test.rb @@ -0,0 +1,49 @@ +require 'minitest/autorun' +require_relative '../lib/sproc/utils' +require_relative '../lib/sproc/reporter' + +module SProc + # test the sequential process class + class ReporterTests < Minitest::Test + + # bring in the reporting methods + include Reporting + + def setup + # avoid keeping data in stdout buffer before writing it out + $stdout.sync = true + # since not even a simple cmd like 'ping' has the same flags + # under windows/linux (grrr), we need to pass different flags + # depending on os + @count_flag = case OSInfo.host_os + when OSInfo::OS::WINDOWS then '-n' + when OSInfo::OS::LINUX then '-c' + else raise 'Unsupported OS!' + end + @logger_io = StringIO.new + Reporting.logger = Logger.new(@logger_io) + Reporting.logger.level = Logger::INFO + end + + # Kick-off single, synchronous processes and wait for + # their completion + def test_report_sync + sp = report_sync('Pinging Localhost', 'ping', [@count_flag, '2', '127.0.0.1']) + + # we expect this to succeed (ie exit with '0') + assert_equal(true, sp.exit_zero?) + assert(!@logger_io.string.empty?) + end + + def test_report_async + sp = report_async('Pinging Localhost', 'ping', [@count_flag, '2', '127.0.0.1']) + sp.wait_on_completion + report_completed(sp) + + # we expect this to succeed (ie exit with '0') + assert_equal(true, sp.exit_zero?) + # assert_equal("hej",@logger_io.string) + assert(!@logger_io.string.empty?) + end + end +end