image_filter request_time

[Sovigod]

День добрый!

Столкнулся с проблемой логирования.

Переменная в $request_time всегда равна 0 в запросах использующих ресайз
картинки модулем image_filter

Формат лога
        log_format main
                '$remote_addr [$time_local] '
                '$host "$request" St:"$status" $bytes_sent
Cookie:"$http_cookie"'
                '"$http_referer" "$http_user_agent" '
                '"$upstream_addr"  ReqTime:"$request_time"
"$upstream_response_time" Cache:"$upstream_cache_status"';


Примеры из лога

127.0.0.1 [20/Apr/2015:15:22:15 +0300] cdn2 "GET
/r/GoqWrJ_RZ0IOiC4zBOWgtw/-x180/user/106/1062391/201501/18f778458b1f94f84ea5f2a53630e4a4.jpg
HTTP/1.1" St:"200" 17582 Cookie:"-""http://www..ru/" "Mozilla/5.0 (Windows
NT 5.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.115
YaBrowser/15.2.2214.3645 Safari/537.36" "-"  ReqTime:"0.000" "-" Cache:"-"
127.0.0.1 [20/Apr/2015:15:22:16 +0300] img "GET
/r/QIO69D7020HASPoycSl87w/-x180/0/7/5/075a6864f64655922ee112ab6e99ee05.jpg
HTTP/1.1" St:"404" 334 Cookie:"-""-" "msnbot-media/1.1
(+http://search.msn.com/msnbot.htm)" "-"  ReqTime:"0.000" "-" Cache:"-"
127.0.0.1 [20/Apr/2015:15:22:16 +0300] cdn "GET
/r/Bqbdq4LKoZXz9cTH_xKAMA/60x60/navatar/75/752884/141aa5e66843f2e56651043be9b4408a.jpg
HTTP/1.1" St:"200" 4031 Cookie:"-""http://m..ru/" "Mozilla/5.0 (iPhone; CPU
iPhone OS 8_2 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko)
Version/8.0 Mobile/12D508 Safari/600.1.4" "-"  ReqTime:"0.000" "-"
Cache:"-"


конфиг сервера


	server {
	        listen      8081;
		access_log "/var/log/nginx/img-resize-access_log" main;
		error_log "/var/log/nginx/img-resize-error_log" info;
		error_page 403 404 415 500 502 503 504 = /404;

		image_filter_buffer 3M;

		location ~ ^/i/([^/]+)/(.+) {
			alias /mnt/imgbbr4/$2;
			secure_link $1;
			secure_link_md5  123/$2;
			try_files "" /404;
			if ($secure_link = "") { return 404; }
			image_filter size;
		}

                location ~ ^/c/([^/]+)/(\d+|-)x(\d+|-)/(.+) {
			secure_link $1;
			secure_link_md5  123/$4;
                        set $width  $2;
                        set $height $3;
                        alias /mnt/imgbbr4/$4;
                        try_files "" /404;
                        if ($secure_link = "") { return 404; }
                        image_filter crop  $width  $height;
                }

                location ~ ^/r/([^/]+)/(\d+|-)x(\d+|-)/(.+) {
			secure_link $1;
			secure_link_md5  123/$4;
                        set $width  $2;
                        set $height $3;
                        alias /mnt/imgbbr4/$4;
                        try_files "" /404;
                        if ($secure_link = "") { return 404; }
			image_filter_jpeg_quality 95;
                        image_filter resize  $width  $height;
                }

                location /404 { return 404; }
	    }


cdn01 inc # nginx -V
nginx version: nginx/1.7.6
TLS SNI support enabled
configure arguments: --prefix=/usr --conf-path=/etc/nginx/nginx.conf
--error-log-path=/var/log/nginx/error_log --pid-path=/run/nginx.pid
--lock-path=/run/lock/nginx.lock --with-cc-opt=-I/usr/include
--with-ld-opt=-L/usr/lib64 --http-log-path=/var/log/nginx/access_log
--http-client-body-temp-path=//var/lib/nginx/tmp/client
--http-proxy-temp-path=//var/lib/nginx/tmp/proxy
--http-fastcgi-temp-path=//var/lib/nginx/tmp/fastcgi
--http-scgi-temp-path=//var/lib/nginx/tmp/scgi
--http-uwsgi-temp-path=//var/lib/nginx/tmp/uwsgi --with-file-aio
--with-aio_module --with-ipv6 --with-pcre --with-http_geoip_module
--with-http_image_filter_module --with-http_secure_link_module
--with-http_stub_status_module --with-http_realip_module
--add-module=external_module/headers-more-nginx-module-0.25
--add-module=external_module/ngx_slowfs_cache-1.10
--add-module=external_module/nginx-push-stream-module-0.4.0
--with-http_ssl_module --without-mail_imap_module --without-mail_pop3_module
--without-mail_smtp_module --user=nginx --group=nginx

Posted at Nginx Forum: http://forum.nginx.org/read.php?21,258211,258211#msg-258211