How to log real client ip in rails log when behind proxy like nginx

ruby ruby-on-rails-3 logging nginx reverse-proxy
cbliard picture cbliard · Nov 21, 2013 · Viewed 14.5k times · Source

Problem

I have a rails 3.2.15 with rack 1.4.5 setup on two servers. First server is a nginx proxy serving static assets. Second server is a unicorn serving the rails app.

In Rails production.log I always see the nginx IP address (10.0.10.150) and not my client IP address (10.0.10.62):

Started GET "/" for 10.0.10.150 at 2013-11-21 13:51:05 +0000

I want to have the real client IP in logs.

Our Setup

The HTTP headers X-Forwarded-For and X-Real-IP are setup correctly in nginx and I have defined 10.0.10.62 as not being a trusted proxy address by setting config.action_dispatch.trusted_proxies = /^127\.0\.0\.1$/ in config/environments/production.rb, thanks to another answer. I can check it is working because I log them in the application controller:

in app/controllers/application_controller.rb:

class ApplicationController < ActionController::Base
    before_filter :log_ips

    def log_ips
        logger.info("request.ip = #{request.ip} and request.remote_ip = #{request.remote_ip}")
    end
end

in production.log:

request.ip = 10.0.10.150 and request.remote_ip = 10.0.10.62

Investigation

When investigating, I saw that Rails::Rack::Logger is responsible for logging the IP address:

def started_request_message(request)
  'Started %s "%s" for %s at %s' % [
    request.request_method,
    request.filtered_path,
    request.ip,
    Time.now.to_default_s ]
end

request is an instance of ActionDispatch::Request. It inherits Rack::Request which defines how the IP address is computed:

def trusted_proxy?(ip)
  ip =~ /^127\.0\.0\.1$|^(10|172\.(1[6-9]|2[0-9]|30|31)|192\.168)\.|^::1$|^fd[0-9a-f]{2}:.+|^localhost$/i
end

def ip
  remote_addrs = @env['REMOTE_ADDR'] ? @env['REMOTE_ADDR'].split(/[,\s]+/) : []
  remote_addrs.reject! { |addr| trusted_proxy?(addr) }

  return remote_addrs.first if remote_addrs.any?

  forwarded_ips = @env['HTTP_X_FORWARDED_FOR'] ? @env['HTTP_X_FORWARDED_FOR'].strip.split(/[,\s]+/) : []

  if client_ip = @env['HTTP_CLIENT_IP']
    # If forwarded_ips doesn't include the client_ip, it might be an
    # ip spoofing attempt, so we ignore HTTP_CLIENT_IP
    return client_ip if forwarded_ips.include?(client_ip)
  end

  return forwarded_ips.reject { |ip| trusted_proxy?(ip) }.last || @env["REMOTE_ADDR"]
end

The forwarded IP address are filtered with trusted_proxy?. Because our nginx server is using a public IP address and not a private IP address, Rack::Request#ip thinks it is not a proxy but the real client ip that tries to do some IP spoofing. That's why I see nginx IP address in my logs.

In log excerpts, client and servers have IP address 10.0.10.x because I am using virtual machines to reproduce our production environment.

Our current solution

To circumvent this behavior, I wrote a little Rack middleware located in app/middleware/remote_ip_logger.rb:

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

  def call(env)
    remote_ip = env["action_dispatch.remote_ip"]
    Rails.logger.info "Remote IP: #{remote_ip}" if remote_ip
    @app.call(env)
  end
end

And I insert it just after the ActionDispatch::RemoteIp middleware

config.middleware.insert_after ActionDispatch::RemoteIp, "RemoteIpLogger"

This way I can see the real client IP in logs:

Started GET "/" for 10.0.10.150 at 2013-11-21 13:59:06 +0000
Remote IP: 10.0.10.62

I feel a little uncomfortable with this solution. nginx+unicorn is a common setup for rails application. If I have to log the client IP myself, it means I have missed something. Is it because the Nginx server is using a public IP address when communicating with the rails server? Is there a way to customize the trusted_proxy? method of Rack::Request?

EDITED: add nginx configuration and a HTTP request capture

/etc/nginx/sites-enabled/site.example.com.conf:

server {
    server_name    site.example.com;
    listen         80;


    location ^~ /assets/ {
       root /home/deployer/site/shared;
       expires 30d;
    }

    location / {
      root /home/deployer/site/current/public;
      try_files $uri @proxy;
    }

    location @proxy {
      access_log  /var/log/nginx/site.access.log combined_proxy;
      proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
      proxy_set_header X-Forwarded-Proto $scheme;
      proxy_set_header Host $http_host;
      proxy_redirect off;
      proxy_read_timeout 300;

      proxy_pass http://rails.example.com:8080;
    }
}

Nginx server is 10.0.10.150. Rails server is 10.0.10.190. My machine is 10.0.10.62 When doing curl http://10.0.10.150/ from my machine, a tcpdump port 8080 -i eth0 -Aq -s 0 on rails server show theses request HTTP headers:

GET / HTTP/1.0
X-Forwarded-For: 10.0.10.62
X-Forwarded-Proto: http
Host: 10.0.10.150
Connection: close
User-Agent: curl/7.29.0
Accept: */*

And the rails log /home/deployer/site/current/log/production.log (Remote IP and request.ip lines being added by custom code):

Started GET "/" for 10.0.10.150 at 2013-11-22 08:01:17 +0000
Remote IP: 10.0.10.62
Processing by Devise::RegistrationsController#new as */*
request.ip = 10.0.10.150 and request.remote_ip = 10.0.10.62
  Rendered devise/shared/_links.erb (0.1ms)
  Rendered devise/registrations/new.html.erb within layouts/application (2.3ms)
  Rendered layouts/_landing.html.erb (1.5ms)
Completed 200 OK in 8.9ms (Views: 7.5ms | ActiveRecord: 0.0ms)

Answer

Denis de Bernardy picture Denis de Bernardy · Nov 25, 2013

In my opinion, your current approach is the only sane one. The only step that is missing is overwriting the IP address in env.

The typical REMOTE_ADDR seldom holds the correct IP if you've any amount of layers of proxies and load balancers and what not -- you're not unique in this respect. Each potentially adds or changes remote IP-related headers. And you cannot assume that each of those fields necessarily correspond to a single IP address, at that. Some will push or unshift an IP to a list instead.

There is only one way to know for sure which field holds the correct value and how, and that is to dive in there and look. You've evidently done that already. Now, just overwrite env['REMOTE_ADDR'] with its correct value using your Rack middleware. There's little point in letting any piece of code you didn't write log or process the wrong IP address, as is happening now.

(This being Ruby, you could also monkey patch Rack::Request, of course...)

For colorful reading that illustrate the varying degrees of which exotic setups can mess up attempts at finding a client's real IP address, see for instance the unending discussions that occurred about this for WordPress:

It's PHP but the gist of the points raised apply equally well to Ruby. (Note that they're unresolved as I write this, too, and that they've been around for aeons.)

Related questions

Rails console is not outputting SQL Statements to my Development Log

When I access my Webrick server via the localhost, or when I run rails migrations, my development.log is correctly written to. However, when I bootup my rails console with "rails c" and then try and create a new database …

Read More
How to get a random number in Ruby

How do I generate a random number between 0 and n?

Read More
How to remove a key from Hash and get the remaining hash in Ruby/Rails?

To add a new pair to Hash I do: {:a => 1, :b => 2}.merge!({:c => 3}) #=> {:a => 1, :b => 2, :c => 3} Is there a similar way to delete a key from Hash ? This works: {:a => 1, :b => 2}.…

Read More