clogger.git  about / heads / tags
configurable request logging for Rack
blob 156f11e364c5e7822162990d8c541b19be4168d8 5355 bytes (raw)
$ git show HEAD:lib/clogger/pure.rb	# shows this blob on the CLI

  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
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
 
# -*- encoding: binary -*-
# :stopdoc:

# Not at all optimized for performance, this was written based on
# the original C extension code so it's not very Ruby-ish...
class Clogger

  attr_accessor :env, :status, :headers, :body
  attr_writer :body_bytes_sent, :start

  RackHeaders = if Object.const_defined?("Rack::Headers")
    # Rack >= 3.0
    Rack::Headers
  else
    # Rack < 3.0
    Rack::Utils::HeaderHash
  end

  def initialize(app, opts = {})
    @app = app
    @logger = opts[:logger]
    path = opts[:path]
    path && @logger and
      raise ArgumentError, ":logger and :path are independent"
    path and @logger = File.open(path, "ab")

    @logger.sync = true if @logger.respond_to?(:sync=)
    @fmt_ops = compile_format(opts[:format] || Format::Common, opts)
    @wrap_body = need_wrap_body?(@fmt_ops)
    @reentrant = opts[:reentrant]
    @need_resp = need_response_headers?(@fmt_ops)
    @body_bytes_sent = 0
  end

  def call(env)
    start = mono_now
    resp = @app.call(env)
    unless resp.instance_of?(Array) && resp.size == 3
      log(env, 500, {}, start)
      raise TypeError, "app response not a 3 element Array: #{resp.inspect}"
    end
    status, headers, body = resp
    headers = RackHeaders[headers] if @need_resp
    if @wrap_body
      @reentrant = env['rack.multithread'] if @reentrant.nil?
      wbody = @reentrant ? self.dup : self
      wbody.start = start
      wbody.env = env
      wbody.status = status
      wbody.headers = headers
      wbody.body = body
      return [ status, headers, wbody ]
    end
    log(env, status, headers, start)
    [ status, headers, body ]
  end

  def each
    @body_bytes_sent = 0
    @body.each do |part|
      @body_bytes_sent += part.bytesize
      yield part
    end
    self
  end

  def close
    @body.close if @body.respond_to?(:close)
  ensure
    log(@env, @status, @headers)
  end

  def reentrant?
    @reentrant
  end

  def wrap_body?
    @wrap_body
  end

  def fileno
    @logger.respond_to?(:fileno) ? @logger.fileno : nil
  end

  def respond_to?(method, include_all=false)
    :close == method.to_sym || @body.respond_to?(method, include_all)
  end

  def to_path
    rv = @body.to_path
    @body_bytes_sent = File.size(rv)
    rv
  end

private

  def byte_xs(s)
    s = s.dup
    if s.is_a?(Array)
      s = s.join("\n")
    end
    s.force_encoding(Encoding::BINARY) if defined?(Encoding::BINARY)
    s.gsub!(/(['"\x00-\x1f\x7f-\xff])/) do |x|
      "\\x#{$1.unpack('H2').first.upcase}"
    end
    s
  end

  SPECIAL_RMAP = SPECIAL_VARS.inject([]) { |ary, (k,v)| ary[v] = k; ary }

  def request_uri(env)
    ru = env['REQUEST_URI'] and return byte_xs(ru)
    qs = env['QUERY_STRING']
    qs.empty? or qs = "?#{byte_xs(qs)}"
    "#{byte_xs(env['PATH_INFO'])}#{qs}"
  end

  def special_var(special_nr, env, status, headers)
    case SPECIAL_RMAP[special_nr]
    when :body_bytes_sent
      @body_bytes_sent.to_s
    when :status
      status = status.to_i
      status >= 100 && status <= 999 ? ('%03d' % status) : '-'
    when :request
      version = env['HTTP_VERSION'] and version = " #{byte_xs(version)}"
      qs = env['QUERY_STRING']
      qs.empty? or qs = "?#{byte_xs(qs)}"
      "#{byte_xs(env['REQUEST_METHOD'] || '')} #{request_uri(env)}#{version}"
    when :request_uri
      request_uri(env)
    when :request_length
      env['rack.input'].size.to_s
    when :response_length
      @body_bytes_sent == 0 ? '-' : @body_bytes_sent.to_s
    when :ip
      xff = env['HTTP_X_FORWARDED_FOR'] and return byte_xs(xff)
      env['REMOTE_ADDR'] || '-'
    when :pid
      $$.to_s
    when :time_iso8601
      Time.now.iso8601
    when :time_local
      # %b in Ruby is locale-independent, unlike strftime(3) in C
      Time.now.strftime('%d/%b/%Y:%H:%M:%S %z')
    when :time_utc
      Time.now.utc.strftime('%d/%b/%Y:%H:%M:%S %z')
    else
      raise "EDOOFUS #{special_nr}"
    end
  end

  def time_format(sec, usec, format, div)
    format % [ sec, usec / div ]
  end

  def log(env, status, headers, start = @start)
    str = @fmt_ops.map { |op|
      case op[0]
      when OP_LITERAL; op[1]
      when OP_REQUEST; byte_xs(env[op[1]] || "-")
      when OP_RESPONSE; byte_xs(headers[op[1]] || "-")
      when OP_SPECIAL; special_var(op[1], env, status, headers)
      when OP_EVAL; eval(op[1]).to_s rescue "-"
      when OP_TIME_LOCAL; Time.now.strftime(op[1])
      when OP_TIME_UTC; Time.now.utc.strftime(op[1])
      when OP_REQUEST_TIME
        t = mono_now - start
        t = t * (10 ** op[3])
        time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
      when OP_TIME
        t = Time.now
        time_format(t.to_i, t.usec, op[1], op[2])
      when OP_COOKIE
        (byte_xs(env['rack.request.cookie_hash'][op[1]]) rescue "-") || "-"
      else
        raise "EDOOFUS #{op.inspect}"
      end
    }.join('')

    l = @logger
    if l
      l << str
    else
      env['rack.errors'].write(str)
    end
    nil
  end

  # favor monotonic clock if possible, and try to use clock_gettime in
  # more recent Rubies since it generates less garbage
  if defined?(Process::CLOCK_MONOTONIC)
    def mono_now; Process.clock_gettime(Process::CLOCK_MONOTONIC); end
  elsif defined?(Process::CLOCK_REALTIME)
    def mono_now; Process.clock_gettime(Process::CLOCK_REALTIME); end
  else
    def mono_now; Time.now.to_f; end
  end
end

git clone https://yhbt.net/clogger.git