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)