Implement logging

lib/coursemology/evaluator.rb

@@ -14,6 +14,14 @@ module Coursemology::Evaluator
 
   autoload :Client
   autoload :CLI
+  autoload :Logging
   autoload :Models
   autoload :Services
+
+  # The logger to use for the client.
+  mattr_reader(:logger) { ActiveSupport::Logger.new(STDOUT) }
+  Logging.start
+
+  # Application cache, like Rails. Currently nil.
+  mattr_reader(:cache)
 end

lib/coursemology/evaluator/client.rb

@@ -27,8 +27,14 @@ def run
 
   # Requests evaluations from the server.
   def allocate_evaluations
-    evaluations = Coursemology::Evaluator::Models::ProgrammingEvaluation.allocate
+    evaluations =
+      ActiveSupport::Notifications.instrument('allocate.client.evaluator.coursemology') do
+        Coursemology::Evaluator::Models::ProgrammingEvaluation.allocate
+      end
+
     on_allocate(evaluations)
+  rescue ActiveRestClient::HTTPUnauthorisedClientException => e
+    ActiveSupport::Notifications.publish('allocate_fail.client.evaluator.coursemology', e: e)
   end
 
   # The callback for handling an array of allocated evaluations.
@@ -46,8 +52,14 @@ def on_allocate(evaluations)
   # @param [Coursemology::Evaluator::Models::ProgrammingEvaluation] evaluation The evaluation
   #   retrieved from the server.
   def on_evaluation(evaluation)
-    evaluation.evaluate
-    evaluation.save
+    ActiveSupport::Notifications.instrument('evaluate.client.evaluator.coursemology',
+                                            evaluation: evaluation) do
+      evaluation.evaluate
+    end
+
+    ActiveSupport::Notifications.instrument('save.client.evaluator.coursemology') do
+      evaluation.save
+    end
   end
 
   # The callback for handling SIGTERM sent to the process.

lib/coursemology/evaluator/logging.rb

@@ -0,0 +1,14 @@
+module Coursemology::Evaluator::Logging
+  extend ActiveSupport::Autoload
+
+  autoload :ClientLogSubscriber
+  autoload :DockerLogSubscriber
+
+  def self.start
+    DockerLogSubscriber.subscribe
+    ClientLogSubscriber.subscribe
+  end
+end
+
+# Define +Rails+ to trick ActiveSupport into logging to our logger.
+Rails = Coursemology::Evaluator

lib/coursemology/evaluator/logging/client_log_subscriber.rb

@@ -0,0 +1,26 @@
+class Coursemology::Evaluator::Logging::ClientLogSubscriber < ActiveSupport::LogSubscriber
+  def self.subscribe
+    attach_to(:'client.evaluator.coursemology')
+  end
+
+  def publish(name, *args)
+    send(name.split('.').first, *args)
+  end
+
+  def allocate(event)
+    info color("Client: Allocate (#{event.duration.round(1)}ms)", MAGENTA)
+  end
+
+  def allocate_fail(e:)
+    error color("Client: Allocate failed: #{e.message}", RED)
+  end
+
+  def evaluate(event)
+    info "#{color("Client: Evaluate (#{event.duration.round(1)}ms)", CYAN)} "\
+      "#{event.payload[:evaluation].language.class.display_name}"
+  end
+
+  def save(event)
+    info color("Client: Save (#{event.duration.round(1)}ms)", GREEN)
+  end
+end

lib/coursemology/evaluator/logging/docker_log_subscriber.rb

@@ -0,0 +1,15 @@
+class Coursemology::Evaluator::Logging::DockerLogSubscriber < ActiveSupport::LogSubscriber
+  def self.subscribe
+    attach_to(:'docker.evaluator.coursemology')
+  end
+
+  def create(event)
+    info "#{color("Docker Create (#{event.duration.round(1)}ms)", MAGENTA)} "\
+      "#{event.payload[:image]} => #{event.payload[:container].id}"
+  end
+
+  def destroy(event)
+    info "#{color("Docker Destroy (#{event.duration.round(1)}ms)", CYAN)} "\
+      "#{event.payload[:container]}"
+  end
+end

lib/coursemology/evaluator/models/base.rb

@@ -16,6 +16,7 @@ def initialize
     end
   end
 
+  verbose!
   before_request :add_authentication
 
   private

lib/coursemology/evaluator/services/evaluate_programming_package_service.rb

@@ -39,13 +39,16 @@ def execute
     Result.new(container.logs(stdout: true), container.logs(stderr: true),
                extract_test_report(container))
   ensure
-    container.delete if container
+    destroy_container(container) if container
   end
 
   def create_container(image)
     image_identifier = "coursemology/evaluator-image-#{image}"
-    Docker::Image.create('fromImage' => image_identifier)
-    Docker::Container.create('Image' => image_identifier)
+    ActiveSupport::Notifications.instrument('create.docker.evaluator.coursemology',
+                                            image: image_identifier) do |payload|
+      Docker::Image.create('fromImage' => image_identifier)
+      payload[:container] = Docker::Container.create('Image' => image_identifier)
+    end
   end
 
   # Copies the contents of the package to the container.
@@ -120,4 +123,11 @@ def extract_test_report(container)
       return file.read
     end
   end
+
+  def destroy_container(container)
+    ActiveSupport::Notifications.instrument('destroy.docker.evaluator.coursemology',
+                                            container: container.id) do
+      container.delete
+    end
+  end
 end

spec/coursemology/evaluator/client_spec.rb

@@ -38,6 +38,25 @@
         expect(subject).to receive(:on_evaluation).with(dummy_evaluation)
         subject.send(:allocate_evaluations)
       end
+
+      it 'instruments the allocation request' do
+        expect { subject.send(:allocate_evaluations) }.to \
+          instrument_notification('allocate.client.evaluator.coursemology')
+      end
+    end
+
+    context 'when allocation fails' do
+      context 'when allocation fails due to a HTTP Unauthorized' do
+        with_mock_client(host: 'http://localhost:3000', api_user_email: '', api_token: '') do
+          it 'publishes the allocate_fail event' do
+            expect do
+              VCR.use_cassette('client/allocation_unauthorized') do
+                subject.send(:allocate_evaluations)
+              end
+            end.to publish_notification('allocate_fail.client.evaluator.coursemology')
+          end
+        end
+      end
     end
   end
 
@@ -48,6 +67,16 @@
       expect(dummy_evaluation).to receive(:evaluate)
       subject.send(:on_evaluation, dummy_evaluation)
     end
+
+    it 'instruments the evaluation' do
+      expect { subject.send(:on_evaluation, dummy_evaluation) }.to \
+        instrument_notification('evaluate.client.evaluator.coursemology')
+    end
+
+    it 'instruments the save' do
+      expect { subject.send(:on_evaluation, dummy_evaluation) }.to \
+        instrument_notification('save.client.evaluator.coursemology')
+    end
   end
 
   describe '#on_sig_term' do

spec/coursemology/evaluator/services/evaluate_programming_package_service_spec.rb

@@ -24,6 +24,14 @@
 
       container
     end
+
+    it 'instruments the creation' do
+      expect(Docker::Image).to receive(:create)
+      expect(Docker::Container).to receive(:create)
+
+      expect { subject.send(:create_container, image) }.to \
+        instrument_notification('create.docker.evaluator.coursemology')
+    end
   end
 
   describe '#copy_package' do
@@ -54,6 +62,7 @@
   describe '#execute_package' do
     let(:image) { 'python:2.7' }
     let(:container) { subject.send(:create_container, image) }
+    after { subject.send(:destroy_container, container) }
 
     def evaluate_result
       expect(container).to receive(:start!).and_call_original
@@ -85,9 +94,21 @@ def evaluate_result
         tar.read
       end
     end
+    after { subject.send(:destroy_container, container) }
 
     it 'returns the test report' do
       expect(subject.send(:extract_test_report, container)).to eq(report_contents)
     end
   end
+
+  describe '#destroy_container' do
+    it 'instruments the destruction' do
+      container = double
+      allow(container).to receive(:delete)
+      allow(container).to receive(:id).and_return('')
+
+      expect { subject.send(:destroy_container, container) }.to \
+        instrument_notification('destroy.docker.evaluator.coursemology')
+    end
+  end
 end

spec/support/active_support_notifications.rb

@@ -0,0 +1,27 @@
+RSpec::Matchers.define(:instrument_notification) do |name|
+  match do |actual|
+    allow(ActiveSupport::Notifications).to receive(:instrument).and_call_original
+    actual.call
+
+    expect(ActiveSupport::Notifications).to have_received(:instrument).with(name, any_args).
+      at_least(:once)
+  end
+
+  description { "instrument #{name}" }
+  failure_message { |actual| "expected that #{actual} instrument the notification #{name}" }
+  supports_block_expectations
+end
+
+RSpec::Matchers.define(:publish_notification) do |name|
+  match do |actual|
+    allow(ActiveSupport::Notifications).to receive(:publish).and_call_original
+    actual.call
+
+    expect(ActiveSupport::Notifications).to have_received(:publish).with(name, any_args).
+      at_least(:once)
+  end
+
+  description { "publish #{name}" }
+  failure_message { |actual| "expected that #{actual} publish the notification #{name}" }
+  supports_block_expectations
+end