День добрый!

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

Переменная в $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