Switch logging to milliseconds and add more details

* By design, most logging happens in an `ensure` block. This ensures that no return value is modified unexpectedly.

lib/runner/connection.rb

@@ -17,6 +17,7 @@ class Runner::Connection
   attr_reader :error
 
   def initialize(url, strategy, event_loop, locale = I18n.locale)
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Opening connection to #{url}" }
     # The `ping` value is measured in seconds and specifies how often a Ping frame should be sent.
     # Internally, Faye::WebSocket uses EventMachine and the `ping` value is used to wake the EventMachine thread
     # The `tls` option is used to customize the validation of TLS connections.
@@ -55,7 +56,7 @@ class Runner::Connection
   # Send arbitrary data in the WebSocket connection
   def send_data(raw_data)
     encoded_message = encode(raw_data)
-    Rails.logger.debug { "#{Time.zone.now.getutc}: Sending to #{@socket.url}: #{encoded_message.inspect}" }
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Sending to #{@socket.url}: #{encoded_message.inspect}" }
     @socket.send(encoded_message)
   end
 
@@ -102,7 +103,7 @@ class Runner::Connection
   # independent of the JSON specification that is used within the WebSocket once established.
 
   def on_message(raw_event)
-    Rails.logger.debug { "#{Time.zone.now.getutc}: Receiving from #{@socket.url}: #{raw_event.data.inspect}" }
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Receiving from #{@socket.url}: #{raw_event.data.inspect}" }
     event = decode(raw_event.data)
     return unless BACKEND_OUTPUT_SCHEMA.valid?(event)
 
@@ -117,6 +118,7 @@ class Runner::Connection
   end
 
   def on_open(_event)
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Established connection to #{@socket.url}" }
     @start_callback.call
   end
 
@@ -128,7 +130,7 @@ class Runner::Connection
   end
 
   def on_close(_event)
-    Rails.logger.debug { "#{Time.zone.now.getutc}: Closing connection to #{@socket.url} with status: #{@status}" }
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Closing connection to #{@socket.url} with status: #{@status}" }
     flush_buffers
 
     # Depending on the status, we might want to destroy the runner at management.
@@ -149,6 +151,7 @@ class Runner::Connection
         @strategy.destroy_at_management
         @error = Runner::Error::Unknown.new('Execution terminated with an unknown reason')
     end
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Closed connection to #{@socket.url} with status: #{@status}" }
     @event_loop.stop
   end
 

lib/runner/strategy/docker_container_pool.rb

@@ -14,12 +14,17 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy
   end
 
   def self.request_from_management(environment)
-    container_id = JSON.parse(Faraday.get("#{config[:pool][:location]}/docker_container_pool/get_container/#{environment.id}").body)['id']
+    url = "#{config[:pool][:location]}/docker_container_pool/get_container/#{environment.id}"
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Requesting new runner at #{url}" }
+    response = Faraday.get url
+    container_id = JSON.parse(response.body)['id']
     container_id.presence || raise(Runner::Error::NotAvailable.new("DockerContainerPool didn't return a container id"))
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to DockerContainerPool failed: #{e.inspect}")
   rescue JSON::ParserError => e
     raise Runner::Error::UnexpectedResponse.new("DockerContainerPool returned invalid JSON: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished new runner request" }
   end
 
   def initialize(runner_id, _environment)
@@ -28,6 +33,7 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy
   end
 
   def copy_files(files)
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Sending files to #{local_workspace_path}" }
     FileUtils.mkdir_p(local_workspace_path)
     clean_workspace
     files.each do |file|
@@ -48,12 +54,18 @@ class Runner::Strategy::DockerContainerPool < Runner::Strategy
       end
     end
     FileUtils.chmod_R('+rwtX', local_workspace_path)
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished copying files" }
   end
 
   def destroy_at_management
-    Faraday.get("#{self.class.config[:pool][:location]}/docker_container_pool/destroy_container/#{container.id}")
+    url = "#{self.class.config[:pool][:location]}/docker_container_pool/destroy_container/#{container.id}"
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Destroying runner at #{url}" }
+    Faraday.get(url)
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to DockerContainerPool failed: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished destroying runner" }
   end
 
   def attach_to_execution(command, event_loop)

lib/runner/strategy/poseidon.rb

@@ -36,6 +36,7 @@ class Runner::Strategy::Poseidon < Runner::Strategy
       executionEnvironmentId: environment.id,
       inactivityTimeout: config[:unused_runner_expiration_time].seconds,
     }
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Requesting new runner at #{url}" }
     connection = Faraday.new nil, ssl: {ca_file: config[:ca_file]}
     response = connection.post url, body.to_json, headers
 
@@ -51,6 +52,8 @@ class Runner::Strategy::Poseidon < Runner::Strategy
     end
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to Poseidon failed: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished new runner request" }
   end
 
   def self.handle_error(response)
@@ -88,13 +91,15 @@ class Runner::Strategy::Poseidon < Runner::Strategy
   end
 
   def copy_files(files)
+    url = "#{runner_url}/files"
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Sending files to #{url}" }
+
     copy = files.map do |file|
       {
         path: file.filepath,
         content: Base64.strict_encode64(file.content),
       }
     end
-    url = "#{runner_url}/files"
 
     # First, clean the workspace and second, copy all files to their location.
     # This ensures that no artefacts from a previous submission remain in the workspace.
@@ -107,6 +112,8 @@ class Runner::Strategy::Poseidon < Runner::Strategy
     self.class.handle_error response
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to Poseidon failed: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished copying files" }
   end
 
   def attach_to_execution(command, event_loop)
@@ -117,11 +124,14 @@ class Runner::Strategy::Poseidon < Runner::Strategy
   end
 
   def destroy_at_management
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Destroying runner at #{runner_url}" }
     connection = Faraday.new nil, ssl: {ca_file: self.class.config[:ca_file]}
     response = connection.delete runner_url, nil, self.class.headers
     self.class.handle_error response unless response.status == 204
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to Poseidon failed: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished destroying runner" }
   end
 
   def websocket_header
@@ -136,8 +146,10 @@ class Runner::Strategy::Poseidon < Runner::Strategy
   def execute_command(command)
     url = "#{runner_url}/execute"
     body = {command: command, timeLimit: @execution_environment.permitted_execution_time}
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Preparing command execution at #{url}: #{command}" }
     connection = Faraday.new nil, ssl: {ca_file: self.class.config[:ca_file]}
     response = connection.post url, body.to_json, self.class.headers
+
     case response.status
       when 200
         response_body = self.class.parse response
@@ -151,6 +163,8 @@ class Runner::Strategy::Poseidon < Runner::Strategy
     end
   rescue Faraday::Error => e
     raise Runner::Error::FaradayError.new("Request to Poseidon failed: #{e.inspect}")
+  ensure
+    Rails.logger.debug { "#{Time.zone.now.getutc.inspect}: Finished command execution preparation" }
   end
 
   def runner_url