Issue while logging after client sent duplicate header

[fffilimonov@…]

Found in a wild. Some proxy from china.
Possible UC-browser.

X-UCBrowser-UA: dv(Mi A1);pr(UCBrowser/12.0.0.1088);ov(Android 8.0.0);ss(423*752);pi(1080*1920);bt(GJ);pm(1);bv(1);nm(0);im(0);sr(0);nt(1);bi(355);fi(145);dn(25926126305-886b8f7e);ai(720089404747345);
User-Agent: Mozilla/5.0 (Linux; U; Android 8.0.0; en-US; Mi A1 Build/OPR1.170623.026) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/57.0.2987.108 UCBrowser/12.0.0.1088 Mobile Safari/537.36

Configuration:

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

		access_log /sites/$host/logs/${year}_${month}_${day}.log;

Request to reproduce:

printf "GET / HTTP/1.1\r\nHost: test.com\r\nIf-None-Match: \"5a2027cf-6d6\"\r\nIf-None-Match: 13:10009~2:10009:4521798~1:10009:4521798\r\n\r\n" | netcat 127.0.0.1 80

The problem:

2018/02/26 22:05:08 [debug] 58329#0: *5 http close request
2018/02/26 22:05:08 [debug] 58329#0: *5 http log handler
2018/02/26 22:05:08 [warn] 58329#0: *5 using uninitialized "year" variable while logging request, client: 127.0.0.1, server: , request: "GET /trk5.js?867435 HTTP/1.1", host: "test.com"
2018/02/26 22:05:08 [warn] 58329#0: *5 using uninitialized "month" variable while logging request, client: 127.0.0.1, server: , request: "GET /trk5.js?867435 HTTP/1.1", host: "test.com"
2018/02/26 22:05:08 [warn] 58329#0: *5 using uninitialized "day" variable while logging request, client: 127.0.0.1, server: , request: "GET /trk5.js?867435 HTTP/1.1", host: "test.com"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script copy: "/sites/"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script var: "test.com"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script copy: "/logs/"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script var: ""
2018/02/26 22:05:08 [debug] 58329#0: *5 http script copy: "_"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script var: ""
2018/02/26 22:05:08 [debug] 58329#0: *5 http script copy: "_"
2018/02/26 22:05:08 [debug] 58329#0: *5 http script var: ""
2018/02/26 22:05:08 [debug] 58329#0: *5 http script copy: ".log"
2018/02/26 22:05:08 [debug] 58329#0: *5 http log "/sites//logs/__.log"

But the real proxy sends request where Host header located after f-None-Match:

printf "GET / HTTP/1.1\r\nIf-None-Match: \"5a2027cf-6d6\"\r\nIf-None-Match: 13:10009~2:10009:4521798~1:10009:4521798\r\nHost: test.com\r\n\r\n" | netcat 127.0.0.1 80

In this case $host is empty:

2018/02/26 22:14:52 [debug] 58332#0: *7 http close request
2018/02/26 22:14:52 [debug] 58332#0: *7 http log handler
2018/02/26 22:14:52 [warn] 58332#0: *7 using uninitialized "year" variable while logging request, client: 127.0.0.1, server: , request: "GET / HTTP/1.1"
2018/02/26 22:14:52 [warn] 58332#0: *7 using uninitialized "month" variable while logging request, client: 127.0.0.1, server: , request: "GET / HTTP/1.1"
2018/02/26 22:14:52 [warn] 58332#0: *7 using uninitialized "day" variable while logging request, client: 127.0.0.1, server: , request: "GET / HTTP/1.1"
2018/02/26 22:14:52 [debug] 58332#0: *7 http script copy: "/sites/"
2018/02/26 22:14:52 [debug] 58332#0: *7 http script var: ""
2018/02/26 22:14:52 [debug] 58332#0: *7 http script copy: "/logs/"
2018/02/26 22:14:52 [debug] 58332#0: *7 http script var: ""
2018/02/26 22:14:52 [debug] 58332#0: *7 http script copy: "_"
2018/02/26 22:14:52 [debug] 58332#0: *7 http script var: ""
2018/02/26 22:14:52 [debug] 58332#0: *7 http script copy: "_"
2018/02/26 22:14:52 [debug] 58332#0: *7 http script var: ""
2018/02/26 22:14:52 [debug] 58332#0: *7 http script copy: ".log"
2018/02/26 22:14:52 [debug] 58332#0: *7 http log "/sites//logs/__.log"
2018/02/26 22:14:52 [debug] 58332#0: *7 add cleanup: 00007FC32D005BE8
2018/02/26 22:14:52 [crit] 58332#0: *7 open() "/sites//logs/__.log" failed (2: No such file or directory) while logging request, client: 127.0.0.1, server: , request: "GET / HTTP/1.1"

[Maxim Dounin]

The observed behaviour is not a bug in nginx, but rather a result of the incorrect configuration. If a request is rejected during early processing stages (in this particular case - while parsing request headers), before executing ​rewrite module directives, variables $year, $month, and $day are not set. And nginx correctly complains about using uninitialized variables.

Fixing this will require re-writing the configuration to behave properly in such edge cases. I personally would recommend to use a fixed log file name and ​log rotation, as it is fastest and the most reliable approach. If you really need to use a log file name with date for some reason, consider using ​map