Merge pull request #640 from PRX/feat/json_logging

Init json logging

.gitignore

@@ -7,6 +7,7 @@ capybara-*.html
 /.bundle
 /vendor/bundle
 /log/*
+!/log/.keep
 /tmp/*
 /db/*.sqlite3
 /public/system/*

Gemfile

@@ -77,8 +77,12 @@ gem 'dotenv-rails'
 gem 'highline'
 gem 'rake'
 
-# monitoring
+# monitoring/logging
+gem 'logger'
+gem 'lograge'
 gem 'newrelic_rpm'
+gem 'ougai'
+gem 'ougai-formatters-customizable'
 
 # elasticsearch
 gem 'elasticsearch-dsl'

Gemfile.lock

@@ -47,6 +47,7 @@ GEM
     ansi (1.5.0)
     arel (6.0.4)
     ast (2.4.0)
+    awesome_print (1.9.2)
     aws-sdk (2.10.122)
       aws-sdk-resources (= 2.10.122)
     aws-sdk-core (2.10.122)
@@ -322,6 +323,12 @@ GEM
       celluloid (~> 0.16.0)
       rb-fsevent (>= 0.9.3)
       rb-inotify (>= 0.9)
+    logger (1.5.3)
+    lograge (0.11.2)
+      actionpack (>= 4)
+      activesupport (>= 4)
+      railties (>= 4)
+      request_store (~> 1.0)
     loofah (2.12.0)
       crass (~> 1.0.2)
       nokogiri (>= 1.5.9)
@@ -368,8 +375,13 @@ GEM
       multi_json (~> 1.3)
       multi_xml (~> 0.5)
       rack (>= 1.2, < 3)
-    oj (2.18.0)
+    oj (3.10.8)
     oj_mimic_json (1.0.1)
+    ougai (1.8.2)
+      oj (~> 3.4)
+    ougai-formatters-customizable (1.0.0)
+      awesome_print (~> 1.8, >= 1.8.0)
+      ougai (~> 1.7, >= 1.7.0)
     parallel (1.19.1)
     paranoia (2.2.0)
       activerecord (>= 4.0, < 5.1)
@@ -445,6 +457,8 @@ GEM
     redcarpet (3.3.4)
     representable (2.3.0)
       uber (~> 0.0.7)
+    request_store (1.7.0)
+      rack (>= 1.4)
     responders (2.3.0)
       railties (>= 4.2.0, < 5.1)
     reverse_markdown (1.0.3)
@@ -561,6 +575,8 @@ DEPENDENCIES
   icalendar (~> 2.5.0)
   kaminari
   left_joins
+  logger
+  lograge
   loofah
   m (~> 1.5.0)
   minitest (~> 5.9.1)
@@ -573,6 +589,8 @@ DEPENDENCIES
   oauth2
   oj
   oj_mimic_json
+  ougai
+  ougai-formatters-customizable
   paranoia (~> 2.0)
   prx_auth-rails (~> 1.2.0)
   pry-byebug (~> 3.4.1)

config/application.rb

@@ -77,5 +77,50 @@ class Application < Rails::Application
     proto = (ENV['CMS_HOST'] || '').include?('.docker') ? 'http' : 'https'
     cms_url_options = { host: ENV['CMS_HOST'], protocol: proto }
     Rails.application.routes.default_url_options = cms_url_options
+
+    # Logging
+    module ActiveSupport::TaggedLogging::Formatter
+      def call(severity, time, progname, data)
+        data = {msg: data.to_s} unless data.is_a?(Hash)
+        tags = current_tags
+        data[:tags] = tags if tags.present?
+        _call(severity, time, progname, data)
+      end
+    end
+
+    require "#{Rails.root}/lib/cms_logger.rb"
+    config.logger = ActiveSupport::TaggedLogging.new(CmsLogger.new($stdout))
+
+    # Used when invoking the async workers via supervisord.
+    if ENV['USE_SYNC_STDOUT'].present?
+      $stdout.sync = true
+    end
+
+    config.lograge.enabled = true
+    config.lograge.custom_payload do |controller|
+      exclude = %w[controller action format id authenticity_token access_token id_token]
+      {
+        params: controller.request.params.except(*exclude),
+        user_agent: controller.request.user_agent,
+        user_id: Rails.env.test? ? nil : controller.try(:prx_auth_token)&.user_id&.to_i,
+        user_ip: controller.request.ip,
+        user_ref: controller.request.referrer
+      }.compact
+    end
+    config.lograge.ignore_custom = lambda do |event|
+      if event.payload[:path] == '/' && event.payload[:status] == 302
+        true
+      elsif event.payload[:path] == '/api/v1'
+        true
+      end
+    end
+
+    config.lograge.formatter = Class.new do |fmt|
+      def fmt.call(data)
+        {msg: 'Request', request: data.except('unpermitted_params')}
+      end
+    end
+
+    # config.log_tags = [:request_id]
   end
 end

config/environments/development.rb

@@ -29,9 +29,4 @@
 
   # Just allow all docker-compose requests
   config.web_console.whitelisted_ips = '0.0.0.0/0'
-
-  # Better logging for docker-compose, except when re-indexing ES via rake.
-  unless ENV['CLASS']
-    config.logger = Logger.new(STDOUT)
-  end
 end

config/environments/test.rb

@@ -38,4 +38,7 @@
   config.active_support.test_order = :random
 
   config.active_job.queue_adapter = :test
+
+  # Use a local file for logging test results
+  config.logger = ActiveSupport::TaggedLogging.new(CmsLogger.new('log/test.log'))
 end

config/initializers/time_formats.rb

@@ -0,0 +1,2 @@
+Date::DATE_FORMATS[:default] = Date::DATE_FORMATS[:iso8601]
+Time::DATE_FORMATS[:default] = Time::DATE_FORMATS[:iso8601]

lib/cms_logger.rb

@@ -0,0 +1,46 @@
+class CmsLogger < Ougai::Logger
+  # include ActiveSupport::LoggerThreadSafeLevel
+  # include ActiveSupport::LoggerSilence
+
+  def create_formatter
+    if Rails.env.development? || Rails.env.test?
+      color_config = Ougai::Formatters::Colors::Configuration.new
+      formatter = Ougai::Formatters::Customizable.new(
+        format_msg: proc do |severity, datetime, _progname, data|
+          format(
+            '%<severity>s %<datetime>s: %<msg>s %<data>s',
+            severity: color_config.color(:severity, severity, severity),
+            datetime: color_config.color(:datetime, datetime, severity),
+            msg: color_config.color(:msg, data.delete(:msg).try(:squish), severity),
+            data: data.ai(multiline: false)
+          )
+        end,
+        # this appears to be redundant with format_msg, so just no-op
+        format_data: proc { |_data| }
+      )
+      formatter.datetime_format = '%H:%M:%S.%L'
+      formatter
+    else
+      Ougai::Formatters::Bunyan.new
+    end
+  end
+
+  def elapsed(msg = '', args = {}, &block)
+    measure(:info, msg, args, &block)
+  end
+
+  def debug_elapsed(msg = '', args = {}, &block)
+    measure(:debug, msg, args, &block)
+  end
+
+  private
+
+  def measure(level, msg, args, &block)
+    elapsed = Benchmark.measure(&block)
+    if msg.is_a? Hash
+      public_send(level, msg.merge(elapsed: elapsed.real))
+    else
+      public_send(level, msg, args.merge(elapsed: elapsed.real))
+    end
+  end
+end