From ca0b5c415032ffa5abe13370e9a66435dd2a3f81 Mon Sep 17 00:00:00 2001
From: Jeremy Yap <jeremy.yapjl@gmail.com>
Date: Thu, 12 Jan 2017 22:37:10 +0800
Subject: [PATCH] Patch logger to match Superlogger format, insert
 instrumentation logs

---
 lib/coursemology/evaluator.rb                 |  1 +
 lib/coursemology/evaluator/client.rb          |  4 +++
 .../models/programming_evaluation.rb          |  2 ++
 lib/simple_formatter_patch.rb                 | 35 +++++++++++++++++++
 4 files changed, 42 insertions(+)
 create mode 100644 lib/simple_formatter_patch.rb

diff --git a/lib/coursemology/evaluator.rb b/lib/coursemology/evaluator.rb
index e7b4d78..7a02216 100644
--- a/lib/coursemology/evaluator.rb
+++ b/lib/coursemology/evaluator.rb
@@ -1,5 +1,6 @@
 # frozen_string_literal: true
 require 'active_support/all'
+require 'simple_formatter_patch'
 require 'flexirest'
 require 'faraday_middleware'
 require 'docker'
diff --git a/lib/coursemology/evaluator/client.rb b/lib/coursemology/evaluator/client.rb
index 1a03ed2..81f7943 100644
--- a/lib/coursemology/evaluator/client.rb
+++ b/lib/coursemology/evaluator/client.rb
@@ -67,11 +67,15 @@ def on_allocate(evaluations)
   # @param [Coursemology::Evaluator::Models::ProgrammingEvaluation] evaluation The evaluation
   #   retrieved from the server.
   def on_evaluation(evaluation)
+    Coursemology::Evaluator.logger.info(event: 'Evaluation job retrieved',
+                                        evaluation_id: evaluation.id)
     ActiveSupport::Notifications.instrument('evaluate.client.evaluator.coursemology',
                                             evaluation: evaluation) do
       evaluation.evaluate
     end
 
+    Coursemology::Evaluator.logger.info(event: 'Evaluation job completed',
+                                        evaluation_id: evaluation.id)
     ActiveSupport::Notifications.instrument('save.client.evaluator.coursemology') do
       evaluation.save
     end
diff --git a/lib/coursemology/evaluator/models/programming_evaluation.rb b/lib/coursemology/evaluator/models/programming_evaluation.rb
index 3655d3f..66c8589 100644
--- a/lib/coursemology/evaluator/models/programming_evaluation.rb
+++ b/lib/coursemology/evaluator/models/programming_evaluation.rb
@@ -36,6 +36,8 @@ def package
     @package ||= begin
       body = self.class._plain_request('courses/assessment/programming_evaluations/:id/package',
                                        :get, id: id)
+      Coursemology::Evaluator.logger.info(event: 'Evaluation package received',
+                                          evaluation_id: id)
       Package.new(Coursemology::Evaluator::StringIO.new(body))
     end
   end
diff --git a/lib/simple_formatter_patch.rb b/lib/simple_formatter_patch.rb
new file mode 100644
index 0000000..017105e
--- /dev/null
+++ b/lib/simple_formatter_patch.rb
@@ -0,0 +1,35 @@
+# frozen_string_literal: true
+ActiveSupport::LogSubscriber.colorize_logging = false
+
+class ActiveSupport::Logger::SimpleFormatter
+  def call(severity, time, progname, msg)
+    formatted_severity = severity[0]
+    formatted_time = time.strftime("%Y-%m-%d %H:%M:%S.") << time.usec.to_s[0..2].rjust(3)
+    caller_location = get_caller_location
+    args = format_args(msg)
+
+    "#{formatted_time} | CMEvaluator | CMEvaluator | #{formatted_severity} | #{caller_location} | #{args}\n"
+  end
+
+  def format_args(args)
+    output = if args.is_a?(Hash)
+               # Format args in key=value pair, separated by pipes
+               args.map do |key, value|
+                 "#{key}=#{value}"
+               end.join(' | ')
+             else
+               args.to_s.gsub(/\033\[1;4;32m(.*)\033\[0m/, '\1')
+             end
+    output.squish
+  end
+
+  def get_caller_location
+    location = caller_locations(6, 1).first
+
+    # Extract filename without file extension from location.path
+    # eg. superlogger/lib/superlogger/logger.rb
+    file = location.path.split('/').last.split('.').first
+
+    "#{file}:#{location.lineno}"
+  end
+end