Class: ParallelCucumber::Worker

Inherits:
Object
  • Object
show all
Includes:
Helper::Utils
Defined in:
lib/parallel_cucumber/worker.rb

Instance Method Summary collapse

Methods included from Helper::Utils

#time_it

Constructor Details

#initialize(options, index, stdout_logger) ⇒ Worker

Returns a new instance of Worker.



26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
 
# File 'lib/parallel_cucumber/worker.rb', line 26

def initialize(options, index, stdout_logger)
  @batch_size = options[:batch_size]
  @group_by = options[:group_by]
  @batch_timeout = options[:batch_timeout]
  @batch_error_timeout = options[:batch_error_timeout]
  @precheck_timeout = options[:precheck_timeout]
  @setup_timeout = options[:setup_timeout]
  @cucumber_options = options[:cucumber_options]
  @test_command = options[:test_command]
  @pre_check = options[:pre_check]
  @on_batch_error = options[:on_batch_error]
  @index = index
  @queue_connection_params = options[:queue_connection_params]
  @setup_worker = options[:setup_worker]
  @teardown_worker = options[:teardown_worker]
  @worker_delay = options[:worker_delay]
  @debug = options[:debug]
  @log_decoration = options[:log_decoration]
  @log_dir = options[:log_dir]
  @log_file = "#{@log_dir}/worker_#{index}.log"
  @stdout_logger = stdout_logger # .sync writes only.
end

Instance Method Details

#autoshutting_file ⇒ Object 



49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
 
# File 'lib/parallel_cucumber/worker.rb', line 49

def autoshutting_file
  file_handle = { log_file: @log_file }

  def file_handle.write(message)
    File.open(self[:log_file], 'a') { |f| f << message }
  rescue => e
    STDERR.puts "Log failure: #{e} writing '#{message.to_s.chomp}' to #{self[:log_file]}"
  end

  def file_handle.close
  end

  def file_handle.fsync
  end

  def file_handle.path
    self[:log_file]
  end

  file_handle
end

#on_batch_error(batch_env, batch_id, error_file, tests, error) ⇒ Object 



180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
 
# File 'lib/parallel_cucumber/worker.rb', line 180

def on_batch_error(batch_env, batch_id, error_file, tests, error)
  return unless @on_batch_error

  begin
    error_info = {
      class: error.class,
      message: error.message,
      backtrace: error.backtrace
    }
    batch_error_info = {
      batch_id: batch_id,
      tests: tests,
      error: error_info
    }
    File.write(error_file, batch_error_info.to_json)
    command = "#{@on_batch_error} #{error_file}"
    Helper::Command.exec_command(
      batch_env, 'on_batch_error', command, @logger, @log_decoration, timeout: @batch_error_timeout
    )
  rescue => e
    message = "on-batch-error failed: #{e.message}"
    @logger.warn(message)
  end
end

#parse_results(f) ⇒ Object 



314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
 
# File 'lib/parallel_cucumber/worker.rb', line 314

def parse_results(f)
  unless File.file?(f)
    @logger.error("Results file does not exist: #{f}")
    return { results_missing: 1 }
  end
  json_report = File.read(f)
  if json_report.empty?
    @logger.error("Results file is empty: #{f}")
    return { results_empty: 1 }
  end
  Helper::Cucumber.parse_json_report(json_report)
rescue => e
  trace = e.backtrace.join("\n\t").sub("\n\t", ": #{$ERROR_INFO}#{e.class ? " (#{e.class})" : ''}\n\t")
  @logger.error("Threw: JSON parse of results caused #{trace}")
  { json_fail: 1 }
end

#precheck(env) ⇒ Object 



168
169
170
171
172
173
174
175
176
177
178
 
# File 'lib/parallel_cucumber/worker.rb', line 168

def precheck(env)
  return 'default no-op pre_check' unless @pre_check
  begin
    return Helper::Command.exec_command(
      env, 'precheck', @pre_check, @logger, @log_decoration, timeout: @precheck_timeout, capture: true
    )
  rescue
    @logger.error('Pre-check failed: quitting immediately')
    raise 'Pre-check failed: quitting immediately'
  end
end

#process_results(batch_results, tests) ⇒ Object 



218
219
220
221
222
223
224
225
226
227
228
229
230
 
# File 'lib/parallel_cucumber/worker.rb', line 218

def process_results(batch_results, tests)
  batch_keys = batch_results.keys
  test_syms = tests.map(&:to_sym)
  unrun = test_syms - batch_keys
  surfeit = batch_keys - test_syms
  unrun.each { |test| batch_results[test] = Status::UNKNOWN }
  surfeit.each { |test| batch_results.delete(test) }
  @logger.error("Did not run #{unrun.count}/#{tests.count}: #{unrun.join(' ')}") unless unrun.empty?
  @logger.error("Extraneous runs (#{surfeit.count}): #{surfeit.join(' ')}") unless surfeit.empty?
  return if surfeit.empty?
  # Don't see how this can happen, but...
  @logger.error("Tests/result mismatch: #{tests.count}!=#{batch_results.count}: #{tests}/#{batch_keys}")
end

#run_batch(env, queue_tracker, results, running_total, tests) ⇒ Object 



139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
 
# File 'lib/parallel_cucumber/worker.rb', line 139

def run_batch(env, queue_tracker, results, running_total, tests)
  batch_id = "#{Time.now.to_i}-#{@index}"
  @logger.debug("Batch ID is #{batch_id}")
  @logger.info("Took #{tests.count} from the queue (#{queue_tracker.status}): #{tests.join(' ')}")

  batch_mm, batch_ss = time_it do
    begin
      Hooks.fire_before_batch_hooks(tests, batch_id, env)
    rescue StandardError => e
      trace = e.backtrace.join("\n\t")
      @logger.warn("There was exception in before_batch hook #{e.message} \n #{trace}")
    end

    batch_results = test_batch(batch_id, env, running_total, tests)
    begin
      Hooks.fire_after_batch_hooks(batch_results, batch_id, env)
    rescue StandardError => e
      trace = e.backtrace.join("\n\t")
      @logger.warn("There was exception in after_batch hook #{e.message} \n #{trace}")
    end
    process_results(batch_results, tests)
    running_totals(batch_results, running_total)
    results.merge!(batch_results)
  end
ensure
  @logger.debug("Batch #{batch_id} took #{batch_mm} minutes #{batch_ss} seconds")
  @logger.update_into(@stdout_logger)
end

#running_totals(batch_results, running_total) ⇒ Object 



205
206
207
208
209
210
211
212
213
214
215
216
 
# File 'lib/parallel_cucumber/worker.rb', line 205

def running_totals(batch_results, running_total)
  batch_info = Status.constants.map do |status|
    status = Status.const_get(status)
    [status, batch_results.select { |_t, s| s == status }.keys]
  end.to_h
  batch_info.each do |s, tt|
    @logger.info("#{s.to_s.upcase} #{tt.count} tests: #{tt.join(' ')}") unless tt.empty?
    running_total[s] += tt.count unless tt.empty?
  end
  running_total[:batches] += 1
  @logger.info(running_total.sort.to_s + ' t=' + Time.now.to_s)
end

#setup(env) ⇒ Object 



297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
 
# File 'lib/parallel_cucumber/worker.rb', line 297

def setup(env)
  return unless @setup_worker
  mm, ss = time_it do
    @logger.info('Setup running')

    begin
      Helper::Command.exec_command(env, 'setup', @setup_worker, @logger, @log_decoration, timeout: @setup_timeout)
    rescue
      @logger.warn("Setup failed: #{@index} quitting immediately")
      raise 'Setup failed: quitting immediately'
    end
  end
ensure
  @logger.debug("Setup took #{mm} minutes #{ss} seconds")
  @logger.update_into(@stdout_logger)
end

#start(env) ⇒ Object 



71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
 
# File 'lib/parallel_cucumber/worker.rb', line 71

def start(env)
  env = env.dup.merge!('WORKER_LOG' => @log_file)

  File.delete(@log_file) if File.exist?(@log_file)

  @logger = ParallelCucumber::CustomLogger.new(autoshutting_file)
  @logger.progname = "Worker-#{@index}"
  @logger.level = @debug ? ParallelCucumber::CustomLogger::DEBUG : ParallelCucumber::CustomLogger::INFO

  results = {}
  begin
    @logger.info("Logging to #{@log_file}")

    unless @worker_delay.zero?
      @logger.info("Waiting #{@worker_delay * @index} seconds before start")
      sleep(@worker_delay * @index)
    end

    @logger.debug(<<-LOG)
    Additional environment variables: #{env.map { |k, v| "#{k}=#{v}" }.join(' ')}
    LOG
    @logger.update_into(@stdout_logger)

    # TODO: Replace running total with queues for passed, failed, unknown, skipped.
    running_total = Hash.new(0) # Default new keys to 0
    running_total[:group] = env[@group_by] if @group_by
    begin
      setup(env)

      queue = ParallelCucumber::Helper::Queue.new(@queue_connection_params)
      directed_queue = ParallelCucumber::Helper::Queue.new(@queue_connection_params, "_#{@index}")
      queue_tracker = Tracker.new(queue)

      loop_mm, loop_ss = time_it do
        loop do
          break if queue.empty? && directed_queue.empty?
          batch = []
          precmd = precheck(env)
          if (m = precmd.match(/precmd:retry-after-(\d+)-seconds/))
            sleep(1 + m[1].to_i)
            next
          end
          @batch_size.times do
            # TODO: Handle recovery of possibly toxic dequeued undirected tests if a worker dies mid-processing.
            batch << (directed_queue.empty? ? queue : directed_queue).dequeue
          end
          batch.compact!
          batch.sort! # Workaround for https://github.com/cucumber/cucumber-ruby/issues/952
          break if batch.empty?

          run_batch(env, queue_tracker, results, running_total, batch)
        end
      end
      @logger.debug("Loop took #{loop_mm} minutes #{loop_ss} seconds")
      @logger.update_into(@stdout_logger)
    rescue => e
      trace = e.backtrace.join("\n\t").sub("\n\t", ": #{$ERROR_INFO}#{e.class ? " (#{e.class})" : ''}\n\t")
      @logger.error("Threw: #{e.inspect} #{trace}")
    ensure
      results[":worker-#{@index}"] = running_total
      teardown(env)
    end
  ensure
    @logger.update_into(@stdout_logger)
  end
  results
end

#teardown(env) ⇒ Object 



279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
 
# File 'lib/parallel_cucumber/worker.rb', line 279

def teardown(env)
  return unless @teardown_worker
  mm, ss = time_it do
    @logger.info("\nTeardown running at #{Time.now}\n")

    begin
      Helper::Command.exec_command(
        env, 'teardown', @teardown_worker, @logger, @log_decoration, timeout: @setup_timeout
      )
    rescue
      @logger.warn('Teardown finished with error')
    end
  end
ensure
  @logger.debug("Teardown took #{mm} minutes #{ss} seconds")
  @logger.update_into(@stdout_logger)
end

#test_batch(batch_id, env, running_total, tests) ⇒ Object 



232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
 
# File 'lib/parallel_cucumber/worker.rb', line 232

def test_batch(batch_id, env, running_total, tests)
  # Prefer /tmp to Mac's brain-dead /var/folders/y8/8kqjszcs2slchjx2z5lrw2t80000gp/T/w-1497514590-0 nonsense
  prefer_tmp = ENV.fetch('PREFER_TMP', Dir.tmpdir)
  test_batch_dir = "#{Dir.exist?(prefer_tmp) ? prefer_tmp : Dir.tmpdir}/w-#{batch_id}"
  FileUtils.rm_rf(test_batch_dir)
  FileUtils.mkpath(test_batch_dir)

  test_state = "#{test_batch_dir}/test_state.json"
  cmd = "#{@test_command} --format ParallelCucumber::Helper::Cucumber::JsonStatusFormatter --out #{test_state} #{@cucumber_options} "
  batch_env = {
    :TEST_BATCH_ID.to_s => batch_id,
    :TEST_BATCH_DIR.to_s => test_batch_dir,
    :BATCH_NUMBER.to_s => running_total[:batches].to_s
  }.merge(env)
  mapped_batch_cmd, file_map = Helper::Cucumber.batch_mapped_files(cmd, test_batch_dir, batch_env)
  file_map.each { |_user, worker| FileUtils.mkpath(worker) if worker =~ %r{\/$} }
  mapped_batch_cmd += ' ' + tests.join(' ')
  begin
    ParallelCucumber::Helper::Command.exec_command(
      batch_env, 'batch', mapped_batch_cmd, @logger, @log_decoration,
      timeout: @batch_timeout, return_script_error: true
    )
  rescue => e
    @logger << "ERROR #{e} #{e.backtrace.first(5)}"
    error_file = "#{test_batch_dir}/error.json"
    on_batch_error(batch_env, batch_id, error_file, tests, e)
    return { script_failure: 1 }
  end
  parse_results(test_state)
ensure
  Helper::Command.wrap_block(@log_decoration, "file copy #{Time.now}", @logger) do
    # Copy files we might have renamed or moved
    file_map.each do |user, worker|
      next if worker == user
      Helper::Processes.cp_rv(worker, user, @logger)
    end
    @logger << "\nCopied files in map: #{file_map.first(5)}...#{file_map.count}  #{Time.now}\n"
    # Copy everything else too, in case it's interesting.
    Helper::Processes.cp_rv("#{test_batch_dir}/*", @log_dir, @logger)
    @logger << "\nCopied everything else #{Time.now}  #{Time.now}\n"
  end
  @logger.update_into(@stdout_logger)
  FileUtils.rm_rf(test_batch_dir)
  @logger << "\nRemoved all files  #{Time.now}\n" # Tracking down 30 minute pause!
  @logger.update_into(@stdout_logger)
end