Opened 12 years ago

Closed 12 years ago

Last modified 12 years ago

#96 closed defect (worksforme)

Default_server catch all block not working

Reported by: www.google.com/accounts/o8/id?id=AItOawnxEpaUM9BjPLuvymmX1VMwI3fyJckZUx0 Owned by: somebody
Priority: major Milestone:
Component: nginx-core Version: 1.1.x
Keywords: default_server 444 Cc:
uname -a: Linux web2.forvo.com 2.6.32-5-xen-amd64 #1 SMP Wed Jan 12 05:46:49 UTC 2011 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.1.8
built by gcc 4.6.2 (Debian 4.6.2-4)
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-log-path=/var/log/nginx/access.log --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --lock-path=/var/lock/nginx.lock --pid-path=/var/run/nginx.pid --with-debug --with-http_addition_module --with-http_dav_module --with-http_geoip_module --with-http_gzip_static_module --with-http_image_filter_module --with-http_realip_module --with-http_stub_status_module --with-http_ssl_module --with-http_sub_module --with-http_xslt_module --with-ipv6 --with-sha1=/usr/include/openssl --with-md5=/usr/include/openssl --with-mail --with-mail_ssl_module --add-module=/tmp/buildd/nginx-1.1.8/debian/modules/nginx-echo --add-module=/tmp/buildd/nginx-1.1.8/debian/modules/nginx-upstream-fair

Description

Nginx after a Load Balancer and proxying Apache php site behaves in a strange way when defining a default_server catch-all block.
Scenario :: Only one site-enabled with several server blocks defined on it. Each server has plenty of server_name (as ServerAlias does have the underlying apache). Next block is defined at the very beggining of site-enabled/onlysite :

server {
  listen 80 default_server;
  server_name _;
  proxy_intercept_errors on;
  error_log /var/log/nginx/000default-error.log debug;
  access_log /var/log/nginx/000default-access.log;
  return 444;
}

Result:
.- As soon as i enable the above block, Server seems to respond Ok, returning 444 to every request like nonexistantsubdomain.mydomain.com but the 000default-access.log starts to be filled with:

..-[A] Plenty of requests which souhld be ok responded with the 444 code
..- [B] Plenty of strange request like this ::: [01/Feb/2012:12:13:40 +0100] "-" 400 0 "-" "-"

.- In less than 3 minutes, suddenly the above access log stops receiving that bunch of 444 responded requests[A] and it only shows the [B] from time to time (some buffer overloaded?). From that moment on, any request gets error as reponse.

Change History (6)

comment:1 by Maxim Dounin, 12 years ago

Please do the following:

  1. Make sure you see the same behaviour with latest nginx (1.1.14) without any 3rd party modules and/or patches.
  2. Please provide *full config* you are able to reproduce the problem with, not just a snippet. That is, full config starting from nginx.conf, with all included files.
  3. Please provide unmodified log lines for requests you think were wrongly responded with 444 with a detailed explanation why you think it's wrong. Please provide ​debug log for at least one such request.
  4. Please make sure you have error_log defined at global level, set to at least 'error' logging level, and there are no errors reported during testing. If there are any errors reported - please provide details. The same applies for all other error_logs in your configuration. Ideally, please make sure to comment out all error_log's from your configuration except global one, to make sure all problems are logged into single log.

Note also that 400 log lines aren't strange. They are expected to be in catch-all server as there is no host information available due to request being bad. Such log lines appear e.g. if client opens connection to a server, and then closes it without sending any request. Some modern browsers (notably Chrome) pre-open several connections to reduce latency, thus causing such lines to appear if there are less requests than pre-opened connections.

comment:2 by www.google.com/accounts/o8/id?id=AItOawnxEpaUM9BjPLuvymmX1VMwI3fyJckZUx0, 12 years ago

Currenty running 1.1.14

Full nginx config following the above default block (by now, fake server/domain names)

server {
        listen   80; ## listen for ipv4
        server_name mydom.com www.mydom.com xx.mydom.com yy.mydom.com zz.my.dom.com;
        server_name aa.mydom.com bb.mydom.com ro.mydom.com lotsof.mydom.com;
        error_log  /var/log/nginx/mydom.error.log warn;
        error_page  404  /404.php;
        error_page  502 503 504 400 /50x.html;
        large_client_header_buffers     4 4k;
        location = /50x.html {
                root /var/www/mydom.com/static;
                #internal
        }
       location ~* \.(ogg|mp3|flv)$ {
               root   /var/www/datos;
               expires     1y;
               #access_log  /var/log/nginx/static.direct.log ;
       }
        location ~* \.(jpg|jpeg|gif|png|css|bmp|ico|txt|html|swf)$ {
                root   /var/www/mydom.com;
                expires     1y;
                #PERFORMANCE# access_log  /var/log/nginx/static.direct.log ;
        }
        location / {

                proxy_pass         http://127.0.0.1:60080/;
                proxy_redirect     off;

                proxy_set_header   Host             $host;
                proxy_set_header   X-Real-IP        $remote_addr;
                proxy_set_header   X-Forwarded-For  $proxy_add_x_forwarded_for;

                client_max_body_size       10m;
                client_body_buffer_size    128k;

                proxy_connect_timeout      60;
                proxy_send_timeout         90;
                proxy_read_timeout         120;
                #proxy_read_timeout         90;

                proxy_buffering         on;
                proxy_buffer_size          4k;
                proxy_buffers              4 32k;
                proxy_busy_buffers_size    64k;
                proxy_temp_file_write_size 64k;
   }
}

/var/log/nginx/000default-access.log: request which should not return 444

Following request is the regular checking from EC2 ElasticLoadBalancer. When the default_server block disabled, this works fine and no problem at all; when enabled, after a lapse of time (+/- 1 minute) it starts returning 444 as many others which shouldn't neither.

10.194.165.253 - - [06/Feb/2012:09:58:40 +0100] "GET /btest.php HTTP/1.1" 444 0 "-" "ELB-HealthChecker/1.0"

others

10.194.165.253 - - [06/Feb/2012:09:58:40 +0100] "GET /key/6934110cec1af51ff71bb947868e46a5/format/xml/action/word-pronunciations/word/pat/language/en/order/rate-desc/limit/1 HTTP/1.1" 444 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:39:48 +0100] "GET /robots.txt HTTP/1.1" 444 0 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"

/var/log/nginx/000default-error.log: the above 1st request shown in error /debug mode log

2012/02/06 09:58:39 [debug] 24727#0: *6715 http header done
2012/02/06 09:58:40 [debug] 24727#0: *6715 posix_memalign: 0000000002411950:4096 @16
2012/02/06 09:58:40 [debug] 24727#0: *6715 http process request line
2012/02/06 09:58:40 [debug] 24727#0: *6715 http request line: "GET /word/imilu/ HTTP/1.1"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http uri: "/word/imilu/"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http args: ""
2012/02/06 09:58:40 [debug] 24727#0: *6715 http exten: ""
2012/02/06 09:58:40 [debug] 24727#0: *6715 http process request header line
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "host: www.mydom.com"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Accept: */*"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Accept-Encoding: gzip, deflate"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Cache-Control: no-cache"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "From: bingbot(at)microsoft.com"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Pragma: no-cache"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "User-Agent: Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "X-Forwarded-For: 207.46.13.117"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "X-Forwarded-Port: 80"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "X-Forwarded-Proto: http"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Connection: keep-alive"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header done

At the end the only 000default-access.log are

0.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"

....
and so on

The same time on 000default-error.log

2012/02/06 09:41:10 [debug] 21915#0: *72411 malloc: 0000000001B903F0:1296
2012/02/06 09:41:10 [debug] 21915#0: *72411 posix_memalign: 0000000001C7CBD0:256 @16
2012/02/06 09:41:10 [debug] 21915#0: *72411 malloc: 0000000001C699B0:1024
2012/02/06 09:41:10 [debug] 21915#0: *72411 posix_memalign: 0000000001C4D9E0:4096 @16
2012/02/06 09:41:10 [debug] 21915#0: *72411 http process request line
2012/02/06 09:41:10 [debug] 21915#0: *72411 recv: fd:61 799 of 1024
2012/02/06 09:41:10 [debug] 21915#0: *72411 http request line: "GET /_presentation/js/functions.js HTTP/1.1"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http uri: "/_presentation/js/functions.js"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http args: ""
2012/02/06 09:41:10 [debug] 21915#0: *72411 http exten: "js"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http process request header line
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "host: ro.mydom.com"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept: */*"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Charset: utf-8, iso-8859-1, utf-16, *;q=0.7"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Encoding: gzip"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Language: ro-RO, en-US"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Cookie: AWSELB=85196F1108271F7FD2BF6FD21E898489CC91299968F3B4FA38F688A76A130A8DA3D08F359D48A4087B71B003F5BF6E0DAF5AEF9EAC869DB995FA5A4BE4F116DBB347EE0917D8672EA2D7360071DFE4E78D64E9A301; PHPSESSID=cpqqi57ep6qc3onpgva7jgati1"
2012/02/06 09:41:10 [debug] 21915#0: *72411 malloc: 0000000001B903F0:1296
2012/02/06 09:41:10 [debug] 21915#0: *72411 posix_memalign: 0000000001C7CBD0:256 @16
2012/02/06 09:41:10 [debug] 21915#0: *72411 malloc: 0000000001C699B0:1024
2012/02/06 09:41:10 [debug] 21915#0: *72411 posix_memalign: 0000000001C4D9E0:4096 @16
2012/02/06 09:41:10 [debug] 21915#0: *72411 http process request line
2012/02/06 09:41:10 [debug] 21915#0: *72411 recv: fd:61 799 of 1024
2012/02/06 09:41:10 [debug] 21915#0: *72411 http request line: "GET /_presentation/js/functions.js HTTP/1.1"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http uri: "/_presentation/js/functions.js"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http args: ""
2012/02/06 09:41:10 [debug] 21915#0: *72411 http exten: "js"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http process request header line
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "host: ro.mydom.com"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept: */*"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Charset: utf-8, iso-8859-1, utf-16, *;q=0.7"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Encoding: gzip"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Accept-Language: ro-RO, en-US"
2012/02/06 09:41:10 [debug] 21915#0: *72411 http header: "Cookie: AWSELB=85196F1108271F7FD2BF6FD21E898489CC91299968F3B4FA38F688A76A130A8DA3D08F359D48A4087B71B003F5BF6E0DAF5AEF9EAC869DB995FA5A4BE4F116DBB347EE0917D8672EA2D7360071DFE4E78D64E9A301; PHPSESSID=cpqqi57ep6qc3onpgva7jgati1"

in reply to:  2 comment:3 by Maxim Dounin, 12 years ago

Replying to www.google.com/accounts/o8/id?id=AItOawnxEpaUM9BjPLuvymmX1VMwI3fyJckZUx0:

Full nginx config following the above default block (by now, fake server/domain names)

Are provided two server{} blocks are the only server blocks in config?

See below - you still haven't provided info for us to think something is wrong, but modified names won't work. The most likely reason for the problem you describe is mishandling of some names - either by nginx or by you. In both cases we need unmodified names to say something.

Following request is the regular checking from EC2 ElasticLoadBalancer. When the default_server block disabled, this works fine and no problem at all; when enabled, after a lapse of time (+/- 1 minute) it starts returning 444 as many others which shouldn't neither.

10.194.165.253 - - [06/Feb/2012:09:58:40 +0100] "GET /btest.php HTTP/1.1" 444 0 "-" "ELB-HealthChecker/1.0"

others

10.194.165.253 - - [06/Feb/2012:09:58:40 +0100] "GET /key/6934110cec1af51ff71bb947868e46a5/format/xml/action/word-pronunciations/word/pat/language/en/order/rate-desc/limit/1 HTTP/1.1" 444 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:39:48 +0100] "GET /robots.txt HTTP/1.1" 444 0 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"

Again: what makes you think that these requests shouldn't end up in a catchall block?

/var/log/nginx/000default-error.log: the above 1st request shown in error /debug mode log

2012/02/06 09:58:39 [debug] 24727#0: *6715 http header done
2012/02/06 09:58:40 [debug] 24727#0: *6715 posix_memalign: 0000000002411950:4096 @16
2012/02/06 09:58:40 [debug] 24727#0: *6715 http process request line
2012/02/06 09:58:40 [debug] 24727#0: *6715 http request line: "GET /word/imilu/ HTTP/1.1"
...
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "host: www.mydom.com"
...
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header: "Connection: keep-alive"
2012/02/06 09:58:40 [debug] 24727#0: *6715 http header done

This request is unrelated to the above requests you claim to be incorrectly processed.

It also looks like you've only set error_log to debug level in catchall block. Note log provided stops at "http header done". This actually indicate that rest of the request was processed in another server context, i.e. there is nothing wrong with this particular request.

At the end the only 000default-access.log are

0.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"
10.194.165.253 - - [06/Feb/2012:09:41:10 +0100] "-" 400 0 "-" "-"

....
and so on

As I already explained above, there is nothing wrong with 400 errors. They are expected to be logged in a default server block.

comment:4 by Maxim Dounin, 12 years ago

Resolution: → worksforme
Status: new → closed

Feedback timeout.

comment:5 by Koldo Basterra, 12 years ago

Sorry for taking so long to answer. Posting my production servers config here could be a risk for me so, could I send you private message (to mail accounts referred at mdouin ru) with whole configuration file and whole relevant logs? It's quite important for me to get rid of this strange behaviour.
Tnx in advance.

comment:6 by Maxim Dounin, 12 years ago

Feel free to.

Note: See TracTickets for help on using tickets.