Class: TestRunner::Executor

Inherits:
Object
  • Object
show all
Defined in:
lib/test-runner/executor.rb

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(test_scripts, **opts) ⇒ Executor

Returns a new instance of Executor.

Parameters:

Options Hash (**opts):

  • :state_dir (String)
  • :jobs (Integer)
  • :default_timeout (Integer)
  • :stop_on_failure (Boolean)
  • :destructive (Boolean)
  • :recreate_disks (Boolean) 


24
25
26
27
28
29
30
31
32
33
34
 
# File 'lib/test-runner/executor.rb', line 24

def initialize(test_scripts, **opts)
  @test_scripts = test_scripts
  @opts = opts
  @workers = []
  @queue = Queue.new
  @results = []
  @stop_work = false
  @mutex = Mutex.new

  fill_queue
end

Instance Attribute Details

#mutex ⇒ Object (readonly, protected)

Returns the value of attribute mutex.



115
116
117
 
# File 'lib/test-runner/executor.rb', line 115

def mutex
  @mutex
end

#opts ⇒ Hash (readonly)

Returns:

  • (Hash) 


11
12
13
 
# File 'lib/test-runner/executor.rb', line 11

def opts
  @opts
end

#queue ⇒ Object (readonly, protected)

Returns the value of attribute queue.



115
116
117
 
# File 'lib/test-runner/executor.rb', line 115

def queue
  @queue
end

#results ⇒ Array<TestResult> (readonly)

Returns:



14
15
16
 
# File 'lib/test-runner/executor.rb', line 14

def results
  @results
end

#test_scripts ⇒ Array<TestScript> (readonly)

Returns:



8
9
10
 
# File 'lib/test-runner/executor.rb', line 8

def test_scripts
  @test_scripts
end

#workers ⇒ Object (readonly, protected)

Returns the value of attribute workers.



115
116
117
 
# File 'lib/test-runner/executor.rb', line 115

def workers
  @workers
end

Instance Method Details

#build_accumulated_test_result(test, scripts, latest_script_results, elapsed_time, last_result) ⇒ Object (protected) 



228
229
230
231
232
233
234
235
236
237
238
239
240
 
# File 'lib/test-runner/executor.rb', line 228

def build_accumulated_test_result(test, scripts, latest_script_results, elapsed_time, last_result)
  script_results = scripts.map do |script|
    latest_script_results.fetch(script) { TestScriptResult.new(script, false, -1) }
  end

  TestResult.new(
    test,
    script_results,
    last_result&.successful? || false,
    elapsed_time,
    last_result&.state_dir || test_state_dir(test)
  )
end

#fill_queue ⇒ Object (protected) 



117
118
119
120
121
122
123
124
125
126
127
128
129
130
 
# File 'lib/test-runner/executor.rb', line 117

def fill_queue
  tests = {}

  test_scripts.each do |ts|
    tests[ts.test] ||= []
    tests[ts.test] << ts
  end

  tests.to_a.shuffle!.each_with_index do |(test, scripts), i|
    @queue << [i, test, scripts.shuffle!]
  end

  @test_count = tests.length
end

#last_nonempty_line(path, max_bytes: 8192) ⇒ Object (protected) 



425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
 
# File 'lib/test-runner/executor.rb', line 425

def last_nonempty_line(path, max_bytes: 8192)
  return nil unless File.file?(path)

  size = File.size(path)
  return nil if size <= 0

  offset = [size - max_bytes, 0].max
  data = File.open(path, 'rb') do |f|
    f.seek(offset)
    f.read
  end

  data.lines.reverse_each do |line|
    stripped = line.strip
    return stripped unless stripped.empty?
  end

  nil
rescue Errno::ENOENT, Errno::EACCES
  nil
end

#log(msg = '') ⇒ Object (protected) 



447
448
449
 
# File 'lib/test-runner/executor.rb', line 447

def log(msg = '')
  mutex.synchronize { puts "[#{Time.now}] #{msg}" }
end

#run ⇒ Array<TestResult>

Returns:



37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
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
 
# File 'lib/test-runner/executor.rb', line 37

def run
  log("Running #{test_scripts.length} scripts of #{@test_count} tests, #{opts[:jobs]} tests at a time")
  log("State directory is #{state_dir}")
  t1 = Time.now

  opts[:jobs].times do |i|
    start_worker(i)
  end

  wait_for_workers

  log("Run #{results.inject(0) { |acc, r| acc + r.script_results.length }} test scripts of #{@test_count} tests in #{(Time.now - t1).round(2)} seconds")

  expected_successful = results.select do |r|
    r.expected_to_succeed? && r.successful?
  end

  expected_failed = results.select do |r|
    r.expected_to_fail? && r.failed?
  end

  unexpected_failed = results.select do |r|
    r.expected_to_succeed? && r.failed?
  end

  unexpected_successful = results.select do |r|
    r.expected_to_fail? && r.successful?
  end

  if expected_successful.any?
    log("#{expected_successful.length} tests successful")
  end

  if expected_failed.any?
    log("#{expected_failed.length} tests failed as expected")
  end

  if unexpected_failed.any?
    log("#{unexpected_failed.length} tests should have succeeded, but failed")
  end

  if unexpected_successful.any?
    log("#{unexpected_successful.length} tests should have failed, but succeeded")
  end

  if unexpected_failed.any?
    log('Unexpectedly failed test scripts:')

    unexpected_failed.each do |test_result|
      test_result.script_results.each do |test_script_result|
        next if test_script_result.expected_result?

        log("  #{test_script_result.test_script.path}")
      end
    end

    puts
  end

  if unexpected_successful.any?
    log('Unexpectedly successful test scripts:')

    unexpected_successful.each do |test_result|
      test_result.script_results.each do |test_script_result|
        next if test_script_result.expected_result?

        log("  #{test_script_result.test_script.path}")
      end
    end

    puts
  end

  results
end

#run_test(test, scripts, prefix:) ⇒ Object (protected) 



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
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
 
# File 'lib/test-runner/executor.rb', line 242

def run_test(test, scripts, prefix:)
  t1 = Time.now
  dir = test_state_dir(test)
  r, w = IO.pipe

  # 4 ports for use with boot.qemu.networks.[i].socket.mcast.port
  mcast_ports = OsVm::PortReservation.get_ports(key: "test:#{test.path}", size: 4)

  pid = Process.fork do
    r.close
    FileUtils.mkdir_p(dir)

    out = File.open(File.join(dir, 'test-runner.log'), 'w')
    $stdout.reopen(out)
    $stderr.reopen(out)
    $stdin.close

    OsVm::PortReservation.reset_to_ports(mcast_ports)

    ev = TestRunner::TestEvaluator.new(
      test,
      scripts,
      system: opts[:system],
      test_config_path: opts[:test_config_path],
      state_dir: dir,
      sock_dir: test_sock_dir,
      default_timeout: opts[:default_timeout],
      destructive: opts[:destructive],
      recreate_disks: opts[:recreate_disks]
    )

    ev.run do |result_hash|
      w.puts(result_hash.to_json)
    end
  end

  w.close

  script_results = []
  test_runner_log = File.join(dir, 'test-runner.log')
  heartbeat_interval = 300
  next_heartbeat_at = Time.now + heartbeat_interval

  begin
    loop do
      timeout = [next_heartbeat_at - Time.now, 0].max
      ready = r.wait_readable(timeout)

      if ready.nil?
        elapsed = (Time.now - t1).round(2)
        msg = "#{prefix} Test '#{test.path}' still running after #{elapsed} seconds, log: #{test_runner_log}"
        last_line = last_nonempty_line(test_runner_log)
        msg += ", last output: #{last_line}" if last_line
        log(msg)
        next_heartbeat_at = Time.now + heartbeat_interval
        next
      end

      line = r.gets
      break if line.nil?

      next_heartbeat_at = Time.now + heartbeat_interval

      begin
        result_hash = JSON.parse(line)
      rescue JSON::ParserError
        warn "Unable to parse test script result json: #{line.inspect}"
        next
      end

      case result_hash['type']
      when 'script'
        test_script = test.test_scripts[result_hash['script']]
        script_result = TestScriptResult.from_h(test_script, result_hash)
        script_results << script_result

        next if test_script.singleton?

        secs = script_result.elapsed_time.round(2)

        if script_result.expected_result?
          if script_result.successful?
            log("#{prefix} Script '#{test_script.path}' successful in #{secs} seconds")
          else
            log("#{prefix} Script '#{test_script.path}' failed as expected in #{secs} seconds")
          end
        else # unexpected result
          if script_result.successful?
            log("#{prefix} Script '#{test_script.path}' unexpectedly succeeded in #{secs} seconds")
          else
            log("#{prefix} Script '#{test_script.path}' failed after #{secs} seconds")
          end

          stop_work! if opts[:stop_on_failure]
        end
      when 'example'
        status =
          if result_hash['success']
            if result_hash['pending']
              'pending'
            elsif result_hash['skip']
              'skipped'
            else
              'succeeded'
            end
          elsif result_hash['pending']
            'unexpectedly succeeded'
          else
            'failed'
          end

        log("#{prefix} Example [#{result_hash['progress']}/#{result_hash['total']}] '#{result_hash['example']}' #{status} in #{result_hash['elapsed_time'].round(2)} seconds")
      end
    end
  rescue EOFError
    # pass
  end

  Process.wait(pid)

  OsVm::PortReservation.release_ports(key: "test:#{test.path}")

  # Complement script results if some are missing
  scripts.each do |script|
    script_result = script_results.detect { |sr| sr.test_script == script }
    next if script_result

    script_results << TestScriptResult.new(script, false, -1)
  end

  result = TestResult.new(
    test,
    script_results,
    $?.exitstatus == 0,
    Time.now - t1,
    dir
  )

  File.open(File.join(dir, 'test-result.txt'), 'w') do |f|
    str =
      if result.expected_result?
        if result.successful?
          'expected_success'
        else
          'expected_failure'
        end
      elsif result.successful?
        'unexpected_success'
      else
        'unexpected_failure'
      end

    f.puts(str)
  end

  result
end

#run_test_attempt(i, test, scripts, attempt) ⇒ Object (protected) 



194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
 
# File 'lib/test-runner/executor.rb', line 194

def run_test_attempt(i, test, scripts, attempt)
  prefix = "[#{i + 1}/#{@test_count}]"
  script_list = scripts.map { |v| "##{v.name}" }.join(', ')
  max_attempts = scripts.map(&:attempts).max

  if attempt > 0
    log("#{prefix} Retrying test '#{test.path}' (#{script_list}) (attempt #{attempt + 1}/#{max_attempts})")
  else
    log("#{prefix} Running test '#{test.path}' (#{script_list})")
  end

  result = run_test(test, scripts, prefix:)

  secs = result.elapsed_time.round(2)

  if result.expected_result?
    if result.successful?
      log("#{prefix} Test '#{test.path}' successful in #{secs} seconds")
    else
      log("#{prefix} Test '#{test.path}' failed as expected in #{secs} seconds")
    end
  else # unexpected result
    if result.successful?
      log("#{prefix} Test '#{test.path}' unexpectedly succeeded in #{secs} seconds, see #{result.state_dir}")
    else
      log("#{prefix} Test '#{test.path}' failed after #{secs} seconds, see #{result.state_dir}")
    end

    stop_work! if opts[:stop_on_failure]
  end

  result
end

#run_test_with_retries(i, test, scripts) ⇒ Object (protected) 



156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
 
# File 'lib/test-runner/executor.rb', line 156

def run_test_with_retries(i, test, scripts)
  latest_script_results = {}
  remaining_scripts = scripts
  elapsed_time = 0
  last_result = nil
  attempt = 0

  loop do
    last_result = run_test_attempt(i, test, remaining_scripts, attempt)
    elapsed_time += last_result.elapsed_time

    last_result.script_results.each do |script_result|
      latest_script_results[script_result.test_script] = script_result
    end

    break if stop_work?

    remaining_scripts = remaining_scripts.select do |script|
      script_result = latest_script_results.fetch(script)

      script_result.unexpected_result? && attempt + 1 < script.attempts
    end

    break if remaining_scripts.empty?

    sleep(5)
    attempt += 1
  end

  build_accumulated_test_result(
    test,
    scripts,
    latest_script_results,
    elapsed_time,
    last_result
  )
end

#run_worker(_w_i) ⇒ Object (protected) 



140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
 
# File 'lib/test-runner/executor.rb', line 140

def run_worker(_w_i)
  loop do
    return if stop_work?

    begin
      i, test, scripts = queue.pop(true)
    rescue ThreadError
      return
    end

    result = run_test_with_retries(i, test, scripts)

    mutex.synchronize { results << result }
  end
end

#start_worker(i) ⇒ Object (protected) 



132
133
134
 
# File 'lib/test-runner/executor.rb', line 132

def start_worker(i)
  workers << Thread.new { run_worker(i) }
end

#state_dir ⇒ Object (protected) 



416
417
418
 
# File 'lib/test-runner/executor.rb', line 416

def state_dir
  opts[:state_dir]
end

#stop_work! ⇒ Object (protected) 



400
401
402
 
# File 'lib/test-runner/executor.rb', line 400

def stop_work!
  @stop_work = true
end

#stop_work? ⇒ Boolean (protected)

Returns:

  • (Boolean) 


404
405
406
 
# File 'lib/test-runner/executor.rb', line 404

def stop_work?
  @stop_work
end

#test_sock_dir ⇒ Object (protected) 



412
413
414
 
# File 'lib/test-runner/executor.rb', line 412

def test_sock_dir
  File.join(state_dir, 'socks')
end

#test_state_dir(test) ⇒ Object (protected) 



408
409
410
 
# File 'lib/test-runner/executor.rb', line 408

def test_state_dir(test)
  File.join(state_dir, "os-test-#{test_state_key(test)}")
end

#test_state_key(test) ⇒ Object (protected) 



420
421
422
423
 
# File 'lib/test-runner/executor.rb', line 420

def test_state_key(test)
  slug = test.path.gsub(/[^A-Za-z0-9_.-]+/, '__')
  "#{slug}-#{Digest::SHA256.hexdigest(test.path)[0, 8]}"
end

#wait_for_workers ⇒ Object (protected) 



136
137
138
 
# File 'lib/test-runner/executor.rb', line 136

def wait_for_workers
  workers.each(&:join)
end