<div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Dec 23, 2015 at 6:35 PM, Maxim Dounin <span dir="ltr"><<a href="mailto:mdounin@mdounin.ru" target="_blank">mdounin@mdounin.ru</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">Hello!<br>
<span class=""><br>
On Wed, Dec 23, 2015 at 11:57:53AM +0300, Руслан Закиров wrote:<br>
<br>
> On Tue, Dec 22, 2015 at 4:49 PM, Maxim Dounin <<a href="mailto:mdounin@mdounin.ru">mdounin@mdounin.ru</a>> wrote:<br>
><br>
> > Hello!<br>
> ><br>
> > On Tue, Dec 22, 2015 at 02:43:11PM +0300, Руслан Закиров wrote:<br>
> ><br>
> > [...]<br>
> ><br>
> > > Our error log has "ignore long locked inactive cache entry" alerts, but I<br>
> > > really couldn't match it to "defreeze" event. Access log has<br>
> > STALE/UPDATING<br>
> > > requests between the alert and EXPIRED (cache updating) request.<br>
> ><br>
> > The "ignore long locked inactive cache entry" alerts indicate that<br>
> > a cache entry was locked by some request, and wasn't unlocked for<br>
> > a long time.  The alert is expected to appear if a cache node is<br>
> > locked for cache inactive time (as set by proxy_cache_path<br>
> > inactive=, 10 minutes by default).<br>
><br>
><br>
> Inactive is defined in the config, but it's set to default 10m.<br>
><br>
> What happens with requests after this time? Do they hit backend and update<br>
> cache? Do they use stale version?<br>
<br>
</span>As long as an entry is locked and not accessed for the inactive<br>
time, it will cause the alert in question to be logged by cache<br>
manager.  Nothing else happens - that is, the entry is still<br>
locked, and if it contains information that the entry is currently<br>
being updated, requests to this entry will return stale content<br>
with UPDATING status as per proxy_cache_use_stale.<br>
<br>
This alert may in theory happen in normal situation if a backend<br>
response takes longer than the inactive time set.  But in general<br>
it indicates that there is a problem.<br></blockquote><div><br></div><div>uwsgi on backends has harakiri setting at 9 seconds and 10 seconds timeout in</div><div>nginx. Index page takes 0.2-0.7 seconds to render.</div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
(Note well that "locked" here should not be confused with<br>
request-level locks as in proxy_cache_lock.)<br>
<span class=""><br>
> I'm going to check "long locked" messages in the log to see how many was<br>
> for "/" location.<br>
> The hash should be the same if we didn't change cache key, right?<br>
<br>
</span>Any message indicate that there is a problem.  If the "/" location<br>
is requested often, it'll likely won't be mentioned in the "ignore long<br>
locked" messages.<br>
<span class=""><br>
> > Most likely reason is that a worker died or was killed<br>
> > while holding a lock on a cache node (i.e., while a request was<br>
> > waiting for a new response from a backend).<br>
> ><br>
><br>
> Shouldn't be there a record in error log? Error log level at warn.<br>
<br>
</span>There should be something like "worker process exited" messages,<br>
though at least some of them may be on the "notice" level (e.g.,<br>
if you force nginx worker to quit by sending SIGTERM to it<br>
directly).<br>
<span class=""><br>
> > Trivial things to consider:<br>
> ><br>
> > - check logs for segmentation faults;<br>
><br>
> no seg faults in logs<br>
<br>
</span>Any other alerts, crit or emerg messages?  Any alerts about<br>
socket leaks on configuration reloads ("open socket left..."),<br>
sockets in CLOSED state?  How long relevant requests to upstream<br>
server take (i.e., make sure that the behaviour observed isn't a<br>
result of an upstream server just being very slow)?<br></blockquote><div><br></div><div>Looks like we have some misconfiguration and I get the following:</div><div>







<p class=""><span class="">2015/12/17 01:49:13 [</span><span class=""><b>crit</b></span><span class="">] 5232#0: *599273664 rename() "/var/nginx/cache/0080683483" to "/var/www/storage/img/ru-cyber/answers/10-5.jpg" failed (13: Permission denied) while reading upstream, client: 188.115.151.67, server: <a href="http://www.sports.ru">www.sports.ru</a>, request: "GET /storage/img/ru-cyber/answers/10-5.jpg HTTP/1.1", upstream: "<a href="http://192.168.1.10:80/storage/img/ru-cyber/answers/10-5.jpg">http://192.168.1.10:80/storage/img/ru-cyber/answers/10-5.jpg</a>", host: "<a href="http://www.sports.ru">www.sports.ru</a>", referrer: "<a href="http://cyber.sports.ru/dota2/1034151992.html">http://cyber.sports.ru/dota2/1034151992.html</a>"</span></p>
<p class=""><span class="">2015/12/17 01:50:17 [</span><span class=""><b>crit</b></span><span class="">] 5229#0: *599313395 open() "/var/www/storage/img/fantasy/shirts/ule/slo.png" failed (13: Permission denied), client: 192.168.1.10, server: <a href="http://www.sports.ru">www.sports.ru</a>, request: "GET /storage/img/fantasy/shirts/ule/slo.png HTTP/1.0", host: "<a href="http://www.sports.ru">www.sports.ru</a>", referrer: "<a href="http://fantasy-h2h.ru/analytics/fantasy_statistics/liga_europa_2015">http://fantasy-h2h.ru/analytics/fantasy_statistics/liga_europa_2015</a>"</span></p></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><span class="">
> - if you are using 3rd party modules / patches, try without them;<br>
> ><br>
><br>
> from freebsd port, updated gist [1] with `nginx -V` output<br>
</span>> [1] <a href="https://gist.github.com/ruz/05456767750715f6b54e" rel="noreferrer" target="_blank">https://gist.github.com/ruz/05456767750715f6b54e</a><br>
<br>
The only suspicious thing I see there is "ssi on" and<br>
"proxy_cache_lock" at the same time.  There were some fixes<br>
related to proxy_cache_lock with subrequests in more recent<br>
versions.<br>
<span class=""><br>
> > - make sure you don't kill worker processes yourself or using some<br>
> >   automation scripts (in particular, don't try to terminate old<br>
> >   worker processes after a configuration reload).<br>
> ><br>
><br>
> One recent appearance of the problem was at 1:30AM and I checked<br>
> logs for crazy midnight deploys - nothing.<br>
><br>
> Also, we don't use anything custom to restart nginx, just regular services<br>
> management tools.<br>
<br>
</span>Just a regular kill will be enough screw up things.  On the other<br>
hand, it may be an nginx bug as well.<br>
<br>
Note though, that the version you are using is quite old.<br>
Debugging anything but 1.9.x hardly make sense.  You may want to<br>
try upgrading to the latest nginx-devel port.<br></blockquote><div><br></div><div>As I said before 1.8.0 made things worse. May be we will try nginx 1.9.x on one of frontends and see how it goes.</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<br>
Note well that if a problem happens, it's a good idea to either<br>
completely restart nginx or do binary upgrade procedure ("service<br>
nginx upgrade") to make sure shared memory structures are intact.<br>
<div class=""><div class="h5"><br>
--<br>
Maxim Dounin<br>
<a href="http://nginx.org/" rel="noreferrer" target="_blank">http://nginx.org/</a><br>
<br>
_______________________________________________<br>
nginx mailing list<br>
<a href="mailto:nginx@nginx.org">nginx@nginx.org</a><br>
<a href="http://mailman.nginx.org/mailman/listinfo/nginx" rel="noreferrer" target="_blank">http://mailman.nginx.org/mailman/listinfo/nginx</a></div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br><div class="gmail_signature"><div dir="ltr"><div>Руслан Закиров</div><div>Руководитель отдела разработки веб-сервисов</div><div><span>+7(916) 597-92-69</span>, <span>ruz @ <a href="http://www.sports.ru/" target="_blank"><img src="http://farm7.static.flickr.com/6235/6210250811_19a888dbba_o.jpg" width="43" height="14" style="vertical-align: bottom; margin-right: 0px;"></a></span></div></div></div>
</div></div>