feat: more consistent logging

Gemfile

@@ -20,6 +20,7 @@ gem "hashie"
 gem "highline", require: false
 gem "jwt"
 gem "kaminari"
+gem "klogger-logger"
 gem "mail"
 gem "moonrope"
 gem "mysql2"

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

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
 

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

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

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

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

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 }

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') %>

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

lib/postal/app_logger.rb

@@ -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

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

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 = {})

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 = {})

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

lib/postal/message_inspector.rb

@@ -15,7 +15,7 @@ module Postal
     private
 
     def logger
-      Postal.logger_for(:message_inspection)
+      Postal.logger
     end
 
     class << self

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

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

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

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

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