greenlet.switch() raises a SystemError

[flub]

Very occasionally we get .switch() raising this exception on 0.3.3:

SystemError: error return without exception set

Which means switch returns an error status to the python api but did not set the exception state. After a very quick look it seems like the return tuple of g_switch() is never checked for NULL, I have no idea what PyTuple_SetItem() would do if the tuple it has to operate on is NULL, but it is conceivable that it could end up clearing the exception state. In any case, that failure path should probably not be undefined.

Another item that popped is the assumption in that function that args is always going to contain a valid python object. I assume this was on purpose and correct, but am writing it down since I haven't traced it down yet so could be something to check.

I'll update our code to use 0.3.4 and see if we still see this with that version before investigating more thoroughly (is 0.4 due to be released soon? the NEWS file seems to suggest so).

Regards
Floris

[flub]

Just realised it's a method so args will always contain self. Also I didn't show the full traceback but the call to .switch() has no extra args or kwargs, so this would never hit the PyTuple_New() code but end up with g_passaround_return_args which seems pretty safe at first sight.

[snaury]

Hi, what you see in the traceback is a return from .switch(), which happens when the greenlet that you had .switch'ed switches back. From what I see the only way for the actual .switch() to fail is when g_save fails to allocate memory, but in that case there's PyErr_NoMemory(), so there should be a MemoryError exception raised. The only suspicious thing is that passaround args in that case are cleared, so if deallocating args/kwargs causes some finalizers to hit, they might clear MemoryError. There's other stuff that looks shaky if that ever happens.

I'll try to look a little more, but it would be super cool if you could reproduce the issue.

[snaury]

Hmm, no that doesn't seem to be it, passaround args and kwargs should pretty much always have an extra ref in the caller, so decrefing them shouldn't cause any deallocations. Could you tell me more about your environment (OS, compilers, architecture)?

[snaury]

Ok, I've pushed some fixes to master. Could you try if any of this helps you?

[flub]

We get this on a SPARC T1000 running solaris10, compiled with gcc 4.3.3. This machine has 24 virtual CPUs to the OS which usually makes it the first one where odd things start showing.

The changes look promising. Tomorrow I'll first try to reproduce this before trying the changes however, my colleague seemed fairly confident he could re-create it within a few hours.

[schmir]

Floris Bruynooghe writes:

I'll update our code to use 0.3.4 and see if we still see this with
that version before investigating more thoroughly (is 0.4 due to be
released soon? the NEWS file seems to suggest so).

I planned to release it the next few days...but I'll put it on hold and
see if the issue can be fixed before.

[flub]

Just a quick update, we've been running a version with and one without these latest fixes for about 24h now but so far have failed to reproduce this with either version. We'll leave them running for at least a few more days but I'm not sure we'll be able to prove much at all unfortunately. It seems like reproducing this is rather based on luck so far.

[flub]

Unfortunately while it's hard to prove it's fixed I can prove it is not fixed. We did get the error again, but only on the code using greenlet trunk, not on 0.3.4. It appears the same exception appears twice, the part of the stack from icmp.py down (towards the most recent call) should only be able to show up in the first traceback, it should not be part of the second stack which should probably have stopped at hub.py:177.

Traceback (most recent call last):
  File "asagent/python/asagent/monitor/workers.py", line 132, in process_samples
            samples = coro.wait()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/greenthread.py", line 166, in wait
        return self._exit_event.wait()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/event.py", line 120, in wait
            current.throw(*self._exc)
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/greenthread.py", line 192, in main
            result = function(*args, **kwargs)
  File "asagent/python/asagent/samplers/net/icmp.py", line 100, in one_host
        send_times, recv_times = self.ping(sock)
  File "asagent/python/asagent/samplers/net/icmp.py", line 196, in ping
                excess_data = recv_data(sock, icmp.data.id,
                                        send_times, recv_times, excess_data)
  File "asagent/python/asagent/samplers/net/icmp.py", line 216, in recv_data
            recv_data += sock.recv(BUFSIZE)
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/greenio.py", line 238, in recv
                timeout_exc=socket.timeout("timed out"))
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/hubs/__init__.py", line 121, in trampoline
            return hub.switch()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 177, in switch
        return self.greenlet.switch()
SystemError: error return without exception set

Traceback (most recent call last):
  File "asagent/python/common/mtmthreading.py", line 92, in wrapper
                target(*args, **kwargs)
  File "asagent/python/asagent/monitor/workers.py", line 59, in run
            mon = self.inputq.get()
  File "thirdparty/python27/lib/python2.7/Queue.py", line 168, in get
                    self.not_empty.wait()
  File "asagent/python/asagent/tools/gsync.py", line 606, in wait
            gotit = self._notif.wait(timeout, waiter)
  File "asagent/python/asagent/tools/gsync.py", line 322, in wait
        waiter.block(timeout)
  File "asagent/python/asagent/tools/gsync.py", line 114, in block
            return self._gblock(timeout)
  File "asagent/python/asagent/tools/gsync.py", line 128, in _gblock
            self._hub.switch()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 177, in switch
        return self.greenlet.switch()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/greenthread.py", line 192, in main
            result = function(*args, **kwargs)
  File "asagent/python/asagent/samplers/net/icmp.py", line 100, in one_host
        send_times, recv_times = self.ping(sock)
  File "asagent/python/asagent/samplers/net/icmp.py", line 196, in ping
                excess_data = recv_data(sock, icmp.data.id,
                                        send_times, recv_times, excess_data)
  File "asagent/python/asagent/samplers/net/icmp.py", line 216, in recv_data
            recv_data += sock.recv(BUFSIZE)
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/greenio.py", line 238, in recv
                timeout_exc=socket.timeout("timed out"))
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/hubs/__init__.py", line 121, in trampoline
            return hub.switch()
  File "thirdparty/eventlet/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 177, in switch
        return self.greenlet.switch()
SystemError: error return without exception set

[flub]

The line shown from greenio.py is a bit confusing it's part of the call to trampoline:

            trampoline(fd, 
                read=True, 
                timeout=self.gettimeout(), 
                timeout_exc=socket.timeout("timed out"))

[snaury]

Ok, what I think I see here is a possible receive timeout, which results in hub doing greenlet.throw() with that timeout exception, but by the time the switch happens the exception is already gone. The problem is that I don't really see how that can happen. There are some more weak points that I found, though:

1. Greenlet's dealloc could clobber exceptions when printing "GreenletExit did not kill ..." during switches, but I don't see how dealloc like that could happen in eventlet (which greenlet would that even be?), nor you report anything like that. In any case, I moved exception restore downwards. (fixed in master)
2. If PyDict_DelItem in green_updatecurrent fails, it would result in PyErr_Clear(), but I don't see how that can ever happen (if GetItem succeeds, DelItem cannot really fail), and is only relevant for multi-threaded greenlet usage. (will not be fixed, but will show unraisable exception from now on, so if it happens you will see it)
3. PyDict_GetItem, as it turns out, does PyErr_Clear if it fails to hash the string key, but it should never happen in our case, because keys are strings and hash should never fail. (will not be fixed, not applicable)

I removed unnecessary PyErr_Fetch/PyErr_Restore from master (it seems that deallocators are expected to keep exception state intact, which makes sense, as otherwise it's utter madness) and implemented some possible fixes for the above. Keep in mind, that I haven't looked at the asm switching code, since you were the last to change it I kind of assume it's correct (otherwise if stack corrupts all bets are off and any weirdness is possible), but I'll try to look at it later. Would be awesome if you could build your greenlet (just the way you use it) with CFLAGS=-S and attach build/.../greenlet.o file (which in reality would be a .s file), so I could see the actual code.

P.S. What other C-extensions are you maybe using, apart from Python stdlib?
P.P.S. The "double" stack-trace could be normal for greenlet if exception propagates from one greenlet to hub back to another greenlet (via gsync?) back to hub again, in those cases stack trace grows, since exception crosses greenlet boundaries.

[snaury]

Ok, I found one real case where exception could be lost on throw, fixed in commit bae12e9. But I don't see how you could possibly hit that in real code, especially when using eventlet, so it's probably not that...

[snaury]

I did some code review and found more bugs, but I'm not sure if any one of them is even remotely related to your case. I'd like you to test the latest master and see if this happens again. I hope it's fixed, though, because I don't know where else to look... :(

[snaury]

As for the slp switch code I'm not sure it's correct, after all. I found a piece of code that implements switching on sparc (http://www.cs.ucsb.edu/~tyang/class/170.f10/projects/nachos/threads/switch.s) and you can see there that i0-i5 and i7 (the latter is a return address?) are saved there, but in greenlet they are not clobbered. When looking at gcc/config/sparc/sparc.h I can see that l0-l7 and i0-i5 are the only non-call-used registers, where l7 seems to be a pic register. Now I don't know what ST_FLUSH_WINDOWS really does, so this might be excessive (maybe only i0-i5 are needed), but shouldn't switch code be something like this?

diff --git a/platform/switch_sparc_sun_gcc.h b/platform/switch_sparc_sun_gcc.h
index 1f701a2..4860da1 100644
--- a/platform/switch_sparc_sun_gcc.h
+++ b/platform/switch_sparc_sun_gcc.h
@@ -29,6 +29,9 @@

 #define STACK_MAGIC 0
 #define ST_FLUSH_WINDOWS 3
+/* %l7 may be used as a pic register, might need manual saving */
+#define REGS_TO_SAVE "%l0", "%l1", "%l2", "%l3", "%l4", "%l5", "%l6", \
+                     "%i0", "%i1", "%i2", "%i3", "%i4", "%i5"

 static int
 slp_switch(void)
@@ -41,7 +44,7 @@ slp_switch(void)
     __asm__ volatile (
         "ta %1\n\t"
         "mov %%sp, %0"
-        : "=r" (stackref) :  "i" (ST_FLUSH_WINDOWS));
+        : "=r" (stackref) : "i" (ST_FLUSH_WINDOWS) : REGS_TO_SAVE);

     {
         /* Thou shalt put SLP_SAVE_STATE into a local block */
@@ -56,15 +59,15 @@ slp_switch(void)

         /* Copy new stack from it's save store on the heap */
         SLP_RESTORE_STATE();
-
-        /* No need to restore any registers from the stack nor clear them: the
-         * frame pointer has just been set and the return value register is
-         * also being set by the return statement below.  After returning a
-         * restore instruction is given and the frame below us will load all
-         * it's registers using a fill_trap if required. */
-
-        return 0;
     }
+
+    /* No need to restore any registers from the stack nor clear them: the
+     * frame pointer has just been set and the return value register is
+     * also being set by the return statement below.  After returning a
+     * restore instruction is given and the frame below us will load all
+     * it's registers using a fill_trap if required. */
+    __asm__ volatile ("" : : : REGS_TO_SAVE);
+    return 0;
 }

 #endif

[snaury]

Oh, after reading http://icps.u-strasbg.fr/people/loechner/public_html/enseignement/SPARC/sparcstack.html I realize that sparc is significantly different in this regard. :) No registers need saving, because %l0-%l7 are local and can be used freely, and %i0-%i5 are also free to use, they map to %o0-%o5 in the caller and so are volatile. Looks like switching code is correct, after all...

[snaury]

After some more review and looking at every python call whether it may affect exceptions or not, I commited 98fb1a8 which might (or might not) fix your issue. While it's basically the last place left, I'm not convinced that's really it, because to affect exceptions a whole lot of things should probably align just right:

1. Non-string object in thread-state dict, which should be very unusual (stdlib and greenlet use strings)
2. That object's masked hash equal to that of ts_curkey
3. That object's equality operator overriden
4. Equality operator clobbers exceptions

I really-really hope latest master will work for you now.

[snaury]

Come to think of it, your mysterious bug report is the best thing that could happen to greenlet, given how it forced me to review the code over and over again, thinking of all possible twisted scenarios. ;) Fixed a nasty multithreaded bug in 81129df. :)

[snaury]

Finally! I think I found a side effect that looks like it might be the root of your issue. Fixed in cf910a9.

[flub]

Hi, just a quick note to apologise for my quietness, I've been on holiday last week. I hope to find time by Tuesday to kick off our test case. Thanks for all the work!

[flub]

Some of the changes seems to have broken our windows build: in "static int GREENLET_NOINLINE(g_initialstub)(void* mark)" you added a call to PyErr_Fetch() (line 639) after which you declare the run variable. AFAIK this isn't strictly valid C and our Visual Studio version does fail on it.

[snaury]

Ooops, sorry about that, my compiler on OS X doesn't even issue any warnings for this... Fixed in master. But other than that, does it work ok?

[flub]

I've kicked off our test case which I'll leave running at least till the end of the week so will let you know my findings at the latest on Friday.

One of your commits was in respect too thread-safety which reminded me that I probably didn't mention here we use threads. We only run the eventlet hub in one thread but do create hubs in other threads which we never switch too. So each thread with other hubs will have exactly one greenlet created, but never started.

[flub]

I'm afraid the same SystemError is still happening with exactly the same traceback. Is there a way of core dumping instead of a SystemError? That way we could get the C stack of when this occurs which should give us a reasonable indication of where to look. Probably requires modifying python, I'll investigate this but if you have any other ideas on how to approach this let me know.

[flub]

Actually a coredump at SystemError time would be too late, I wonder if there are other debugging tricks to do. Maybe I should investigate and learn some DTrace since this is on Solaris anyway.

[snaury]

I fixed one more possible problem (run_info deallocated before the initial switch, which would only be a problem in case of horrible messing with __getattribute__ so that run != run_info), but it's unlikely it's even remotely related to your case, and really I can't see anything else. All paths from switch/throw to the actual return on another side look like they can't lose args/exceptions anymore. Also, in fear PyDict_Size or PySequence_Length (over a tuple!) would do something weird (which is very unlikely) I made it extra careful and air-tight, but once again I doubt it helps (since it can't be PyDict_Size and switch args is always a tuple).

Since it still happens I need to know more about your environment. What other C-extensions are you using? (maybe there's a bug in their dealloc) What kind of values do you send over switch/throw? Do you use some metaprogramming hacks I couldn't think about (like mock), maybe something with __getattributes__ goes over switch? Can you maybe make your tests shorter/publish them? Can you try building Python --with-pydebug and looking if something weird is caught during your tests?

As a last resort you could try applying something ugly like this and gather output somewhere, to at least see what switches/throws immediately before the error:

diff --git a/greenlet.c b/greenlet.c
index 506e7e2..6dc0519 100644
--- a/greenlet.c
+++ b/greenlet.c
@@ -511,6 +511,12 @@ g_switch(PyGreenlet* target, PyObject* args, PyObject* kwargs)
        return NULL;
    }

+   if (args) {
+       printf("switch %p (%s) -> %p (%s), args=%p (%s), kwargs=%p\n", ts_current, Py_TYPE(ts_current)->tp_name, target, Py_TYPE(target)->tp_name, args, Py_TYPE(args)->tp_name, kwargs);
+   } else {
+       PyObject* exc = PyErr_Occurred();
+       printf("throw %p (%s) -> %p (%s), exc=%p (%s)\n", ts_current, Py_TYPE(ts_current)->tp_name, target, Py_TYPE(target)->tp_name, exc, exc ? (PyType_Check(exc) ? ((PyTypeObject*)exc)->tp_name : "non-type") : "null");
+   }
    ts_passaround_args = args;
    ts_passaround_kwargs = kwargs;

[snaury]

Ouch, it turns out args may not always be exactly tuple after all... for example when using apply()! Then, if __len__ is overridden and kwargs is specified, Python code would be executed. But it's way too exotic and I very much doubt anyone in their right mind would do that...

[snaury]

@flub Any news regarding this bug? Could you also try the latest changes? (switch machinery is more atomic now)

@schmir You said above "but I'll put it on hold and see if the issue can be fixed before", roughly how much time is there left? I finally added experimental tracing support (release notes would need to say it is experimental, probably subject to change, etc.) and there are quite a few changes already. I'm still hoping this bug miraculously fixes itself along the lines, but if it doesn't perhaps we should just give up on it for now and release 0.4 anyway... I'll try to review it one more time with a fresh eye in a couple of days (in case I introduced new bugs), but other than that I'm not holding much breath.

[schmir]

Alexey Borzenkov writes:

@schmir You said above "but I'll put it on hold and see if the issue
can be fixed before", roughly how much time is there left?

Probably sometime next week. I'll have to fully automate building and
uploading on windows before...

Thanks for your amazing work on this!

[flub]

@schmir I don't think you should delay a release because of this issue, it seems like this might take a while and only seems to be a corner case one one platform that no one else has managed to trigger before.

@snaury Since currently we're only seeing this when we're soak testing our entire application I'll try to build a smaller example script that triggers it which I can publish, eliminating any other extension modules etc. (there's a bunch: faulthandler, storm, lxml, pycrypto, psi, and a few more that probably don't get imported in this test case). I'll try out your other suggestions too. However it will probably be sometime next week before I get round to doing these things.

[flub]

Quick update, after a few days being busy with other stuff I have created a stand-alone test script which does roughly the same. I've now started this with the latest greenlet code as well as re-started the previous test. If/when one of these fail again I'll go down the --pydebug build and the printf path you described above.

[flub]

Ok, the script I created manages to trigger the same SystemError (and this time core-dumped afterwards, this seems to be sometimes the case). It uses no extension modules other then greenlet. The only dependencies are dpkt and eventlet.

Eventlet needs a few patches/bug fixes however: the IPv6 patches from https://bitbucket.org/flub/eventlet-ipv6 (you can just take that repo) plus the "xthread" patch from this patch queue: https://bitbucket.org/flub/eventlet-queue/ You can probably avoid using the IPv6 patches by manually fixing the bad getaddrinfo results you get (even for IPv4) in that case.

And here's the test script: https://gist.github.com/2964760

[snaury]

@flub wow, I tried running it on Mac OS X and got an immediate kernel panic both times I tried. :D Looks like there's something really wrong with IPv6 on the Mac. %)

Other than that, how long do you usually run it before it hits the bug? Btw, if there are races in the code you could probably hit them faster by adding this at the top of the file:

import sys
sys.setcheckinterval(0)

There are definitely some races in your code, because I often get these marvelous tracebacks:

starting producer
Exception in thread producer:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/threading.py", line 532, in __bootstrap_inner
    self.run()
  File "zzme.py", line 48, in run
    self.queue.put(dest)
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/Queue.py", line 140, in put
    self.not_full.release()
  File "/Users/dragonfox/tmp/eventlet-ipv6/eventlet/xthread.py", line 583, in release
    self._lock.release(*args, **kwargs)
  File "/Users/dragonfox/tmp/eventlet-ipv6/eventlet/xthread.py", line 459, in release
    self._notif.notify()
  File "/Users/dragonfox/tmp/eventlet-ipv6/eventlet/xthread.py", line 345, in notify
    waiter = self._waiters.pop()
KeyError: 'pop from an empty set'

Also, you forget to reverse byte-order of ip.len. If should be:

            if not LINUX:
                # These platforms subtracted the header of the total lenght
                hl = ip.hl * 4
                ip.len = ((ip.len >> 8) | (ip.len << 8)) & 0xff
                ip.len += hl
                ip.data = ip.icmp = dpkt.icmp.ICMP(recv_data[hl:])

Other than that I can't seem to reproduce it yet.

[flub]

Just how can eventlet trigger kernel panics? That sounds scary. I presume you where actually using IPv6 addresses when you got these (I was doing this test with IPv4 only, but need the fixed getaddrinfo). If you think this is a bug in the eventlet-ipv6 branch please let me know.

This usually occurs after a few hours, less then 1-2 days. But since I started the pydebug build and added the printf's in greenlet it hasn't happened yet (1.5 days). I'm away over the weekend so will leave it running till monday before trying it with just one of pydebug or printf.

Good tip on sys.setcheckinterval(0), and also tanks for the bug report in xthread - none of my tests managed to find that yet. And for noticing the ip header issue, I'm surprised my tests didn't find that yet.

[flub]

Hi,

I'm starting to think your last few fixes might have solved it. I'm starting the test script again without any instrumentation, so no pydebug and no printf, to see if it still occurs then. I'll keep updating this issue.

And on the rather unrelated ip.len issue, I realised all my non-Linux boxes are big endian which is why I didn't notice that error. But it also means your byte-order reversing is wrong, I think you should instead do dpkt.ip.IP.__hdr_fmt__ = '@' + dpkt.ip.IP.__hdr_fmt__[1:] somewhere so native byte ordering will be used to decode all IP header fields by dpkt.

[flub]

Ok, so it's not solved yet. Just appears the instrumentation makes it not happen. I'm going to try with only part of the instrumentation next.

[flub]

Hi, apologies for the super-long pause but I've recently had the time/opportunity to pick this up again. So far not much to report yet, but I have come up with a simplified crasher script which is pretty reliable and much quicker then the one from before. Additionally it uses just greenlet code and does not depend on anything from eventlet or anything else: https://gist.github.com/flub/6365845

I'll keep playing with that script, it might be possible to simplify it even more. From some of the core dumps I'm also suspecting the SPARC switching code does not behave correctly wrt threads so I'm going to look into the SPARC manuals again to find more info.

I'll update here if I make any progress.

[flub]

Right, it seems like I've made an error is the last update to the SPARC slp_switch code. I appear to have this fixed locally but am still leaving various tests running over the weekend. If they're still fine by Monday I'll create a pull request for it.