560381 - random and hard to reproduce python crashes (500 errors)

Status: VERIFIED FIXED

(addons.mozilla.org Graveyard :: Code Quality, defect)

Description

[Wil Clouser [:clouserw]]

Around 40ish% of requests to add-on details is giving a 500 error and crashing python(!) with this:

python: Modules/gcmodule.c:262: update_refs: Assertion `gc->gc.gc_refs != 0' failed.

If I pull out all our {% cache %} tags and unload caching.ext.cache the 500s go away, so that's what I think is causing it for now.  I can reproduce this somewhat reliably on my dev copy with the following URL sequence:

[19/Apr/2010 16:04:56] "GET /en-US/firefox/addon/2848/ HTTP/1.0" 200 35040
[19/Apr/2010 16:04:56] "GET /en-US/firefox/addon/14697/ HTTP/1.0" 200 40145
[19/Apr/2010 16:04:57] "GET /en-US/firefox/addon/59338/ HTTP/1.0" 200 34151
[19/Apr/2010 16:04:58] "GET /en-US/firefox/addon/60914/ HTTP/1.0" 200 40639
[19/Apr/2010 16:05:05] "GET /mn/firefox/addon/11549/ HTTP/1.0" 200 35166
[19/Apr/2010 16:05:06] "GET /cs/firefox/addon/12213/ HTTP/1.0" 200 33202
python: Modules/gcmodule.c:262: update_refs: Assertion `gc->gc.gc_refs != 0' failed.

However, sometimes it gets past that point so it's not 100%, and in fact, if you try that URL yourself it'll probably work:  https://preview.addons.mozilla.org/z/cs/firefox/addon/12213/.  

If I load only en-US URLs I don't seem to hit the problem, but loading one particular language doesn't seem to always break it either.

I'm happy to try to debug more, but I'm filing what I know now.

Comment 1

[Jeff Balogh (:jbalogh)]

I couldn't reproduce this locally, so I played with it on clouserw's setup on khan.  It was reliably happening after returning from the {% cache %} block inside apps/sharing/templates/sharing/addon_sharing.html.  But only in /ja.

It was suggested that this was somehow being caused by a wonky AST returned to jinja2.  But {% cache %} doesn't mess with the AST, it just returns whatever string was rendered by the template.

Eventually I looked at `python --version`, which returned 2.6.2.  I have 2.6.4, and can't reproduce locally, so I installed 2.6.5 in my local directory on khan.  The assertion error went away.  I've been running through ~clouserw/amologs/details.log with logreplay and haven't seen any errors (it's been going for a long time).

Bug 560444 gets our pythons upgraded.  I hope preview is running 2.6.2, or this theory is shot.

Comment 2

[Jeff Balogh (:jbalogh)]

clouserw: r? http://github.com/jbalogh/jingo/compare/localizer-error

This is jinja's _MarkupEscapeHelper class:


class _MarkupEscapeHelper(object):
    """Helper for Markup.__mod__"""

    def __init__(self, obj):
        self.obj = obj

    __getitem__ = lambda s, x: _MarkupEscapeHelper(s.obj[x])
    __str__ = lambda s: str(escape(s.obj))
    __unicode__ = lambda s: unicode(escape(s.obj))
    __repr__ = lambda s: str(escape(repr(s.obj)))
    __int__ = lambda s: int(s.obj)
    __float__ = lambda s: float(s.obj)

It's used by Jinja to safely do interpolation on an escaped string.

If we have {% trans users=... %}blah {{ users }}{% endtrans %} and the localizer has "blah %(user)s" in their gettext catalog, there will be a KeyError when Python looks for the users variable.

Jinja does something like Markup(<trans string>) % {'users': ...}, but the localized string has the wrong key.  A KeyError is raised in the __getitem__ lambda, and for some reason the traceback object associated with it does not have proper reference counting.  When the garbage collector is run, it's discovered that the traceback has 0 references and Python decides to quit.

Switching to ``def __getitem__(s, x)`` with the same internal code removes the reference error.  My branch goes a little further and catches the KeyError so that localizers can't break our page.

I figured out what was happening with this patch to Python:

--- Modules/gcmodule.c.bak      2010-04-26 16:57:37.000000000 -0700
+++ Modules/gcmodule.c  2010-04-26 17:28:10.000000000 -0700
@@ -241,6 +241,11 @@
        for (; gc != containers; gc = gc->gc.gc_next) {
                assert(gc->gc.gc_refs == GC_REACHABLE);
                gc->gc.gc_refs = Py_REFCNT(FROM_GC(gc));
+               if (gc->gc.gc_refs == 0) {
+                   printf("omg:\n%s\n", PyObject_REPR(FROM_GC(gc)));
+                   PyObject *f_stderr = PySys_GetObject("stderr");
+                   PyTraceBack_Print(FROM_GC(gc), f_stderr);
+               }
                /* Python's cyclic gc should never see an incoming refcount
                 * of 0:  if something decref'ed to 0, it should have been
                 * deallocated immediately at that time.

I'll look into minimizing a test case for redhat or Python or Jinja sometime soon.

Comment 3

[Jeff Balogh (:jbalogh)]

http://github.com/jbalogh/jingo/commit/d250add08e0679ca9d413ad80f7946f5a930806c

Comment 4

[Stephen Donner [:stephend] Not actively reading bugmail]

Verified FIXED; along with the symlinks bug (bug 548839), we've been pretty stable [1]

[1] /me crosses fingers