Patch logger to match Superlogger format, insert instrumentation logs

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'

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

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

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