diff --git a/app/controllers/execution_environments_controller.rb b/app/controllers/execution_environments_controller.rb index ae640521..4a665fe8 100644 --- a/app/controllers/execution_environments_controller.rb +++ b/app/controllers/execution_environments_controller.rb @@ -30,7 +30,7 @@ class ExecutionEnvironmentsController < ApplicationController def execute_command runner = Runner.for(current_user, @execution_environment) output = runner.execute_command(params[:command], raise_exception: false) - render json: output + render json: output.except(:messages) end def working_time_query diff --git a/app/controllers/submissions_controller.rb b/app/controllers/submissions_controller.rb index 3018e4de..74eec3a6 100644 --- a/app/controllers/submissions_controller.rb +++ b/app/controllers/submissions_controller.rb @@ -9,6 +9,7 @@ class SubmissionsController < ApplicationController before_action :require_user! before_action :set_submission, only: %i[download download_file render_file run score show statistics test] + before_action :set_testrun, only: %i[run score test] before_action :set_files, only: %i[download show] before_action :set_files_and_specific_file, only: %i[download_file render_file run test] before_action :set_mime_type, only: %i[download_file render_file] @@ -103,6 +104,7 @@ class SubmissionsController < ApplicationController case event[:cmd].to_sym when :client_kill + @testrun[:status] = :client_kill close_client_connection(client_socket) Rails.logger.debug('Client exited container.') when :result, :canvasevent, :exception @@ -128,62 +130,62 @@ class SubmissionsController < ApplicationController end end - @output = +'' - durations = @submission.run(@file) do |socket| + @testrun[:output] = +'' + durations = @submission.run(@file) do |socket, starting_time| runner_socket = socket client_socket.send_data JSON.dump({cmd: :status, status: :container_running}) runner_socket.on :stdout do |data| - json_data = prepare data, :stdout - @output << json_data[0, max_output_buffer_size - @output.size] + json_data = prepare data, :stdout, starting_time + @testrun[:output] << json_data[0, max_output_buffer_size - @testrun[:output].size] client_socket.send_data(json_data) end runner_socket.on :stderr do |data| - json_data = prepare data, :stderr - @output << json_data[0, max_output_buffer_size - @output.size] + json_data = prepare data, :stderr, starting_time + @testrun[:output] << json_data[0, max_output_buffer_size - @testrun[:output].size] client_socket.send_data(json_data) end runner_socket.on :exit do |exit_code| - @exit_code = exit_code + @testrun[:exit_code] = exit_code exit_statement = - if @output.empty? && exit_code.zero? - @status = :ok + if @testrun[:output].empty? && exit_code.zero? + @testrun[:status] = :ok t('exercises.implement.no_output_exit_successful', timestamp: l(Time.zone.now, format: :short), exit_code: exit_code) - elsif @output.empty? - @status = :failed + elsif @testrun[:output].empty? + @testrun[:status] = :failed t('exercises.implement.no_output_exit_failure', timestamp: l(Time.zone.now, format: :short), exit_code: exit_code) elsif exit_code.zero? - @status = :ok + @testrun[:status] = :ok "\n#{t('exercises.implement.exit_successful', timestamp: l(Time.zone.now, format: :short), exit_code: exit_code)}" else - @status = :failed + @testrun[:status] = :failed "\n#{t('exercises.implement.exit_failure', timestamp: l(Time.zone.now, format: :short), exit_code: exit_code)}" end client_socket.send_data JSON.dump({cmd: :write, stream: :stdout, data: "#{exit_statement}\n"}) if exit_code == 137 client_socket.send_data JSON.dump({cmd: :out_of_memory}) - @status = :out_of_memory + @testrun[:status] = :out_of_memory end close_client_connection(client_socket) end end - @container_execution_time = durations[:execution_duration] - @waiting_for_container_time = durations[:waiting_duration] + @testrun[:container_execution_time] = durations[:execution_duration] + @testrun[:waiting_for_container_time] = durations[:waiting_duration] rescue Runner::Error::ExecutionTimeout => e client_socket.send_data JSON.dump({cmd: :status, status: :timeout}) close_client_connection(client_socket) Rails.logger.debug { "Running a submission timed out: #{e.message}" } - @output = "timeout: #{@output}" - @status = :timeout + @testrun[:output] = "timeout: #{@testrun[:output]}" + @testrun[:status] = :timeout extract_durations(e) rescue Runner::Error => e client_socket.send_data JSON.dump({cmd: :status, status: :container_depleted}) close_client_connection(client_socket) Rails.logger.debug { "Runner error while running a submission: #{e.message}" } - @status = :container_depleted + @testrun[:status] = :container_depleted extract_durations(e) ensure save_testrun_output 'run' @@ -203,8 +205,8 @@ class SubmissionsController < ApplicationController tubesock.send_data JSON.dump({cmd: :status, status: :container_depleted}) kill_client_socket(tubesock) Rails.logger.debug { "Runner error while scoring submission #{@submission.id}: #{e.message}" } - @passed = false - @status = :container_depleted + @testrun[:passed] = false + @testrun[:status] = :container_depleted extract_durations(e) save_testrun_output 'assess' end @@ -228,8 +230,8 @@ class SubmissionsController < ApplicationController tubesock.send_data JSON.dump({cmd: :status, status: :container_depleted}) kill_client_socket(tubesock) Rails.logger.debug { "Runner error while testing submission #{@submission.id}: #{e.message}" } - @passed = false - @status = :container_depleted + @testrun[:passed] = false + @testrun[:status] = :container_depleted extract_durations(e) save_testrun_output 'assess' end @@ -279,16 +281,16 @@ class SubmissionsController < ApplicationController end def extract_durations(error) - @container_execution_time = error.execution_duration - @waiting_for_container_time = error.waiting_duration + @testrun[:container_execution_time] = error.execution_duration + @testrun[:waiting_for_container_time] = error.waiting_duration end def extract_errors results = [] - if @output.present? + if @testrun[:output].present? @submission.exercise.execution_environment.error_templates.each do |template| pattern = Regexp.new(template.signature).freeze - results << StructuredError.create_from_template(template, @output, @submission) if pattern.match(@output) + results << StructuredError.create_from_template(template, @testrun[:output], @submission) if pattern.match(@testrun[:output]) end end results @@ -302,12 +304,11 @@ class SubmissionsController < ApplicationController end end - def prepare(data, stream) - if valid_command? data - data - else - JSON.dump({cmd: :write, stream: stream, data: data}) - end + def prepare(data, stream, starting_time) + message = retrieve_message_from_output data, stream + message[:timestamp] = ActiveSupport::Duration.build(Time.zone.now - starting_time) + @testrun[:messages].push message + JSON.dump(message) end def sanitize_filename @@ -318,15 +319,16 @@ class SubmissionsController < ApplicationController def save_testrun_output(cause) testrun = Testrun.create!( file: @file, - passed: @passed, + passed: @testrun[:passed], cause: cause, submission: @submission, - exit_code: @exit_code, # might be nil, e.g., when the run did not finish - status: @status, - output: @output.presence, # TODO: Remove duplicated saving of the output after creating TestrunMessages - container_execution_time: @container_execution_time, - waiting_for_container_time: @waiting_for_container_time + exit_code: @testrun[:exit_code], # might be nil, e.g., when the run did not finish + status: @testrun[:status], + output: @testrun[:output].presence, # TODO: Remove duplicated saving of the output after creating TestrunMessages + container_execution_time: @testrun[:container_execution_time], + waiting_for_container_time: @testrun[:waiting_for_container_time] ) + TestrunMessage.create_for(testrun, @testrun[:messages]) TestrunExecutionEnvironment.create(testrun: testrun, execution_environment: @submission.used_execution_environment) end @@ -361,10 +363,26 @@ class SubmissionsController < ApplicationController authorize! end - def valid_command?(data) + def set_testrun + @testrun = { + messages: [], + exit_code: nil, + status: nil, + } + end + + def retrieve_message_from_output(data, stream) parsed = JSON.parse(data) - parsed.instance_of?(Hash) && parsed.key?('cmd') + if parsed.instance_of?(Hash) && parsed.key?('cmd') + parsed.symbolize_keys! + # Symbolize two values if present + parsed[:cmd] = parsed[:cmd].to_sym + parsed[:stream] = parsed[:stream].to_sym if parsed.key? :stream + parsed + else + {cmd: :write, stream: stream, data: data} + end rescue JSON::ParserError - false + {cmd: :write, stream: stream, data: data} end end diff --git a/app/models/application_record.rb b/app/models/application_record.rb index a851eca6..2e96397b 100644 --- a/app/models/application_record.rb +++ b/app/models/application_record.rb @@ -8,7 +8,8 @@ class ApplicationRecord < ActiveRecord::Base def strip_strings # trim whitespace from beginning and end of string attributes # except for the `content` of CodeOcean::Files - attribute_names.without('content').each do |name| + # and except the `log` of TestrunMessages or the `output` of Testruns + attribute_names.without('content', 'log', 'output').each do |name| if send(name.to_sym).respond_to?(:strip) send("#{name}=".to_sym, send(name).strip) end diff --git a/app/models/runner.rb b/app/models/runner.rb index 88e36ae5..6da8d657 100644 --- a/app/models/runner.rb +++ b/app/models/runner.rb @@ -62,7 +62,7 @@ class Runner < ApplicationRecord # initializing its Runner::Connection with the given event loop. The Runner::Connection class ensures that # this event loop is stopped after the socket was closed. event_loop = Runner::EventLoop.new - socket = @strategy.attach_to_execution(command, event_loop, &block) + socket = @strategy.attach_to_execution(command, event_loop, starting_time, &block) event_loop.wait raise socket.error if socket.error.present? rescue Runner::Error => e @@ -74,30 +74,34 @@ class Runner < ApplicationRecord end def execute_command(command, raise_exception: true) - output = {} - stdout = +'' - stderr = +'' + output = { + stdout: +'', + stderr: +'', + messages: [], + exit_code: 1, # default to error + } try = 0 - exit_code = 1 # default to error begin if try.nonzero? request_new_id save end - execution_time = attach_to_execution(command) do |socket| + execution_time = attach_to_execution(command) do |socket, starting_time| socket.on :stderr do |data| - stderr << data + output[:stderr] << data + output[:messages].push({cmd: :write, stream: :stderr, log: data, timestamp: Time.zone.now - starting_time}) end socket.on :stdout do |data| - stdout << data + output[:stdout] << data + output[:messages].push({cmd: :write, stream: :stdout, log: data, timestamp: Time.zone.now - starting_time}) end socket.on :exit do |received_exit_code| - exit_code = received_exit_code + output[:exit_code] = received_exit_code end end - output.merge!(container_execution_time: execution_time, status: exit_code.zero? ? :ok : :failed) + output.merge!(container_execution_time: execution_time, status: output[:exit_code].zero? ? :ok : :failed) rescue Runner::Error::ExecutionTimeout => e Rails.logger.debug { "Running command `#{command}` timed out: #{e.message}" } output.merge!(status: :timeout, container_execution_time: e.execution_duration) @@ -122,8 +126,7 @@ class Runner < ApplicationRecord raise e if raise_exception && defined?(e) && e.present? # If the process was killed with SIGKILL, it is most likely that the OOM killer was triggered. - output[:status] = :out_of_memory if exit_code == 137 - output.merge!(stdout: stdout, stderr: stderr, exit_code: exit_code) + output[:status] = :out_of_memory if output[:exit_code] == 137 end end diff --git a/app/models/submission.rb b/app/models/submission.rb index 3f3852f0..3aa1ef3d 100644 --- a/app/models/submission.rb +++ b/app/models/submission.rb @@ -258,6 +258,7 @@ class Submission < ApplicationRecord container_execution_time: output[:container_execution_time], waiting_for_container_time: output[:waiting_for_container_time] ) + TestrunMessage.create_for(testrun, output[:messages]) TestrunExecutionEnvironment.create(testrun: testrun, execution_environment: @used_execution_environment) filename = file.filepath diff --git a/app/models/testrun.rb b/app/models/testrun.rb index feea7a09..44464c7d 100644 --- a/app/models/testrun.rb +++ b/app/models/testrun.rb @@ -12,6 +12,7 @@ class Testrun < ApplicationRecord container_depleted: 2, timeout: 3, out_of_memory: 4, + client_kill: 5, }, _default: :ok, _prefix: true validates :exit_code, numericality: {only_integer: true, min: 0, max: 255}, allow_nil: true diff --git a/app/models/testrun_message.rb b/app/models/testrun_message.rb index db30717a..67299e2a 100644 --- a/app/models/testrun_message.rb +++ b/app/models/testrun_message.rb @@ -18,6 +18,7 @@ class TestrunMessage < ApplicationRecord client_kill: 11, exception: 12, result: 13, + canvasevent: 14, }, _default: :write, _prefix: true enum stream: { @@ -28,9 +29,28 @@ class TestrunMessage < ApplicationRecord validates :cmd, presence: true validates :timestamp, presence: true - + validates :stream, length: {minimum: 0, allow_nil: false}, if: -> { cmd_write? } + validates :log, length: {minimum: 0, allow_nil: false}, if: -> { cmd_write? } validate :either_data_or_log + def self.create_for(testrun, messages) + messages.map! do |message| + # We create a new hash and move all known keys + result = {} + result[:testrun] = testrun + result[:log] = message.delete(:log) || (message.delete(:data) if message[:cmd] == :write) + result[:timestamp] = message.delete :timestamp + result[:stream] = message.delete :stream + result[:cmd] = message.delete :cmd + # The remaining keys will be stored in the `data` column + result[:data] = message.presence + result + end + + # An array with hashes is passed, all are stored + TestrunMessage.create!(messages) + end + def either_data_or_log if [data, log].count(&:present?) > 1 errors.add(log, "can't be present if data is also present") diff --git a/lib/runner/strategy.rb b/lib/runner/strategy.rb index 313d35fa..6b2093c6 100644 --- a/lib/runner/strategy.rb +++ b/lib/runner/strategy.rb @@ -33,7 +33,7 @@ class Runner::Strategy raise NotImplementedError end - def attach_to_execution(_command, _event_loop) + def attach_to_execution(_command, _event_loop, _starting_time) raise NotImplementedError end diff --git a/lib/runner/strategy/docker_container_pool.rb b/lib/runner/strategy/docker_container_pool.rb index fa4ef574..cf328244 100644 --- a/lib/runner/strategy/docker_container_pool.rb +++ b/lib/runner/strategy/docker_container_pool.rb @@ -108,7 +108,7 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished copying files" } end - def attach_to_execution(command, event_loop) + def attach_to_execution(command, event_loop, starting_time) reset_inactivity_timer @command = command @@ -119,7 +119,7 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy begin Timeout.timeout(@execution_environment.permitted_execution_time) do socket.send_data(command) - yield(socket) + yield(socket, starting_time) event_loop.wait event_loop.stop end diff --git a/lib/runner/strategy/null.rb b/lib/runner/strategy/null.rb index 4702e6f4..a47ac51c 100644 --- a/lib/runner/strategy/null.rb +++ b/lib/runner/strategy/null.rb @@ -25,11 +25,11 @@ class Runner::Strategy::Null < Runner::Strategy def copy_files(_files); end - def attach_to_execution(command, event_loop) + def attach_to_execution(command, event_loop, starting_time) socket = Connection.new(nil, self, event_loop) # We don't want to return an error if the execution environment is changed socket.status = :terminated_by_codeocean if command == ExecutionEnvironment::VALIDATION_COMMAND - yield(socket) + yield(socket, starting_time) socket end diff --git a/lib/runner/strategy/poseidon.rb b/lib/runner/strategy/poseidon.rb index b0bb6607..477ae0f1 100644 --- a/lib/runner/strategy/poseidon.rb +++ b/lib/runner/strategy/poseidon.rb @@ -133,10 +133,10 @@ class Runner::Strategy::Poseidon < Runner::Strategy Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished copying files" } end - def attach_to_execution(command, event_loop) + def attach_to_execution(command, event_loop, starting_time) websocket_url = execute_command(command) socket = Connection.new(websocket_url, self, event_loop) - yield(socket) + yield(socket, starting_time) socket end