diff --git a/lib/runner/connection.rb b/lib/runner/connection.rb index ac13818f..02c65922 100644 --- a/lib/runner/connection.rb +++ b/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 diff --git a/lib/runner/strategy/docker_container_pool.rb b/lib/runner/strategy/docker_container_pool.rb index e1059d2e..3e0f2e3b 100644 --- a/lib/runner/strategy/docker_container_pool.rb +++ b/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) diff --git a/lib/runner/strategy/poseidon.rb b/lib/runner/strategy/poseidon.rb index 7080ddd9..5dc649ff 100644 --- a/lib/runner/strategy/poseidon.rb +++ b/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