From 044058d0f159f444c4c1d8d7765307bb64529ca4 Mon Sep 17 00:00:00 2001 From: Adam Cooke Date: Thu, 1 Feb 2024 17:41:45 +0000 Subject: [PATCH] feat: more consistent logging --- Gemfile | 1 + Gemfile.lock | 6 +++ 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 | 64 ------------------------------- lib/postal/config.rb | 38 +++++++++--------- 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 | 8 ++-- lib/postal/worker.rb | 36 ++++++++--------- 21 files changed, 160 insertions(+), 171 deletions(-) create mode 100644 config/initializers/logging.rb delete mode 100644 lib/postal/app_logger.rb diff --git a/Gemfile b/Gemfile index 31b5bef..c072b2e 100644 --- a/Gemfile +++ b/Gemfile @@ -20,6 +20,7 @@ gem "hashie" gem "highline", require: false gem "jwt" gem "kaminari" +gem "klogger-logger" gem "mail" gem "moonrope" gem "mysql2" diff --git a/Gemfile.lock b/Gemfile.lock index 83cf9a0..2344799 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -147,6 +147,10 @@ GEM activerecord kaminari-core (= 1.2.2) kaminari-core (1.2.2) + klogger-logger (1.3.2) + concurrent-ruby (>= 1.0, < 2.0) + json + rouge (>= 3.30, < 5.0) loofah (2.22.0) crass (~> 1.0.2) nokogiri (>= 1.12.0) @@ -229,6 +233,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) @@ -345,6 +350,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 97d4b6f..ada4e34 100644 --- a/app/models/webhook_request.rb +++ b/app/models/webhook_request.rb @@ -53,41 +53,42 @@ class WebhookRequest < ApplicationRecord 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 d0fb313..12e8c27 100644 --- a/config/application.rb +++ b/config/application.rb @@ -38,9 +38,11 @@ module Postal 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 ab18723..fed7a60 100644 --- a/config/cron.rb +++ b/config/cron.rb @@ -4,7 +4,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 cca5f81..386e938 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -72,12 +72,6 @@ Rails.application.configure do # 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 0000000..5108da4 --- /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 a9a1de2..dcc06a1 100644 --- a/config/initializers/smtp.rb +++ b/config/initializers/smtp.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true 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 dc65e34..2c9fa33 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 982fcec..69922c9 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 13fd044..0000000 --- a/lib/postal/app_logger.rb +++ /dev/null @@ -1,64 +0,0 @@ -# frozen_string_literal: true - -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 - # 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" - COLORS = [32, 34, 35, 31, 32, 33].freeze - - 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 6dd148d..1f1f42d 100644 --- a/lib/postal/config.rb +++ b/lib/postal/config.rb @@ -49,14 +49,6 @@ module Postal 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") @@ -93,16 +85,11 @@ module Postal 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 @@ -187,4 +174,19 @@ module Postal 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 0de927f..e07a637 100644 --- a/lib/postal/http_sender.rb +++ b/lib/postal/http_sender.rb @@ -61,7 +61,7 @@ module Postal 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 32759cb..1311d1f 100644 --- a/lib/postal/job.rb +++ b/lib/postal/job.rb @@ -30,7 +30,7 @@ module Postal 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 bdf0222..061e1e4 100644 --- a/lib/postal/message_db/database.rb +++ b/lib/postal/message_db/database.rb @@ -325,12 +325,12 @@ module Postal 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.positive? && 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}" ActiveRecord::ConnectionAdapters::MySQL::ExplainPrettyPrinter.new.pp(explain_result, time).split("\n").each do |line| - slow_query_logger.info "[#{id}] " + line + logger.info " [#{id}] " + line end end result @@ -340,10 +340,6 @@ module Postal defined?(Rails) ? Rails.logger : Logger.new($stdout) end - def slow_query_logger - Postal.logger_for(:slow_message_db_queries) - end - def with_mysql(&block) self.class.connection_pool.use(&block) end diff --git a/lib/postal/message_inspector.rb b/lib/postal/message_inspector.rb index 5eeadc8..2b01a49 100644 --- a/lib/postal/message_inspector.rb +++ b/lib/postal/message_inspector.rb @@ -15,7 +15,7 @@ module Postal 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 a42732f..31e5510 100644 --- a/lib/postal/message_requeuer.rb +++ b/lib/postal/message_requeuer.rb @@ -20,7 +20,7 @@ module Postal 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 e158390..764b057 100644 --- a/lib/postal/smtp_sender.rb +++ b/lib/postal/smtp_sender.rb @@ -234,7 +234,7 @@ module Postal 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 790e7dc..6aedcfc 100644 --- a/lib/postal/smtp_server/client.rb +++ b/lib/postal/smtp_server/client.rb @@ -48,16 +48,18 @@ module Postal 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 @@ -93,7 +95,7 @@ module Postal 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 bd7cd74..3a110a0 100644 --- a/lib/postal/smtp_server/server.rb +++ b/lib/postal/smtp_server/server.rb @@ -14,8 +14,10 @@ module Postal end def run - listen - run_event_loop + logger.tagged(component: "smtp-server") do + listen + run_event_loop + end end private @@ -264,7 +266,7 @@ module Postal end def logger - Postal.logger_for(:smtp_server) + Postal.logger end end diff --git a/lib/postal/worker.rb b/lib/postal/worker.rb index 7d5f858..969d81e 100644 --- a/lib/postal/worker.rb +++ b/lib/postal/worker.rb @@ -49,33 +49,25 @@ module Postal 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 @@ -92,13 +84,21 @@ module Postal 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 @@ -106,9 +106,9 @@ module Postal 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 @@ -198,7 +198,7 @@ module Postal class << self def logger - Postal.logger_for(:worker) + Postal.logger end def job_channel