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?