Log4r Formatters

human.rb

# frozen_string_literal: true

require "log4r"

require "pakyow/connection"
require "pakyow/error"

require "pakyow/logger/colorizer"
require "pakyow/logger/timekeeper"

require "pakyow/connection/statuses"

module Pakyow
  class Logger
    module Formatters
      # Formats log messages for humans.
      #
      # @example
      #   19.00μs http.c730cb72 | GET / (for 127.0.0.1 at 2016-06-20 10:00:49 -0500)
      #    1.97ms http.c730cb72 | hello 2016-06-20 10:00:49 -0500
      #    3.78ms http.c730cb72 | 200 (OK)
      #
      # @api private
      class Human < Log4r::Formatter
        def format(event)
          entry = String.new

          case event.data
          when Hash
            if event.data.key?(:logger) && event.data.key?(:message)
              format_logger_message(event.data, entry)
            else
              entry << event.data.to_s
            end
          else
            entry << event.data.to_s
          end

          Colorizer.colorize(entry, event.level) << "\n"
        end

        private

        def format_logger_message(logger_message, entry)
          logger, message = logger_message.values_at(:logger, :message)

          format_info(entry, id: logger.id, type: logger.type, elapsed: logger.elapsed)

          case message
          when Hash
            if connection = message[:prologue]
              format_prologue(connection, entry)
            elsif connection = message[:epilogue]
              format_epilogue(connection, entry)
            elsif error = message[:error]
              format_error(error, entry)
            else
              format_message(message, entry)
            end
          when Exception
            format_error(message, entry)
          else
            format_message(message, entry)
          end
        end

        def format_prologue(connection, entry)
          entry << connection.request_method << " " << connection.path
          entry << " (for " << connection.ip << " at " << connection.timestamp.to_s << ")"
        end

        def format_epilogue(connection, entry)
          entry << connection.status.to_s << " (" << Connection::Statuses.describe(connection.status) << ")"
        end

        def format_info(entry, id:, type:, elapsed:)
          entry << Timekeeper.format_elapsed_time(elapsed).rjust(8, " ")
          entry << " " << type.to_s << "." << id << " | "
        end

        def format_message(message, entry)
          message.to_s.each_line.with_index do |line, i|
            if i == 0
              entry << line.rstrip
            else
              entry << "\n                       | " << line.rstrip
            end
          end
        end

        def format_error(error, entry)
          unless error.is_a?(Error)
            error = Error.build(error)
          end

          format_message(Error::CLIFormatter.new(error), entry)
        end
      end
    end
  end
end

json.rb

# frozen_string_literal: true

require "json"
require "log4r"

require "pakyow/logger"
require "pakyow/logger/timekeeper"

module Pakyow
  class Logger
    module Formatters
      # Formats log messages as json.
      #
      # @example
      #   {"severity":"info","timestamp":"2016-06-20 10:07:30 -0500","id":"c8af6a8b","type":"http","elapsed":"0.01ms","method":"GET","path":"/","ip":"127.0.0.1"}
      #   {"severity":"info","timestamp":"2016-06-20 10:07:30 -0500","id":"c8af6a8b","type":"http","elapsed":"1.24ms","message":"hello 2016-06-20 10:07:30 -0500"}
      #   {"severity":"info","timestamp":"2016-06-20 10:07:30 -0500","id":"c8af6a8b","type":"http","elapsed":"3.08ms","status":200}
      #
      # @api private
      class JSON < Log4r::Formatter
        def format(event)
          entry = {
            severity: Logger::NICE_LEVELS[event.level],
            timestamp: Time.now
          }

          case event.data
          when Hash
            if event.data.key?(:logger) && event.data.key?(:message)
              format_logger_message(event.data, entry)
            else
              entry.merge!(event.data)
            end
          else
            entry[:message] = event.data.to_s
          end

          serialize(entry)
        end

        private

        def format_logger_message(logger_message, entry)
          logger, message = logger_message.values_at(:logger, :message)

          format_entry(
            entry, id: logger.id, type: logger.type, elapsed: logger.elapsed
          )

          case message
          when Hash
            if connection = message.delete(:prologue)
              format_prologue(connection, entry)
            elsif connection = message.delete(:epilogue)
              format_epilogue(connection, entry)
            elsif error = message.delete(:error)
              format_error(error, entry)
            else
              entry.update(message)
            end
          else
            entry[:message] = message.to_s
          end

          serialize(
            entry
          )
        end

        def format_prologue(connection, entry)
          entry[:method] = connection.request_method
          entry[:uri] = connection.path
          entry[:ip] = connection.ip
        end

        def format_epilogue(connection, entry)
          entry[:status] = connection.status
        end

        def format_error(error, entry)
          entry[:exception] = error.class
          entry[:message] = error.to_s
          entry[:backtrace] = error.backtrace
        end

        def format_entry(entry, id:, type:, elapsed:)
          entry[:id] = id
          entry[:type] = type
          entry[:elapsed] = Timekeeper.format_elapsed_time_in_milliseconds(elapsed)
          entry
        end

        def serialize(entry)
          entry.to_json << "\n"
        end
      end
    end
  end
end

logfmt.rb

# frozen_string_literal: true

require "pakyow/logger/formatters/json"

module Pakyow
  class Logger
    module Formatters
      # Formats log messages as logfmt.
      #
      # @example
      #   severity=INFO timestamp="2016-06-20 10:08:29 -0500" id=678cf582 type=http elapsed=0.01ms method=GET uri=/ ip=127.0.0.1
      #   severity=INFO timestamp="2016-06-20 10:08:29 -0500" id=678cf582 type=http elapsed=1.56ms message="hello 2016-06-20 10:08:29 -0500"
      #   severity=INFO timestamp="2016-06-20 10:08:29 -0500" id=678cf582 type=http elapsed=3.37ms status=200
      #
      # @api private
      class Logfmt < Pakyow::Logger::Formatters::JSON
        private

        UNESCAPED_STRING = /\A[\w\.\-\+\%\,\:\;\/]*\z/i

        def serialize(message)
          escape(message).each_with_object(String.new) { |(key, value), buffer|
            buffer << "#{key}=#{value} "
          }.rstrip << "\n"
        end

        # From polyfox/moon-logfmt.
        #
        def escape(message)
          return enum_for(:escape, message) unless block_given?

          message.each_pair do |key, value|
            value = case value
            when Array
              value.join(",")
            else
              value.to_s
            end

            unless value =~ UNESCAPED_STRING
              value = value.dump
            end

            yield key.to_s, value
          end
        end
      end
    end
  end
end

logger.rb

# frozen_string_literal: true

require "log4r"
require "securerandom"

module Pakyow
  # Logs messages throughout the lifetime of an environment, connection, etc.
  #
  # In addition to logging standard messages, this class provides a way to log a `prologue` and
  # `epilogue` for a connection, as well as a `houston` method for logging errors.
  #
  class Logger
    LEVELS = %i(
      all
      verbose
      debug
      info
      warn
      error
      fatal
      unknown
      off
    ).freeze

    LOGGED_LEVELS = LEVELS.dup
    LOGGED_LEVELS.delete(:all)
    LOGGED_LEVELS.delete(:off)
    LOGGED_LEVELS.freeze

    NICE_LEVELS = Hash[LEVELS.map.with_index { |level, i|
      [i + 1, level]
    }].freeze

    require "pakyow/logger/colorizer"
    require "pakyow/logger/timekeeper"

    # @!attribute [r] id
    #   @return [String] the unique id of the logger instance
    attr_reader :id

    # @!attribute [r] started_at
    #   @return [Time] the time when logging started
    attr_reader :started_at

    # @!attribute [r] type
    #   @return [Symbol] the type of logger
    attr_reader :type

    # @!attribute [r] level
    #   @return [Integer] the current log level
    attr_reader :level

    # @!attribute [r] output
    #   @return [Symbol] where log entries are written
    attr_reader :output

    # @param type [Symbol] the type of logging being done (e.g. :http, :sock)
    # @param started_at [Time] when the logging began
    # @param output [Object] the object that will perform the logging
    # @param id [String] a unique id used to identify the request
    def initialize(type, started_at: Time.now, output: Pakyow.global_logger, id: SecureRandom.hex(4), level: output.level)
      @type, @started_at, @output, @id, @level = type, started_at, output, id

      @level = case level
      when Integer
        level
      else
        NICE_LEVELS.key(level)
      end
    end

    # Temporarily silences logs, up to +temporary_level+.
    #
    def silence(temporary_level = :error)
      original_level = @level
      @level = NICE_LEVELS.key(temporary_level)
      yield
    ensure
      @level = original_level
    end

    LOGGED_LEVELS.each do |method|
      class_eval <<~CODE, __FILE__, __LINE__ + 1
        def #{method}(message = nil, &block)
          if log?(#{NICE_LEVELS.key(method)})
            @output.#{method} { decorate(message, &block) }
          end
        end
      CODE
    end

    def <<(message)
      if log?(8)
        add(:unknown, message)
      end
    end

    def add(level, message = nil, &block)
      if log?(NICE_LEVELS.key(level))
        @output.public_send(level) { decorate(message, &block) }
      end
    end
    alias log add

    # Logs the beginning of a request, including the time, request method,
    # request uri, and originating ip address.
    #
    # @param env [Hash] the rack env for the request
    #
    def prologue(connection)
      info { formatted_prologue(connection) }
    end

    # Logs the conclusion of a request, including the response status.
    #
    # @param res [Array] the rack response array
    #
    def epilogue(connection)
      info { formatted_epilogue(connection) }
    end

    # Logs an error raised when processing the request.
    #
    # @param error [Object] the error object
    #
    def houston(error)
      error { formatted_error(error) }
    end

    def elapsed
      (Time.now - @started_at)
    end

    private

    def log?(level)
      level >= @level
    end

    def decorate(message = nil)
      message = yield if block_given?
      { logger: self, message: message }
    end

    def formatted_prologue(connection)
      { prologue: connection }
    end

    def formatted_epilogue(connection)
      { epilogue: connection }
    end

    def formatted_error(error)
      { error: error }
    end
  end
end