diff --git a/.gitignore b/.gitignore index 27688b20..5f740007 100644 --- a/.gitignore +++ b/.gitignore @@ -7,6 +7,7 @@ capybara-*.html /.bundle /vendor/bundle /log/* +!/log/.keep /tmp/* /db/*.sqlite3 /public/system/* diff --git a/Gemfile b/Gemfile index 76dba976..68f7db37 100644 --- a/Gemfile +++ b/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' diff --git a/Gemfile.lock b/Gemfile.lock index 75b2ef09..f00eb94c 100644 --- a/Gemfile.lock +++ b/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) diff --git a/config/application.rb b/config/application.rb index ea0581b4..350ee796 100644 --- a/config/application.rb +++ b/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 diff --git a/config/environments/development.rb b/config/environments/development.rb index 369400ee..d3f07df7 100644 --- a/config/environments/development.rb +++ b/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 diff --git a/config/environments/test.rb b/config/environments/test.rb index d1f70dcb..3a3626b0 100644 --- a/config/environments/test.rb +++ b/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 diff --git a/config/initializers/time_formats.rb b/config/initializers/time_formats.rb new file mode 100644 index 00000000..d81082bc --- /dev/null +++ b/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] diff --git a/lib/cms_logger.rb b/lib/cms_logger.rb new file mode 100644 index 00000000..2697c9ba --- /dev/null +++ b/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( + '%s %s: %s %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 diff --git a/log/.keep b/log/.keep new file mode 100644 index 00000000..e69de29b