Extend storage of Testrun Messages and truncate long output

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'],

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));
   },

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
+        message = retrieve_message_from_output data, :stdout
-        @testrun[:output] << json_data[0, max_output_buffer_size - @testrun[:output].size]
+        @testrun[:output] << message[:data][0, max_output_buffer_size - @testrun[:output].size] if message[:data]
-        client_socket.send_data(json_data)
+        send_and_store client_socket, message
       end
 
       runner_socket.on :stderr do |data|
-        json_data = prepare data, :stderr, starting_time
+        message = retrieve_message_from_output data, :stderr
-        @testrun[:output] << json_data[0, max_output_buffer_size - @testrun[:output].size]
+        @testrun[:output] << message[:data][0, max_output_buffer_size - @testrun[:output].size] if message[:data]
-        client_socket.send_data(json_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
 

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
 

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

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)

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

app/models/testrun_message.rb

@@ -11,14 +11,14 @@ class TestrunMessage < ApplicationRecord
     turtlebatch: 4,
     render: 5,
     exit: 6,
-    timeout: 7,
+    status: 7,
-    out_of_memory: 8,
+    hint: 8,
-    status: 9,
+    client_kill: 9,
-    hint: 10,
+    exception: 10,
-    client_kill: 11,
+    result: 11,
-    exception: 12,
+    canvasevent: 12,
-    result: 13,
+    timeout: 13, # TODO: Shouldn't be in the data, this is a status and can be removed after the migration finished
-    canvasevent: 14,
+    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

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