DEV Community: Tasos Latsas

faraday requests instrumentation

Tasos Latsas — Thu, 25 Feb 2021 22:00:00 +0000

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/1we 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.faradayby 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 subscribeblock 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!

a simple web proxy using WEBrick

Tasos Latsas — Sat, 23 Jan 2021 22:00:00 +0000

As the README states, “WEBrick is an HTTP server toolkit that can be configured as an HTTPS server, a proxy server, and a virtual-host server”. I recently needed to create a small proxy, with minimal effort, in order to hide some functionality of a proof-of-concept API. WEBrick is quite powerful, and a small proxy does not require more than 20-25 lines or code.

The AbstractServletclass allows us to respond to GET, HEAD and OPTIONS requests. We can use it to encapsulate our logic of receiving a request, forwarding it to the server (possibly changing it) and responding back.

Let’s write a simple proxy, that receives a request, appends a custom query param and forwards it to the API server https://api-server.com. We will append the realm query parameter with a hardcoded value of qa-realm.

First, let’s create our proxy as a subclass of AbstractServlet. We will implement the do_GET method as we care only for GET requests. The incoming request object is stored in the request parameter, we will manipulate this later in order to add our query parameter. In order to respond, we need to set the content_type and body values on the response object.

require "webrick"

class MyProxy < WEBrick::HTTPServlet::AbstractServlet
  def do_GET(request, response)
    response.content_type = "text/plain"
    response.body = "It works!"
  end
end

Next, we will add the realm parameter. We need to parse the request URL in order to make sure that we handle correctly all use cases involving any existing parameters. We will use URI for this.

require "webrick"
require "uri"

class MyProxy < WEBrick::HTTPServlet::AbstractServlet
  REALM = "qa-realm"

  def do_GET(request, response)
    uri = forwarded_uri(request.unparsed_uri)

    response.content_type = "text/plain"
    response.body = "It works! New URI is #{uri}"
  end

  private

  def forwarded_uri(unparsed_uri)
    uri = URI(unparsed_uri)
    params = URI.decode_www_form(uri.query || "") << ["realm", REALM]
    uri.query = URI.encode_www_form(params)
    uri.to_s
  end
end

Right now, we manipulate the request URI, but we don’t forward anything to the intended endpoint. We will use Net::HTTP to forward the request and pass the response back. We will also use the body, and the content type we retrieve from the proxied server when we pass the response back.

require "webrick"
require "net/http"
require "uri"

class MyProxy < WEBrick::HTTPServlet::AbstractServlet
  HOST = "api-server.com"
  REALM = "qa-realm"

  def do_GET(request, response)
    uri = forwarded_uri(request.unparsed_uri)

    http = Net::HTTP.new(HOST, 443)
    http.use_ssl = true
    resp = http.request(Net::HTTP::Get.new(uri))
    body = resp.body

    response.content_type = resp["content-type"]
    response.body = body
  end

  private

  def forwarded_uri(unparsed_uri)
    uri = URI(unparsed_uri)
    params = URI.decode_www_form(uri.query || "") << ["realm", REALM]
    uri.query = URI.encode_www_form(params)
    uri.to_s
  end
end

In order to run our proxy, we need a few more missing pieces. First we need to create a newWEBrick::HTTPServer

server = WEBrick::HTTPServer.new(:Port => ENV["PORT"] || 8080)

Then we need to mount our proxy under an endpoint, we can use the root endpoint or any other we want.

server.mount "/", MyProxy

Finally, let’s allow stopping the server using Ctrl+C and then start the server.

trap("INT"){ server.shutdown }
server.start

If we run our proxy with ruby myproxy.rb it will start serving using port 8080 under /.

[2021-01-24 21:36:00] INFO WEBrick 1.6.0
[2021-01-24 21:36:00] INFO ruby 2.7.1 (2020-03-31) [x86_64-darwin18]
[2021-01-24 21:36:00] INFO WEBrick::HTTPServer#start: pid=47104 port=8080

The final code is the following:

#!/usr/bin/env ruby
# frozen_string_literal: true

require "webrick"
require "net/http"
require "uri"

class MyProxy < WEBrick::HTTPServlet::AbstractServlet
  HOST = "api-server.com"
  REALM = "qa-realm"

  def do_GET(request, response)
    uri = forwarded_uri(request.unparsed_uri)

    http = Net::HTTP.new(HOST, 443)
    http.use_ssl = true

    resp = http.request(Net::HTTP::Get.new(uri))
    body = resp.body

    response.content_type = resp["content-type"]
    response.body = body
  end

  private

  def forwarded_uri(unparsed_uri)
    uri = URI(unparsed_uri)
    params = URI.decode_www_form(uri.query || "") << ["realm", REALM]
    uri.query = URI.encode_www_form(params)
    uri.to_s
  end
end

server = WEBrick::HTTPServer.new(:Port => ENV["PORT"] || 8080)
server.mount "/", MyProxy

trap("INT"){ server.shutdown }
server.start