Nginx-1.0.4

dubstep · June 1, 2011, 11:35am

Changes with nginx 1.0.4 01 Jun
2011

*) Change: now regular expressions case sensitivity in the "map"
   directive is given by prefixes "~" or "~*".

*) Feature: now shared zones and caches use POSIX semaphores on

Linux.
Thanks to Denis F. Latypoff.

*) Bugfix: "stalled" cache updating" alert.

*) Bugfix: nginx could not be built

–without-http_auth_basic_module;
the bug had appeared in 1.0.3.

–
Igor S.

imixaly4 · June 15, 2011, 12:12am

Hello!

On Tue, Jun 14, 2011 at 04:48:04PM -0400, brunohardhouse wrote:

0.0.0.0:80
error:0 while closing request, client: 200.219.211.202, server:
0.0.0.0:80
2011/06/13 10:51:05 [alert] 27747#0: *25098108 stalled cache updating,
error:0 while closing request, client: 200.219.211.202, server:
0.0.0.0:80

Any ideia?

Could you please provide nginx -V output, config and debug log?
See here for more details:

Maxim D.

imixaly4 · June 14, 2011, 10:48pm

Hi Igor.

Uptade to nginx-1.0.4, but alerts persists.

/usr/local/nginx/sbin/nginx -v
nginx: nginx version: nginx/1.0.4

tail -f /var/log/nginx/error.log
2011/06/13 09:28:02 [alert] 27724#0: *24550041 stalled cache updating,
error:0 while closing request, client: 200.255.122.27, server:
0.0.0.0:80
2011/06/13 09:36:55 [alert] 27750#0: *24599084 stalled cache updating,
error:0 while closing request, client: 187.77.132.124, server:
0.0.0.0:80
2011/06/13 09:37:07 [alert] 27755#0: *24601014 stalled cache updating,
error:0 while closing request, client: 189.47.172.58, server:
0.0.0.0:80
2011/06/13 10:02:28 [alert] 27725#0: *24756871 stalled cache updating,
error:0 while closing request, client: 200.171.142.31, server:
0.0.0.0:80
2011/06/13 10:51:05 [alert] 27747#0: *25098105 stalled cache updating,
error:0 while closing request, client: 200.219.211.202, server:
0.0.0.0:80
2011/06/13 10:51:05 [alert] 27747#0: *25098108 stalled cache updating,
error:0 while closing request, client: 200.219.211.202, server:
0.0.0.0:80

Any ideia?

Thanks

Posted at Nginx Forum:

imixaly4 · June 15, 2011, 10:00am

Hello!

On Tue, Jun 14, 2011 at 11:07:50PM -0400, brunohardhouse wrote:

            server x.x.x.x;
              }
2011/06/14 23:41:22 [debug] 4717#0: *27130 finalize http proxy request
Could you please show at least all lines with ’ *27130 ’ from the
log? You showed only some last lines from the connection in
question, and this is clearly not enough to say anything.

[…]

2011/06/14 23:41:22 [debug] 4704#0: epoll timer: 7044
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache cleanup
2011/06/14 23:41:22 [alert] 4717#0: *27130 stalled cache updating,
error:0 while closing request, client: 189.58.56.239, server:
0.0.0.0:80
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache free, fd: 53

[…]

Maxim D.

imixaly4 · June 15, 2011, 5:08am

Sorry,

/usr/local/nginx/sbin/nginx -V
nginx: nginx version: nginx/1.0.4
nginx: built by gcc 4.4.3 (Ubuntu 4.4.3-4ubuntu5)
nginx: TLS SNI support enabled
nginx: configure arguments: --with-http_ssl_module --with-debug
–with-http_gzip_static_module --with-http_stub_status_module

Part of Config:

http {
proxy_cache_path /usr/local/nginx/html/cache levels=1:2
keys_zone=my-cache:8m max_size=1000m inactive=600m;
proxy_temp_path /usr/local/nginx/html/cache/tmp;
}

server {

   upstream backend-img  {
            server x.x.x.x;
            server x.x.x.x;
    }


   location ~* \.(png|gif|jpg|bmp|jpeg|swf|fla|js|css)$ {
            proxy_buffering           on;
            proxy_cache my-cache;
            proxy_cache_valid  200 302  120m;
           #proxy_cache_valid  404      1m;
            expires 86400;
            proxy_pass http://backend-img;
              }
  }

Debug log:

2011/06/14 23:41:22 [debug] 4704#0: *27136 http copy filter:
“/201103/04/I_M_44112691.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 finalize http upstream
request: -1
2011/06/14 23:41:22 [debug] 4704#0: *27136 http postpone filter
“/201103/04/I_M_44112691.JPG?” 00007FFF0E740E10
2011/06/14 23:41:22 [debug] 4717#0: *27130 finalize http proxy request
2011/06/14 23:41:22 [debug] 4704#0: *27136 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free rr peer 2 0
2011/06/14 23:41:22 [debug] 4704#0: *27136 http write filter: l:1 f:0
s:0
2011/06/14 23:41:22 [debug] 4717#0: *27130 close http upstream
connection: 54
2011/06/14 23:41:22 [debug] 4704#0: *27136 http copy filter: 0
“/201103/04/I_M_44112691.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer del: 54:
1308106282252
2011/06/14 23:41:22 [debug] 4704#0: *27136 http finalize request: 0,
“/201103/04/I_M_44112691.JPG?” a:1, c:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 reusable connection: 0
2011/06/14 23:41:22 [debug] 4704#0: *27136 http request count:1 blk:0
2011/06/14 23:41:22 [debug] 4704#0: *27136 http close request
2011/06/14 23:41:22 [debug] 4704#0: *27136 http log handler
2011/06/14 23:41:22 [debug] 4704#0: *27136 posix_memalign:
00000000023BCBD0:4096 @16
2011/06/14 23:41:22 [debug] 4704#0: *27136 run cleanup:
0000000002396688
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 000000000239CBC0
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002395740,
unused: 2
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002398760,
unused: 80
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 00000000023BCBD0,
unused: 3560
2011/06/14 23:41:22 [debug] 4717#0: *27130 http finalize request: -1,
“/201010/01/I_P_41105460.JPG?” a:1, c:1
2011/06/14 23:41:22 [debug] 4704#0: *27136 close http connection: 102
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate request
count:1
2011/06/14 23:41:22 [debug] 4704#0: *27136 reusable connection: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate cleanup
count:1 blk:0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http posted request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate handler
count:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 http request count:1 blk:0
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002396750
2011/06/14 23:41:22 [debug] 4717#0: *27130 http close request
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002391D00
2011/06/14 23:41:22 [debug] 4717#0: *27130 http log handler
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002391700
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002393230,
unused: 8
2011/06/14 23:41:22 [debug] 4704#0: *27136 free: 0000000002391BF0,
unused: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 run cleanup:
000000000238E7E0
2011/06/14 23:41:22 [debug] 4704#0: posted event 0000000000000000
2011/06/14 23:41:22 [debug] 4717#0: *27130 file cleanup: fd:53
2011/06/14 23:41:22 [debug] 4704#0: worker cycle
2011/06/14 23:41:22 [debug] 4704#0: accept mutex locked
2011/06/14 23:41:22 [debug] 4717#0: *27130 run cleanup:
000000000238E780
2011/06/14 23:41:22 [debug] 4704#0: epoll timer: 7044
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache cleanup
2011/06/14 23:41:22 [alert] 4717#0: *27130 stalled cache updating,
error:0 while closing request, client: 189.58.56.239, server:
0.0.0.0:80
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache free, fd: 53
2011/06/14 23:41:22 [debug] 4717#0: shmtx lock
2011/06/14 23:41:22 [debug] 4717#0: shmtx unlock
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023A9CB0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 000000000238D830,
unused: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023654E0,
unused: 86
2011/06/14 23:41:22 [debug] 4717#0: *27130 close http connection: 47
2011/06/14 23:41:22 [debug] 4717#0: *27130 reusable connection: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023950F0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 0000000002370520
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 000000000235E100,
unused: 8
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023A9980,
unused: 128
2011/06/14 23:41:22 [debug] 4717#0: timer delta: 2
2011/06/14 23:41:22 [debug] 4717#0: posted events 0000000000000000
2011/06/14 23:41:22 [debug] 4717#0: worker cycle
2011/06/14 23:41:22 [debug] 4717#0: accept mutex lock failed: 0
2011/06/14 23:41:22 [debug] 4717#0: epoll timer: 500
2011/06/14 23:41:22 [debug] 4722#0: epoll: fd:65 ev:0005
d:00007F6C76ED9390
2011/06/14 23:41:22 [debug] 4722#0: *26419 http upstream request:
“/imovel/flat-alugar/sp/sao-paulo/jardins/90665944.iw?precomaximo=2000&quartos=1,2,3,4,5&idtipoimovel=2,1,4&idlocalidade=118,34,121,478,127,49,53,129,130,464,139&idlocalizacao=1&idsublocalizacao=3”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http upstream process header
2011/06/14 23:41:22 [debug] 4722#0: *26419 malloc:
00000000023986B0:131072
2011/06/14 23:41:22 [debug] 4722#0: *26419 posix_memalign:
0000000002389DA0:4096 @16
2011/06/14 23:41:22 [debug] 4722#0: *26419 recv: fd:65 2896 of 131072
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy status 200 “200
OK”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“Cache-Control: private”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“Content-Type: text/html; charset=utf-8”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“Content-Encoding: gzip”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header: “Server:
Microsoft-IIS/7.5”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“X-AspNet-Version: 2.0.50727”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“X-Powered-By: ASP.NET”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header: “Date:
Wed, 15 Jun 2011 02:43:53 GMT”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“Connection: close”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header:
“Content-Length: 52416”
2011/06/14 23:41:22 [debug] 4722#0: *26419 http proxy header done
2011/06/14 23:41:22 [debug] 4722#0: *26419 HTTP/1.1 200 OK^M
Server: nginx/1.0.4^M
Date: Wed, 15 Jun 2011 02:41:22 GMT^M
Content-Type: text/html; charset=utf-8^M
Connection: keep-alive^M
Cache-Control: private^M
Content-Encoding: gzip^M
Content-Length: 52416^M

Thanks.

Posted at Nginx Forum:

imixaly4 · June 16, 2011, 4:21pm

Ok,

2011/06/14 23:40:31 [debug] 4709#0: *21381 cache file:
“/usr/local/nginx/html/cache/d/4a/177447d52a18b467b727130b5cee34ad”
2011/06/14 23:41:11 [debug] 4705#0: *25910 event timer: 105, old:
1308106271290, new: 1308106271300
2011/06/14 23:41:22 [debug] 4717#0: *27130 accept: 189.58.56.239 fd:47
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer add: 47:
60000:1308105742222
2011/06/14 23:41:22 [debug] 4717#0: *27130 epoll add event: fd:47 op:1
ev:80000001
2011/06/14 23:41:22 [debug] 4717#0: *27130 malloc:
0000000002370520:1256
2011/06/14 23:41:22 [debug] 4717#0: *27130 posix_memalign:
00000000023A9980:256 @16
2011/06/14 23:41:22 [debug] 4717#0: *27130 malloc:
00000000023950F0:1024
2011/06/14 23:41:22 [debug] 4717#0: *27130 posix_memalign:
000000000238D830:4096 @16
2011/06/14 23:41:22 [debug] 4717#0: *27130 http process request line
2011/06/14 23:41:22 [debug] 4717#0: *27130 recv: fd:47 872 of 1024
2011/06/14 23:41:22 [debug] 4717#0: *27130 http request line: “GET
/201010/01/I_P_41105460.JPG HTTP/1.1”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http uri:
“/201010/01/I_P_41105460.JPG”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http args: “”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http exten: “JPG”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http process request header
line
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “Host:
f3.site.com.br”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “Connection:
keep-alive”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “Referer:
http://www.zura.com.br/imoveis--casa.html?utm_medium=cpc&utm_campaign=Google&utm_source=google”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “User-Agent:
Mozilla/5.0 (Windows NT 6.0) AppleWebKit/534.30 (KHTML, like Gecko)
Chrome/12.0.742.91 Safari/534.30”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “Accept: /”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header:
“Accept-Encoding: gzip,deflate,sdch”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header:
“Accept-Language: pt-BR,pt;q=0.8,en-US;q=0.6,en;q=0.4”
2011/06/14 23:41:22 [debug] 4717#0: 27130 http header: "Accept-Charset:
ISO-8859-1,utf-8;q=0.7,;q=0.3"
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header: “Cookie:
__utmz=244711514.1308105741.9.9.utmgclid=CKiw4-XxtqkCFcwS2godfTUf9A|utmccn=(not%20set)|utmcmd=(not%20set)|utmctr=casa%20locaÃ§ao%20maringa;
__utma=244711514.1662326553.1306429956.1307998954.1308105741.9;
__utmb=244711514.1.10.1308105741;__utmc=244711514;
OASiw_ad_operacao=OASiw_ad_operacao=4;
OASiw_ad_estado=OASiw_ad_estado=24; OASiw_ad_cidade=OASiw_ad_cidade=379;
OASiw_ad_tipo=OASiw_ad_tipo=1”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http header done
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer del: 47:
1308105742222
2011/06/14 23:41:22 [debug] 4717#0: *27130 rewrite phase: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 test location: “/”
2011/06/14 23:41:22 [debug] 4717#0: *27130 test location: “50x.html”
2011/06/14 23:41:22 [debug] 4717#0: *27130 test location: ~
“.(png|gif|jpg|bmp|jpeg|swf|fla|js|css)$”
2011/06/14 23:41:22 [debug] 4717#0: *27130 using configuration
“.(png|gif|jpg|bmp|jpeg|swf|fla|js|css)$”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http cl:-1 max:73400320
2011/06/14 23:41:22 [debug] 4717#0: *27130 rewrite phase: 2
2011/06/14 23:41:22 [debug] 4717#0: *27130 post rewrite phase: 3
2011/06/14 23:41:22 [debug] 4717#0: *27130 generic phase: 4
2011/06/14 23:41:22 [debug] 4717#0: *27130 generic phase: 5
2011/06/14 23:41:22 [debug] 4717#0: *27130 access phase: 6
2011/06/14 23:41:22 [debug] 4717#0: *27130 access phase: 7
2011/06/14 23:41:22 [debug] 4717#0: *27130 post access phase: 8
2011/06/14 23:41:22 [debug] 4717#0: *27130 http init upstream, client
timer: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 epoll add event: fd:47 op:3
ev:80000005
2011/06/14 23:41:22 [debug] 4717#0: *27130 posix_memalign:
00000000023654E0:4096 @16
2011/06/14 23:41:22 [debug] 4717#0: *27130 http cache key:
“http://backend-img”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http cache key:
“/201010/01/I_P_41105460.JPG”
2011/06/14 23:41:22 [debug] 4717#0: *27130 add cleanup:
000000000238E780
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache exists: 0
e:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 cache file:
“/usr/local/nginx/html/cache/a/9f/d17d197d0f71972be71dae9a835809fa”
2011/06/14 23:41:22 [debug] 4717#0: *27130 add cleanup:
000000000238E7E0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache fd: 53
2011/06/14 23:41:22 [debug] 4717#0: *27130 read: 53, 00000000023656D0,
336, 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache expired: 4
1307706389 1308105682
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream cache: 4
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy: "Host: "
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script var:
“f3.site.com.br”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy: "^M
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy: "X-Real-IP:
"
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script var:
“189.58.56.239”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy: "^M
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy:
"X-Forwarded-For: "
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script var:
“189.58.56.239”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy: "^M
2011/06/14 23:41:22 [debug] 4717#0: *27130 http script copy:
“Connection: close^M
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Referer:
http://www.zura.com.br/imoveis--casa.html?utm_medium=cpc&utm_campaign=Google&utm_source=google”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“User-Agent: Mozilla/5.0 (Windows NT 6.0) AppleWebKit/534.30 (KHTML,
like Gecko) Chrome/12.0.742.91 Safari/534.30”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Accept:
/”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Accept-Encoding: gzip,deflate,sdch”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Accept-Language: pt-BR,pt;q=0.8,en-US;q=0.6,en;q=0.4”
2011/06/14 23:41:22 [debug] 4717#0: 27130 http proxy header:
"Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.3”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Cookie:
__utmz=244711514.1308105741.9.9.utmgclid=CKiw4-XxtqkCFcwS2godfTUf9A|utmccn=(not%20set)|utmcmd=(not%20set)|utmctr=casa%20locaÃ§ao%20maringa;
__utma=244711514.1662326553.1306429956.1307998954.1308105741.9;
__utmb=244711514.1.10.130815741; __utmc=244711514;
OASiw_ad_operacao=OASiw_ad_operacao=4;
OASiw_ad_estado=OASiw_ad_estado=24; OASiw_ad_cidade=OASiw_ad_cidade=379;
OASiw_ad_tipo=OASiw_ad_tipo=1”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
2011/06/14 23:41:22 [debug] 4717#0: *27130 http cleanup add:
0000000002365C70
2011/06/14 23:41:22 [debug] 4717#0: *27130 get rr peer, try: 2
2011/06/14 23:41:22 [debug] 4717#0: *27130 get rr peer, current: 1 1
2011/06/14 23:41:22 [debug] 4717#0: *27130 socket 54
2011/06/14 23:41:22 [debug] 4717#0: *27130 epoll add connection: fd:54
ev:80000005
2011/06/14 23:41:22 [debug] 4717#0: *27130 connect to 10.1.111.13:80,
fd:54 #27135
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream connect: -2
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer add: 54:
600000:1308106282252
2011/06/14 23:41:22 [debug] 4717#0: *27130 http finalize request: -4,
“/201010/01/I_P_41105460.JPG?” a:1, c:2
2011/06/14 23:41:22 [debug] 4717#0: *27130 http request count:2 blk:0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http run request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream check client,
write event:0, “/201010/01/I_P_41105460.JPG”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream recv(): 0 (115:
Operation now in progress)
2011/06/14 23:41:22 [info] 4717#0: *27130 client closed prematurely
connection while connecting to upstream, client: 189.58.56.239, server:
localhost, request: “GET /201010/01/I_P_41105460.JPG HTTP/1.1”,
upstream: “http://10.1.111.13:80/201010/01/I_P_41105460.JPG”, host:
“f3.site.com.br”, referrer:
“http://www.zura.com.br/imoveis--casa.html?utm_medium=cpc&utm_campaign=Google&utm_source=google”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http run request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream check client,
write event:1, “/201010/01/I_P_41105460.JPG”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream send request
handler
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream send request
2011/06/14 23:41:22 [debug] 4717#0: *27130 chain writer buf fl:1 s:925
2011/06/14 23:41:22 [debug] 4717#0: *27130 chain writer in:
000000000238E820
2011/06/14 23:41:22 [debug] 4717#0: *27130 writev: 925
2011/06/14 23:41:22 [debug] 4717#0: *27130 chain writer out:
0000000000000000
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer del: 54:
1308106282252
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer add: 54:
600000:1308106282252
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http upstream process header
2011/06/14 23:41:22 [debug] 4717#0: *27130 malloc:
00000000023A9CB0:131072
2011/06/14 23:41:22 [debug] 4717#0: *27130 recv: fd:54 2896 of 130980
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy status 200 “200
OK”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Cache-Control: no-cache”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Content-Type: image/jpeg”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Last-Modified: Fri, 01 Oct 2010 19:38:35 GMT”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Accept-Ranges: bytes”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: "ETag:
“dc8fb3ca061cb1:0"”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Server:
Microsoft-IIS/7.5”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“X-Powered-By: ASP.NET”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Date:
Wed, 15 Jun 2011 02:43:52 GMT”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Connection: close”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header:
“Content-Length: 34474”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header done
2011/06/14 23:41:22 [debug] 4717#0: *27130 HTTP/1.1 200 OK^M
2011/06/14 23:41:22 [debug] 4717#0: *27130 finalize http upstream
request: -1
2011/06/14 23:41:22 [debug] 4717#0: *27130 finalize http proxy request
2011/06/14 23:41:22 [debug] 4717#0: *27130 free rr peer 2 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 close http upstream
connection: 54
2011/06/14 23:41:22 [debug] 4717#0: *27130 event timer del: 54:
1308106282252
2011/06/14 23:41:22 [debug] 4717#0: *27130 reusable connection: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http finalize request: -1,
“/201010/01/I_P_41105460.JPG?” a:1, c:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate request
count:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate cleanup
count:1 blk:0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http posted request:
“/201010/01/I_P_41105460.JPG?”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http terminate handler
count:1
2011/06/14 23:41:22 [debug] 4717#0: *27130 http request count:1 blk:0
2011/06/14 23:41:22 [debug] 4717#0: *27130 http close request
2011/06/14 23:41:22 [debug] 4717#0: *27130 http log handler
2011/06/14 23:41:22 [debug] 4717#0: *27130 run cleanup:
000000000238E7E0
2011/06/14 23:41:22 [debug] 4717#0: *27130 file cleanup: fd:53
2011/06/14 23:41:22 [debug] 4717#0: *27130 run cleanup:
000000000238E780
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache cleanup
2011/06/14 23:41:22 [alert] 4717#0: *27130 stalled cache updating,
error:0 while closing request, client: 189.58.56.239, server:
0.0.0.0:80
2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache free, fd: 53
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023A9CB0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 000000000238D830,
unused: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023654E0,
unused: 86
2011/06/14 23:41:22 [debug] 4717#0: *27130 close http connection: 47
2011/06/14 23:41:22 [debug] 4717#0: *27130 reusable connection: 0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023950F0
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 0000000002370520
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 000000000235E100,
unused: 8
2011/06/14 23:41:22 [debug] 4717#0: *27130 free: 00000000023A9980,
unused: 128
2011/06/14 23:42:47 [debug] 4722#0: *35619 event timer add: 54:
60000:1308105827130
2011/06/14 23:42:47 [debug] 4722#0: *35621 event timer add: 69:
60000:1308105827130
2011/06/14 23:42:47 [debug] 4722#0: *35619 event timer del: 54:
1308105827130
2011/06/14 23:42:47 [debug] 4722#0: *35621 event timer del: 69:
1308105827130
2011/06/14 23:42:53 [debug] 4708#0: *36339 http header: “Content-Length:
27130”
2011/06/14 23:42:53 [debug] 4708#0: *36339 http cl:27130 max:73400320
2011/06/14 23:42:54 [debug] 4708#0: *36339 http proxy header:
“Content-Length: 27130”
Content-Length: 27130^M

Thanks

Posted at Nginx Forum:

imixaly4 · June 18, 2011, 1:35am

Hello!

On Thu, Jun 16, 2011 at 10:20:53AM -0400, brunohardhouse wrote:

[…]

2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache expired: 4 1307706389
1308105682

[…]

2011/06/14 23:41:22 [info] 4717#0: *27130 client closed prematurely connection
while connecting to upstream, …

[…]

2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy status 200 “200 OK”
2011/06/14 23:41:22 [debug] 4717#0: *27130 http proxy header: “Cache-Control:
no-cache”

[…]

2011/06/14 23:41:22 [debug] 4717#0: *27130 http file cache cleanup
2011/06/14 23:41:22 [alert] 4717#0: *27130 stalled cache updating …

Thank you for details, I was able to reproduce this issue here.
Key points are:

Existing expired cache entry (i.e. cache updating).
Client abort before nginx was able to receive response header
from upstream.
Non-cacheable response from upstream.

I’ll take a look how to properly fix this.

Maxim D.

imixaly4 · June 24, 2011, 5:03am

Hello!

On Sat, Jun 18, 2011 at 03:35:31AM +0400, Maxim D. wrote:

[…]

I’ll take a look how to properly fix this.
Please try the attached patch.

Maxim D.

imixaly4 · June 29, 2011, 3:59pm

Very nice,

I’ll test the patch.

Thanks for the help.

Posted at Nginx Forum:

imixaly4 · June 22, 2011, 4:25pm

Thanks Maxim D…

Posted at Nginx Forum: