Merge pull request #1242 from openHPI/refactor_testrun_table

Refactor testrun table

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

app/models/runner.rb

@@ -62,10 +62,11 @@ 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
+      e.starting_time = starting_time
       e.execution_duration = Time.zone.now - starting_time
       raise
     end
@@ -74,30 +75,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 +127,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
 

app/models/submission.rb

@@ -257,6 +257,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
@@ -271,6 +272,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,8 +12,13 @@ class Testrun < ApplicationRecord
     container_depleted: 2,
     timeout: 3,
     out_of_memory: 4,
+    terminated_by_client: 5,
   }, _default: :ok, _prefix: true
 
   validates :exit_code, numericality: {only_integer: true, min: 0, max: 255}, allow_nil: true
   validates :status, presence: true
+
+  def log
+    testrun_messages.output.select(:log).map(&:log).join.presence
+  end
 end

app/models/testrun_message.rb

@@ -11,13 +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,
+    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: {
@@ -28,9 +29,62 @@ 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
 
+  default_scope { order(timestamp: :asc) }
+  scope :output, -> { where(cmd: 1, stream: %i[stdout stderr]) }
+
+  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 || message.key?(:log)
+      result[:timestamp] = message.delete :timestamp
+      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 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!(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
     if [data, log].count(&:present?) > 1
       errors.add(log, "can't be present if data is also present")