Opened 6 years ago

Closed 6 years ago

Last modified 3 years ago

#1600 closed defect (invalid)

nginx not fully parsing config file on 400 errors

Reported by: KlavsKlavsen@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.10.x
Keywords: Cc:
uname -a: Linux p-concurrency01.yousee.idk 4.4.0-112-generic #135-Ubuntu SMP Fri Jan 19 11:48:36 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.10.3 (Ubuntu)
built with OpenSSL 1.0.2g 1 Mar 2016
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-ipv6 --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_addition_module --with-http_dav_module --with-http_geoip_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module --with-http_v2_module --with-http_sub_module --with-http_xslt_module --with-stream --with-stream_ssl_module --with-mail --with-mail_ssl_module --with-threads

Description

I have setup our hosts to log to a file with date in it (to make nginx automaticly rotate - and have it log to to a file with current date in it - to log verification in ELk stack system possible (I verify all logs have entered the system - and when nginx switches on EXACT time - I can just do line-counts comparison - instead of having to check for all md5sums).

The config looks like this:

if ($time_iso8601 ~ "(\d{4})-(\d{2})-(\d{2})") {
set $year $1;
set $month $2;
set $day $3;
}

access_log /var/log/nginx/concurrency_access-$year$month$day.log access_log_ok;

However we receive a "few logs" - daily or sometimes only weekly, logged to /var/log/nginx/concurrency_access-.log.

These are ALL HTTP 400 errors.. mostly triggered by people trying to hack the site and a few from real clients (sending bad http request we assume).

The thesis on my end is that nginx identifies the requests as bad HTTP at such an early stage, that it hasn't set the "date" variables above, and yet HAS set the access_log..

Running Ubuntu 16.04 with its nginx.

Change History (2)

comment:1 by Ruslan Ermilov, 6 years ago

Assuming the if block with the set directives is specified on the server{} level, variables are normally initialized during the "server rewrite" request processing phase, see ​http://nginx.org/en/docs/http/ngx_http_rewrite_module.html for details. For an invalid request, nginx terminates it without executing the set directives, so this is expected behavior, not a bug. For example:

2018/07/25 14:47:11 [info] 54356#9236256: *2 client sent invalid method while reading client request line, client: 127.0.0.1, server: , request: "blabla"
2018/07/25 14:47:11 [warn] 54356#9236256: *2 using uninitialized "year" variable while logging request, client: 127.0.0.1, server: , request: "blabla"
2018/07/25 14:47:11 [warn] 54356#9236256: *2 using uninitialized "month" variable while logging request, client: 127.0.0.1, server: , request: "blabla"
2018/07/25 14:47:11 [warn] 54356#9236256: *2 using uninitialized "day" variable while logging request, client: 127.0.0.1, server: , request: "blabla"

comment:2 by Ruslan Ermilov, 6 years ago

Resolution: → invalid
Status: new → closed
Note: See TracTickets for help on using tickets.