1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
require "fileutils"
require "logger"
require "pathname"
require "rack"

module ProTacts
  # Rack middleware that dumps the full request and response exchange to a
  # Logger: method, path, every header, and the full body on both sides.
  # Every line is prefixed ">>" (request) or "<<" (response) so multi-line
  # XML/vCard bodies stay readable.
  #
  # Off by default because it logs contact data. The only card right now is
  # fictional, so the debug path stays verbose while the normal one-line path
  # (Roda's common_logger) can be narrowed later without losing this.
  class DebugLogger
    # @rbs @app: Rack::_App
    # @rbs @logger: Logger

    # Builds the Logger the middleware writes to: appended and unbuffered
    # (Logger syncs its own device), one timestamped line per dump. path
    # "stderr" writes to the process's stderr.
    #: (String | Pathname path) -> Logger
    def self.open_log(path)
      target = if path.to_s == "stderr"
                 $stderr
               else
                 FileUtils.mkdir_p(Pathname.new(path).dirname)
                 path.to_s
               end

      Logger.new(target).tap do |logger|
        logger.level = :debug
        logger.formatter = proc do |_severity, datetime, _progname, msg|
          "#{datetime.strftime('%Y-%m-%dT%H:%M:%S.%3N')} #{msg}\n"
        end
      end
    end

    #: (Rack::_App app, logger: Logger) -> void
    def initialize(app, logger:)
      @app = app
      @logger = logger
    end

    #: (Rack::env env) -> Rack::response
    def call(env)
      log_request(env)
      status, headers, body = @app.call(env)
      parts = log_response(status, headers, body)
      [status, headers, parts]
    end

    private

    #: (Rack::env env) -> void
    def log_request(env)
      write(">>", "#{env.fetch('REQUEST_METHOD')} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL')}")
      each_header(env) do |name, value|
        write(">>", "#{name}: #{value}")
      end
      body = read_request_body(env)
      write(">>", body) unless body.empty?
    end

    # Returns the body parts it consumed, for the caller to send on in
    # place of the body it read.
    #: (Integer status, Rack::headers headers, Rack::_Body body) -> Array[String]
    def log_response(status, headers, body)
      write("<<", "#{status}#{reason(status)}")
      headers.each do |name, value|
        write("<<", "#{name}: #{value}")
      end
      parts = [] #: Array[String]
      body.each do |part|
        parts << part
      end
      # A body holding a resource closes it. No signature can say
      # "close if you have one", so the cast carries what respond_to?
      # has already established.
      (_ = body).close if body.respond_to?(:close)
      write("<<", parts.join) unless parts.join.empty?
      parts
    end

    #: (Rack::env env) -> String
    def full_path(env)
      path = env["PATH_INFO"].to_s
      query = env["QUERY_STRING"].to_s
      query.empty? ? path : "#{path}?#{query}"
    end

    #: (Rack::env env) { (String, untyped) -> void } -> void
    def each_header(env)
      env.each do |key, value|
        case key
        when /\AHTTP_(.+)\z/
          yield header_name(key.delete_prefix("HTTP_")), value
        when "CONTENT_TYPE"
          yield "Content-Type", value
        when "CONTENT_LENGTH"
          yield "Content-Length", value
        end
      end
    end

    #: (String name) -> String
    def header_name(name)
      name.split("_").map(&:capitalize).join("-")
    end

    #: (Rack::env env) -> String
    def read_request_body(env)
      input = env["rack.input"]
      return "" if input.nil?
      body = input.read
      input.rewind
      body
    end

    #: (Integer status) -> String
    def reason(status)
      phrase = Rack::Utils::HTTP_STATUS_CODES[status]
      phrase ? " #{phrase}" : ""
    end

    #: (String prefix, String text) -> void
    def write(prefix, text)
      text.to_s.lines(chomp: true).each do |line|
        @logger.debug("#{prefix} #{line}")
      end
    end
  end
end