Migrate ::Logs model to AR

NEWS.md

@@ -20,6 +20,7 @@ Development
 * Fix export of Google Sheet files larger than 10MB [#15903](https://github.com/CartoDB/cartodb/pull/15903)
 * Adding `builder_url` to `api/v4/me` endpoint [#15904](https://github.com/CartoDB/cartodb/pull/15904)
 * Fix local tests run by parsing database config with ERB [#15901](https://github.com/CartoDB/cartodb/pull/15901)
+* Migrate `Log` model to `ActiveRecord` [#15896](https://github.com/CartoDB/cartodb/pull/15896)
 
 4.42.0 (2020-09-28)
 -------------------

app/models/carto/geocoding.rb

@@ -44,9 +44,9 @@ def remaining_quota
       user.remaining_geocoding_quota
     end
 
-    # TODO: Properly migrate log to AR and remove this
     def log
-      CartoDB::Log[log_id]
+      Carto::Log.find(log_id)
     end
+
   end
 end

app/models/carto/log.rb

@@ -1,72 +1,257 @@
-class Carto::Log < ActiveRecord::Base
+module Carto
+  class Log < ActiveRecord::Base
 
-  has_one :data_import, class_name: Carto::DataImport, foreign_key: :logger
+    include ::LoggerHelper
 
-  MAX_ENTRY_LENGTH = 256
+    has_one :data_import, class_name: Carto::DataImport, foreign_key: :logger
 
-  ENTRY_POSTFIX = "\n"
-  ENTRY_FORMAT = "%s: %s#{ENTRY_POSTFIX}"
+    after_initialize :after_initialize_callback
 
-  TYPE_USER_CREATION = 'user_creation'.freeze
+    MAX_ENTRY_LENGTH = 256
+    MAX_LOG_ENTRIES = 1000
 
-  # INFO: disable ActiveRecord inheritance column
-  self.inheritance_column = :_type
+    ENTRY_POSTFIX = "\n".freeze
 
-  def self.new_user_creation
-    log = Carto::Log.new
-    log.entries = 'New user creation'
-    log.type = TYPE_USER_CREATION
-    log
-  end
+    ENTRY_FORMAT = "%s: %s#{ENTRY_POSTFIX}".freeze
+    ENTRY_REHYDRATED_FORMAT = "%s#{ENTRY_POSTFIX}".freeze
 
-  def append(line, truncate = true, timestamp = Time.now.utc)
-    line.slice!(MAX_ENTRY_LENGTH..-1) if truncate
+    HALF_OF_LOG_MARK = "===LOG HALF===\n".freeze
+    END_OF_LOG_MARK  = '===LOG END==='.freeze
 
-    entry = ENTRY_FORMAT % [ timestamp, line.slice(0..MAX_ENTRY_LENGTH) ]
-    self.entries = "#{self.entries}#{entry}"
-    self.save
-  end
+    TYPE_DATA_IMPORT            = 'import'.freeze
+    TYPE_SYNCHRONIZATION        = 'sync'.freeze
+    TYPE_USER_CREATION          = 'user_creation'.freeze
+    TYPE_GEOCODING              = 'geocoding'.freeze
+    TYPE_USER_MIGRATION_EXPORT  = 'user_migration_export'.freeze
+    TYPE_USER_MIGRATION_IMPORT  = 'user_migration_import'.freeze
+    TYPE_VISUALIZATION_EXPORT   = 'visualization_export'.freeze
 
-  def append_exception(line, exception:, truncate: true, timestamp: Time.now.utc)
-    append("#{line}: #{exception_to_string(exception)}", truncate, timestamp)
-  end
+    SUPPORTED_TYPES = [
+      TYPE_DATA_IMPORT,
+      TYPE_SYNCHRONIZATION,
+      TYPE_USER_CREATION,
+      TYPE_GEOCODING,
+      TYPE_USER_MIGRATION_EXPORT,
+      TYPE_USER_MIGRATION_IMPORT,
+      TYPE_VISUALIZATION_EXPORT
+    ].freeze
 
-  def store
-    self.save
-  end
+    # INFO: disable ActiveRecord inheritance column
+    self.inheritance_column = :_type
 
-  def logger
-    @logger ||= LogWriter.new(self)
-  end
+    def after_initialize_callback
+      if MAX_LOG_ENTRIES < 2 || MAX_LOG_ENTRIES.odd?
+        raise StandardError, 'MAX_LOG_ENTRIES must be greater than 2 and an even number'
+      end
 
-  private
+      @dirty = true if new_record?
 
-  def exception_to_string(error)
-    error.inspect + "\n" + error.backtrace.join("\n") + "\n"
-  end
+      clear_entries
+      rehydrate_entries_from_string(entries)
+    end
 
-  # A logger implementation that logs to this Carto::Log
-  class LogWriter < ::Logger
-    SAVE_BLOCK = 10 # Save the changes to DB every X lines
+    def logger
+      @logger ||= LogWriter.new(self)
+    end
 
-    def initialize(log)
-      @log = log
-      @stored_entries = 0
+    def self.new_visualization_export
+      Carto::Log.new(
+        type: TYPE_VISUALIZATION_EXPORT
+      )
     end
 
-    def add(_severity, _progname = nil, message = nil)
-      if message.present?
-        @log.entries += message.to_s + "\n"
-        @stored_entries += 1
-        if @stored_entries >= SAVE_BLOCK
-          @stored_entries = 0
-          @log.save
+    def self.new_user_creation
+      Carto::Log.new(
+        entries: 'New user creation',
+        type: TYPE_USER_CREATION
+      )
+    end
+
+    def self.new_user_migration_export
+      Carto::Log.new(
+        type: TYPE_USER_MIGRATION_EXPORT
+      )
+    end
+
+    def self.new_user_migration_import
+      Carto::Log.new(
+        type: TYPE_USER_MIGRATION_IMPORT
+      )
+    end
+
+    def self.new_data_import(user_id = nil)
+      Carto::Log.new(
+        type: TYPE_DATA_IMPORT,
+        user_id: user_id
+      )
+    end
+
+    def self.new_synchronization(user_id = nil)
+      Carto::Log.new(
+        type: TYPE_SYNCHRONIZATION,
+        user_id: user_id
+      )
+    end
+
+    def self.new_geocoding(user_id = nil)
+      Carto::Log.new(
+        type: TYPE_GEOCODING,
+        user_id: user_id
+      )
+    end
+
+    def collect_entries
+      (@fixed_entries_half + ordered_circular_entries_half).join('')
+    end
+
+    def append(content, truncate = true, timestamp = Time.now.utc)
+      @dirty = true
+      content.slice!(MAX_ENTRY_LENGTH..-1) if truncate
+      add_to_entries(format(ENTRY_FORMAT, timestamp, content))
+    end
+
+    def append_and_store(content, truncate = true, timestamp = Time.now.utc)
+      reload
+      # Sync content from other processes. Ie. geocoding cancel
+      rehydrate_entries_from_string(entries)
+      append(content, truncate, timestamp)
+      store
+    end
+
+    def append_exception(line, exception:, truncate: true, timestamp: Time.now.utc)
+      append("#{line}: #{exception_to_string(exception)}", truncate, timestamp)
+    end
+
+    def clear
+      @dirty = true
+    end
+
+    def store
+      if @dirty
+        self.entries = collect_entries
+        save
+        @dirty = false
+      end
+    rescue StandardError => e
+      log_error(message: 'Error appending log, likely an encoding issue', exception: e, log_id: id)
+      begin
+        fix_entries_encoding
+        save
+      rescue StandardError => e
+        log_error(message: 'Error saving fallback log info.', exception: e, log_id: id)
+        begin
+          self.entries = "Previous log entries stripped because of an error, check Rollbar. Id: #{id}\n" +
+                         END_OF_LOG_MARK
+          save
+        rescue StandardError => e
+          log_error(message: 'Error saving stripped fallback log info.', exception: e, log_id: id)
         end
       end
     end
 
-    def close
-      @log.save
+    def to_s
+      # Just as a safeguard, no real store will be done if there's no data to flush
+      store
+
+      list = @fixed_entries_half
+      circular_half = ordered_circular_entries_half
+      list += [HALF_OF_LOG_MARK] if circular_half.any?
+      (list + circular_half + [END_OF_LOG_MARK]).join('')
     end
+
+    private
+
+    def add_to_entries(content)
+      if @fixed_entries_half.length < half_max_size
+        @fixed_entries_half << content
+      else
+        @circular_entries_half[@circular_index] = content
+        @circular_index = (@circular_index + 1) % half_max_size
+      end
+    end
+
+    def ordered_circular_entries_half
+      (@circular_entries_half[@circular_index..-1] + @circular_entries_half[0...@circular_index]).compact
+    end
+
+    def rehydrate_entries_from_string(source)
+      existing_entries = source.nil? ? [] : source.split(ENTRY_POSTFIX.to_s)
+
+      # If rehydrated data, assume nothing changed yet
+      @dirty = false if existing_entries.any?
+
+      @fixed_entries_half = existing_entries.slice!(0, half_max_size)
+                                            .map { |entry| format(ENTRY_REHYDRATED_FORMAT, entry) }
+      @fixed_entries_half = [] if @fixed_entries_half.nil? # Log was empty
+
+      return if existing_entries.empty?
+
+      index = existing_entries.length > half_max_size ? -half_max_size : -existing_entries.length
+      @circular_entries_half = existing_entries.slice(index, half_max_size)
+                                               .map { |entry| format(ENTRY_REHYDRATED_FORMAT, entry) }
+      # Fill circular part
+      if @circular_entries_half.length < half_max_size
+        @circular_index = @circular_entries_half.length
+        @circular_entries_half += Array.new(half_max_size - @circular_entries_half.length)
+      else
+        @circular_index = 0
+      end
+    end
+
+    def clear_entries
+      @fixed_entries_half = []
+      @circular_entries_half = Array.new(half_max_size)
+      @circular_index = 0
+      ''
+    end
+
+    def exception_to_string(error)
+      "#{error.inspect}\n#{error.backtrace.join("\n")}\n"
+    end
+
+    def half_max_size
+      MAX_LOG_ENTRIES / 2
+    end
+
+    def fix_entries_encoding
+      @fixed_entries_half = @fixed_entries_half.map do |entry|
+        entry&.encode('UTF-8', 'binary', invalid: :replace, undef: :replace, replace: '?????')
+      end
+      @circular_entries_half = @circular_entries_half.map do |entry|
+        entry&.encode('UTF-8', 'binary', invalid: :replace, undef: :replace, replace: '?????')
+      end
+      @dirty = true
+
+      self.entries = collect_entries
+    end
+
+    # A logger implementation that logs to this Carto::Log
+    class LogWriter < ::Logger
+
+      SAVE_BLOCK = 100 # Save the changes to DB every X lines
+
+      def initialize(log)
+        @log = log
+        @stored_entries = 0
+      end
+
+      def add(_severity, _progname = nil, message = nil)
+        return unless message.present?
+
+        @log.append(message.to_s)
+        @stored_entries += 1
+
+        return unless @stored_entries >= SAVE_BLOCK
+
+        @stored_entries = 0
+        @log.store
+      end
+
+      def close
+        @log.store
+      end
+
+    end
+
   end
 end

app/models/carto/user_creation.rb

@@ -204,7 +204,7 @@ def log_transition_end
   end
 
   def log_transition(prefix)
-    self.log.append("#{prefix}: State: #{self.state}")
+    log.append("#{prefix}: State: #{state}")
   end
 
   def initialize_user

app/models/carto/user_migration_export.rb

@@ -145,7 +145,9 @@ def validate_export_data
     end
 
     def set_defaults
-      self.log = Carto::Log.create(type: 'user_migration_export') unless log
+      self.log ||= Carto::Log.new_user_migration_export
+      log.save
+
       self.state = STATE_PENDING unless state
       save
     end

app/models/carto/user_migration_import.rb

@@ -219,7 +219,8 @@ def import_job_arguments(data_dir)
     end
 
     def set_defaults
-      self.log = Carto::Log.create(type: 'user_migration_import') unless log
+      self.log = Carto::Log.new_user_migration_import unless log
+      log.save
       self.state = STATE_PENDING unless state
       save
     end

app/models/carto/visualization_export.rb

@@ -30,7 +30,7 @@ def exporter_folder
     end
 
     def run_export!(file_upload_helper: default_file_upload_helper, download_path: nil)
-      logger = Carto::Log.new(type: 'visualization_export')
+      logger = Carto::Log.new_visualization_export
 
       logger.append('Exporting')
       update_attributes(state: STATE_EXPORTING, log: logger)