log context when using local rails buffered logger

This was already supported for Syslog, but not for the BufferedLogger
class. Also add an option to disable the context logging.

This also fixes a bug where the session logging was always using the
default session cookie name (_normandy_session), rather than the
configured one.

refs #5094

Change-Id: I4c8389f1051a70c25a92bfe018044cd15f45422b
Reviewed-on: https://gerrit.instructure.com/4795
Reviewed-by: Cody Cutrer <cody@instructure.com>
Tested-by: Hudson <hudson@instructure.com>

config/environment.rb

@@ -35,20 +35,29 @@ Rails::Initializer.run do |config|
   # Run "rake -D time" for a list of tasks for finding time zone names. Comment line to use default local time.
   config.time_zone = 'UTC'
 
+  if ENV['RUNNING_AS_DAEMON'] == 'true'
+    config.log_path = Rails.root+'log/delayed_job.log'
+  end
+
   log_config = File.exists?(Rails.root+"config/logging.yml") && YAML.load_file(Rails.root+"config/logging.yml")[RAILS_ENV]
-  if log_config && log_config["logger"] == "syslog"
+  if log_config
-    require 'syslog_wrapper'
+    opts = {}
-    log_config["app_ident"] ||= "canvas-lms"
+    opts[:skip_thread_context] = true if log_config['log_context'] == false
-    log_config["daemon_ident"] ||= "canvas-lms-daemon"
+    case log_config["logger"]
-    facilities = 0
+    when "syslog"
-    (log_config["facilities"] || []).each do |facility|
+      require 'syslog_wrapper'
-      facilities |= Syslog.const_get "LOG_#{facility.to_s.upcase}"
+      log_config["app_ident"] ||= "canvas-lms"
-    end
+      log_config["daemon_ident"] ||= "canvas-lms-daemon"
-    ident = ENV['RUNNING_AS_DAEMON'] == 'true' ? log_config["daemon_ident"] : log_config["app_ident"]
+      facilities = 0
-    config.logger = RAILS_DEFAULT_LOGGER = SyslogWrapper.new(ident, facilities)
+      (log_config["facilities"] || []).each do |facility|
-  else
+        facilities |= Syslog.const_get "LOG_#{facility.to_s.upcase}"
-    if ENV['RUNNING_AS_DAEMON'] == 'true'
+      end
-      config.log_path = Rails.root+'log/delayed_job.log'
+      ident = ENV['RUNNING_AS_DAEMON'] == 'true' ? log_config["daemon_ident"] : log_config["app_ident"]
+      config.logger = RAILS_DEFAULT_LOGGER = SyslogWrapper.new(ident, facilities, opts)
+    else
+      require 'canvas/logger'
+      log_level = ActiveSupport::BufferedLogger.const_get(config.log_level.to_s.upcase)
+      config.logger = RAILS_DEFAULT_LOGGER = CanvasLogger.new(config.log_path, log_level, opts)
     end
   end
 

config/logging.yml.example

@@ -1,5 +1,7 @@
 development:
   logger: rails
+# log_context: false
+# (log_context defaults to true)
 
 test:
   logger: rails

lib/canvas/logger.rb

@@ -0,0 +1,26 @@
+require 'active_support'
+
+class CanvasLogger < ActiveSupport::BufferedLogger
+
+  def initialize(log, level = DEBUG, options = {})
+    super(log, level)
+    @skip_thread_context = options[:skip_thread_context]
+  end
+
+  def add(severity, message=nil, progname=nil, &block)
+    return if @level > severity
+    message = (message || (block && block.call) || progname).to_s
+    # If a newline is necessary then create a new message ending with a newline.
+    # Ensures that the original message is not mutated.
+    if @skip_thread_context
+      message = "#{message}\n" unless message[-1] == ?\n
+    else
+      context = Thread.current[:context] || {}
+      message = "[#{context[:session_id] || "-"} #{context[:request_id] || "-"}] #{message}#{"\n" unless message[-1] == ?\n}"
+    end
+    buffer << message
+    auto_flush
+    message
+  end
+
+end

lib/request_context_generator.rb

@@ -25,7 +25,8 @@ class RequestContextGenerator
   def call(env)
     # This is a crummy way to plumb this data through to the logger
     request_id = UUIDSingleton.instance.generate
-    session_id = CGI::Cookie::parse(env['HTTP_COOKIE'])['_normandy_session'][0] rescue nil
+    @@session_key ||= ActionController::Base.session_options[:key]
+    session_id = CGI::Cookie::parse(env['HTTP_COOKIE'])[@@session_key][0] rescue nil
     Thread.current[:context] = {
       :request_id => request_id,
       :session_id => session_id

lib/syslog_wrapper.rb

@@ -74,6 +74,14 @@ class SyslogWrapper
   
   def close; end
 
+  SEVERITY_MAP = {
+    Logger::DEBUG => :debug,
+    Logger::INFO => :info,
+    Logger::WARN => :warning,
+    Logger::ERROR => :err,
+    Logger::FATAL => :crit,
+    Logger::UNKNOWN => :notice }
+
   def add(severity, message=nil, progname=nil)
     severity ||= Logger::UNKNOWN
     return if @level > severity
@@ -89,12 +97,7 @@ class SyslogWrapper
       context = Thread.current[:context] || {}
       message = "[#{context[:session_id] || "-"} #{context[:request_id] || "-"}] #{message}"
     end
-    $syslog.send({ Logger::DEBUG => :debug,
+    $syslog.send(SEVERITY_MAP[severity], "%s", message)
-                   Logger::INFO => :info,
-                   Logger::WARN => :warning,
-                   Logger::ERROR => :err,
-                   Logger::FATAL => :crit,
-                   Logger::UNKNOWN => :notice }[severity], "%s", message)
   end
   alias_method :log, :add