diff --git a/app/controllers/submissions_controller.rb b/app/controllers/submissions_controller.rb index 376a886b..cf82f546 100644 --- a/app/controllers/submissions_controller.rb +++ b/app/controllers/submissions_controller.rb @@ -193,15 +193,23 @@ class SubmissionsController < ApplicationController kill_socket(tubesock) Rails.logger.debug { "Running a submission timed out: #{e.message}" } @output = "timeout: #{@output}" + extract_durations(e) rescue Runner::Error => e tubesock.send_data JSON.dump({cmd: :status, status: :container_depleted}) kill_socket(tubesock) Rails.logger.debug { "Runner error while running a submission: #{e.message}" } + extract_durations(e) ensure save_run_output end end + def extract_durations(error) + @container_execution_time = error.execution_duration + @waiting_for_container_time = error.waiting_duration + end + private :extract_durations + def kill_socket(tubesock) # search for errors and save them as StructuredError (for scoring runs see submission.rb) errors = extract_errors @@ -293,6 +301,7 @@ class SubmissionsController < ApplicationController def statistics; end # TODO: make this run, but with the test command + # TODO: add this method to the before action for set_submission again # def test # hijack do |tubesock| # unless EventMachine.reactor_running? && EventMachine.reactor_thread.alive? diff --git a/app/errors/runner/error.rb b/app/errors/runner/error.rb index 41b54c31..e943db73 100644 --- a/app/errors/runner/error.rb +++ b/app/errors/runner/error.rb @@ -2,6 +2,8 @@ class Runner class Error < ApplicationError + attr_accessor :waiting_duration, :execution_duration + class BadRequest < Error; end class EnvironmentNotFound < Error; end diff --git a/app/models/runner.rb b/app/models/runner.rb index 5fd0628b..4e93d065 100644 --- a/app/models/runner.rb +++ b/app/models/runner.rb @@ -41,7 +41,14 @@ class Runner < ApplicationRecord end def attach_to_execution(command, &block) - @strategy.attach_to_execution(command, &block) + starting_time = Time.zone.now + begin + @strategy.attach_to_execution(command, &block) + rescue Runner::Error => e + e.execution_duration = Time.zone.now - starting_time + raise + end + Time.zone.now - starting_time # execution duration end def destroy_at_management diff --git a/app/models/submission.rb b/app/models/submission.rb index 648be071..4916bc49 100644 --- a/app/models/submission.rb +++ b/app/models/submission.rb @@ -140,6 +140,7 @@ class Submission < ApplicationRecord def calculate_score file_scores = nil + # If prepared_runner raises an error, no Testrun will be created. prepared_runner do |runner, waiting_duration| file_scores = collect_files.select(&:teacher_defined_assessment?).map do |file| score_command = command_for execution_environment.test_command, file.name_with_extension @@ -163,10 +164,10 @@ class Submission < ApplicationRecord output.merge!(container_execution_time: execution_time, status: exit_code.zero? ? :ok : :failed) rescue Runner::Error::ExecutionTimeout => e Rails.logger.debug("Running tests in #{file.name_with_extension} for submission #{id} timed out: #{e.message}") - output.merge!(status: :timeout) + output.merge!(status: :timeout, container_execution_time: e.execution_duration) rescue Runner::Error => e Rails.logger.debug("Running tests in #{file.name_with_extension} for submission #{id} failed: #{e.message}") - output.merge!(status: :failed) + output.merge!(status: :failed, container_execution_time: e.execution_duration) ensure output.merge!(stdout: stdout, stderr: stderr) end @@ -182,6 +183,9 @@ class Submission < ApplicationRecord prepared_runner do |runner, waiting_duration| durations[:execution_duration] = runner.attach_to_execution(run_command, &block) durations[:waiting_duration] = waiting_duration + rescue Runner::Error => e + e.waiting_duration = waiting_duration + raise end durations end @@ -190,8 +194,13 @@ class Submission < ApplicationRecord def prepared_runner request_time = Time.zone.now - runner = Runner.for(user, exercise) - runner.copy_files(collect_files) + begin + runner = Runner.for(user, exercise) + runner.copy_files(collect_files) + rescue Runner::Error => e + e.waiting_duration = Time.zone.now - request_time + raise + end waiting_duration = Time.zone.now - request_time yield(runner, waiting_duration) end diff --git a/lib/runner/strategy/docker_container_pool.rb b/lib/runner/strategy/docker_container_pool.rb index 9dce17df..adc0089f 100644 --- a/lib/runner/strategy/docker_container_pool.rb +++ b/lib/runner/strategy/docker_container_pool.rb @@ -53,7 +53,6 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy def attach_to_execution(command) @command = command - starting_time = Time.zone.now query_params = 'logs=0&stream=1&stderr=1&stdout=1&stdin=1' websocket_url = "#{self.class.config[:ws_host]}/v1.27/containers/#{@container_id}/attach/ws?#{query_params}" @@ -66,7 +65,6 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy socket.send(command) yield(socket) end - Time.zone.now - starting_time # execution duration in seconds end private diff --git a/lib/runner/strategy/poseidon.rb b/lib/runner/strategy/poseidon.rb index fba0b475..54d51aab 100644 --- a/lib/runner/strategy/poseidon.rb +++ b/lib/runner/strategy/poseidon.rb @@ -86,13 +86,11 @@ class Runner::Strategy::Poseidon < Runner::Strategy end def attach_to_execution(command) - starting_time = Time.zone.now websocket_url = execute_command(command) EventMachine.run do socket = Connection.new(websocket_url, self) yield(socket) end - Time.zone.now - starting_time # execution duration end def destroy_at_management diff --git a/spec/lib/runner/strategy/docker_container_pool_spec.rb b/spec/lib/runner/strategy/docker_container_pool_spec.rb index c8dabb91..26568b6f 100644 --- a/spec/lib/runner/strategy/docker_container_pool_spec.rb +++ b/spec/lib/runner/strategy/docker_container_pool_spec.rb @@ -261,18 +261,10 @@ describe Runner::Strategy::DockerContainerPool do end describe '#attach_to_execution' do - # TODO: add more tests here + # TODO: add tests here let(:command) { 'ls' } let(:action) { -> { container_pool.attach_to_execution(command) } } let(:websocket_url) { 'ws://ws.example.com/path/to/websocket' } - - it 'returns the execution time' do - allow(EventMachine).to receive(:run) - starting_time = Time.zone.now - execution_time = action.call - test_time = Time.zone.now - starting_time - expect(execution_time).to be_between(0.0, test_time).exclusive - end end end diff --git a/spec/lib/runner/strategy/poseidon_spec.rb b/spec/lib/runner/strategy/poseidon_spec.rb index 3de5d957..ef04a6f7 100644 --- a/spec/lib/runner/strategy/poseidon_spec.rb +++ b/spec/lib/runner/strategy/poseidon_spec.rb @@ -289,20 +289,10 @@ describe Runner::Strategy::Poseidon do end describe '#attach_to_execution' do - # TODO: add more tests here + # TODO: add tests here let(:command) { 'ls' } let(:action) { -> { poseidon.attach_to_execution(command) } } let(:websocket_url) { 'ws://ws.example.com/path/to/websocket' } - - it 'returns the execution time' do - allow(poseidon).to receive(:execute_command).with(command).and_return(websocket_url) - allow(EventMachine).to receive(:run) - - starting_time = Time.zone.now - execution_time = action.call - test_time = Time.zone.now - starting_time - expect(execution_time).to be_between(0.0, test_time).exclusive - end end end diff --git a/spec/models/runner_spec.rb b/spec/models/runner_spec.rb index 771f2b4d..5202d403 100644 --- a/spec/models/runner_spec.rb +++ b/spec/models/runner_spec.rb @@ -5,6 +5,7 @@ require 'rails_helper' describe Runner do let(:runner_id) { FactoryBot.attributes_for(:runner)[:runner_id] } let(:strategy_class) { described_class.strategy_class } + let(:strategy) { instance_double(strategy_class) } describe 'attribute validation' do let(:runner) { FactoryBot.create :runner } @@ -44,30 +45,7 @@ describe Runner do end end - describe 'method delegation' do - shared_examples 'delegates method sends to its strategy' do |method, *args| - context "when sending #{method}" do - let(:strategy) { instance_double(strategy_class) } - let(:runner) { described_class.create } - - before do - allow(strategy_class).to receive(:request_from_management).and_return(runner_id) - allow(strategy_class).to receive(:new).and_return(strategy) - end - - it 'delegates to its strategy' do - expect(strategy).to receive(method) - runner.send(method, *args) - end - end - end - - include_examples 'delegates method sends to its strategy', :destroy_at_management - include_examples 'delegates method sends to its strategy', :attach_to_execution, nil - end - - describe '#copy_files' do - let(:strategy) { instance_double(strategy_class) } + describe '#destroy_at_management' do let(:runner) { described_class.create } before do @@ -75,12 +53,59 @@ describe Runner do allow(strategy_class).to receive(:new).and_return(strategy) end - context 'when no error is raised' do - it 'delegates to its strategy' do - expect(strategy).to receive(:copy_files).once - runner.copy_files(nil) + it 'delegates to its strategy' do + expect(strategy).to receive(:destroy_at_management) + runner.destroy_at_management + end + end + + describe '#attach to execution' do + let(:runner) { described_class.create } + let(:command) { 'ls' } + + before do + allow(strategy_class).to receive(:request_from_management).and_return(runner_id) + allow(strategy_class).to receive(:new).and_return(strategy) + end + + it 'delegates to its strategy' do + expect(strategy).to receive(:attach_to_execution) + runner.attach_to_execution(command) + end + + it 'returns the execution time' do + allow(strategy).to receive(:attach_to_execution) + starting_time = Time.zone.now + execution_time = runner.attach_to_execution(command) + test_time = Time.zone.now - starting_time + expect(execution_time).to be_between(0.0, test_time).exclusive + end + + context 'when a runner error is raised' do + before { allow(strategy).to receive(:attach_to_execution).and_raise(Runner::Error) } + + it 'attaches the execution time to the error' do + starting_time = Time.zone.now + expect { runner.attach_to_execution(command) }.to raise_error do |error| + test_time = Time.zone.now - starting_time + expect(error.execution_duration).to be_between(0.0, test_time).exclusive + end end end + end + + describe '#copy_files' do + let(:runner) { described_class.create } + + before do + allow(strategy_class).to receive(:request_from_management).and_return(runner_id) + allow(strategy_class).to receive(:new).and_return(strategy) + end + + it 'delegates to its strategy' do + expect(strategy).to receive(:copy_files).once + runner.copy_files(nil) + end context 'when a RunnerNotFound exception is raised' do before do