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 _______________________________________________ nginx mailing list nginx@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx