Faradayのログをきれいにしたり、通信時間などをログ出力する方法
※ Rails または ActiveSupportが必要
検索用キーワード: faraday change custom format log output url time elapsed

デフォルトのログ出力はあまりきれいではない

例えば以下のような感じ

I, [2015-03-23T18:25:52.041359 #10667]  INFO -- : post http://localhost:3000/
D, [2015-03-23T18:25:52.041475 #10667] DEBUG -- request: User-Agent: "Faraday v0.9.1"
Content-Type: "application/x-www-form-urlencoded"
I, [2015-03-23T18:25:52.366326 #10667]  INFO -- Status: 200
D, [2015-03-23T18:25:52.366479 #10667] DEBUG -- response: x-frame-options: "SAMEORIGIN"
x-xss-protection: "1; mode=block"
x-content-type-options: "nosniff"
content-type: "text/html; charset=utf-8"
etag: "W/\"505a83f220c02df2f85c3810cd9ceb38\""
cache-control: "max-age=0, private, must-revalidate"
x-request-id: "c4eb0384-12d5-43ae-8755-d516f02959c6"
x-runtime: "0.301850"
server: "WEBrick/1.3.1 (Ruby/2.1.2/2014-05-08)"
date: "Tue, 24 Mar 2015 01:25:52 GMT"
content-length: "7"
connection: "close"
set-cookie: "request_method=POST; path=/"

ログのサンプル参照元

通常のデフォルトのログ出力の設定はconnectionを作成するところなどで、以下のように設定する

Faraday.new(:url => base_url) do |faraday|
  ...
  faraday.response :logger 
  ...

ログ出力を整形する

faraday_middlewareを追加

Gemfile

gem 'faraday_middleware'

gemの場合

mygem.gemspec

spec.add_dependency "faraday_middleware"

lib/mygem.rb

require "faraday_middleware"

faraday初期化時のオプション

connection(session)作成箇所やdefault optionsを指定している箇所で

Faraday.new(:url => base_url) do |faraday|
  ...
  # faraday.response :logger 
  faraday.use FaradayMiddleware::Instrumentation
  ...

ログ出力設定 Active Support Instrumentation

Railsの場合、initializerなどで

config/initializers/faraday_logger.rb

if Rails.env.development?
  ActiveSupport::Notifications.subscribe('request.faraday') do |name, starts, ends, _, env|
    url = env[:url]
    http_method = env[:method].to_s.upcase
    duration = ends - starts
    Rails.logger.debug "#{http_method} '#{url}' takes #{duration} seconds"
  end
end

gemのテストなどではspec/support/faraday.rbなどに置けば良い

Active Support Instrumentation — Ruby on Rails Guides
FaradayMiddleware::Instrumentation

ログ出力の例

GET 'http://example.com/foo?abc=123' takes 0.100123 seconds
POST 'http://example.com/bar' takes 0.500086 seconds

使えそうな情報

> env.keys
[:method, :body, :url, :request, :request_headers, :ssl, :response, :response_headers, :status]

> env[:method]
:get
> env[:url].class
URI::HTTP
> env[:request_headers]
{"User-Agent"=>"Mozilla/5.0 ..."}
> env[:body]
"<HTML><HEAD><TITLE>..."
> env[:status] # env[:response].status
200
> env[:response_headers] # env[:response].headers
{"date"=>"Fri, 06 Feb 2015 14:13:31 GMT", "set-cookie"=>...}

Faradayのログをきれいに出す