From 638e4090f89fb7ca1223da7b2ce926ec9049fba7 Mon Sep 17 00:00:00 2001
From: Joel Low <joel@joelsplace.sg>
Date: Wed, 20 Jan 2016 18:50:59 +0800
Subject: [PATCH 1/2] Implement logging skeleton.

This implements logging for the following actions:
 - ActiveRestClient
 - Client allocate/evaluate/save
 - Docker container create/destroy
---
 lib/coursemology/evaluator.rb                 |  8 +++++++
 lib/coursemology/evaluator/client.rb          | 16 +++++++++++---
 lib/coursemology/evaluator/logging.rb         | 14 +++++++++++++
 .../logging/client_log_subscriber.rb          | 18 ++++++++++++++++
 .../logging/docker_log_subscriber.rb          | 15 +++++++++++++
 lib/coursemology/evaluator/models/base.rb     |  1 +
 .../evaluate_programming_package_service.rb   | 16 +++++++++++---
 spec/coursemology/evaluator/client_spec.rb    | 15 +++++++++++++
 ...aluate_programming_package_service_spec.rb | 21 +++++++++++++++++++
 spec/support/active_support_notifications.rb  | 14 +++++++++++++
 10 files changed, 132 insertions(+), 6 deletions(-)
 create mode 100644 lib/coursemology/evaluator/logging.rb
 create mode 100644 lib/coursemology/evaluator/logging/client_log_subscriber.rb
 create mode 100644 lib/coursemology/evaluator/logging/docker_log_subscriber.rb
 create mode 100644 spec/support/active_support_notifications.rb

diff --git a/lib/coursemology/evaluator.rb b/lib/coursemology/evaluator.rb
index c8f40be..58c2984 100644
--- a/lib/coursemology/evaluator.rb
+++ b/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
diff --git a/lib/coursemology/evaluator/client.rb b/lib/coursemology/evaluator/client.rb
index c6de0ed..91585b2 100644
--- a/lib/coursemology/evaluator/client.rb
+++ b/lib/coursemology/evaluator/client.rb
@@ -27,7 +27,11 @@ 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)
   end
 
@@ -46,8 +50,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.
diff --git a/lib/coursemology/evaluator/logging.rb b/lib/coursemology/evaluator/logging.rb
new file mode 100644
index 0000000..8598158
--- /dev/null
+++ b/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
diff --git a/lib/coursemology/evaluator/logging/client_log_subscriber.rb b/lib/coursemology/evaluator/logging/client_log_subscriber.rb
new file mode 100644
index 0000000..c862ade
--- /dev/null
+++ b/lib/coursemology/evaluator/logging/client_log_subscriber.rb
@@ -0,0 +1,18 @@
+class Coursemology::Evaluator::Logging::ClientLogSubscriber < ActiveSupport::LogSubscriber
+  def self.subscribe
+    attach_to(:'client.evaluator.coursemology')
+  end
+
+  def allocate(event)
+    info color("Client: Allocate (#{event.duration.round(1)}ms)", MAGENTA)
+  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
diff --git a/lib/coursemology/evaluator/logging/docker_log_subscriber.rb b/lib/coursemology/evaluator/logging/docker_log_subscriber.rb
new file mode 100644
index 0000000..fdf1393
--- /dev/null
+++ b/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
diff --git a/lib/coursemology/evaluator/models/base.rb b/lib/coursemology/evaluator/models/base.rb
index e867f18..b32ec7b 100644
--- a/lib/coursemology/evaluator/models/base.rb
+++ b/lib/coursemology/evaluator/models/base.rb
@@ -16,6 +16,7 @@ def initialize
     end
   end
 
+  verbose!
   before_request :add_authentication
 
   private
diff --git a/lib/coursemology/evaluator/services/evaluate_programming_package_service.rb b/lib/coursemology/evaluator/services/evaluate_programming_package_service.rb
index 0f76f8c..5a1f21d 100644
--- a/lib/coursemology/evaluator/services/evaluate_programming_package_service.rb
+++ b/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
diff --git a/spec/coursemology/evaluator/client_spec.rb b/spec/coursemology/evaluator/client_spec.rb
index 20b0b64..bea33fd 100644
--- a/spec/coursemology/evaluator/client_spec.rb
+++ b/spec/coursemology/evaluator/client_spec.rb
@@ -38,6 +38,11 @@
         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
   end
 
@@ -48,6 +53,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
diff --git a/spec/coursemology/evaluator/services/evaluate_programming_package_service_spec.rb b/spec/coursemology/evaluator/services/evaluate_programming_package_service_spec.rb
index 65206ba..d68741c 100644
--- a/spec/coursemology/evaluator/services/evaluate_programming_package_service_spec.rb
+++ b/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
diff --git a/spec/support/active_support_notifications.rb b/spec/support/active_support_notifications.rb
new file mode 100644
index 0000000..15f38a7
--- /dev/null
+++ b/spec/support/active_support_notifications.rb
@@ -0,0 +1,14 @@
+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
+

From e4f5d67084b22326caa242877d4f9af1a1444d79 Mon Sep 17 00:00:00 2001
From: Joel Low <joel@joelsplace.sg>
Date: Wed, 20 Jan 2016 20:20:07 +0800
Subject: [PATCH 2/2] Handle HTTP 401 errors when asking for allocations from
 the server.

---
 lib/coursemology/evaluator/client.rb          |  2 +
 .../logging/client_log_subscriber.rb          |  8 +++
 spec/coursemology/evaluator/client_spec.rb    | 14 +++++
 .../client/allocation_unauthorized.yml        | 54 +++++++++++++++++++
 spec/support/active_support_notifications.rb  | 13 +++++
 5 files changed, 91 insertions(+)
 create mode 100644 spec/fixtures/vcr/cassettes/client/allocation_unauthorized.yml

diff --git a/lib/coursemology/evaluator/client.rb b/lib/coursemology/evaluator/client.rb
index 91585b2..e2e04af 100644
--- a/lib/coursemology/evaluator/client.rb
+++ b/lib/coursemology/evaluator/client.rb
@@ -33,6 +33,8 @@ def allocate_evaluations
       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.
diff --git a/lib/coursemology/evaluator/logging/client_log_subscriber.rb b/lib/coursemology/evaluator/logging/client_log_subscriber.rb
index c862ade..ab89d82 100644
--- a/lib/coursemology/evaluator/logging/client_log_subscriber.rb
+++ b/lib/coursemology/evaluator/logging/client_log_subscriber.rb
@@ -3,10 +3,18 @@ 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}"
diff --git a/spec/coursemology/evaluator/client_spec.rb b/spec/coursemology/evaluator/client_spec.rb
index bea33fd..fe708e7 100644
--- a/spec/coursemology/evaluator/client_spec.rb
+++ b/spec/coursemology/evaluator/client_spec.rb
@@ -44,6 +44,20 @@
           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
 
   describe '#on_evaluation' do
diff --git a/spec/fixtures/vcr/cassettes/client/allocation_unauthorized.yml b/spec/fixtures/vcr/cassettes/client/allocation_unauthorized.yml
new file mode 100644
index 0000000..422f896
--- /dev/null
+++ b/spec/fixtures/vcr/cassettes/client/allocation_unauthorized.yml
@@ -0,0 +1,54 @@
+---
+http_interactions:
+- request:
+    method: post
+    uri: http://localhost:3000/courses/assessment/programming_evaluations/allocate
+    body:
+      encoding: US-ASCII
+      string: ''
+    headers:
+      User-Agent:
+      - ActiveRestClient/1.2.0
+      Connection:
+      - Keep-Alive
+      Accept:
+      - application/hal+json, application/json;q=0.5
+      X-User-Email:
+      - ''
+      X-User-Token:
+      - ''
+      Content-Type:
+      - application/x-www-form-urlencoded
+  response:
+    status:
+      code: 401
+      message: 
+    headers:
+      x-frame-options:
+      - SAMEORIGIN
+      x-xss-protection:
+      - 1; mode=block
+      x-content-type-options:
+      - nosniff
+      content-type:
+      - application/json; charset=utf-8
+      cache-control:
+      - no-cache
+      x-request-id:
+      - 2a843e10-83a6-4cd7-b418-c01addc07fce
+      x-runtime:
+      - '2.160943'
+      server:
+      - WEBrick/1.3.1 (Ruby/2.2.4/2015-10-28)
+      date:
+      - Wed, 20 Jan 2016 11:04:32 GMT
+      content-length:
+      - '61'
+      connection:
+      - Keep-Alive
+    body:
+      encoding: UTF-8
+      string: '{"error":"You need to sign in or sign up before continuing."}'
+    http_version: 
+  recorded_at: Wed, 20 Jan 2016 11:04:32 GMT
+recorded_with: VCR 3.0.0
diff --git a/spec/support/active_support_notifications.rb b/spec/support/active_support_notifications.rb
index 15f38a7..c4d34ca 100644
--- a/spec/support/active_support_notifications.rb
+++ b/spec/support/active_support_notifications.rb
@@ -12,3 +12,16 @@
   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