From 4f32f61debb78e2c19020fba69e04f974e3cc2d3 Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 25 Nov 2024 13:00:41 -0700 Subject: [PATCH 1/6] Init json logging --- Gemfile | 6 +++- Gemfile.lock | 20 ++++++++++++- config/application.rb | 45 +++++++++++++++++++++++++++++ config/environments/development.rb | 5 ---- config/environments/test.rb | 3 ++ lib/cms_logger.rb | 46 ++++++++++++++++++++++++++++++ 6 files changed, 118 insertions(+), 7 deletions(-) create mode 100644 lib/cms_logger.rb diff --git a/Gemfile b/Gemfile index 76dba976..e130ef63 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..e881501e 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: controller.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(*%i[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..c05dd889 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/lib/cms_logger.rb b/lib/cms_logger.rb new file mode 100644 index 00000000..c82d1bf7 --- /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 From e457484a00afd1b21d06ec806d053482eaccd0c6 Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 25 Nov 2024 13:18:28 -0700 Subject: [PATCH 2/6] Ensure log directory exists --- .gitignore | 1 + log/.keep | 0 2 files changed, 1 insertion(+) create mode 100644 log/.keep 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/log/.keep b/log/.keep new file mode 100644 index 00000000..e69de29b From 045d66ac55f5b1ba871eb81f0c905cc22d771895 Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 25 Nov 2024 13:27:06 -0700 Subject: [PATCH 3/6] Make token optional --- config/application.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/application.rb b/config/application.rb index e881501e..c7990826 100644 --- a/config/application.rb +++ b/config/application.rb @@ -102,7 +102,7 @@ def call(severity, time, progname, data) { params: controller.request.params.except(*exclude), user_agent: controller.request.user_agent, - user_id: controller.prx_auth_token&.user_id&.to_i, + user_id: controller.try(:prx_auth_token)&.user_id&.to_i, user_ip: controller.request.ip, user_ref: controller.request.referrer }.compact From d45f73bb21c555d8e16e49b6ff36fba69f6d067d Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 25 Nov 2024 14:00:16 -0700 Subject: [PATCH 4/6] Tests depending on mocking prx_auth_token before it gets called here --- config/application.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/application.rb b/config/application.rb index c7990826..2357e1dc 100644 --- a/config/application.rb +++ b/config/application.rb @@ -102,7 +102,7 @@ def call(severity, time, progname, data) { params: controller.request.params.except(*exclude), user_agent: controller.request.user_agent, - user_id: controller.try(:prx_auth_token)&.user_id&.to_i, + 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 From 0a672ad62e8d84a5f6d740684a57f723718f9413 Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 2 Dec 2024 13:23:59 -0700 Subject: [PATCH 5/6] Force OJ/ruby to default to iso8601 formats --- config/initializers/time_formats.rb | 2 ++ 1 file changed, 2 insertions(+) create mode 100644 config/initializers/time_formats.rb 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] From 22dd42cf682d243017c709329752600cb7c4f6d7 Mon Sep 17 00:00:00 2001 From: cavis Date: Mon, 2 Dec 2024 13:39:57 -0700 Subject: [PATCH 6/6] Houuuunddd!!! --- Gemfile | 8 ++++---- config/application.rb | 8 ++++---- config/environments/test.rb | 2 +- lib/cms_logger.rb | 8 ++++---- 4 files changed, 13 insertions(+), 13 deletions(-) diff --git a/Gemfile b/Gemfile index e130ef63..68f7db37 100644 --- a/Gemfile +++ b/Gemfile @@ -78,11 +78,11 @@ gem 'highline' gem 'rake' # monitoring/logging -gem "logger" -gem "lograge" +gem 'logger' +gem 'lograge' gem 'newrelic_rpm' -gem "ougai" -gem "ougai-formatters-customizable" +gem 'ougai' +gem 'ougai-formatters-customizable' # elasticsearch gem 'elasticsearch-dsl' diff --git a/config/application.rb b/config/application.rb index 2357e1dc..350ee796 100644 --- a/config/application.rb +++ b/config/application.rb @@ -92,7 +92,7 @@ def call(severity, time, progname, data) config.logger = ActiveSupport::TaggedLogging.new(CmsLogger.new($stdout)) # Used when invoking the async workers via supervisord. - if ENV["USE_SYNC_STDOUT"].present? + if ENV['USE_SYNC_STDOUT'].present? $stdout.sync = true end @@ -108,16 +108,16 @@ def call(severity, time, progname, data) }.compact end config.lograge.ignore_custom = lambda do |event| - if event.payload[:path] == "/" && event.payload[:status] == 302 + if event.payload[:path] == '/' && event.payload[:status] == 302 true - elsif event.payload[:path] == "/api/v1" + 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(*%i[unpermitted_params])} + {msg: 'Request', request: data.except('unpermitted_params')} end end diff --git a/config/environments/test.rb b/config/environments/test.rb index c05dd889..3a3626b0 100644 --- a/config/environments/test.rb +++ b/config/environments/test.rb @@ -40,5 +40,5 @@ config.active_job.queue_adapter = :test # Use a local file for logging test results - config.logger = ActiveSupport::TaggedLogging.new(CmsLogger.new("log/test.log")) + config.logger = ActiveSupport::TaggedLogging.new(CmsLogger.new('log/test.log')) end diff --git a/lib/cms_logger.rb b/lib/cms_logger.rb index c82d1bf7..2697c9ba 100644 --- a/lib/cms_logger.rb +++ b/lib/cms_logger.rb @@ -8,7 +8,7 @@ def create_formatter formatter = Ougai::Formatters::Customizable.new( format_msg: proc do |severity, datetime, _progname, data| format( - "%s %s: %s %s", + '%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), @@ -18,18 +18,18 @@ def create_formatter # this appears to be redundant with format_msg, so just no-op format_data: proc { |_data| } ) - formatter.datetime_format = "%H:%M:%S.%L" + formatter.datetime_format = '%H:%M:%S.%L' formatter else Ougai::Formatters::Bunyan.new end end - def elapsed(msg = "", args = {}, &block) + def elapsed(msg = '', args = {}, &block) measure(:info, msg, args, &block) end - def debug_elapsed(msg = "", args = {}, &block) + def debug_elapsed(msg = '', args = {}, &block) measure(:debug, msg, args, &block) end