From 5505f717b65afa82bd27c6365ac6094a16beba2c Mon Sep 17 00:00:00 2001 From: John Keiser Date: Tue, 29 Sep 2015 12:08:41 -0700 Subject: Print what happened (and in what order) if test fails --- spec/functional/run_lock_spec.rb | 219 ++++++++++++++++----------------------- 1 file changed, 89 insertions(+), 130 deletions(-) (limited to 'spec/functional') diff --git a/spec/functional/run_lock_spec.rb b/spec/functional/run_lock_spec.rb index ce0598bead..4aee91279c 100644 --- a/spec/functional/run_lock_spec.rb +++ b/spec/functional/run_lock_spec.rb @@ -34,8 +34,15 @@ describe Chef::RunLock do let(:lockfile){ "#{random_temp_root}/this/long/path/does/not/exist/chef-client-running.pid" } # make sure to start with a clean slate. - before(:each){ FileUtils.rm_r(random_temp_root) if File.exist?(random_temp_root) } - after(:each){ FileUtils.rm_r(random_temp_root) if File.exist?(random_temp_root) } + before(:each){ log_event("rm -rf before"); FileUtils.rm_r(random_temp_root) if File.exist?(random_temp_root) } + after(:each){ log_event("rm -rf after"); FileUtils.rm_r(random_temp_root) if File.exist?(random_temp_root) } + + def log_event(message, time=Time.now.strftime("%H:%M:%S.%L")) + events << [ message, time ] + end + def events + @events ||= [] + end WAIT_ON_LOCK_TIME = 1.0 def wait_on_lock @@ -48,111 +55,33 @@ describe Chef::RunLock do raise "Lockfile never created, abandoning test" end - ## - # Side channel via a pipe allows child processes to send errors to the parent - - # Don't lazy create the pipe or else we might not share it with subprocesses - let!(:error_pipe) do - r,w = IO.pipe - w.sync = true - [r,w] - end - - let(:error_read) { error_pipe[0] } - let(:error_write) { error_pipe[1] } - - after do - error_read.close unless error_read.closed? - error_write.close unless error_write.closed? - end - - # Send a RuntimeError from the child process to the parent process. Also - # prints error to $stdout, just in case something goes wrong with the error - # marshaling stuff. - def send_side_channel_error(message) - $stderr.puts(message) - $stderr.puts(caller) - e = RuntimeError.new(message) - error_write.print(Marshal.dump(e)) - end - - # Read the error (if any) from the error channel. If a marhaled error is - # present, it is unmarshaled and raised (which will fail the test) - def raise_side_channel_error! - error_write.close - err = error_read.read - error_read.close - begin - # ArgumentError from Marshal.load indicates no data, which we assume - # means no error in child process. - raise Marshal.load(err) - rescue ArgumentError - nil - end - end - - ## - # Interprocess synchronization via a pipe. This allows us to control the - # state of the processes competing over the lock without relying on sleep. - - let!(:sync_pipe) do - r,w = IO.pipe - w.sync = true - [r,w] - end - let(:sync_read) { sync_pipe[0] } - let(:sync_write) { sync_pipe[1] } - - after do - sync_read.close unless sync_read.closed? - sync_write.close unless sync_write.closed? - end - - # Wait on synchronization signal. If not received within the timeout, an - # error is sent via the error channel, and the process exits. - def sync_wait - if IO.select([sync_read], nil, nil, 20).nil? - # timeout reading from the sync pipe. - send_side_channel_error("Error syncing processes in run lock test (timeout)") - exit!(1) - else - sync_read.getc - end - end - - # Sends a character in the sync pipe, which wakes ("unlocks") another - # process that is waiting on the sync signal - def sync_send - sync_write.putc("!") - sync_write.flush - end - - ## - # IPC to record test results in a pipe. Tests can read pipe contents to - # check that operations occur in the expected order. - - let!(:results_pipe) do - r,w = IO.pipe - w.sync = true - [r,w] - end - let(:results_read) { results_pipe[0] } - let(:results_write) { results_pipe[1] } - - after do - results_read.close unless results_read.closed? - results_write.close unless results_write.closed? - end - CLIENT_PROCESS_TIMEOUT = 2 BREATHING_ROOM = 1 # ClientProcess is defined below let!(:p1) { ClientProcess.new(self, 'p1') } let!(:p2) { ClientProcess.new(self, 'p2') } - after do - p1.stop - p2.stop + after(:each) do |example| + begin + p1.stop + p2.stop + rescue + example.exception = $! + raise + ensure + if example.exception + print_events + end + end + end + + def print_events + # Consume any remaining events that went on the channel and print them all + p1.last_event + p2.last_event + events.each_with_index.sort_by { |(message, time), index| [ time, index ] }.each do |(message, time), index| + puts "#{time} #{message}" + end end context "when the lockfile does not already exist" do @@ -160,6 +89,7 @@ describe Chef::RunLock do before { p1.run_to("acquired lock") } it "the lockfile is created" do + log_event("lockfile exists? #{File.exist?(lockfile)}") expect(File.exist?(lockfile)).to be_truthy end @@ -186,7 +116,7 @@ describe Chef::RunLock do p2.run_to("acquired lock") do # While p2 is trying to acquire, wait a bit and then let p1 complete sleep(BREATHING_ROOM) - expect(p2.last_event).to eq("started") + expect(p2.last_event).to eq("started").or match(/from started to/) p1.run_to_completion end @@ -196,7 +126,7 @@ describe Chef::RunLock do it "and a second client tries to get the lock and the first is killed, the second client gets the lock immediately" do p2.run_to("acquired lock") do sleep BREATHING_ROOM - expect(p2.last_event).to eq("started") + expect(p2.last_event).to eq("started").or match(/from started to/) p1.stop end p2.run_to_completion @@ -233,7 +163,7 @@ describe Chef::RunLock do p2.run_to("acquired lock") do # While p2 is trying to acquire, wait a bit and then let p1 complete sleep(BREATHING_ROOM) - expect(p2.last_event).to eq("started") + expect(p2.last_event).to eq("started").or match(/from started to/) p1.run_to_completion end @@ -243,7 +173,7 @@ describe Chef::RunLock do it "when a second client tries to get the lock and the first is killed, the second client gets the lock immediately" do p2.run_to("acquired lock") do sleep BREATHING_ROOM - expect(p2.last_event).to eq("started") + expect(p2.last_event).to eq("started").or match(/from started to/) p1.stop end p2.run_to_completion @@ -341,44 +271,45 @@ describe Chef::RunLock do attr_reader :name attr_reader :pid - def fire_event(event) - # Let the caller know what event we've reached - write_to_tests.puts(event) - - # Block until the client tells us where to stop - if !@run_to_event || event == @run_to_event - @run_to_event = read_from_tests.gets.strip - end - end - def last_event while true - event = readline_nonblock(read_from_process) - break if event.nil? - @last_event = event.strip + line = readline_nonblock(read_from_process) + break if line.nil? + event, time = line.split("@") + example.log_event("#{name}.last_event got #{event}") + example.log_event("[#{name}] #{event}", time.strip) + @last_event = event end @last_event end - def run_to(event, &background_block) + def run_to(to_event, &background_block) + example.log_event("#{name}.run_to(#{to_event.inspect})") + # Start the process if it's not started start if !pid # Tell the process what to stop at (also means it can go) - write_to_process.puts event + write_to_process.puts to_event # Run the background block background_block.call if background_block # Wait until it gets there Timeout::timeout(CLIENT_PROCESS_TIMEOUT) do - until @last_event == event - @last_event = read_from_process.gets.strip + until @last_event == to_event + got_event, time = read_from_process.gets.split("@") + example.log_event("#{name}.last_event got #{got_event}") + example.log_event("[#{name}] #{got_event}", time.strip) + @last_event = got_event end end + + example.log_event("#{name}.run_to(#{to_event.inspect}) finished") end def run_to_completion + example.log_event("#{name}.run_to_completion") # Start the process if it's not started start if !pid @@ -387,23 +318,30 @@ describe Chef::RunLock do # Wait for the process to exit wait_for_exit + example.log_event("#{name}.run_to_completion finished") end def wait_for_exit + example.log_event("#{name}.wait_for_exit (pid #{pid})") Timeout::timeout(CLIENT_PROCESS_TIMEOUT) do Process.wait(pid) if pid end + example.log_event("#{name}.wait_for_exit finished (pid #{pid})") end def stop if pid + example.log_event("#{name}.stop (pid #{pid})") begin Process.kill(:KILL, pid) + example.log_event("#{name}.stop kill signal sent (pid #{pid})") Timeout::timeout(CLIENT_PROCESS_TIMEOUT) do Process.waitpid2(pid) end + example.log_event("#{name}.stop finished (stopped pid #{pid})") # Process not found is perfectly fine when we're trying to kill a process :) rescue Errno::ESRCH + example.log_event("#{name}.stop finished (pid #{pid} wasn't running)") end end end @@ -416,17 +354,38 @@ describe Chef::RunLock do attr_reader :write_to_process def start + example.log_event("#{name}.start") @pid = fork do - Timeout::timeout(CLIENT_PROCESS_TIMEOUT) do - run_lock = Chef::RunLock.new(example.lockfile) - fire_event("started") - run_lock.acquire - fire_event("acquired lock") - run_lock.save_pid - fire_event("saved pid") - exit!(0) + begin + Timeout::timeout(CLIENT_PROCESS_TIMEOUT) do + run_lock = Chef::RunLock.new(example.lockfile) + fire_event("started") + run_lock.acquire + fire_event("acquired lock") + run_lock.save_pid + fire_event("saved pid") + exit!(0) + end + rescue + fire_event(e.message.lines.join(" // ")) + raise end end + example.log_event("#{name}.start forked (pid #{pid})") + end + + def fire_event(event) + # Let the caller know what event we've reached + write_to_tests.puts("#{event}@#{Time.now.strftime("%H:%M:%S.%L")}") + + # Block until the client tells us where to stop + if !@run_to_event || event == @run_to_event + write_to_tests.puts("waiting for instructions #{event} to ?@#{Time.now.strftime("%H:%M:%S.%L")}") + @run_to_event = read_from_tests.gets.strip + write_to_tests.puts("told to run from #{event} to #{@run_to_event}@#{Time.now.strftime("%H:%M:%S.%L")}") + elsif @run_to_event + write_to_tests.puts("continuing from #{event} to #{@run_to_event}@#{Time.now.strftime("%H:%M:%S.%L")}") + end end def readline_nonblock(fd) -- cgit v1.2.1