Adapt default Rails logs to JSON format

.gitignore

@@ -2,4 +2,5 @@
 .rspec_status
 .rubocop-*rubocop-yml
 .idea
-pkg/
+pkg/
+.byebug_history

Gemfile.lock

@@ -8,6 +8,28 @@ PATH
 GEM
   remote: https://rubygems.org/
   specs:
+    actionmailer (4.2.11.3)
+      actionpack (= 4.2.11.3)
+      actionview (= 4.2.11.3)
+      activejob (= 4.2.11.3)
+      mail (~> 2.5, >= 2.5.4)
+      rails-dom-testing (~> 1.0, >= 1.0.5)
+    actionpack (4.2.11.3)
+      actionview (= 4.2.11.3)
+      activesupport (= 4.2.11.3)
+      rack (~> 1.6)
+      rack-test (~> 0.6.2)
+      rails-dom-testing (~> 1.0, >= 1.0.5)
+      rails-html-sanitizer (~> 1.0, >= 1.0.2)
+    actionview (4.2.11.3)
+      activesupport (= 4.2.11.3)
+      builder (~> 3.1)
+      erubis (~> 2.7.0)
+      rails-dom-testing (~> 1.0, >= 1.0.5)
+      rails-html-sanitizer (~> 1.0, >= 1.0.3)
+    activejob (4.2.11.3)
+      activesupport (= 4.2.11.3)
+      globalid (>= 0.3.0)
     activesupport (4.2.11.3)
       i18n (~> 0.7)
       minitest (~> 5.1)
@@ -17,46 +39,71 @@ GEM
       ffi (~> 1.9)
       ffi-compiler (>= 0.1)
     ast (2.4.1)
-    concurrent-ruby (1.1.6)
-    diff-lcs (1.3)
+    builder (3.2.4)
+    byebug (11.1.3)
+    concurrent-ruby (1.1.7)
+    crass (1.0.6)
+    diff-lcs (1.4.4)
+    erubis (2.7.0)
     ffi (1.13.1)
     ffi-compiler (1.0.1)
       ffi (>= 1.0.0)
       rake
+    globalid (0.4.2)
+      activesupport (>= 4.2.0)
     i18n (0.9.5)
       concurrent-ruby (~> 1.0)
-    minitest (5.14.1)
+    loofah (2.7.0)
+      crass (~> 1.0.2)
+      nokogiri (>= 1.5.9)
+    mail (2.7.1)
+      mini_mime (>= 0.1.1)
+    mini_mime (1.0.2)
+    mini_portile2 (2.4.0)
+    minitest (5.14.2)
+    nokogiri (1.10.10)
+      mini_portile2 (~> 2.4.0)
     parallel (1.19.2)
-    parser (2.7.1.5)
+    parser (2.7.2.0)
       ast (~> 2.4.1)
-    rack (2.2.3)
+    rack (1.6.13)
+    rack-test (0.6.3)
+      rack (>= 1.0)
+    rails-deprecated_sanitizer (1.0.3)
+      activesupport (>= 4.2.0.alpha)
+    rails-dom-testing (1.0.9)
+      activesupport (>= 4.2.0, < 5.0)
+      nokogiri (~> 1.6)
+      rails-deprecated_sanitizer (>= 1.0.1)
+    rails-html-sanitizer (1.3.0)
+      loofah (~> 2.3)
     rainbow (3.0.0)
     rake (13.0.1)
-    regexp_parser (1.8.0)
+    regexp_parser (1.8.2)
     rexml (3.2.4)
-    rspec (3.8.0)
-      rspec-core (~> 3.8.0)
-      rspec-expectations (~> 3.8.0)
-      rspec-mocks (~> 3.8.0)
-    rspec-core (3.8.0)
-      rspec-support (~> 3.8.0)
-    rspec-expectations (3.8.3)
+    rspec (3.9.0)
+      rspec-core (~> 3.9.0)
+      rspec-expectations (~> 3.9.0)
+      rspec-mocks (~> 3.9.0)
+    rspec-core (3.9.3)
+      rspec-support (~> 3.9.3)
+    rspec-expectations (3.9.2)
       diff-lcs (>= 1.2.0, < 2.0)
-      rspec-support (~> 3.8.0)
-    rspec-mocks (3.8.0)
+      rspec-support (~> 3.9.0)
+    rspec-mocks (3.9.1)
       diff-lcs (>= 1.2.0, < 2.0)
-      rspec-support (~> 3.8.0)
-    rspec-support (3.8.0)
-    rubocop (0.92.0)
+      rspec-support (~> 3.9.0)
+    rspec-support (3.9.3)
+    rubocop (0.93.1)
       parallel (~> 1.10)
       parser (>= 2.7.1.5)
       rainbow (>= 2.2.2, < 4.0)
-      regexp_parser (>= 1.7)
+      regexp_parser (>= 1.8)
       rexml
-      rubocop-ast (>= 0.5.0)
+      rubocop-ast (>= 0.6.0)
       ruby-progressbar (~> 1.7)
       unicode-display_width (>= 1.4.0, < 2.0)
-    rubocop-ast (0.5.0)
+    rubocop-ast (1.0.1)
       parser (>= 2.7.1.5)
     rubocop-performance (1.8.1)
       rubocop (>= 0.87.0)
@@ -77,11 +124,13 @@ PLATFORMS
   ruby
 
 DEPENDENCIES
+  actionmailer (~> 4.2)
   bundler (~> 2.0)
+  byebug
   cartodb-common!
   rake (~> 13.0)
   rspec (~> 3.0)
-  rubocop (~> 0.92)
+  rubocop
   rubocop-performance
   rubocop-rails
   rubocop-rspec

cartodb-utils.gemspec

@@ -22,10 +22,12 @@ Gem::Specification.new do |spec|
   spec.add_dependency 'activesupport', '~> 4.2.11.3'
   spec.add_dependency 'argon2', '~> 2.0'
 
+  spec.add_development_dependency 'actionmailer', '~> 4.2'
   spec.add_development_dependency "bundler", "~> 2.0"
+  spec.add_development_dependency 'byebug'
   spec.add_development_dependency "rake", "~> 13.0"
   spec.add_development_dependency "rspec", "~> 3.0"
-  spec.add_development_dependency 'rubocop', '~> 0.92'
+  spec.add_development_dependency 'rubocop'
   spec.add_development_dependency 'rubocop-performance'
   spec.add_development_dependency 'rubocop-rails'
   spec.add_development_dependency 'rubocop-rspec'

lib/carto/common/action_mailer_log_subscriber.rb

@@ -0,0 +1,71 @@
+require 'action_mailer/log_subscriber'
+
+##
+# Extends ActionMailer::LogSubscriber to improve JSON logging capabilities
+# Original source: https://github.com/rails/rails/blob/4-2-stable/actionmailer/lib/action_mailer/log_subscriber.rb
+#
+module Carto
+  module Common
+    class ActionMailerLogSubscriber < ActionMailer::LogSubscriber
+
+      # Indicates Rails received a request to send an email.
+      # The original payload of this event contains very little information
+      def process(event)
+        payload = event.payload
+
+        info(
+          message: 'Mail processed',
+          mailer_class: payload[:mailer],
+          mailer_action: payload[:action],
+          duration_ms: event.duration.round(1)
+        )
+      end
+
+      # Indicates Rails tried to send the email. Does not imply user received it,
+      # as an error can still happen while sending it.
+      def deliver(event)
+        payload = event.payload
+
+        info(
+          message: 'Mail sent',
+          mailer_class: payload[:mailer],
+          message_id: payload[:message_id],
+          current_user: current_user(payload),
+          email_subject: payload[:subject],
+          email_to_hint: email_to_hint(payload),
+          email_from: payload[:from],
+          email_date: payload[:date]
+        )
+      end
+
+      private
+
+      def current_user(event_payload)
+        user_klass = defined?(Carto::User) ? Carto::User : User
+        user_klass.find_by(email: event_payload[:to])&.username
+      end
+
+      def email_to_hint(event_payload)
+        email_to = event_payload[:to]
+
+        if email_to.is_a?(Array)
+          email_to.map { |address| email_address_hint(address) }
+        else
+          [email_address_hint(email_to)]
+        end
+      end
+
+      def email_address_hint(address)
+        return unless address.present?
+        if address.exclude?('@') ||
+           address.length < 8 ||
+           address.split('@').select(&:present?).size != 2
+          return '[ADDRESS]'
+        end
+
+        address.split('@').map { |segment| "#{segment[0]}*****#{segment[-1]}" }.join('@')
+      end
+
+    end
+  end
+end

lib/carto/common/logger.rb

@@ -1,4 +1,5 @@
 require_relative 'action_controller_log_subscriber'
+require_relative 'action_mailer_log_subscriber'
 require_relative 'logger_formatter'
 require_relative 'rack_logger_middleware'
 
@@ -29,13 +30,16 @@ def self.remove_existing_log_subscriptions
             unsubscribe(:action_view, subscriber)
           when ActionController::LogSubscriber
             unsubscribe(:action_controller, subscriber)
+          when ActionMailer::LogSubscriber
+            unsubscribe(:action_mailer, subscriber)
           end
         end
       end
       private_class_method :remove_existing_log_subscriptions
 
       def self.attach_custom_log_subscribers
         Carto::Common::ActionControllerLogSubscriber.attach_to(:action_controller)
+        Carto::Common::ActionMailerLogSubscriber.attach_to(:action_mailer)
       end
       private_class_method :attach_custom_log_subscribers
 
@@ -58,4 +62,4 @@ def self.unsubscribe(component, subscriber)
 
     end
   end
-end
+end

spec/carto/common/action_mailer_log_subscriber_spec.rb

@@ -0,0 +1,117 @@
+require 'spec_helper'
+require './lib/carto/common/action_mailer_log_subscriber'
+
+# Mocks CartoDB & Central users as they don't exist in the context of this gem
+class User
+
+  attr_accessor :email, :username
+
+  @users = []
+
+  class << self
+
+    attr_reader :users
+
+  end
+
+  def self.find_by(params = {})
+    @users.select { |user| user.email == params[:email] }.first
+  end
+
+  def initialize(params = {})
+    self.email = params[:email]
+    self.username = params[:username]
+    User.users << self
+  end
+
+end
+
+RSpec.describe 'Carto::Common::ActionMailerLogSubscriber' do
+  subject { Carto::Common::ActionMailerLogSubscriber.new }
+
+  let(:event_name) {}
+  let(:event_payload) { {} }
+  let(:event) { ActiveSupport::Notifications::Event.new(event_name, Time.now, Time.now + 1.second, 1, event_payload) }
+
+  context '#process' do
+    let(:event_name) { 'process.action_mailer' }
+    let(:event_payload) { { mailer: 'DummyMailer', action: 'dummy_mailer_method' } }
+
+    it 'logs email processing' do
+      expect(subject).to receive(:info).with(
+        message: 'Mail processed',
+        mailer_class: 'DummyMailer',
+        mailer_action: 'dummy_mailer_method',
+        duration_ms: 1000.0
+      )
+
+      subject.process(event)
+    end
+  end
+
+  context '#deliver' do
+    let(:user) { User.new(email: 'somebody@example.com') }
+    let(:event_name) { 'deliver.action_mailer' }
+    let(:receiver_addresses) { [user.email] }
+    let(:event_payload) do
+      {
+        mailer: 'DummyMailer',
+        message_id: 1,
+        subject: 'Subject',
+        from: ['foo@bar.com'],
+        to: receiver_addresses
+      }
+    end
+
+    it 'logs email delivery' do
+      expect(subject).to receive(:info).with(
+        message: 'Mail sent',
+        mailer_class: 'DummyMailer',
+        message_id: 1,
+        current_user: user.username,
+        email_subject: 'Subject',
+        email_to_hint: ['s*****y@e*****m'],
+        email_from: ['foo@bar.com'],
+        email_date: nil
+      )
+
+      subject.deliver(event)
+    end
+
+    context 'when several receivers' do
+      let(:receiver_addresses) { ['first@mail.com', 'second@mail.com'] }
+
+      it 'logs all the addresses' do
+        expect(subject).to receive(:info).with(hash_including(email_to_hint: ['f*****t@m*****m', 's*****d@m*****m']))
+        subject.deliver(event)
+      end
+    end
+
+    context 'when receiver address is missing' do
+      let(:receiver_addresses) { nil }
+
+      it 'does not break' do
+        expect(subject).to receive(:info).with(hash_including(email_to_hint: [nil]))
+        subject.deliver(event)
+      end
+    end
+
+    context 'when receiver address is incorrect' do
+      let(:receiver_addresses) { ['@incorrect'] }
+
+      it 'logs a special string' do
+        expect(subject).to receive(:info).with(hash_including(email_to_hint: ['[ADDRESS]']))
+        subject.deliver(event)
+      end
+    end
+
+    context 'when receiver address is very short' do
+      let(:receiver_addresses) { ['a@b.com'] }
+
+      it 'logs a special string' do
+        expect(subject).to receive(:info).with(hash_including(email_to_hint: ['[ADDRESS]']))
+        subject.deliver(event)
+      end
+    end
+  end
+end