From 5aee2aaba892db57c18c7dab14c0118f49d99761 Mon Sep 17 00:00:00 2001
From: Sebastian Serth <Sebastian.Serth@hpi.de>
Date: Thu, 18 Nov 2021 14:18:41 +0100
Subject: [PATCH] Add more logging for execution requests

---
 app/models/runner.rb     | 2 ++
 app/models/submission.rb | 1 +
 2 files changed, 3 insertions(+)

diff --git a/app/models/runner.rb b/app/models/runner.rb
index 3e005185..63f080f1 100644
--- a/app/models/runner.rb
+++ b/app/models/runner.rb
@@ -53,6 +53,7 @@ class Runner < ApplicationRecord
   end
 
   def attach_to_execution(command, &block)
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Starting execution with Runner #{id} for #{user_type} #{user_id}." }
     starting_time = Time.zone.now
     begin
       # As the EventMachine reactor is probably shared with other threads, we cannot use EventMachine.run with
@@ -68,6 +69,7 @@ class Runner < ApplicationRecord
       e.execution_duration = Time.zone.now - starting_time
       raise
     end
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Stopped execution with Runner #{id} for #{user_type} #{user_id}." }
     Time.zone.now - starting_time # execution duration
   end
 
diff --git a/app/models/submission.rb b/app/models/submission.rb
index 5043c65e..d3281288 100644
--- a/app/models/submission.rb
+++ b/app/models/submission.rb
@@ -199,6 +199,7 @@ class Submission < ApplicationRecord
       runner = Runner.for(user, exercise.execution_environment)
       files = collect_files
       files.reject!(&:teacher_defined_assessment?) if cause == 'run'
+      Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Copying files to Runner #{runner.id} for #{user_type} #{user_id} and Submission #{id}." }
       runner.copy_files(files)
     rescue Runner::Error => e
       e.waiting_duration = Time.zone.now - request_time