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

config/application.rb

@@ -38,9 +38,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

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 @@
   # 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/config.rb

@@ -49,14 +49,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")
@@ -93,16 +85,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
 
@@ -187,4 +174,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

lib/postal/http_sender.rb

@@ -61,7 +61,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 = {})

lib/postal/job.rb

@@ -30,7 +30,7 @@ def perform
     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 @@ 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.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 @@ 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)
         self.class.connection_pool.use(&block)
       end