Class: ParallelCucumber::Worker

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

Instance Attribute Summary collapse

Instance Method Summary collapse

Methods included from Helper::Utils

#time_it

Constructor Details

#initialize(options:, index:, stdout_logger:, manager:) ⇒ Worker

Returns a new instance of Worker.



9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
 
# File 'lib/parallel_cucumber/worker.rb', line 9

def initialize(options:, index:, stdout_logger:, manager:)
  @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]
  @index = index
  @name = "W#{@index}"
  @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.
  @is_busy_running_test = false
  @jobs_queue = Queue.new
  @manager = manager
end

Instance Attribute Details

#index ⇒ Object (readonly)

Returns the value of attribute index.



33
34
35
 
# File 'lib/parallel_cucumber/worker.rb', line 33

def index
  @index
end

Instance Method Details

#assign_job(instruction) ⇒ Object 



35
36
37
 
# File 'lib/parallel_cucumber/worker.rb', line 35

def assign_job(instruction)
  @jobs_queue.enq(instruction)
end

#autoshutting_file ⇒ Object 



43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
 
# File 'lib/parallel_cucumber/worker.rb', line 43

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

#busy_running_test? ⇒ Boolean

Returns:

  • (Boolean) 


39
40
41
 
# File 'lib/parallel_cucumber/worker.rb', line 39

def busy_running_test?
  @is_busy_running_test && @current_thread.alive?
end

#parse_results(f, tests) ⇒ Object 



291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
 
# File 'lib/parallel_cucumber/worker.rb', line 291

def parse_results(f, tests)
  unless File.file?(f)
    @logger.error("Results file does not exist: #{f}")
    return tests.map { |t| [t, ::ParallelCucumber::Status::UNKNOWN] }.to_h
  end
  json_report = File.read(f)
  if json_report.empty?
    @logger.error("Results file is empty: #{f}")
    return tests.map { |t| [t, ::ParallelCucumber::Status::UNKNOWN] }.to_h
  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}")
  tests.map { |t| [t, ::ParallelCucumber::Status::UNKNOWN] }.to_h
end

#precheck(env) ⇒ Object 



164
165
166
167
168
169
170
171
172
173
174
 
# File 'lib/parallel_cucumber/worker.rb', line 164

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 



189
190
191
192
193
194
195
196
197
198
199
200
201
 
# File 'lib/parallel_cucumber/worker.rb', line 189

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, results, running_total, tests) ⇒ Object 



134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
 
# File 'lib/parallel_cucumber/worker.rb', line 134

def run_batch(env, results, running_total, tests)
  @is_busy_running_test = true
  batch_id = "#{Time.now.to_i}-#{@index}"
  @logger.debug("Batch ID is #{batch_id}")

  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)
    @is_busy_running_test = false
  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 



176
177
178
179
180
181
182
183
184
185
186
187
 
# File 'lib/parallel_cucumber/worker.rb', line 176

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 



274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
 
# File 'lib/parallel_cucumber/worker.rb', line 274

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 



65
66
67
68
69
70
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
 
# File 'lib/parallel_cucumber/worker.rb', line 65

def start(env)
  @current_thread = Thread.current
  @manager.inform_idle(@name)

  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)

      loop_mm, loop_ss = time_it do
        loop do
          job = @jobs_queue.pop(false)
          case job.type
          when Job::PRECHECK
            precmd = precheck(env)
            if (m = precmd.match(/precmd:retry-after-(\d+)-seconds/))
              @manager.inform_idle(@name)
              sleep(1 + m[1].to_i)
              next
            end
            @manager.inform_healthy(@name)
          when Job::RUN_TESTS
            run_batch(env, results, running_total, job.details)
            @manager.inform_idle(@name)
          when Job::DIE
            break
          else
            raise("Invalid job #{job.inspect}")
          end
        end
      end
      @logger.debug("Loop took #{loop_mm} minutes #{loop_ss} seconds")
      @logger.update_into(@stdout_logger)
    rescue StandardError => 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 



256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
 
# File 'lib/parallel_cucumber/worker.rb', line 256

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 



203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
 
# File 'lib/parallel_cucumber/worker.rb', line 203

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)}"

    begin
      Hooks.fire_on_batch_error(tests: tests, batch_id: batch_id, env: batch_env, exception: e)
    rescue StandardError => exc
      trace = exc.backtrace.join("\n\t")
      @logger.warn("There was exception in on_batch_error hook #{exc.message} \n #{trace}")
    end

    return tests.map { |t| [t, ::ParallelCucumber::Status::UNKNOWN] }.to_h
  end
  parse_results(test_state, tests)
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