Rack: Why is each middleware called twice on a single request?

Question

I'm trying to understand how Rack works, and I'm testing out an example from this rack tutorial.

The example creates a "hello world" rack app, as well as two trivial pieces of middleware, and then runs them all:

Example Rack App With Middleware

This is working code, and you can save it to a file called app.rb and run it locally with ruby app.rb at the command line:

require 'rack'
require 'rack/server'

class EnsureJsonResponse
  def initialize(app)
    @app = app
  end

  # Set the 'Accept' header to 'application/json' no matter what.
  # Hopefully the next middleware respects the accept header :)
  def call(env)
    puts "JSON"
    env['HTTP_ACCEPT'] = 'application/json'
    @app.call env
  end
end

class Timer
  def initialize(app)
    @app = app
  end

  def call(env)
    puts "Timer"
    before = Time.now
    status, headers, body = @app.call env

    headers['X-Timing'] = (Time.now - before).to_s

    [status, headers, body]
  end
end

class HelloWorldApp
  def self.call(env)
    puts "HelloWorld"
    [200, {}, ["hello world"]]
  end
end

app = Rack::Builder.new do 
  use Timer # put the timer at the top so it captures everything below it
  use EnsureJsonResponse
  run HelloWorldApp
end

Rack::Server.start :app => app

The output

Here's what you'll see if you make a single request to the web page:

+>ruby app.rb
>> Thin web server (v1.4.1 codename Chromeo)
>> Maximum connections set to 1024
>> Listening on 0.0.0.0:8080, CTRL+C to stop
Timer
JSON
HelloWorld
Timer
JSON
HelloWorld

Why is each middleware, as well as the bottom app, called two times on a single request?

Answer 1

I copied your app and ran it locally. This happened:

[2014-03-08 22:01:29] INFO  WEBrick 1.3.1
[2014-03-08 22:01:29] INFO  ruby 2.0.0 (2013-06-27) [x86_64-darwin13.0.0]
[2014-03-08 22:01:29] INFO  WEBrick::HTTPServer#start: pid=74593 port=8080
Timer
JSON
HelloWorld
localhost - - [08/Mar/2014:22:01:33 PST] "GET / HTTP/1.1" 200 11
- -> /
Timer
JSON
HelloWorld
localhost - - [08/Mar/2014:22:01:33 PST] "GET /favicon.ico HTTP/1.1" 200 11
- -> /favicon.ico
Timer
JSON
HelloWorld
localhost - - [08/Mar/2014:22:01:33 PST] "GET /favicon.ico HTTP/1.1" 200 11

It seems likely to me that you saw your browser silently requesting a favicon.ico file. Is that possible?

---

FWIW, whenever I'm debugging something at this low of a level, I always find curl to be a helpful command.

$ curl -i localhost:8080
HTTP/1.1 200 OK
X-Timing: 2.7e-05
Server: WEBrick/1.3.1 (Ruby/2.0.0/2013-06-27)
Date: Sun, 09 Mar 2014 06:03:58 GMT
Content-Length: 11
Connection: Keep-Alive

hello world%

results in the server printing the following:

[2014-03-08 22:03:49] INFO  WEBrick 1.3.1
[2014-03-08 22:03:49] INFO  ruby 2.0.0 (2013-06-27) [x86_64-darwin13.0.0]
[2014-03-08 22:03:49] INFO  WEBrick::HTTPServer#start: pid=74662 port=8080
Timer
JSON
HelloWorld
localhost - - [08/Mar/2014:22:03:58 PST] "GET / HTTP/1.1" 200 11
- -> /

Huzzah!

Answer 2

Most browsers tend to request for a favicon. Perhaps you want to change our app to find out what paths where requested:

class HelloWorldApp
  def self.call(env)
    puts "HelloWorld"
    puts "requested path: #{env["PATH_INFO"]}"
    [200, {}, ["hello world"]]
  end
end