From a7b2b725b444779f8bfded5f2888ebe75e091552 Mon Sep 17 00:00:00 2001 From: Adam Cooke Date: Thu, 1 Feb 2024 17:41:45 +0000 Subject: [PATCH] wip: add klogger --- Gemfile | 1 + Gemfile.lock | 11 +++--- app/models/webhook_request.rb | 63 ++++++++++++++++--------------- config/application.rb | 6 ++- config/cron.rb | 2 +- config/environments/production.rb | 6 --- config/initializers/logging.rb | 51 +++++++++++++++++++++++++ config/initializers/smtp.rb | 1 + config/postal.defaults.yml | 6 +-- docker/ci-config/postal.test.yml | 3 -- lib/postal/app_logger.rb | 62 ------------------------------ lib/postal/config.rb | 40 +++++++++++--------- lib/postal/http_sender.rb | 2 +- lib/postal/job.rb | 2 +- lib/postal/message_db/database.rb | 10 ++--- lib/postal/message_inspector.rb | 2 +- lib/postal/message_requeuer.rb | 2 +- lib/postal/smtp_sender.rb | 2 +- lib/postal/smtp_server/client.rb | 20 +++++----- lib/postal/smtp_server/server.rb | 17 +++++---- lib/postal/worker.rb | 36 +++++++++--------- 21 files changed, 167 insertions(+), 178 deletions(-) create mode 100644 config/initializers/logging.rb delete mode 100644 lib/postal/app_logger.rb diff --git a/Gemfile b/Gemfile index ef6caaf76..afe1ce206 100644 --- a/Gemfile +++ b/Gemfile @@ -18,6 +18,7 @@ gem "highline", require: false gem "execjs", '~> 2.7', "< 2.8" gem "jwt" gem "kaminari" +gem "klogger-logger" gem "mail" gem "moonrope" gem "mysql2" diff --git a/Gemfile.lock b/Gemfile.lock index 076323ca7..a8eec6de4 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -145,6 +145,10 @@ GEM activerecord kaminari-core (= 1.2.2) kaminari-core (1.2.2) + klogger-logger (1.3.1) + concurrent-ruby (>= 1.0, < 2.0) + json + rouge (>= 3.30, < 5.0) loofah (2.19.1) crass (~> 1.0.2) nokogiri (>= 1.5.9) @@ -156,7 +160,6 @@ GEM marcel (1.0.2) method_source (1.0.0) mini_mime (1.1.2) - mini_portile2 (2.8.1) minitest (5.18.0) moonrope (2.0.2) deep_merge (~> 1.0) @@ -177,9 +180,6 @@ GEM activerecord (>= 4.0.0) activesupport (>= 4.0.0) nio4r (2.7.0) - nokogiri (1.14.3) - mini_portile2 (~> 2.8.0) - racc (~> 1.4) nokogiri (1.14.3-arm64-darwin) racc (~> 1.4) nokogiri (1.14.3-x86_64-linux) @@ -225,6 +225,7 @@ GEM regexp_parser (2.7.0) resolv (0.2.2) rexml (3.2.5) + rouge (4.2.0) rspec (3.12.0) rspec-core (~> 3.12.0) rspec-expectations (~> 3.12.0) @@ -310,7 +311,6 @@ GEM PLATFORMS arm64-darwin-22 - ruby x86_64-linux DEPENDENCIES @@ -339,6 +339,7 @@ DEPENDENCIES jquery-rails jwt kaminari + klogger-logger mail moonrope mysql2 diff --git a/app/models/webhook_request.rb b/app/models/webhook_request.rb index 5fc30433b..8b33fb6da 100644 --- a/app/models/webhook_request.rb +++ b/app/models/webhook_request.rb @@ -51,41 +51,42 @@ def queue end def deliver - logger = Postal.logger_for(:webhooks) payload = { event: event, timestamp: created_at.to_f, payload: self.payload, uuid: uuid }.to_json - logger.info "[#{id}] Sending webhook request to `#{url}`" - result = Postal::HTTP.post(url, sign: true, json: payload, timeout: 5) - self.attempts += 1 - self.retry_after = RETRIES[self.attempts]&.from_now - server.message_db.webhooks.record( - event: event, - url: url, - webhook_id: webhook_id, - attempt: self.attempts, - timestamp: Time.now.to_f, - payload: self.payload.to_json, - uuid: uuid, - status_code: result[:code], - body: result[:body], - will_retry: (retry_after ? 0 : 1) - ) + Postal.logger.tagged(event: event, url: url, component: "webhooks") do + Postal.logger.info "Sending webhook request" + result = Postal::HTTP.post(url, sign: true, json: payload, timeout: 5) + self.attempts += 1 + self.retry_after = RETRIES[self.attempts]&.from_now + server.message_db.webhooks.record( + event: event, + url: url, + webhook_id: webhook_id, + attempt: self.attempts, + timestamp: Time.now.to_f, + payload: self.payload.to_json, + uuid: uuid, + status_code: result[:code], + body: result[:body], + will_retry: (retry_after ? 0 : 1) + ) - if result[:code] >= 200 && result[:code] < 300 - logger.info "[#{id}] -> Received #{result[:code]} status code. That's OK." - destroy - webhook&.update_column(:last_used_at, Time.now) - true - else - logger.error "[#{id}] -> Received #{result[:code]} status code. That's not OK." - self.error = "Couldn't send to URL. Code received was #{result[:code]}" - if retry_after - logger.info "[#{id}] -> Will retry #{retry_after} (this was attempt #{self.attempts})" - save - else - logger.info "[#{id}] -> Have tried #{self.attempts} times. Giving up." + if result[:code] >= 200 && result[:code] < 300 + Postal.logger.info "Received #{result[:code]} status code. That's OK." destroy + webhook&.update_column(:last_used_at, Time.now) + true + else + Postal.logger.error "Received #{result[:code]} status code. That's not OK." + self.error = "Couldn't send to URL. Code received was #{result[:code]}" + if retry_after + Postal.logger.info "Will retry #{retry_after} (this was attempt #{self.attempts})" + save + else + Postal.logger.info "Have tried #{self.attempts} times. Giving up." + destroy + end + false end - false end end diff --git a/config/application.rb b/config/application.rb index 336159246..111e71fcc 100644 --- a/config/application.rb +++ b/config/application.rb @@ -36,9 +36,11 @@ class Application < Rails::Application require "postal/tracking_middleware" config.middleware.insert_before ActionDispatch::HostAuthorization, Postal::TrackingMiddleware - config.logger = Postal.logger_for(:rails) - config.hosts << Postal.config.web.host + if Postal.config.logging.rails_log == false + config.logger = Logger.new("/dev/null") + end + end end diff --git a/config/cron.rb b/config/cron.rb index b9def9455..6b20dc255 100644 --- a/config/cron.rb +++ b/config/cron.rb @@ -2,7 +2,7 @@ module Clockwork configure do |config| config[:tz] = "UTC" - config[:logger] = Postal.logger_for(:cron) + config[:logger] = Postal.logger end every 1.minute, "every-1-minutes" do diff --git a/config/environments/production.rb b/config/environments/production.rb index 8c12538fb..7e65fd1de 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -70,12 +70,6 @@ # require 'syslog/logger' # config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new 'app-name') - if ENV["RAILS_LOG_TO_STDOUT"].present? - logger = ActiveSupport::Logger.new(STDOUT) - logger.formatter = config.log_formatter - config.logger = ActiveSupport::TaggedLogging.new(logger) - end - # Do not dump schema after migrations. config.active_record.dump_schema_after_migration = false end diff --git a/config/initializers/logging.rb b/config/initializers/logging.rb new file mode 100644 index 000000000..5108da4c6 --- /dev/null +++ b/config/initializers/logging.rb @@ -0,0 +1,51 @@ +begin + def add_exception_to_payload(payload, event) + return unless exception = event.payload[:exception_object] + + payload[:exception_class] = exception.class.name + payload[:exception_message] = exception.message + payload[:exception_backtrace] = exception.backtrace[0, 4].join("\n") + end + + ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + + payload = { + event: "request", + transaction: event.transaction_id, + controller: event.payload[:controller], + action: event.payload[:action], + format: event.payload[:format], + method: event.payload[:method], + path: event.payload[:path], + request_id: event.payload[:request].request_id, + ip_address: event.payload[:request].ip, + status: event.payload[:status], + view_runtime: event.payload[:view_runtime], + db_runtime: event.payload[:db_runtime] + } + + add_exception_to_payload(payload, event) + + string = "#{payload[:method]} #{payload[:path]} (#{payload[:status]})" + + if payload[:exception_class] + Postal.logger.error(string, **payload) + else + Postal.logger.info(string, **payload) + end + end + + ActiveSupport::Notifications.subscribe "deliver.action_mailer" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + + Postal.logger.info({ + event: "send_email", + transaction: event.transaction_id, + message_id: event.payload[:message_id], + subject: event.payload[:subject], + from: event.payload[:from], + to: event.payload[:to].is_a?(Array) ? event.payload[:to].join(", ") : event.payload[:to].to_s + }) + end +end diff --git a/config/initializers/smtp.rb b/config/initializers/smtp.rb index 938082584..374ee79e1 100644 --- a/config/initializers/smtp.rb +++ b/config/initializers/smtp.rb @@ -1,4 +1,5 @@ require "postal/config" + if Postal.config&.smtp ActionMailer::Base.delivery_method = :smtp ActionMailer::Base.smtp_settings = { address: Postal.config.smtp.host, user_name: Postal.config.smtp.username, password: Postal.config.smtp.password, port: Postal.config.smtp.port || 25 } diff --git a/config/postal.defaults.yml b/config/postal.defaults.yml index ab5bb6d9d..7ecfac7b3 100644 --- a/config/postal.defaults.yml +++ b/config/postal.defaults.yml @@ -51,13 +51,11 @@ rabbitmq: tls_ca_certificates: <%= ENV.fetch('RABBITMQ_TLS_CA_CERTIFICATES', '/etc/ssl/certs/ca-certificates.crt'.split(',').inspect) %> logging: - stdout: <%= ENV.fetch('LOGGING_STDOUT', 'false') %> - root: <%= ENV.fetch('LOGGING_ROOT', '') %> - max_log_file_size: <%= ENV.fetch('LOGGING_MAX_LOG_FILES', '20') %> - max_log_files: <%= ENV.fetch('LOGGING_MAX_LOG_FILES', '10') %> + rails_log: <%= ENV.fetch('LOGGING_RAILS_LOG', 'false') %> graylog: host: <%= ENV.fetch('GRAYLOG_HOST', '') %> port: <%= ENV.fetch('GRAYLOG_PORT', '12201') %> + facility: <%= ENV.fetch('GRAYLOG_FACILITY', 'postal') %> workers: threads: <%= ENV.fetch('WORKER_THREADS', '4') %> diff --git a/docker/ci-config/postal.test.yml b/docker/ci-config/postal.test.yml index 982fcecd2..69922c939 100644 --- a/docker/ci-config/postal.test.yml +++ b/docker/ci-config/postal.test.yml @@ -8,9 +8,6 @@ web_server: smtp_server: port: 2525 -logging: - stdout: false - main_db: host: mariadb username: root diff --git a/lib/postal/app_logger.rb b/lib/postal/app_logger.rb deleted file mode 100644 index 4bac388ed..000000000 --- a/lib/postal/app_logger.rb +++ /dev/null @@ -1,62 +0,0 @@ -require "logger" - -module Postal - - class AppLogger < Logger - - def initialize(log_name, *args) - @log_name = log_name - super(*args) - self.formatter = LogFormatter.new - end - - def add(severity, message = nil, progname = nil) - super - if severity >= @level && n = self.class.graylog_notifier - begin - if message.nil? - message = block_given? ? yield : progname - end - message = message.to_s.force_encoding("UTF-8").scrub - message_without_ansi = begin - message.gsub(/\e\[([\d;]+)?m/, "") - rescue StandardError - message - end - n.notify!(short_message: message_without_ansi, log_name: @log_name, facility: "postal", application_name: "postal", process_name: ENV.fetch("PROC_NAME", nil), pid: Process.pid) - rescue StandardError => e - # Can't log this to GELF. Soz. - end - end - true - end - - def self.graylog? - !!Postal.config.logging.graylog&.host - end - - def self.graylog_notifier - @graylog_notifier ||= graylog? ? GELF::Notifier.new(Postal.config.logging.graylog.host, Postal.config.logging.graylog.port) : nil - end - - end - - class LogFormatter - - TIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%3N".freeze - COLORS = [32, 34, 35, 31, 32, 33] - - def call(severity, datetime, progname, msg) - time = datetime.strftime(TIME_FORMAT) - if number = ENV["PROC_NAME"] - id = number.split(".").last.to_i - proc_text = "\e[#{COLORS[id % COLORS.size]}m[#{ENV['PROC_NAME']}:#{Process.pid}]\e[0m" - else - proc_text = "[#{Process.pid}]" - end - "#{proc_text} [#{time}] #{severity} -- : #{msg}\n" - end - - end - -end diff --git a/lib/postal/config.rb b/lib/postal/config.rb index b0c8e2a1a..6a156ffa1 100644 --- a/lib/postal/config.rb +++ b/lib/postal/config.rb @@ -8,6 +8,8 @@ require_relative "version" module Postal + module Config + end def self.host @host ||= config.web.host || "localhost:5000" @@ -42,14 +44,6 @@ def self.config_root end end - def self.log_root - if config.logging.root - @log_root ||= Pathname.new(config.logging.root) - else - @log_root ||= app_root.join("log") - end - end - def self.config_file_path if env == "default" @config_file_path ||= File.join(config_root, "postal.yml") @@ -86,16 +80,11 @@ def self.defaults end end - def self.logger_for(name) - @loggers ||= {} - @loggers[name.to_sym] ||= begin - require "postal/app_logger" - if config.logging.stdout || ENV["LOG_TO_STDOUT"] - Postal::AppLogger.new(name, STDOUT) - else - FileUtils.mkdir_p(log_root) - Postal::AppLogger.new(name, log_root.join("#{name}.log"), config.logging.max_log_files, config.logging.max_log_file_size.megabytes) - end + def self.logger + @logger ||= begin + k = Klogger.new(nil, destination: Rails.env.test? ? "/dev/null" : $stdout, highlight: Rails.env.development?) + k.add_destination(graylog_logging_destination) if config.logging.graylog.host.present? + k end end @@ -180,4 +169,19 @@ def self.ip_pools? config.general.use_ip_pools? end + def self.graylog_logging_destination + @graylog_destination ||= begin + notifier = GELF::Notifier.new(config.logging.graylog.host, config.logging.graylog.port, "WAN") + proc do |_logger, payload, group_ids| + short_message = payload.delete(:message) || "[message missing]" + notifier.notify!(short_message: short_message, **{ + facility: config.logging.graylog.facility, + _environment: Rails.env.to_s, + _version: Postal::VERSION.to_s, + _group_ids: group_ids.join(" ") + }.merge(payload.transform_keys { |k| "_#{k}".to_sym }.transform_values(&:to_s))) + end + end + end + end diff --git a/lib/postal/http_sender.rb b/lib/postal/http_sender.rb index c6a23eed6..b6c4ab1a4 100644 --- a/lib/postal/http_sender.rb +++ b/lib/postal/http_sender.rb @@ -58,7 +58,7 @@ def send_message(message) private def log(text) - Postal.logger_for(:http_sender).info("[#{@log_id}] #{text}") + Postal.logger.info text, id: @log_id, component: "http-sender" end def parameters(message, options = {}) diff --git a/lib/postal/job.rb b/lib/postal/job.rb index 56b872eb9..961c610f4 100644 --- a/lib/postal/job.rb +++ b/lib/postal/job.rb @@ -28,7 +28,7 @@ def perform end def log(text) - Worker.logger.info "[#{@id}] #{text}" + Worker.logger.info(text) end def self.queue(queue, params = {}) diff --git a/lib/postal/message_db/database.rb b/lib/postal/message_db/database.rb index e63ba7e60..368149ab4 100644 --- a/lib/postal/message_db/database.rb +++ b/lib/postal/message_db/database.rb @@ -319,12 +319,12 @@ def query_on_connection(connection, query) result = connection.query(query, cast_booleans: true) time = Time.now.to_f - start_time logger.debug " \e[4;34mMessageDB Query (#{time.round(2)}s) \e[0m \e[33m#{query}\e[0m" - if time > 0.5 && query =~ /\A(SELECT|UPDATE|DELETE) / + if time > 0 && query =~ /\A(SELECT|UPDATE|DELETE) / id = Nifty::Utils::RandomString.generate(length: 6).upcase explain_result = ResultForExplainPrinter.new(connection.query("EXPLAIN #{query}")) - slow_query_logger.info "[#{id}] EXPLAIN #{query}" + logger.info " [#{id}] EXPLAIN #{query}" for line in ActiveRecord::ConnectionAdapters::MySQL::ExplainPrettyPrinter.new.pp(explain_result, time).split("\n") - slow_query_logger.info "[#{id}] " + line + logger.info " [#{id}] " + line end end result @@ -334,10 +334,6 @@ def logger defined?(Rails) ? Rails.logger : Logger.new(STDOUT) end - def slow_query_logger - Postal.logger_for(:slow_message_db_queries) - end - def with_mysql(&block) MessageDB::MySQL.client(&block) end diff --git a/lib/postal/message_inspector.rb b/lib/postal/message_inspector.rb index f522eb34d..8ba3f28df 100644 --- a/lib/postal/message_inspector.rb +++ b/lib/postal/message_inspector.rb @@ -13,7 +13,7 @@ def inspect_message(message, scope, inspection) private def logger - Postal.logger_for(:message_inspection) + Postal.logger end class << self diff --git a/lib/postal/message_requeuer.rb b/lib/postal/message_requeuer.rb index ec4d2e346..aea4db6f8 100644 --- a/lib/postal/message_requeuer.rb +++ b/lib/postal/message_requeuer.rb @@ -18,7 +18,7 @@ def run private def log(text) - Postal.logger_for(:message_requeuer).info text + Postal.logger.info text, component: "message-requeuer" end def check_exit diff --git a/lib/postal/smtp_sender.rb b/lib/postal/smtp_sender.rb index bd6121d6e..f912caa8b 100644 --- a/lib/postal/smtp_sender.rb +++ b/lib/postal/smtp_sender.rb @@ -229,7 +229,7 @@ def servers end def log(text) - Postal.logger_for(:smtp_sender).info "[#{@log_id}] #{text}" + Postal.logger.info text, id: @log_id, component: "smtp-sender" end def destination_host_description diff --git a/lib/postal/smtp_server/client.rb b/lib/postal/smtp_server/client.rb index d67918566..800518682 100644 --- a/lib/postal/smtp_server/client.rb +++ b/lib/postal/smtp_server/client.rb @@ -40,16 +40,18 @@ def id end def handle(data) - if @state == :preauth - return proxy(data) - end + Postal.logger.tagged(id: id) do + if @state == :preauth + return proxy(data) + end - log "\e[32m<= #{sanitize_input_for_log(data.strip)}\e[0m" - if @proc - @proc.call(data) + log "\e[32m<= #{sanitize_input_for_log(data.strip)}\e[0m" + if @proc + @proc.call(data) - else - handle_command(data) + else + handle_command(data) + end end end @@ -98,7 +100,7 @@ def handle_command(data) def log(text) return false unless @logging_enabled - Postal.logger_for(:smtp_server).debug "[#{id}] #{text}" + Postal.logger.debug(text, id: id) end private diff --git a/lib/postal/smtp_server/server.rb b/lib/postal/smtp_server/server.rb index 5aae3fb4f..fd056af50 100644 --- a/lib/postal/smtp_server/server.rb +++ b/lib/postal/smtp_server/server.rb @@ -276,21 +276,24 @@ def run if ENV["PID_FILE"] File.write(ENV["PID_FILE"], Process.pid.to_s + "\n") end + # If we have been spawned to replace an existing processm shut down the # parent after listening. - if ENV["SERVER_FD"] - listen - kill_parent - else - listen + logger.tagged(component: "smtp-server") do + if ENV["SERVER_FD"] + listen + kill_parent + else + listen + end + run_event_loop end - run_event_loop end private def logger - Postal.logger_for(:smtp_server) + Postal.logger end end diff --git a/lib/postal/worker.rb b/lib/postal/worker.rb index e73884157..8117ffaa8 100644 --- a/lib/postal/worker.rb +++ b/lib/postal/worker.rb @@ -47,33 +47,25 @@ def work private - def receive_job(delivery_info, properties, body) - message = begin - JSON.parse(body) - rescue StandardError - nil - end + def receive_job(delivery_info, properties, message) if message && message["class_name"] @running_jobs << message["id"] set_process_name start_time = Time.now Thread.current[:job_id] = message["id"] - logger.info "[#{message['id']}] Started processing \e[34m#{message['class_name']}\e[0m job" + logger.info "Processing job" begin klass = message["class_name"].constantize.new(message["id"], message["params"]) klass.perform GC.start rescue StandardError => e klass.on_error(e) if defined?(klass) - logger.warn "[#{message['id']}] \e[31m#{e.class}: #{e.message}\e[0m" - e.backtrace.each do |line| - logger.warn "[#{message['id']}] " + line - end + logger.exception(e) if defined?(Sentry) Sentry.capture_exception(e, extra: { job_id: message["id"] }) end ensure - logger.info "[#{message['id']}] Finished processing \e[34m#{message['class_name']}\e[0m job in #{Time.now - start_time}s" + logger.info "Finished job", time: (Time.now - start_time).to_i end end ensure @@ -90,13 +82,21 @@ def receive_job(delivery_info, properties, body) def join_queue(queue) if @active_queues[queue] - logger.info "Attempted to join queue #{queue} but already joined." + logger.error "attempted to join queue but already joined", queue: queue else consumer = self.class.job_queue(queue).subscribe(manual_ack: true) do |delivery_info, properties, body| - receive_job(delivery_info, properties, body) + message = begin + JSON.parse(body) + rescue StandardError + nil + end + + logger.tagged(job_id: message["id"], queue: queue, job_class: message["class_name"]) do + receive_job(delivery_info, properties, message) + end end @active_queues[queue] = consumer - logger.info "Joined \e[32m#{queue}\e[0m queue" + logger.info "joined queue", queue: queue end end @@ -104,9 +104,9 @@ def leave_queue(queue) if consumer = @active_queues[queue] consumer.cancel @active_queues.delete(queue) - logger.info "Left \e[32m#{queue}\e[0m queue" + logger.info "left queue", queue: queue else - logger.info "Not joined #{queue} so cannot leave" + logger.error "requested to leave queue, but not joined", queue: queue end end @@ -194,7 +194,7 @@ def logger end def self.logger - Postal.logger_for(:worker) + Postal.logger end def self.job_channel