Faraday is a flexible HTTP client library for Ruby. It supports multiple adapters and is built using a rack-inspired middleware stack. Various middlewares can be enabled to modify or log information during the request/response cycle.
Quite often, it is useful to log detailed information or metrics about the API requests your backend performs, while serving an HTTP request. There is a logger middleware, which provides plenty configuration options such as logging request headers, the request body, filtering sensitive information, or customizing the log format. However, one of the most important metrics you would usually need, is the duration of the request. This is not supported by the logger middleware. Enter, the instrumentation middleware.
The instrumentation middleware allows us to use the excellent Active Support Instrumentation to instrument our requests. Active Support includes an instrumentation API, which allows us to hook into various parts of our Rails application to take measurements. It is built using a pub/sub mechanism, we define events to be broadcasted, and also define subscribers who listen for these events. Rails, provides itself a wide range of predefined events that we can subscribe to, but also allows us to create custom events.
For this article, we have a minimal sample Rails application, which stores some primitive information about movies. Let’s assume that it stores the movie name, release year and a rating. We also have access to an external API, which we can use to query using the same movie id, to retrieve the movie’s cast. The idea is to hit the /movies/:id
endpoint, retrieve all the information we have about this movie from our database, then query the external API for the extra information (cast), and pass this info to our view. We will show how we can use faraday for querying the external API and use the instrumentation middleware to log the API call duration.
First, we need to install faraday.
bundle add faraday
Our Rails application has the following parts:
# db/migrate20210220175430_create_movies.rb
class CreateMovies < ActiveRecord::Migration[6.1]
def change
create_table :movies do |t|
t.string :title
t.string :year
t.float :rating
t.timestamps
end
end
end
# config/routes.rb
resources :movies
# app/controllers/movies_controller.rb
class MoviesController < ApplicationController
def show
@movie = Movie.find(params[:id])
end
end
# app/models/movie.rb
class Movie < ApplicationRecord
end
Pretty basic. The db table could definitely be better, but for our use case is fine. We have also defined app/views/movies/show.html.erb
to just render our controller instance variables (omitted for brevity).
Now we will add a new model which will use our external API to retrieve the extra movie information. This won’t be an ActiveRecord model, we will use a simple PORO.
# app/models/movie_info.rb
class MovieInfo
HOST = 'bf74dc7a-7b56-47f6-9fcb-0881f7a36ff9.mock.pstmn.io'.freeze
class << self
def find(id)
conn = Faraday.new(url: "https://#{HOST}/movies/#{id}")
res = conn.get
JSON.parse(res.body)
end
end
end
This class defines a find
class method which accepts an id, then constructs a new faraday connection object, and performs an API call to the configured endpoint. Finally, it returns the response body as a ruby hash. Faraday uses Net::HTTP by default, for this example we will not be configuring another adapter.
Defining a class method named find
is inspired by the Rails ActiveRecord API, so updating our controller to use this model will look like this:
def show
@movie = Movie.find(params[:id])
@extra_movie_info = MovieInfo.find(params[:id])
end
With the current setup, if we access our application through http://localhost:3000/movies/1
we will get the following log output:
Started GET "/movies/1" for 127.0.0.1 at 2021-02-25 13:18:21 +0200
Processing by MoviesController#show as HTML
Parameters: {"id"=>"1"}
Movie Load (0.2ms) SELECT "movies".* FROM "movies" WHERE "movies"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]]
↳ app/controllers/movies_controller.rb:3:in `show'
Rendering layout layouts/application.html.erb
Rendering movies/show.html.erb within layouts/application
Rendered movies/show.html.erb within layouts/application (Duration: 0.4ms | Allocations: 139)
[Webpacker] Everything's up-to-date. Nothing to do
Rendered layout layouts/application.html.erb (Duration: 9.8ms | Allocations: 3583)
Completed 200 OK in 1109ms (Views: 10.6ms | ActiveRecord: 0.2ms | Allocations: 5164)
Notice that by default we don’t get any info about the performed API request whatsoever. If we enable the logging middleware that we briefly mentioned at the beginning of the article, we will get some basic output on what is happening. Let’s enable the logging middleware in our faraday configuration:
def find(id)
conn = Faraday.new(url: "https://#{HOST}/movies/#{id}") do |faraday|
faraday.response :logger, nil, { headers: false, bodies: false }
end
res = conn.get
JSON.parse(res.body)
end
Then, the output will look like this:
Started GET "/movies/1" for 127.0.0.1 at 2021-02-20 20:25:07 +0200
Processing by MoviesController#show as HTML
Parameters: {"id"=>"1"}
(0.1ms) SELECT sqlite_version(*)
↳ app/controllers/movies_controller.rb:11:in `show'
Movie Load (0.1ms) SELECT "movies".* FROM "movies" WHERE "movies"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]]
↳ app/controllers/movies_controller.rb:11:in `show'
I, [2021-02-20T20:25:07.573589 #39486] INFO -- request: GET https://bf74dc7a-7b56-47f6-9fcb-0881f7a36ff9.mock.pstmn.io/movies/1
I, [2021-02-20T20:25:08.647338 #39486] INFO -- response: Status 200
Rendering layout layouts/application.html.erb
Rendering movies/show.html.erb within layouts/application
Rendered movies/show.html.erb within layouts/application (Duration: 1.2ms | Allocations: 139)
[Webpacker] Everything's up-to-date. Nothing to do
Rendered layout layouts/application.html.erb (Duration: 47.3ms | Allocations: 3549)
Completed 200 OK in 1140ms (Views: 52.1ms | ActiveRecord: 1.9ms | Allocations: 8848)
Notice the two INFO log lines starting with I
. Definitely better than before, but what we are aiming for here, is to get a line which includes the call duration. Much like the lines which show the view rendering duration, or the time ActiveRecord took to retrieve the data from our database.
Let’s swap the logger with the instrumentation middleware:
def find(id)
conn = Faraday.new(url: "https://#{HOST}/movies/#{id}") do |faraday|
faraday.request :instrumentation, name: "movies.faraday"
end
res = conn.get
JSON.parse(res.body)
end
The name
parameter defines the name of the event that will be broadcasted. The Rails convention for defining event names is event.library
and faraday sets this to request.faraday
by default.
The next step is to subscribe to listening to those events. This is done by defining an ActiveSupport::Notifications.subscribe
block, usually in an initializer or under /lib
.
# /lib/faraday_subscriber.rb
ActiveSupport::Notifications.subscribe("movies.faraday") do |name, starts, ends, _, env|
url = env[:url]
http_method = env[:method].to_s.upcase
duration = ((ends - starts) * 1000.0).round(1)
log_prefix = name.split(".").last.camelize
output = "[%s] %s %s %s (Duration: %sms)" % [log_prefix, url.host, http_method, url.request_uri, duration]
Rails.logger.info(output)
end
Quite a few things happening here. The name
argument is set to the broadcasted event name, in our casemovies.faraday
. The starts
and ends
are Time objects representing the time our event started and ended respectively. The env
argument is a Faraday::Env
object which holds various information about our request. In the Rails instrumentation documentation, we can see more details about the subscribe
block arguments.
The env
argument which holds the faraday request information can be used to extract the API request host and HTTP method, as well as the headers, and the response body. In our example we use the host, HTTP method and request uri to construct our log line.
The starts
and ends
are used to calculate the duration. According to the Time
documentation, by subtracting two Time
objects we get a Float
representing the difference in seconds. So we go one step further to calculate the time in milliseconds.
After restarting our application, the log output looks like this:
Started GET "/movies/1" for 127.0.0.1 at 2021-02-25 20:20:00 +0200
(0.9ms) SELECT sqlite_version(*)
(0.1ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by MoviesController#show as HTML
Parameters: {"id"=>"1"}
Movie Load (0.2ms) SELECT "movies".* FROM "movies" WHERE "movies"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]]
↳ app/controllers/movies_controller.rb:3:in `show'
[Faraday] bf74dc7a-7b56-47f6-9fcb-0881f7a36ff9.mock.pstmn.io GET /movies/1 (Duration: 1262.7ms)
Rendering layout layouts/application.html.erb
Rendering movies/show.html.erb within layouts/application
Rendered movies/show.html.erb within layouts/application (Duration: 1.2ms | Allocations: 411)
[Webpacker] Everything's up-to-date. Nothing to do
Rendered layout layouts/application.html.erb (Duration: 12.9ms | Allocations: 5527)
Completed 200 OK in 1299ms (Views: 16.5ms | ActiveRecord: 1.1ms | Allocations: 13035)
Our log is prepended with [Faraday]
and includes the host, the HTTP method, the API endpoint and the total request duration. Success!
The subscribe block can be simplified a bit more. We can construct an ActiveSupport::Notifications::Event object from the arguments. This will give us an object-oriented interface to the event data.
ActiveSupport::Notifications.subscribe("movies.faraday") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
url = event.payload[:url]
http_method = event.payload[:method].to_s.upcase
log_prefix = event.name.split(".").last.camelize
output = "[%s] %s %s %s (Duration: %sms)" % [log_prefix, url.host, http_method, url.request_uri, event.duration]
Rails.logger.info(output)
end
We even get the duration calculation for free (in ms), neat!
Top comments (0)