Persist TestrunMessages and store timestamp

So far, the Testrun messages are in addition to the Tesstrun.output column

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

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 = +''
+    @testrun[:output] = +''
-    durations = @submission.run(@file) do |socket|
+    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
+        json_data = prepare data, :stdout, starting_time
-        @output << json_data[0, max_output_buffer_size - @output.size]
+        @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
+        json_data = prepare data, :stderr, starting_time
-        @output << json_data[0, max_output_buffer_size - @output.size]
+        @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?
+          if @testrun[:output].empty? && exit_code.zero?
-            @status = :ok
+            @testrun[:status] = :ok
             t('exercises.implement.no_output_exit_successful', timestamp: l(Time.zone.now, format: :short), exit_code: exit_code)
-          elsif @output.empty?
+          elsif @testrun[:output].empty?
-            @status = :failed
+            @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]
+    @testrun[:container_execution_time] = durations[:execution_duration]
-    @waiting_for_container_time = durations[:waiting_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}"
+    @testrun[:output] = "timeout: #{@testrun[:output]}"
-    @status = :timeout
+    @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
+          @testrun[:passed] = false
-          @status = :container_depleted
+          @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
+          @testrun[:passed] = false
-          @status = :container_depleted
+          @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
+    @testrun[:container_execution_time] = error.execution_duration
-    @waiting_for_container_time = error.waiting_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)
+  def prepare(data, stream, starting_time)
-    if valid_command? data
+    message = retrieve_message_from_output data, stream
-      data
+    message[:timestamp] = ActiveSupport::Duration.build(Time.zone.now - starting_time)
-    else
+    @testrun[:messages].push message
-      JSON.dump({cmd: :write, stream: stream, data: data})
+    JSON.dump(message)
-    end
   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
+      exit_code: @testrun[:exit_code], # might be nil, e.g., when the run did not finish
-      status: @status,
+      status: @testrun[:status],
-      output: @output.presence, # TODO: Remove duplicated saving of the output after creating TestrunMessages
+      output: @testrun[:output].presence, # TODO: Remove duplicated saving of the output after creating TestrunMessages
-      container_execution_time: @container_execution_time,
+      container_execution_time: @testrun[:container_execution_time],
-      waiting_for_container_time: @waiting_for_container_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

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,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 = {}
+    output = {
-    stdout = +''
+      stdout: +'',
-    stderr = +''
+      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[:status] = :out_of_memory if output[:exit_code] == 137
-      output.merge!(stdout: stdout, stderr: stderr, exit_code: exit_code)
     end
   end
 

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

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

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")

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
 

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

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
 

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