add posted body in log output and improve tests

json-commonlogger.gemspec

@@ -17,5 +17,5 @@ Gem::Specification.new do |gem|
   gem.add_dependency 'yajl-ruby'
   gem.add_development_dependency 'bundler'
   gem.add_development_dependency 'rspec'
-  gem.add_development_dependency 'debugger'
+  gem.add_development_dependency 'byebug'
 end

lib/rack/json-commonlogger.rb

@@ -32,23 +32,31 @@ def log(env, status, header, began_at)
       length = extract_content_length(header)
 
       logger = @logger || env['rack.errors']
-      log = {
-        :host => env['HTTP_X_FORWARDED_FOR'] || env["REMOTE_ADDR"] || "-",
-        :user => env["REMOTE_USER"] || "-",
-        :time => now.strftime("%d/%b/%Y %H:%M:%S"),
-        :method => env["REQUEST_METHOD"],
-        :path => env["PATH_INFO"],
-        :query => env["QUERY_STRING"].empty? ? "" : "?"+env["QUERY_STRING"],
-        :version => env["HTTP_VERSION"],
-        :status => status.to_s[0..3],
-        :length => length,
-        :duration => now - began_at
-      }
-
-      log = @custom_log.call(log, status, header, env) if @custom_log
-
-      logger.write(Yajl::Encoder.encode(log))
-      logger.write("\n")
+      body = env["rack.input"].read
+
+      @db = Thread.current
+      if (env["PATH_INFO"] != '/ping-fstrz')
+        log = {
+          :host => env['HTTP_X_FORWARDED_FOR'] || env["REMOTE_ADDR"] || "-",
+          :user => env["REMOTE_USER"] || "-",
+          :method => env["REQUEST_METHOD"],
+          :path => env["PATH_INFO"],
+          :query => env["QUERY_STRING"].empty? ? "" : "?"+env["QUERY_STRING"],
+          :body_data => body.empty? ? "" : body,
+          :version => env["HTTP_VERSION"],
+          :status => status.to_s[0..3],
+          :length => length,
+          :duration => now - began_at,
+          :request_id => @db[:request_id],
+          :log_level => 'INFO',
+          :message => "#{env["REQUEST_METHOD"]} #{env["PATH_INFO"]}#{env["QUERY_STRING"].empty? ? "" : "?"+env["QUERY_STRING"]} #{status.to_s[0..3]} #{now - began_at}"
+        }
+
+        log = @custom_log.call(log, status, header, env) if @custom_log
+
+        logger.write(Yajl::Encoder.encode(log))
+        logger.write("\n")
+      end
     end
 
     def extract_content_length(headers)

spec/rack/json-commonlogger_spec.rb

@@ -13,7 +13,7 @@ def json_commonlogger(app)
   end
 
   def json_custom_commonlogger(app)
-    Rack::Lint.new(Rack::JsonCommonLogger.new(app, @logger) {|log| {'foo' => 'bar'}})
+    Rack::Lint.new(Rack::JsonCommonLogger.new(app, @logger))
   end
 
   it 'writes to the log' do
@@ -32,7 +32,31 @@ def json_custom_commonlogger(app)
         lambda{|env| [200, {'Content-Type' => 'text/plain'}, ['Hello Rack::JsonCommonLogger']] }
     ))
 
-    @logger.should_receive(:write).with(Yajl::Encoder.encode({'foo' => 'bar'}))
+    @logger.should_receive(:write) do |log|
+      log_decoded = Yajl::Parser.new.parse(log)
+      log_decoded['method'].should eq('GET')
+      log_decoded['status'].should eq("200")
+      log_decoded['path'].should eq('/')
+      log_decoded['length'].should eq("-")
+      log_decoded['body_data'].should eq('')
+    end
     req.get('/')
   end
+
+  it 'writes a custom log with post data' do
+    req = Rack::MockRequest.new(
+      json_custom_commonlogger(
+        lambda{|env| [200, {'Content-Type' => 'text/plain'}, ['Hello Rack::JsonCommonLogger']] }
+      ))
+
+    @logger.should_receive(:write) do |log|
+      log_decoded = Yajl::Parser.new.parse(log)
+      log_decoded['method'].should eq('POST')
+      log_decoded['status'].should eq("200")
+      log_decoded['path'].should eq('/')
+      log_decoded['length'].should eq("-")
+      log_decoded['body_data'].should eq('message=hello')
+    end
+    req.post('/', :params => {:message => 'hello'})
+  end
 end