module CartoDB # Motivation: Logs usually are quite small, but in some scenarios, or due to encoding errors, parsing errors, etc. # they can grow and even end with 1 line per source row. Thus the need of having a log that hits as less as possible # the DB, and that stores critical parts of the log events; this is, the beggining (data recognized, etc.) and the end # (how it ended, and last 'errored rows' if present). The middle area is not important and for small logs will still # be included class Log < Sequel::Model MAX_ENTRY_LENGTH = 256 MAX_LOG_ENTRIES = 1000 ENTRY_POSTFIX = "\n" ENTRY_FORMAT = "%s: %s#{ENTRY_POSTFIX}" ENTRY_REHYDRATED_FORMAT = "%s#{ENTRY_POSTFIX}" HALF_OF_LOG_MARK = "===LOG HALF===\n".freeze END_OF_LOG_MARK = '===LOG END==='.freeze TYPE_DATA_IMPORT = 'import'.freeze TYPE_SYNCHRONIZATION = 'sync'.freeze TYPE_USER_CREATION = 'user_creation'.freeze TYPE_GEOCODING = 'geocoding'.freeze SUPPORTED_TYPES = [ TYPE_DATA_IMPORT, TYPE_SYNCHRONIZATION, TYPE_USER_CREATION, TYPE_GEOCODING ] # @param id Numeric # @param type String # @param user_id String (uuid) # @param created_at DateTime # @param updated_at DateTime # @param entries String def after_initialize super if (MAX_LOG_ENTRIES < 2 || MAX_LOG_ENTRIES % 2 != 0) raise StandardError.new('MAX_LOG_ENTRIES must be greater than 2 and an even number') end @dirty = true if new? clear_entries # Reset internal lists rehydrate_entries_from_string(self.entries) # And now load if proceeds end def clear @dirty = true end def to_s # Just as a safeguard, no real store will be done if there's no data to flush # TODO: Check all usages of Log to see if could be removed store # Extra decoration only for string presentation list = @fixed_entries_half circular_half = ordered_circular_entries_half if circular_half.length > 0 list = list + [HALF_OF_LOG_MARK] end list = (list + circular_half + [END_OF_LOG_MARK]).join('') end def store if @dirty self.entries = collect_entries save @dirty = false end rescue => e CartoDB.notify_error("Error appending log, likely an encoding issue", { error_info: "id: #{id}. #{self.inspect} --------- #{e.backtrace.join}" }) begin fix_entries_encoding self.save rescue => e2 CartoDB.notify_exception(e2, { message: "Error saving fallback log info.", error_info: "id: #{id}" }) begin self.entries = "Previous log entries stripped because of an error, check Rollbar. Id: #{id}\n" + END_OF_LOG_MARK self.save rescue => e3 CartoDB.notify_exception(e3, { message: "Error saving stripped fallback log info.", error_info: "id: #{id}" }) end end end # INFO: Does not store log, only appends in-memory def append(content, truncate = true, timestamp = Time.now.utc) @dirty = true content.slice!(MAX_ENTRY_LENGTH..-1) if truncate add_to_entries(ENTRY_FORMAT % [ timestamp, content ]) end def append_and_store(content, truncate = true, timestamp = Time.now.utc) refresh # Sync content from other processes. Ie. geocoding cancel rehydrate_entries_from_string(entries) append(content, truncate, timestamp) store 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 clear_entries @fixed_entries_half = [] @circular_entries_half = Array.new(half_max_size) @circular_index = 0 '' end def rehydrate_entries_from_string(source) existing_entries = source.nil? ? [] : source.split("#{ENTRY_POSTFIX}") # If rehydrated data, assume nothing changed yet @dirty = false if existing_entries.length > 0 @fixed_entries_half = existing_entries.slice!(0, half_max_size) .map { |entry| ENTRY_REHYDRATED_FORMAT % [entry] } @fixed_entries_half = [] if @fixed_entries_half.nil? # Log was empty if (existing_entries.length > 0) 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| ENTRY_REHYDRATED_FORMAT % [entry] } # Fill circular part if @circular_entries_half.length < half_max_size @circular_index = @circular_entries_half.length @circular_entries_half = @circular_entries_half + Array.new(half_max_size - @circular_entries_half.length) else @circular_index = 0 end end end def ordered_circular_entries_half # Reorder circular buffer: entries 0 to @circular_index-1 have been more recently overwritten (@circular_entries_half[@circular_index..-1] + @circular_entries_half[0...@circular_index]).compact end def collect_entries (@fixed_entries_half + ordered_circular_entries_half).join('') end # INFO: To ease testing def half_max_size @half_max_entries_size ||= MAX_LOG_ENTRIES / 2 end def fix_entries_encoding @fixed_entries_half = @fixed_entries_half.map { |entry| entry.encode('UTF-8', 'binary', invalid: :replace, undef: :replace, replace: '?????') unless entry.nil? } @circular_entries_half = @circular_entries_half.map { |entry| entry.encode('UTF-8', 'binary', invalid: :replace, undef: :replace, replace: '?????') unless entry.nil? } @dirty = true self.entries = collect_entries end def validate super errors.add(:type, 'unsupported type') unless SUPPORTED_TYPES.include?(self.type) end def before_save super self.updated_at = Time.now end end end