lib/clogger/pure.rb

   1 # -*- encoding: binary -*-
   2 # :stopdoc:
   3
   4 # Not at all optimized for performance, this was written based on
   5 # the original C extension code so it's not very Ruby-ish...
   6 class Clogger
   7
   8   attr_accessor :env, :status, :headers, :body
   9   attr_writer :body_bytes_sent, :start
  10
  11   RackHeaders = if Object.const_defined?("Rack::Headers")
  12     # Rack >= 3.0
  13     Rack::Headers
  14   else
  15     # Rack < 3.0
  16     Rack::Utils::HeaderHash
  17   end
  18
  19   def initialize(app, opts = {})
  20     @app = app
  21     @logger = opts[:logger]
  22     path = opts[:path]
  23     path && @logger and
  24       raise ArgumentError, ":logger and :path are independent"
  25     path and @logger = File.open(path, "ab")
  26
  27     @logger.sync = true if @logger.respond_to?(:sync=)
  28     @fmt_ops = compile_format(opts[:format] || Format::Common, opts)
  29     @wrap_body = need_wrap_body?(@fmt_ops)
  30     @reentrant = opts[:reentrant]
  31     @need_resp = need_response_headers?(@fmt_ops)
  32     @body_bytes_sent = 0
  33   end
  34
  35   def call(env)
  36     start = mono_now
  37     resp = @app.call(env)
  38     unless resp.instance_of?(Array) && resp.size == 3
  39       log(env, 500, {}, start)
  40       raise TypeError, "app response not a 3 element Array: #{resp.inspect}"
  41     end
  42     status, headers, body = resp
  43     headers = RackHeaders[headers] if @need_resp
  44     if @wrap_body
  45       @reentrant = env['rack.multithread'] if @reentrant.nil?
  46       wbody = @reentrant ? self.dup : self
  47       wbody.start = start
  48       wbody.env = env
  49       wbody.status = status
  50       wbody.headers = headers
  51       wbody.body = body
  52       return [ status, headers, wbody ]
  53     end
  54     log(env, status, headers, start)
  55     [ status, headers, body ]
  56   end
  57
  58   def each
  59     @body_bytes_sent = 0
  60     @body.each do |part|
  61       @body_bytes_sent += part.bytesize
  62       yield part
  63     end
  64     self
  65   end
  66
  67   def close
  68     @body.close if @body.respond_to?(:close)
  69   ensure
  70     log(@env, @status, @headers)
  71   end
  72
  73   def reentrant?
  74     @reentrant
  75   end
  76
  77   def wrap_body?
  78     @wrap_body
  79   end
  80
  81   def fileno
  82     @logger.respond_to?(:fileno) ? @logger.fileno : nil
  83   end
  84
  85   def respond_to?(method, include_all=false)
  86     :close == method.to_sym || @body.respond_to?(method, include_all)
  87   end
  88
  89   def to_path
  90     rv = @body.to_path
  91     @body_bytes_sent = File.size(rv)
  92     rv
  93   end
  94
  95 private
  96
  97   def byte_xs(s)
  98     s = s.dup
  99     if s.is_a?(Array)
 100       s = s.join("\n")
 101     end
 102     s.force_encoding(Encoding::BINARY) if defined?(Encoding::BINARY)
 103     s.gsub!(/(['"\x00-\x1f\x7f-\xff])/) do |x|
 104       "\\x#{$1.unpack('H2').first.upcase}"
 105     end
 106     s
 107   end
 108
 109   SPECIAL_RMAP = SPECIAL_VARS.inject([]) { |ary, (k,v)| ary[v] = k; ary }
 110
 111   def request_uri(env)
 112     ru = env['REQUEST_URI'] and return byte_xs(ru)
 113     qs = env['QUERY_STRING']
 114     qs.empty? or qs = "?#{byte_xs(qs)}"
 115     "#{byte_xs(env['PATH_INFO'])}#{qs}"
 116   end
 117
 118   def special_var(special_nr, env, status, headers)
 119     case SPECIAL_RMAP[special_nr]
 120     when :body_bytes_sent
 121       @body_bytes_sent.to_s
 122     when :status
 123       status = status.to_i
 124       status >= 100 && status <= 999 ? ('%03d' % status) : '-'
 125     when :request
 126       version = env['HTTP_VERSION'] and version = " #{byte_xs(version)}"
 127       qs = env['QUERY_STRING']
 128       qs.empty? or qs = "?#{byte_xs(qs)}"
 129       "#{byte_xs(env['REQUEST_METHOD'] || '')} #{request_uri(env)}#{version}"
 130     when :request_uri
 131       request_uri(env)
 132     when :request_length
 133       env['rack.input'].size.to_s
 134     when :response_length
 135       @body_bytes_sent == 0 ? '-' : @body_bytes_sent.to_s
 136     when :ip
 137       xff = env['HTTP_X_FORWARDED_FOR'] and return byte_xs(xff)
 138       env['REMOTE_ADDR'] || '-'
 139     when :pid
 140       $$.to_s
 141     when :time_iso8601
 142       Time.now.iso8601
 143     when :time_local
 144       # %b in Ruby is locale-independent, unlike strftime(3) in C
 145       Time.now.strftime('%d/%b/%Y:%H:%M:%S %z')
 146     when :time_utc
 147       Time.now.utc.strftime('%d/%b/%Y:%H:%M:%S %z')
 148     else
 149       raise "EDOOFUS #{special_nr}"
 150     end
 151   end
 152
 153   def time_format(sec, usec, format, div)
 154     format % [ sec, usec / div ]
 155   end
 156
 157   def log(env, status, headers, start = @start)
 158     str = @fmt_ops.map { |op|
 159       case op[0]
 160       when OP_LITERAL; op[1]
 161       when OP_REQUEST; byte_xs(env[op[1]] || "-")
 162       when OP_RESPONSE; byte_xs(headers[op[1]] || "-")
 163       when OP_SPECIAL; special_var(op[1], env, status, headers)
 164       when OP_EVAL; eval(op[1]).to_s rescue "-"
 165       when OP_TIME_LOCAL; Time.now.strftime(op[1])
 166       when OP_TIME_UTC; Time.now.utc.strftime(op[1])
 167       when OP_REQUEST_TIME
 168         t = mono_now - start
 169         t = t * (10 ** op[3])
 170         time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
 171       when OP_TIME
 172         t = Time.now
 173         time_format(t.to_i, t.usec, op[1], op[2])
 174       when OP_COOKIE
 175         (byte_xs(env['rack.request.cookie_hash'][op[1]]) rescue "-") || "-"
 176       else
 177         raise "EDOOFUS #{op.inspect}"
 178       end
 179     }.join('')
 180
 181     l = @logger
 182     if l
 183       l << str
 184     else
 185       env['rack.errors'].write(str)
 186     end
 187     nil
 188   end
 189
 190   # favor monotonic clock if possible, and try to use clock_gettime in
 191   # more recent Rubies since it generates less garbage
 192   if defined?(Process::CLOCK_MONOTONIC)
 193     def mono_now; Process.clock_gettime(Process::CLOCK_MONOTONIC); end
 194   elsif defined?(Process::CLOCK_REALTIME)
 195     def mono_now; Process.clock_gettime(Process::CLOCK_REALTIME); end
 196   else
 197     def mono_now; Time.now.to_f; end
 198   end
 199 end