Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#818 closed defect (invalid)

error_log host information is confusing

Reported by: tamere22@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.8.x
Keywords: error_log Cc:
uname -a: Linux dsi-portal-front-01 3.2.0-4-amd64 #1 SMP Debian 3.2.68-1+deb7u2 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.8.0
built by gcc 4.7.2 (Debian 4.7.2-5)
built with OpenSSL 1.0.1e 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-http_auth_request_module --with-mail --with-mail_ssl_module --with-file-aio --with-http_spdy_module --with-cc-opt='-g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-z,relro -Wl,--as-needed' --with-ipv6

Description

Hi,

I think it's a bug because log_format is not possible with error_log, and I get some strange behavior in error_logs.

Say I have 2 virtualhosts named siteA.com and siteB.com that point to my nginx (reverse proxy) both.

I put an access/deny on siteB.com based on IP.
When a remote client connects to siteB with an unauthorized IP, I read in the logs "host: siteA.com" or "host: siteB.com" randomly.

I think there should be the IP address insted of IP resolution name.

For sample :

2015/10/21 14:23:02 [error] 17272#0: *10420868 access forbidden by rule, client: 81.18.187.142, server: siteB.com, request: "GET /index.php HTTP/1.1", host: "siteA.com"
2015/10/21 14:24:55 [error] 17273#0: *10431600 access forbidden by rule, client: 81.18.187.142, server: siteB.com, request: "GET /index.php HTTP/1.1", host: "siteB.com"

the "host: " part is one of my dns alias that target my nginx reverse proxy, and is random each time on the logs. Whereas the "server :" part is good and revelant.

Change History (7)

comment:1 by Maxim Dounin, 8 years ago

Resolution: invalid
Status: newclosed

The host is a host from a request (see http://nginx.org/r/$host), and server is the first server_name in the server{} block selected to process the request (see http://nginx.org/r/$server_name). Both are completely unrelated to IP addresses and reverse DNS resolution.

in reply to:  1 comment:2 by tamere22@…, 8 years ago

Replying to mdounin:

The host is a host from a request (see http://nginx.org/r/$host), and server is the first server_name in the server{} block selected to process the request (see http://nginx.org/r/$server_name). Both are completely unrelated to IP addresses and reverse DNS resolution.

Hello,

I'm sorry I don't understand, my english may be terrible but :

Why do I get "host: "siteA.com"" in error_logs of siteB.com error logs files ? Because siteA.com has its own error_log file and config file, different from siteB.com

I am 100% sure the client did request siteB.com so why do I see host: siteA.com in the error log ?
The only correlation I could think of was because siteA.com and siteB.com both are same IP address (our nginx frontend)

Looking at your link, it states :

in this order of precedence: host name from the request line, or host name from the “Host” request header field, or the server name matching a request

Then host should always be siteB.com in the siteB error log files no ?

server {

server_name siteA.com;
include conf.d/listen;
location / {

proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded_Proto $scheme;
proxy_pass http://backend;

}
access_log /var/log/nginx/access.log main;
access_log /var/log/nginx/sites/siteA.com-access.log main;
error_log /var/log/nginx/sites/siteA.com-error.log error;

}

server {

server_name siteB.com;
include conf.d/listen;
location / {

allow 10.0.0.0/8;
allow 172.16.0.0/12;
allow 192.168.0.0/16;
deny all;
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded_Proto $scheme;
proxy_pass http://backend;

}
access_log /var/log/nginx/access.log main;
access_log /var/log/nginx/sites/siteB.com-access.log main;
error_log /var/log/nginx/sites/siteB.com-error.log error;

}

error log file /var/log/nginx/sites/siteB.com-error.log contains siteA.com entries! :

2015/10/21 13:07:24 [error] 17273#0: *9914491 access forbidden by rule, client: 80.215.155.196, server: siteB.com, request: "GET / HTTP/1.1", host: "siteA.com"
2015/10/21 13:07:24 [error] 17273#0: *9914491 access forbidden by rule, client: 80.215.155.196, server: siteB.com, request: "GET /favicon.ico HTTP/1.1", host: "siteB.com"
2015/10/21 13:41:52 [error] 17273#0: *10130318 access forbidden by rule, client: 84.101.96.33, server: siteB.com, request: "GET / HTTP/1.1", host: "siteA.com"

How is it possible ?

Last edited 8 years ago by tamere22@… (previous) (diff)

comment:3 by Maxim Dounin, 8 years ago

This may happen if a connection is accepted on a listening socket which is only present in one server{}, but not another. Or if there is a typo in config (e.g., in the "server_name siteA.com;"). See here for some details. If unsure what goes on in your specific case - try providing full unaltered configuration and logs.

comment:4 by tamere22@…, 8 years ago

Full unaltered configuration is problematic for me as it is our main frontend server with a lot of configurations.

Anyway I just noticed that access_logs were also affected by this behavior.

nginx.conf (partial) :

    log_format  main  '$scheme $http_host $remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

conf.d/listen :

listen 80;

conf.d/listen-ssl-wildcard :

listen 443;
ssl on;

ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
ssl_ciphers 'EECDH+AESGCM:AES256+EECDH:ECDH+AES128:!ADH:!AECDH:!MD5';


ssl_prefer_server_ciphers on;

ssl_certificate         star.pem;
ssl_certificate_key     star.key;

conf.d/sites-available/apoprimoweb-test.conf :

server {
        server_name apoprimoweb-test;
        include conf.d/listen;
        location / {
                rewrite ^ https://$host$request_uri? permanent;
        }
}


server {
        server_name apoprimoweb-test;
        include conf.d/listen-ssl-wildcard;
        location / {
                allow 134.214.0.0/16;
                allow 10.0.0.0/8;
                allow 172.16.0.0/12;
                allow 192.168.0.0/16;
                deny all;
                proxy_set_header Host $http_host;
                proxy_set_header X-Real-IP $remote_addr;
                proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
                proxy_set_header X-Forwarded_Proto $scheme;
                proxy_pass https://denvertest:443;
        }
        access_log  /var/log/nginx/access.log  main;
        access_log /var/log/nginx/infra-metiers/apoprimoweb-test-access.log main;
        error_log /var/log/nginx/infra-metiers/apoprimoweb-test-error.log error;

}

/var/log/nginx/infra-metiers/apoprimoweb-test-access.log

https intranet 195.254.160.194 - - [26/Oct/2015:15:20:06 +0100] "GET / HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https intranet 195.254.160.194 - - [26/Oct/2015:15:20:06 +0100] "GET /favicon.ico HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https intranet 195.254.160.194 - - [26/Oct/2015:15:20:08 +0100] "GET / HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https intranet 195.254.160.194 - - [26/Oct/2015:15:20:08 +0100] "GET /favicon.ico HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https intranet 195.254.160.194 - - [26/Oct/2015:15:20:10 +0100] "GET / HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https intranet 195.254.160.194 - - [26/Oct/2015:15:20:10 +0100] "GET /favicon.ico HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36" "-"
https focalserv 66.249.78.7 - - [26/Oct/2015:15:34:40 +0100] "GET /sciences.htm HTTP/1.1" 403 134 "-" "Mozilla/5.0 (iPhone; CPU iPhone OS 8_3 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) Version/8.0 Mobile/12F70 Safari/600.1.4 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-"
https concours 195.83.153.76 - - [26/Oct/2015:15:50:42 +0100] "HEAD /annales-des-concours/ HTTP/1.1" 403 0 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:41.0) Gecko/20100101 Firefox/41.0" "-"
https concours 195.83.153.76 - - [26/Oct/2015:15:50:42 +0100] "GET /annales-des-concours/ HTTP/1.1" 403 134 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:41.0) Gecko/20100101 Firefox/41.0" "-"
https go 92.157.198.130 - - [26/Oct/2015:16:02:59 +0100] "GET / HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36" "-"
https go 92.157.198.130 - - [26/Oct/2015:16:02:59 +0100] "GET /favicon.ico HTTP/1.1" 403 189 "https://go/" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36" "-"
https go 92.157.198.130 - - [26/Oct/2015:16:03:35 +0100] "GET /infoetu HTTP/1.1" 403 189 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36" "-"
https go 92.157.198.130 - - [26/Oct/2015:16:03:35 +0100] "GET /favicon.ico HTTP/1.1" 403 189 "https://go/infoetu" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36" "-"
https www710 141.8.143.173 - - [26/Oct/2015:16:04:07 +0100] "GET / HTTP/1.1" 403 134 "-" "Mozilla/5.0 (compatible; YandexBot/3.0; +http://yandex.com/bots)" "-"

/var/log/nginx/infra-metiers/apoprimoweb-test-error.log

2015/10/26 09:44:38 [error] 12338#0: *26891713 access forbidden by rule, client: 141.8.143.173, server: apoprimoweb-test, request: "GET / HTTP/1.1", host: "www710"
2015/10/26 09:45:39 [error] 12338#0: *26897325 access forbidden by rule, client: 198.20.69.74, server: apoprimoweb-test, request: "GET / HTTP/1.1", host: "intranet"
2015/10/26 09:45:40 [error] 12338#0: *26897364 access forbidden by rule, client: 198.20.69.74, server: apoprimoweb-test, request: "GET /robots.txt HTTP/1.1", host: "intranet"
2015/10/26 09:45:41 [error] 12338#0: *26897411 access forbidden by rule, client: 198.20.69.74, server: apoprimoweb-test, request: "GET /sitemap.xml HTTP/1.1", host: "concours"

any host name you see in the logs points to this nginx frontend (intranet, concours, folcaserv, go, www710, ...) all are CNAMES to the nginx server's IP

As you can see even in the access_logs (custom log format) the $http_host variable is problematic. I show you the configuration file of another site, on the same nginx frontend, but every host is defined almost the same way :

conf.d/sites-available/go.conf

server {
        server_name go;

        include conf.d/listen;


        ###################################

        location / {

                proxy_pass http://upstream-webtools/;
                proxy_set_header Host $http_host;
                proxy_set_header X-Real-IP $remote_addr;
                proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;

        }


}

comment:5 by Maxim Dounin, 8 years ago

In your configuration as provided, the listen socket on port 443 is only present in the apoprimoweb-test server{} block. This is in line with what was previously said - your configuration is what causes such a behaviour, and there is no nginx bug. If you need further help, please use mailing lists.

comment:6 by tamere22@…, 8 years ago

I understand this is not a bug :) But I don't understand the logic behind this behavior.

So what you are saying is that I should add a listen on ssl port to all the websites that are non-ssl only, or I will keep getting random hosts names in my access and error logs ?

comment:7 by Maxim Dounin, 8 years ago

Please read the article already linked above, it explains how things work and how to live with it. Note again that this is a wrong place to ask questions, there are mailing lists to do this.

Note: See TracTickets for help on using tickets.