Cache always in "UPDATING"

Tue Sep 13 23:52:59 UTC 2016

Dear list,

I'm having a problem that comes on goes the past months:
The cache does not get updated as it seems to stay in "UPDATING" state. This
issue comes at random times/days.

Here's what i got in strace:

accept4(12, {sa_family=AF_INET, sin_port=htons(58777),
sin_addr=inet_addr("127.0.0.2")}, [16], SOCK_NONBLOCK) = 21
epoll_ctl(5, EPOLL_CTL_ADD, 21, {EPOLLIN|EPOLLRDHUP|EPOLLET,
{u32=3067699929, u64=579221740737618649}}) = 0
accept4(12, 0xbff7246d, [110], SOCK_NONBLOCK) = -1 EAGAIN (Resource
temporarily unavailable)
epoll_wait(5, {{EPOLLIN, {u32=3067699929, u64=579221740737618649}}}, 512,
10000) = 1
gettimeofday({1473804868, 803688}, NULL) = 0
recv(21, "GET / HTTP/1.1\r\nUser-Agent: curl/7.38.0\r\nAccept: */*\r\nHost:
XXX\r\n\r\n", 1024, 0) = 77
gettimeofday({1473804868, 803772}, {0, 0}) = 0
epoll_ctl(5, EPOLL_CTL_MOD, 21, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET,
{u32=3067699929, u64=578894043322868441}}) = 0
open("/cache/2/6c/6c73f0510dc53eb46a3a903dbd2436c3",
O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 23
fstat64(23, {st_mode=S_IFREG|0600, st_size=22807, ...}) = 0
futex(0xb69707c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0xb697078, {FUTEX_OP_SET, 0,
FUTEX_OP_CMP_GT, 1}) = 1
futex(0xb697054, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_wait(5, {{EPOLLOUT, {u32=3067699929, u64=578894043322868441}},
{EPOLLIN, {u32=151317344, u64=13218850954218367840}}}, 512, -1) = 2
gettimeofday({1473804868, 803935}, NULL) = 0
gettimeofday({1473804868, 803966}, {0, 0}) = 0
futex(0xb69707c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0xb697078, {FUTEX_OP_SET, 0,
FUTEX_OP_CMP_GT, 1}) = 1
futex(0xb697054, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_wait(5, {{EPOLLIN, {u32=151317344, u64=13218850954218367840}}}, 512,
12000) = 1
gettimeofday({1473804868, 804045}, NULL) = 0
writev(21, [{"HTTP/1.1 200 OK\r\nServer:...............[....]
getsockname(21, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("127.0.0.2")}, [16]) = 0
write(18,...............[....]
close(23)                               = 0
setsockopt(21, SOL_TCP, TCP_NODELAY, [1], 4) = 0
recv(21, 0xb20c838, 1024, 0)            = -1 EAGAIN (Resource temporarily
unavailable)
epoll_wait(5, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=3067699929,
u64=578894043322868441}}}, 512, 15000) = 1
gettimeofday({1473804868, 805467}, NULL) = 0
recv(21, "", 1024, 0)                   = 0
close(21)                               = 0

and debug log (highly edited, left what i think is important)

2016/09/13 22:26:27 [debug] 18410#18410: *131592 http cache key:
"httpwww.XXXXXGET/"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 add cleanup: 0B899EF0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache exists: 0
e:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 cache file:
"/cache/2/6c/6c73f0510dc53eb46a3a903dbd2436c3"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 add cleanup: 0B899F34
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache fd: 18
2016/09/13 22:26:27 [debug] 18410#18410: *131592 thread read: 18, 0AF4D188,
1046, 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http upstream cache: -2
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http finalize request: -4,
"/?" a:1, c:3
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http request count:3 blk:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http finalize request: -4,
"/?" a:1, c:2
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http request count:2 blk:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 post event 0B8D36A0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 delete posted event
0B8D36A0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http run request: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache thread:
"/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 thread read: 18, 0AF4D188,
1046, 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache expired: 5
1473770937 1473805587
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http upstream cache: 5
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy status 200 "200
OK"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header: "Date:
Tue, 13 Sep 2016 12:45:57 GMT"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header: "Server:
Apache/2.2.22"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header:
"Set-Cookie: XXX"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header: "Vary:
Accept-Encoding"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header:
"Connection: close"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header:
"Content-Type: text/html"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http proxy header done
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache send:
/cache/2/6c/6c73f0510dc53eb46a3a903dbd2436c3
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http subs filter header
"/"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 malloc: 0B1FD720:32768
2016/09/13 22:26:27 [debug] 18410#18410: *131592 malloc: 0B47A5E0:32768
2016/09/13 22:26:27 [debug] 18410#18410: *131592 HTTP/1.1 200 OK
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0AF4DBF0, pos 0AF4DBF0, size: 171 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http write filter: l:0 f:0
s:171
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http output filter "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http copy filter: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 malloc: 0B6D93B8:21761
2016/09/13 22:26:27 [debug] 18410#18410: *131592 thread read: 18, 0B6D93B8,
21761, 1046
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http copy filter: -2 "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http finalize request: -2,
"/?" a:1, c:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 event timer add: 10:
12000:631817156
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http run request: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http writer handler: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http output filter "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http copy filter: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 thread read: 18, 0B6D93B8,
21761, 1046
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http subs filter "/"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs in buffer:0AF4DCF0,
size:21761, flush:0, last_buf:0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs process in buffer:
0AF4DCF0 21761, line_in buffer: 0AF4DB3C 0
[..subs..]
2016/09/13 22:26:27 [debug] 18410#18410: *131592 match counts: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 find linefeed: 0B6DE8B1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 match counts: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 find linefeed: 00000000
2016/09/13 22:26:27 [debug] 18410#18410: *131592 the last buffer, not find
linefeed
2016/09/13 22:26:27 [debug] 18410#18410: *131592 match counts: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DDA8,
size:4096, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DDEC,
size:4096, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DE30,
size:4096, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DE74,
size:4096, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DEB8,
size:4096, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out buffer:0AF4DEFC,
size:1340, t:0, l:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http postpone filter "/?"
0AF4DDA0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 4096
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 4096
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 4096
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 4096
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 4096
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http chunk: 1340
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write old buf t:1 f:0
0AF4DBF0, pos 0AF4DBF0, size: 171 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0AF4DFA4, pos 0AF4DFA4, size: 6 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 posix_memalign:
0AEC0330:4096 @16
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0B6A6E48, pos 0B6A6E48, size: 4096 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0B04C848, pos 0B04C848, size: 4096 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0B37BE20, pos 0B37BE20, size: 4096 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0B7B8C00, pos 0B7B8C00, size: 4096 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0AF06900, pos 0AF06900, size: 4096 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:1 f:0
0B6646F0, pos 0B6646F0, size: 1340 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 write new buf t:0 f:0
00000000, pos 08A62A9D, size: 7 file: 0, size: 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http write filter: l:1 f:1
s:22004
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http write filter limit 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 writev: 22004 of 22004
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http write filter 00000000
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DDA8 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DDEC 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DE30 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DE74 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DEB8 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 subs out end: 0AF4DEFC 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http copy filter: -2 "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http writer output filter:
-2, "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http writer done: "/?"
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http finalize request: -2,
"/?" a:1, c:1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 event timer del: 10:
631817156
2016/09/13 22:26:27 [debug] 18410#18410: *131592 set http keepalive handler
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http close request
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http log handler
2016/09/13 22:26:27 [debug] 18410#18410: *131592
ngx_http_testcookie_ok_variable
2016/09/13 22:26:27 [debug] 18410#18410: *131592 run cleanup: 0B899F34
2016/09/13 22:26:27 [debug] 18410#18410: *131592 file cleanup: fd:18
2016/09/13 22:26:27 [debug] 18410#18410: *131592 run cleanup: 0B899EF0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache cleanup
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http file cache free, fd:
18
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B6646F0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0AF06900
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B7B8C00
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B37BE20
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B04C848
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B6A6E48
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B6D93B8
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B47A5E0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B1FD720
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B899000, unused: 3
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0AF4D000, unused: 4
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0AEC0330, unused:
3702
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B20C838
2016/09/13 22:26:27 [debug] 18410#18410: *131592 hc free: 00000000 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 hc busy: 00000000 0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 tcp_nodelay
2016/09/13 22:26:27 [debug] 18410#18410: *131592 reusable connection: 1
2016/09/13 22:26:27 [debug] 18410#18410: *131592 event timer add: 10:
15000:631820156
2016/09/13 22:26:27 [debug] 18410#18410: *131592 post event 0AF97550
2016/09/13 22:26:27 [debug] 18410#18410: *131592 delete posted event
0AF97550
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http keepalive handler
2016/09/13 22:26:27 [debug] 18410#18410: *131592 malloc: 0B20C838:1024
2016/09/13 22:26:27 [debug] 18410#18410: *131592 recv: fd:10 -1 of 1024
2016/09/13 22:26:27 [debug] 18410#18410: *131592 recv() not ready (11:
Resource temporarily unavailable)
2016/09/13 22:26:27 [debug] 18410#18410: *131592 free: 0B20C838
2016/09/13 22:26:27 [debug] 18410#18410: *131592 post event 0AF97550
2016/09/13 22:26:27 [debug] 18410#18410: *131592 post event 0B8D36A0
2016/09/13 22:26:27 [debug] 18410#18410: *131592 delete posted event
0AF97550
2016/09/13 22:26:27 [debug] 18410#18410: *131592 http keepalive handler
2016/09/13 22:26:27 [debug] 18410#18410: *131592 malloc: 0B20C838:1024
2016/09/13 22:26:27 [debug] 18410#18410: *131592 recv: fd:10 0 of 1024
2016/09/13 22:26:27 [info] 18410#18410: *131592 client 127.0.0.2 closed
keepalive connection

We use epoll and aio threads. There is a subs_filter in the context and an
"if" that doesn't match.
We have very short timeouts.

However we also use quite a lot of modules. Is it possible that a module
crashed at a wrong moment and caused a request to be left in "updating" ?

Restarting nginx fixes the issue (until it happens again).

nginx/1.10.1

Any idea why it is finding the cache as being in "updating" status?

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,269545,269545#msg-269545