Attach duration information to the exception object

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?

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

app/models/runner.rb

@@ -41,7 +41,14 @@ class Runner < ApplicationRecord
   end
 
   def 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

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
+    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

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

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

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

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

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,10 +45,7 @@ describe Runner do
     end
   end
 
-  describe 'method delegation' do
+  describe '#destroy_at_management' 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
@@ -56,18 +54,47 @@ describe Runner do
     end
 
     it 'delegates to its strategy' do
-          expect(strategy).to receive(method)
+      expect(strategy).to receive(:destroy_at_management)
-          runner.send(method, *args)
+      runner.destroy_at_management
-        end
     end
   end
 
-    include_examples 'delegates method sends to its strategy', :destroy_at_management
+  describe '#attach to execution' do
-    include_examples 'delegates method sends to its strategy', :attach_to_execution, nil
+    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(:strategy) { instance_double(strategy_class) }
     let(:runner) { described_class.create }
 
     before do
@@ -75,12 +102,10 @@ 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)
     end
-    end
 
     context 'when a RunnerNotFound exception is raised' do
       before do