some more logging (and cleanup)

app/controllers/submissions_controller.rb

@@ -112,13 +112,13 @@ class SubmissionsController < ApplicationController
         end
 
         tubesock.onmessage do |data|
-          Rails.logger.info("Client sending: " + data)
+          Rails.logger.debug("Client sending: " + data)
           # Check wether the client send a JSON command and kill container
           # if the command is 'exit', send it to docker otherwise.
           begin
             parsed = JSON.parse(data)
             if parsed['cmd'] == 'exit'
-              Rails.logger.info("Client exited container.")
+              Rails.logger.debug("Client exited container.")
               @docker_client.exit_container(result[:container])
             else
               socket.send data
@@ -209,6 +209,7 @@ class SubmissionsController < ApplicationController
   end
 
   def stop
+    Rails.logger.debug('stopping submission ' + @submission)
     container = Docker::Container.get(params[:container_id])
     DockerClient.destroy_container(container)
   rescue Docker::Error::NotFoundError

lib/docker_client.rb

@@ -97,6 +97,7 @@ class DockerClient
     container.status = :created
     container
   rescue Docker::Error::NotFoundError => error
+    Rails.logger.info('create_container: Got Docker::Error::NotFoundError: ' + error)
     destroy_container(container)
     #(tries += 1) <= RETRY_COUNT ? retry : raise(error)
   end
@@ -176,7 +177,7 @@ class DockerClient
       timeout = @execution_environment.permitted_execution_time.to_i # seconds
       sleep(timeout)
       if container.status != :returned
-        Rails.logger.info("Killing container after timeout of " + timeout.to_s + " seconds.")
+        Rails.logger.info('Killing container after timeout of ' + timeout.to_s + ' seconds.')
         # send timeout to the tubesock socket
         if(@tubesock)
           @tubesock.send_data JSON.dump({'cmd' => 'timeout'})
@@ -187,6 +188,7 @@ class DockerClient
   end
 
   def exit_container(container)
+    Rails.logger.debug('exiting container ' + container.to_s)
     # exit the timeout thread if it is still alive
     if(@thread && @thread.alive?)
       @thread.exit
@@ -196,6 +198,7 @@ class DockerClient
   end
 
   def kill_container(container)
+    Rails.logger.info('killing container ' + container.to_s)
     # remove container from pool, then destroy it
     if (DockerContainerPool.config[:active])
       DockerContainerPool.remove_from_all_containers(container, @execution_environment)
@@ -282,6 +285,7 @@ class DockerClient
   end
 
   def self.return_container(container, execution_environment)
+    Rails.logger.debug('returning container ' + container.to_s)
     clean_container_workspace(container)
     DockerContainerPool.return_container(container, execution_environment)
     container.status = :returned

lib/docker_container_pool.rb

@@ -30,14 +30,15 @@ class DockerContainerPool
     if(!@containers[execution_environment.id].include?(container))
       @containers[execution_environment.id]+=[container]
     else
-      Rails.logger.info('failed trying to add existing container ' + container.to_s)
+      Rails.logger.info('failed trying to add existing container ' + container.to_s + ' to execution_environment ' + execution_environment.to_s)
     end
   end
 
   def self.create_container(execution_environment)
-     container = DockerClient.create_container(execution_environment)
+    container = DockerClient.create_container(execution_environment)
-     container.status = 'available'
+    container.status = 'available'
-     container
+    Rails.logger.debug('created container ' + container.to_s + ' for execution environment ' + execution_environment.to_s)
+    container
   end
 
   def self.return_container(container, execution_environment)
@@ -45,7 +46,7 @@ class DockerContainerPool
     if(@containers[execution_environment.id] && !@containers[execution_environment.id].include?(container))
       @containers[execution_environment.id].push(container)
     else
-      Rails.logger.info('trying to return existing container ' + container.to_s)
+      Rails.logger.info('trying to return existing container ' + container.to_s + ' to execution_environment ' + execution_environment.to_s)
     end
   end
 
@@ -53,11 +54,11 @@ class DockerContainerPool
     # if pooling is active, do pooling, otherwise just create an container and return it
     if config[:active]
       container = @containers[execution_environment.id].try(:shift) || nil
-      Rails.logger.info('get_container fetched container  ' + container.to_s)
+      Rails.logger.debug('get_container fetched container  ' + container.to_s + ' for execution environment ' + execution_environment.to_s)
       # just access and the following if we got a container. Otherwise, the execution_environment might be just created and not fully exist yet.
       if(container)
-        Rails.logger.info('get_container remaining avail. containers:  ' + @containers[execution_environment.id].size.to_s)
+        Rails.logger.debug('get_container remaining avail. containers:  ' + @containers[execution_environment.id].size.to_s)
-        Rails.logger.info('get_container all container count: ' + @all_containers[execution_environment.id].size.to_s)
+        Rails.logger.debug('get_container all container count: ' + @all_containers[execution_environment.id].size.to_s)
       end
       container
     else