Less test noise

.github/workflows/ruby.yml

@@ -114,3 +114,10 @@ jobs:
       run: .github/install_dependencies.sh
     - name: Run tests
       run: bundle exec rake test
+    - name: Upload logs
+      uses: actions/upload-artifact@v4
+      if: ${{ failure() && contains(matrix.task, 'test') }}
+      with:
+        name: logs-${{ env.ARTIFACT_SUFFIX }}
+        path: test.log
+        retention-days: 5

.gitignore

@@ -7,3 +7,4 @@ Gemfile.lock
 .idea
 .ruby-version
 examples/remote_executor_db.sqlite
+/test.log

lib/dynflow/rails/daemon.rb

@@ -23,23 +23,32 @@ def daemons_class
         @daemons_class || ::Daemons
       end
 
+      def stdout
+        STDOUT
+      end
+
+      def stderr
+        STDERR
+      end
+
       # Load the Rails environment and initialize the executor in this thread.
       def run(rails_root = Dir.pwd, options = {})
-        STDOUT.puts('Starting Rails environment')
+        stdout.puts('Starting Rails environment')
         rails_env_file = File.expand_path('./config/environment.rb', rails_root)
         unless File.exist?(rails_env_file)
           raise "#{rails_root} doesn't seem to be a Rails root directory"
         end
 
-        STDERR.puts("Starting dynflow with the following options: #{options}")
+        stderr.puts("Starting dynflow with the following options: #{options}")
 
         ::Rails.application.dynflow.executor!
 
         if options[:memory_limit] && options[:memory_limit].to_i > 0
           ::Rails.application.dynflow.config.on_init do |world|
+            stdout_cap = stdout
             memory_watcher = initialize_memory_watcher(world, options[:memory_limit], options)
             world.terminated.on_resolution do
-              STDOUT.puts("World has been terminated")
+              stdout_cap.puts("World has been terminated")
               memory_watcher = nil # the object can be disposed
             end
           end
@@ -48,10 +57,10 @@ def run(rails_root = Dir.pwd, options = {})
         require rails_env_file
         ::Rails.application.dynflow.initialize!
         world_id = ::Rails.application.dynflow.world.id
-        STDOUT.puts("Everything ready for world: #{world_id}")
+        stdout.puts("Everything ready for world: #{world_id}")
         sleep
       ensure
-        STDOUT.puts('Exiting')
+        stdout.puts('Exiting')
       end
 
       # run the executor as a daemon
@@ -68,7 +77,7 @@ def run_background(command = 'start', options = {})
           raise "Command exptected to be 'start', 'stop', 'restart', 'run', was #{command.inspect}"
         end
 
-        STDOUT.puts("Dynflow Executor: #{command} in progress")
+        stdout.puts("Dynflow Executor: #{command} in progress")
 
         options[:executors_count].times do
           daemons_class.run_proc(
@@ -79,7 +88,7 @@ def run_background(command = 'start', options = {})
               ::Logging.reopen
               run(options[:rails_root], options)
             rescue => e
-              STDERR.puts e.message
+              stderr.puts e.message
               ::Rails.logger.fatal('Failed running Dynflow daemon')
               ::Rails.logger.fatal(e)
               exit 1

lib/dynflow/testing.rb

@@ -5,7 +5,7 @@ module Testing
     extend Algebrick::TypeCheck
 
     def self.logger_adapter
-      @logger_adapter || LoggerAdapters::Simple.new($stdout, 1)
+      @logger_adapter || LoggerAdapters::Simple.new('test.log', 1)
     end
 
     def self.logger_adapter=(adapter)

test/action_test.rb

@@ -135,7 +135,7 @@ def run(event = nil)
         plan = create_and_plan_action(PlanEventedAction, { time: 0.5 })
         action = run_action plan
 
-        _(action.output[:status]).must_equal nil
+        assert_nil action.output[:status]
         _(action.world.clock.pending_pings.first).wont_be_nil
         _(action.state).must_equal :suspended
 
@@ -150,7 +150,7 @@ def run(event = nil)
         plan = create_and_plan_action(PlanEventedAction, { time: nil })
         action = run_action plan
 
-        _(action.output[:status]).must_equal nil
+        assert_nil action.output[:status]
         _(action.world.clock.pending_pings.first).must_be_nil
         _(action.world.executor.events_to_process.first).wont_be_nil
         _(action.state).must_equal :suspended
@@ -905,7 +905,7 @@ def finalize
 
       it 'collects and drops output chunks' do
         action = create_and_plan_action(OutputChunkAction)
-        _(action.pending_output_chunks).must_equal nil
+        assert_nil action.pending_output_chunks
 
         action = run_action(action)
         _(action.pending_output_chunks.count).must_equal 1

test/concurrency_control_test.rb

@@ -54,7 +54,6 @@ def plan(should_sleep = false)
         def run(event = nil)
           unless output[:slept]
             output[:slept] = true
-            puts "SLEEPING" if input[:should_sleep]
             suspend { |suspended| world.clock.ping(suspended, 100, [:run]) } if input[:should_sleep]
           end
         end

test/daemon_test.rb

@@ -5,8 +5,24 @@
 require 'mocha/minitest'
 require 'logging'
 require 'dynflow/testing'
+require 'ostruct'
 require_relative '../lib/dynflow/rails'
 
+class StdIOWrapper
+  def initialize(logger, error = false)
+    @logger = logger
+    @error = error
+  end
+
+  def puts(msg = nil)
+    if @error
+      @logger.error(msg)
+    else
+      @logger.info(msg)
+    end
+  end
+end
+
 class DaemonTest < ActiveSupport::TestCase
   setup do
     @dynflow_memory_watcher = mock('memory_watcher')
@@ -15,6 +31,9 @@ class DaemonTest < ActiveSupport::TestCase
       @dynflow_memory_watcher,
       @daemons
     )
+    logger = WorldFactory.logger_adapter.logger
+    @daemon.stubs(:stdout).returns(StdIOWrapper.new(logger, false))
+    @daemon.stubs(:stderr).returns(StdIOWrapper.new(logger, true))
     @world_class = mock('dummy world factory')
     @dummy_world = ::Dynflow::Testing::DummyWorld.new
     @dummy_world.stubs(:id => '123')
@@ -27,9 +46,9 @@ class DaemonTest < ActiveSupport::TestCase
       @world_class,
       ::Dynflow::Rails::Configuration.new
     )
-    ::Rails.stubs(:application).returns(OpenStruct.new(:dynflow => @dynflow))
+    ::Rails.stubs(:application).returns(::OpenStruct.new(:dynflow => @dynflow))
     ::Rails.stubs(:root).returns('support/rails')
-    ::Rails.stubs(:logger).returns(Logging.logger(STDOUT))
+    ::Rails.stubs(:logger).returns(logger)
     @dynflow.require!
     @dynflow.config.stubs(:increase_db_pool_size? => false)
     @daemon.stubs(:sleep).returns(true) # don't pause the execution

test/future_execution_test.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require_relative 'test_helper'
+require 'multi_json'
 
 module Dynflow
   module FutureExecutionTest

test/test_helper.rb

@@ -20,7 +20,9 @@
 require 'support/dummy_example'
 require 'support/test_execution_log'
 
-Concurrent.disable_at_exit_handlers!
+Concurrent.global_logger = lambda do |level, progname, message = nil, &block|
+  ::Dynflow::Testing.logger_adapter.logger.add level, message, progname, &block
+end
 
 # To be able to stop a process in some step and perform assertions while paused
 class TestPause
@@ -109,7 +111,7 @@ def self.create_world(klass = Dynflow::World, &block)
   # This world survives though the whole run of the test suite: careful with it, it can
   # introduce unnecessary test dependencies
   def self.logger_adapter
-    @adapter ||= Dynflow::LoggerAdapters::Simple.new $stderr, ::Logger::FATAL
+    ::Dynflow::Testing.logger_adapter
   end
 
   def self.persistence_adapter
@@ -127,7 +129,7 @@ def self.coordinator_adapter
   def self.clean_coordinator_records
     persistence_adapter = WorldFactory.persistence_adapter
     persistence_adapter.find_coordinator_records({}).each do |w|
-      warn "Unexpected coordinator record: #{w}"
+      ::Dynflow::Testing.logger_adapter.logger.warn "Unexpected coordinator record: #{w}"
       persistence_adapter.delete_coordinator_record(w[:class], w[:id])
     end
   end
@@ -234,12 +236,18 @@ def assert_plan_reexecuted(plan)
 end
 
 class MiniTest::Test
+  def logger
+    ::Dynflow::Testing.logger_adapter.logger
+  end
+
   def setup
+    logger.info(">>>>> #{location}")
     WorldFactory.clean_coordinator_records
   end
 
   def teardown
     WorldFactory.terminate_worlds
+    logger.info("<<<<< #{location}")
   end
 end