From 374ab82dd6767056b34a48270f587b20f482bb33 Mon Sep 17 00:00:00 2001 From: David Taylor Date: Fri, 19 Mar 2021 19:51:13 +0000 Subject: [PATCH] FIX: Ensure 100-logster initializer is run before 101-lograge (#12455) The logster initializer tries to adds RailsMultisite::Formatter to the STDOUT logger. In production, the lograge initializer then removes the RailsMultisite:Formatter because the JSON log will include the database. e10a74694a2ed445d57e1740ba349e72dcc4842d used `Rails.application.reloader.to_prepare` to defer running the 100-logster initializer, which meant it ran **after** 101-lograge. This meant that we were writing JSON logs with a non-json text prefix. The `to_prepare` was added because our freedom-patches are now deferred using `to_prepare`, and some initializers were relying on the freedom patches. However, following 1533cbb38ba02eda0dcb1c58a9da0b70fbdddfee, we decided to load the RailsMultisite freedom patch without `to_prepare`. Therefore, `005-site_settings` and `100-logster` no longer need to use `to_prepare`. Removing it means that these initializers are back to running in sequential order, and the logging issue will be resolved. The only remaining initializer which depends on freedom patches is `100-i18n`. I've added a comment to explain why. --- config/initializers/005-site_settings.rb | 34 ++- config/initializers/100-i18n.rb | 1 + config/initializers/100-logster.rb | 270 +++++++++++------------ 3 files changed, 151 insertions(+), 154 deletions(-) diff --git a/config/initializers/005-site_settings.rb b/config/initializers/005-site_settings.rb index f437b739883..4ecaa85df33 100644 --- a/config/initializers/005-site_settings.rb +++ b/config/initializers/005-site_settings.rb @@ -16,26 +16,24 @@ if GlobalSetting.skip_redis? return end -Rails.application.reloader.to_prepare do - reload_settings = lambda { - RailsMultisite::ConnectionManagement.safe_each_connection do - begin - SiteSetting.refresh! +reload_settings = lambda { + RailsMultisite::ConnectionManagement.safe_each_connection do + begin + SiteSetting.refresh! - unless String === SiteSetting.push_api_secret_key && SiteSetting.push_api_secret_key.length == 32 - SiteSetting.push_api_secret_key = SecureRandom.hex - end - rescue ActiveRecord::StatementInvalid - # This will happen when migrating a new database + unless String === SiteSetting.push_api_secret_key && SiteSetting.push_api_secret_key.length == 32 + SiteSetting.push_api_secret_key = SecureRandom.hex end - end - } - - reload_settings.call - - if !Rails.configuration.cache_classes - ActiveSupport::Reloader.to_prepare do - reload_settings.call + rescue ActiveRecord::StatementInvalid + # This will happen when migrating a new database end end +} + +reload_settings.call + +if !Rails.configuration.cache_classes + ActiveSupport::Reloader.to_prepare do + reload_settings.call + end end diff --git a/config/initializers/100-i18n.rb b/config/initializers/100-i18n.rb index 1a49029738f..4165bd75b60 100644 --- a/config/initializers/100-i18n.rb +++ b/config/initializers/100-i18n.rb @@ -5,6 +5,7 @@ require 'i18n/backend/discourse_i18n' require 'i18n/backend/fallback_locale_list' +# Requires the `translate_accelerator.rb` freedom patch to be loaded Rails.application.reloader.to_prepare do I18n.backend = I18n::Backend::DiscourseI18n.new I18n.fallbacks = I18n::Backend::FallbackLocaleList.new diff --git a/config/initializers/100-logster.rb b/config/initializers/100-logster.rb index 5b89d984f58..4cc19f1f1e3 100644 --- a/config/initializers/100-logster.rb +++ b/config/initializers/100-logster.rb @@ -9,144 +9,142 @@ if GlobalSetting.skip_redis? return end -Rails.application.reloader.to_prepare do - if Rails.env.development? && RUBY_VERSION.match?(/^2\.5\.[23]/) - STDERR.puts "WARNING: Discourse development environment runs slower on Ruby 2.5.3 or below" - STDERR.puts "We recommend you upgrade to Ruby 2.6.1 for the optimal development performance" +if Rails.env.development? && RUBY_VERSION.match?(/^2\.5\.[23]/) + STDERR.puts "WARNING: Discourse development environment runs slower on Ruby 2.5.3 or below" + STDERR.puts "We recommend you upgrade to Ruby 2.6.1 for the optimal development performance" - # we have to used to older and slower version of the logger cause the new one exposes a Ruby bug in - # the Queue class which causes segmentation faults - Logster::Scheduler.disable - end + # we have to used to older and slower version of the logger cause the new one exposes a Ruby bug in + # the Queue class which causes segmentation faults + Logster::Scheduler.disable +end - if Rails.env.development? && !Sidekiq.server? && ENV["RAILS_LOGS_STDOUT"] == "1" - console = ActiveSupport::Logger.new(STDOUT) - original_logger = Rails.logger.chained.first - console.formatter = original_logger.formatter - console.level = original_logger.level +if Rails.env.development? && !Sidekiq.server? && ENV["RAILS_LOGS_STDOUT"] == "1" + console = ActiveSupport::Logger.new(STDOUT) + original_logger = Rails.logger.chained.first + console.formatter = original_logger.formatter + console.level = original_logger.level - unless ActiveSupport::Logger.logger_outputs_to?(original_logger, STDOUT) - original_logger.extend(ActiveSupport::Logger.broadcast(console)) - end - end - - if Rails.env.production? - Logster.store.ignore = [ - # honestly, Rails should not be logging this, its real noisy - /^ActionController::RoutingError \(No route matches/, - - /^PG::Error: ERROR:\s+duplicate key/, - - /^ActionController::UnknownFormat/, - /^ActionController::UnknownHttpMethod/, - /^AbstractController::ActionNotFound/, - # ignore any empty JS errors that contain blanks or zeros for line and column fields - # - # Line: - # Column: - # - /(?m).*?Line: (?:\D|0).*?Column: (?:\D|0)/, - - # suppress empty JS errors (covers MSIE 9, etc) - /^(Syntax|Script) error.*Line: (0|1)\b/m, - - # CSRF errors are not providing enough data - # suppress unconditionally for now - /^Can't verify CSRF token authenticity.$/, - - # Yandex bot triggers this JS error a lot - /^Uncaught ReferenceError: I18n is not defined/, - - # related to browser plugins somehow, we don't care - /Error calling method on NPObject/, - - # 404s can be dealt with elsewhere - /^ActiveRecord::RecordNotFound/, - - # bad asset requested, no need to log - /^ActionController::BadRequest/, - - # we can't do anything about invalid parameters - /Rack::QueryParser::InvalidParameterError/, - - # we handle this cleanly in the message bus middleware - # no point logging to logster - /RateLimiter::LimitExceeded.*/m, - - # see https://github.com/rails/rails/issues/34599 - # Poll defines an enum with the value `open` ActiveRecord then attempts - # AR then warns cause #open is being redefined, it is already defined - # privately in Kernel per: http://ruby-doc.org/core-2.5.3/Kernel.html#method-i-open - # Once the rails issue is fixed we can stop this error suppression and stop defining - # scopes for the enums - /^Creating scope :open\. Overwriting existing method Poll\.open\./, - ] - Logster.config.env_expandable_keys.push(:hostname, :problem_db) - end - - Logster.store.max_backlog = GlobalSetting.max_logster_logs - - # TODO logster should be able to do this automatically - Logster.config.subdirectory = "#{GlobalSetting.relative_url_root}/logs" - - Logster.config.application_version = Discourse.git_version - Logster.config.enable_custom_patterns_via_ui = true - Logster.config.enable_js_error_reporting = GlobalSetting.enable_js_error_reporting - - store = Logster.store - redis = Logster.store.redis - store.redis_prefix = Proc.new { redis.namespace } - store.redis_raw_connection = redis.without_namespace - severities = [Logger::WARN, Logger::ERROR, Logger::FATAL, Logger::UNKNOWN] - - RailsMultisite::ConnectionManagement.each_connection do - error_rate_per_minute = SiteSetting.alert_admins_if_errors_per_minute rescue 0 - - if (error_rate_per_minute || 0) > 0 - store.register_rate_limit_per_minute(severities, error_rate_per_minute) do |rate| - MessageBus.publish("/logs_error_rate_exceeded", - { - rate: rate, - duration: 'minute', - publish_at: Time.current.to_i - }, - group_ids: [Group::AUTO_GROUPS[:admins]] - ) - end - end - - error_rate_per_hour = SiteSetting.alert_admins_if_errors_per_hour rescue 0 - - if (error_rate_per_hour || 0) > 0 - store.register_rate_limit_per_hour(severities, error_rate_per_hour) do |rate| - MessageBus.publish("/logs_error_rate_exceeded", - { - rate: rate, - duration: 'hour', - publish_at: Time.current.to_i, - }, - group_ids: [Group::AUTO_GROUPS[:admins]] - ) - end - end - end - - if Rails.configuration.multisite - if Rails.logger.respond_to? :chained - chained = Rails.logger.chained - chained && chained.first.formatter = RailsMultisite::Formatter.new - end - end - - Logster.config.project_directories = [ - { path: Rails.root.to_s, url: "https://github.com/discourse/discourse", main_app: true } - ] - Discourse.plugins.each do |plugin| - next if !plugin.metadata.url - - Logster.config.project_directories << { - path: "#{Rails.root.to_s}/plugins/#{plugin.directory_name}", - url: plugin.metadata.url - } + unless ActiveSupport::Logger.logger_outputs_to?(original_logger, STDOUT) + original_logger.extend(ActiveSupport::Logger.broadcast(console)) end end + +if Rails.env.production? + Logster.store.ignore = [ + # honestly, Rails should not be logging this, its real noisy + /^ActionController::RoutingError \(No route matches/, + + /^PG::Error: ERROR:\s+duplicate key/, + + /^ActionController::UnknownFormat/, + /^ActionController::UnknownHttpMethod/, + /^AbstractController::ActionNotFound/, + # ignore any empty JS errors that contain blanks or zeros for line and column fields + # + # Line: + # Column: + # + /(?m).*?Line: (?:\D|0).*?Column: (?:\D|0)/, + + # suppress empty JS errors (covers MSIE 9, etc) + /^(Syntax|Script) error.*Line: (0|1)\b/m, + + # CSRF errors are not providing enough data + # suppress unconditionally for now + /^Can't verify CSRF token authenticity.$/, + + # Yandex bot triggers this JS error a lot + /^Uncaught ReferenceError: I18n is not defined/, + + # related to browser plugins somehow, we don't care + /Error calling method on NPObject/, + + # 404s can be dealt with elsewhere + /^ActiveRecord::RecordNotFound/, + + # bad asset requested, no need to log + /^ActionController::BadRequest/, + + # we can't do anything about invalid parameters + /Rack::QueryParser::InvalidParameterError/, + + # we handle this cleanly in the message bus middleware + # no point logging to logster + /RateLimiter::LimitExceeded.*/m, + + # see https://github.com/rails/rails/issues/34599 + # Poll defines an enum with the value `open` ActiveRecord then attempts + # AR then warns cause #open is being redefined, it is already defined + # privately in Kernel per: http://ruby-doc.org/core-2.5.3/Kernel.html#method-i-open + # Once the rails issue is fixed we can stop this error suppression and stop defining + # scopes for the enums + /^Creating scope :open\. Overwriting existing method Poll\.open\./, + ] + Logster.config.env_expandable_keys.push(:hostname, :problem_db) +end + +Logster.store.max_backlog = GlobalSetting.max_logster_logs + +# TODO logster should be able to do this automatically +Logster.config.subdirectory = "#{GlobalSetting.relative_url_root}/logs" + +Logster.config.application_version = Discourse.git_version +Logster.config.enable_custom_patterns_via_ui = true +Logster.config.enable_js_error_reporting = GlobalSetting.enable_js_error_reporting + +store = Logster.store +redis = Logster.store.redis +store.redis_prefix = Proc.new { redis.namespace } +store.redis_raw_connection = redis.without_namespace +severities = [Logger::WARN, Logger::ERROR, Logger::FATAL, Logger::UNKNOWN] + +RailsMultisite::ConnectionManagement.each_connection do + error_rate_per_minute = SiteSetting.alert_admins_if_errors_per_minute rescue 0 + + if (error_rate_per_minute || 0) > 0 + store.register_rate_limit_per_minute(severities, error_rate_per_minute) do |rate| + MessageBus.publish("/logs_error_rate_exceeded", + { + rate: rate, + duration: 'minute', + publish_at: Time.current.to_i + }, + group_ids: [Group::AUTO_GROUPS[:admins]] + ) + end + end + + error_rate_per_hour = SiteSetting.alert_admins_if_errors_per_hour rescue 0 + + if (error_rate_per_hour || 0) > 0 + store.register_rate_limit_per_hour(severities, error_rate_per_hour) do |rate| + MessageBus.publish("/logs_error_rate_exceeded", + { + rate: rate, + duration: 'hour', + publish_at: Time.current.to_i, + }, + group_ids: [Group::AUTO_GROUPS[:admins]] + ) + end + end +end + +if Rails.configuration.multisite + if Rails.logger.respond_to? :chained + chained = Rails.logger.chained + chained && chained.first.formatter = RailsMultisite::Formatter.new + end +end + +Logster.config.project_directories = [ + { path: Rails.root.to_s, url: "https://github.com/discourse/discourse", main_app: true } +] +Discourse.plugins.each do |plugin| + next if !plugin.metadata.url + + Logster.config.project_directories << { + path: "#{Rails.root.to_s}/plugins/#{plugin.directory_name}", + url: plugin.metadata.url + } +end