diff --git a/app/assets/javascripts/editor/editor.js.erb b/app/assets/javascripts/editor/editor.js.erb index d40badea..233e6b5a 100644 --- a/app/assets/javascripts/editor/editor.js.erb +++ b/app/assets/javascripts/editor/editor.js.erb @@ -703,6 +703,8 @@ var CodeOceanEditor = { this.showTimeoutMessage(); } else if (output.status === 'container_depleted') { this.showContainerDepletedMessage(); + } else if (output.status === 'out_of_memory') { + this.showOutOfMemoryMessage(); } else if (output.stderr) { $.flash.danger({ icon: ['fa', 'fa-bug'], diff --git a/app/assets/javascripts/editor/execution.js b/app/assets/javascripts/editor/execution.js index 6b2df68b..ec1784c9 100644 --- a/app/assets/javascripts/editor/execution.js +++ b/app/assets/javascripts/editor/execution.js @@ -46,8 +46,6 @@ CodeOceanEditorWebsocket = { this.websocket.on('turtlebatch', this.handleTurtlebatchCommand.bind(this)); this.websocket.on('render', this.renderWebsocketOutput.bind(this)); this.websocket.on('exit', this.handleExitCommand.bind(this)); - this.websocket.on('timeout', this.showTimeoutMessage.bind(this)); - this.websocket.on('out_of_memory', this.showOutOfMemoryMessage.bind(this)); this.websocket.on('status', this.showStatus.bind(this)); this.websocket.on('hint', this.showHint.bind(this)); }, diff --git a/app/controllers/submissions_controller.rb b/app/controllers/submissions_controller.rb index 74eec3a6..0ef7fa11 100644 --- a/app/controllers/submissions_controller.rb +++ b/app/controllers/submissions_controller.rb @@ -93,6 +93,7 @@ class SubmissionsController < ApplicationController client_socket.onclose do |_event| runner_socket&.close(:terminated_by_client) + # We do not update the @testrun[:status] by design, it would be missleading end client_socket.onmessage do |raw_event| @@ -101,10 +102,17 @@ class SubmissionsController < ApplicationController # Otherwise, we expect to receive a JSON: Parsing. event = JSON.parse(raw_event).deep_symbolize_keys + event[:cmd] = event[:cmd].to_sym + event[:stream] = event[:stream].to_sym if event.key? :stream - case event[:cmd].to_sym + # We could store the received event. However, it is also echoed by the container + # and correctly identified as the original input. Therefore, we don't store + # it here to prevent duplicated events. + # @testrun[:messages].push(event) + + case event[:cmd] when :client_kill - @testrun[:status] = :client_kill + @testrun[:status] = :terminated_by_client close_client_connection(client_socket) Rails.logger.debug('Client exited container.') when :result, :canvasevent, :exception @@ -133,18 +141,19 @@ class SubmissionsController < ApplicationController @testrun[:output] = +'' durations = @submission.run(@file) do |socket, starting_time| runner_socket = socket + @testrun[:starting_time] = starting_time client_socket.send_data JSON.dump({cmd: :status, status: :container_running}) runner_socket.on :stdout do |data| - 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) + message = retrieve_message_from_output data, :stdout + @testrun[:output] << message[:data][0, max_output_buffer_size - @testrun[:output].size] if message[:data] + send_and_store client_socket, message end runner_socket.on :stderr do |data| - 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) + message = retrieve_message_from_output data, :stderr + @testrun[:output] << message[:data][0, max_output_buffer_size - @testrun[:output].size] if message[:data] + send_and_store client_socket, message end runner_socket.on :exit do |exit_code| @@ -163,9 +172,9 @@ class SubmissionsController < ApplicationController @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"}) + send_and_store client_socket, {cmd: :write, stream: :stdout, data: "#{exit_statement}\n"} if exit_code == 137 - client_socket.send_data JSON.dump({cmd: :out_of_memory}) + send_and_store client_socket, {cmd: :status, status: :out_of_memory} @testrun[:status] = :out_of_memory end @@ -175,17 +184,15 @@ class SubmissionsController < ApplicationController @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}) + send_and_store client_socket, {cmd: :status, status: :timeout} close_client_connection(client_socket) Rails.logger.debug { "Running a submission timed out: #{e.message}" } @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}) + send_and_store client_socket, {cmd: :status, status: :container_depleted} close_client_connection(client_socket) Rails.logger.debug { "Runner error while running a submission: #{e.message}" } - @testrun[:status] = :container_depleted extract_durations(e) ensure save_testrun_output 'run' @@ -197,17 +204,17 @@ class SubmissionsController < ApplicationController switch_locale do kill_client_socket(tubesock) if @embed_options[:disable_score] + # The score is stored separately, we can forward it to the client immediately tubesock.send_data(JSON.dump(@submission.calculate_score)) # To enable hints when scoring a submission, uncomment the next line: # send_hints(tubesock, StructuredError.where(submission: @submission)) kill_client_socket(tubesock) rescue Runner::Error => e - tubesock.send_data JSON.dump({cmd: :status, status: :container_depleted}) + extract_durations(e) + send_and_store tubesock, {cmd: :status, status: :container_depleted} kill_client_socket(tubesock) Rails.logger.debug { "Runner error while scoring submission #{@submission.id}: #{e.message}" } @testrun[:passed] = false - @testrun[:status] = :container_depleted - extract_durations(e) save_testrun_output 'assess' end end @@ -224,15 +231,15 @@ class SubmissionsController < ApplicationController switch_locale do kill_client_socket(tubesock) if @embed_options[:disable_run] + # The score is stored separately, we can forward it to the client immediately tubesock.send_data(JSON.dump(@submission.test(@file))) kill_client_socket(tubesock) rescue Runner::Error => e - tubesock.send_data JSON.dump({cmd: :status, status: :container_depleted}) + extract_durations(e) + send_and_store tubesock, {cmd: :status, status: :container_depleted} kill_client_socket(tubesock) Rails.logger.debug { "Runner error while testing submission #{@submission.id}: #{e.message}" } @testrun[:passed] = false - @testrun[:status] = :container_depleted - extract_durations(e) save_testrun_output 'assess' end end @@ -253,6 +260,7 @@ class SubmissionsController < ApplicationController end def kill_client_socket(client_socket) + # We don't want to store this (arbitrary) exit command and redirect it ourselves client_socket.send_data JSON.dump({cmd: :exit}) client_socket.close end @@ -281,6 +289,7 @@ class SubmissionsController < ApplicationController end def extract_durations(error) + @testrun[:starting_time] = error.starting_time @testrun[:container_execution_time] = error.execution_duration @testrun[:waiting_for_container_time] = error.waiting_duration end @@ -296,6 +305,13 @@ class SubmissionsController < ApplicationController results end + def send_and_store(client_socket, message) + message[:timestamp] = ActiveSupport::Duration.build(Time.zone.now - @testrun[:starting_time]) + @testrun[:messages].push message + @testrun[:status] = message[:status] if message[:status] + client_socket.send_data JSON.dump(message) + end + def max_output_buffer_size if @submission.cause == 'requestComments' 5000 @@ -304,13 +320,6 @@ class SubmissionsController < ApplicationController end 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 params[:filename].gsub(/\.json$/, '') end @@ -337,7 +346,7 @@ class SubmissionsController < ApplicationController errors = errors.to_a.uniq(&:hint) errors.each do |error| - tubesock.send_data JSON.dump({cmd: 'hint', hint: error.hint, description: error.error_template.description}) + send_and_store tubesock, {cmd: :hint, hint: error.hint, description: error.error_template.description} end end diff --git a/app/errors/runner/error.rb b/app/errors/runner/error.rb index e943db73..139045d1 100644 --- a/app/errors/runner/error.rb +++ b/app/errors/runner/error.rb @@ -2,7 +2,7 @@ class Runner class Error < ApplicationError - attr_accessor :waiting_duration, :execution_duration + attr_accessor :waiting_duration, :execution_duration, :starting_time class BadRequest < Error; end diff --git a/app/models/runner.rb b/app/models/runner.rb index 6da8d657..20909927 100644 --- a/app/models/runner.rb +++ b/app/models/runner.rb @@ -66,6 +66,7 @@ class Runner < ApplicationRecord event_loop.wait raise socket.error if socket.error.present? rescue Runner::Error => e + e.starting_time = starting_time e.execution_duration = Time.zone.now - starting_time raise end diff --git a/app/models/submission.rb b/app/models/submission.rb index 3aa1ef3d..a269de17 100644 --- a/app/models/submission.rb +++ b/app/models/submission.rb @@ -273,6 +273,7 @@ class Submission < ApplicationRecord output.merge!(assessment) output.merge!(filename: filename, message: feedback_message(file, output), weight: file.weight) + output.except!(:messages) end def feedback_message(file, output) diff --git a/app/models/testrun.rb b/app/models/testrun.rb index 44464c7d..18a9b393 100644 --- a/app/models/testrun.rb +++ b/app/models/testrun.rb @@ -12,7 +12,7 @@ class Testrun < ApplicationRecord container_depleted: 2, timeout: 3, out_of_memory: 4, - client_kill: 5, + terminated_by_client: 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 67299e2a..eff0b68c 100644 --- a/app/models/testrun_message.rb +++ b/app/models/testrun_message.rb @@ -11,14 +11,14 @@ class TestrunMessage < ApplicationRecord turtlebatch: 4, render: 5, exit: 6, - timeout: 7, - out_of_memory: 8, - status: 9, - hint: 10, - client_kill: 11, - exception: 12, - result: 13, - canvasevent: 14, + status: 7, + hint: 8, + client_kill: 9, + exception: 10, + result: 11, + canvasevent: 12, + timeout: 13, # TODO: Shouldn't be in the data, this is a status and can be removed after the migration finished + out_of_memory: 14, # TODO: Shouldn't be in the data, this is a status and can be removed after the migration finished }, _default: :write, _prefix: true enum stream: { @@ -34,21 +34,52 @@ class TestrunMessage < ApplicationRecord validate :either_data_or_log def self.create_for(testrun, messages) + # We don't want to store anything if the testrun passed + return if testrun.passed? + 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[:log] = (message.delete(:log) || message.delete(:data)) if message[:cmd] == :write || message.key?(:log) result[:timestamp] = message.delete :timestamp - result[:stream] = message.delete :stream + result[:stream] = message.delete :stream if message.key?(:stream) result[:cmd] = message.delete :cmd # The remaining keys will be stored in the `data` column - result[:data] = message.presence + result[:data] = message.presence if message.present? result end + # Before storing all messages, we truncate some to save storage + filtered_messages = filter_messages_by_size testrun, messages + # An array with hashes is passed, all are stored - TestrunMessage.create!(messages) + TestrunMessage.create!(filtered_messages) + end + + def self.filter_messages_by_size(testrun, messages) + limits = if testrun.submission.cause == 'requestComments' + {data: {limit: 25, size: 0}, log: {limit: 5000, size: 0}} + else + {data: {limit: 10, size: 0}, log: {limit: 500, size: 0}} + end + + filtered_messages = messages.map do |message| + if message.key?(:log) && limits[:log][:size] < limits[:log][:limit] + message[:log] = message[:log][0, limits[:log][:limit] - limits[:log][:size]] + limits[:log][:size] += message[:log].size + elsif message[:data] && limits[:data][:size] < limits[:data][:limit] + limits[:data][:size] += 1 + elsif !message.key?(:log) && limits[:data][:size] < limits[:data][:limit] + # Accept short TestrunMessages (e.g. just transporting a status information) + # without increasing the `limits[:data][:limit]` before the limit is reached + else + # Clear all remaining messages + message = nil + end + message + end + filtered_messages.select(&:present?) end def either_data_or_log diff --git a/spec/models/runner_spec.rb b/spec/models/runner_spec.rb index 5f23e775..5639263a 100644 --- a/spec/models/runner_spec.rb +++ b/spec/models/runner_spec.rb @@ -115,10 +115,12 @@ describe Runner do end it 'attaches the execution time to the error' do - starting_time = Time.zone.now + test_starting_time = Time.zone.now expect { runner.attach_to_execution(command) }.to raise_error do |raised_error| - test_time = Time.zone.now - starting_time + test_time = Time.zone.now - test_starting_time expect(raised_error.execution_duration).to be_between(0.0, test_time).exclusive + # The `starting_time` is shortly after the `test_starting_time`` + expect(raised_error.starting_time).to be > test_starting_time end end end