cbliard cbliard - 1 month ago 29
Ruby Question

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

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

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.)

Comments