Error: cannot switch to a different thread

[jamadden]

• gevent version: 1.5a1
• Python version: 2.7.? (12?)
• Operating System: Linux

I observed several of these errors during an automated test run (from 0126 to 0356, 7 of them, across two different machines running gunicorn with very early gevent monkey-patching, in two processes per machine). I don't recall seeing them before.

What's going on here?

Module logging:1167 in info
>>  self._log(INFO, msg, args, **kwargs)
Module logging:1286 in _log
>>  self.handle(record)
Module logging:1296 in handle
>>  self.callHandlers(record)
Module logging:1336 in callHandlers
>>  hdlr.handle(record)
Module logging:757 in handle
>>  self.acquire()
Module logging:708 in acquire
>>  self.lock.acquire()
Module gevent.lock:223 in acquire
>>  rc = self._block.acquire(blocking)
Module gevent.__semaphore:100 in gevent.__semaphore.Semaphore.acquire
Module gevent.__semaphore:128 in gevent.__semaphore.Semaphore.acquire
Module gevent.__abstract_linkable:192 in gevent.__abstract_linkable.AbstractLinkable._wait
Module gevent.__abstract_linkable:165 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__abstract_linkable:169 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:65 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:35 in gevent.__greenlet_primitives._greenlet_switch
error: cannot switch to a different thread

Module nti.zodb.minmax:248 in __get__
>>  return value.value if self.as_number else value
Module ZODB.Connection:791 in setstate
>>  p, serial = self._storage.load(oid)
Module zc.zlibstorage:59 in load
>>  data, serial = self.base.load(oid, version)
Module perfmetrics:127 in call_with_metric
>>  return f(*args, **kw)
Module relstorage.storage:562 in load
>>  state, tid_int = self.__load_using_method(self._cache.load, oid_int)
Module relstorage.storage:550 in __load_using_method
>>  return meth(cursor, argument)
Module relstorage.cache.storage_cache:535 in load
>>  response = cache(oid_int, cp0, tid2)
Module relstorage.cache.local_client:227 in __call__
>>  with self._lock:
Module gevent.__semaphore:141 in gevent.__semaphore.Semaphore.__enter__
Module gevent.__semaphore:142 in gevent.__semaphore.Semaphore.__enter__
Module gevent.__semaphore:100 in gevent.__semaphore.Semaphore.acquire
Module gevent.__semaphore:100 in gevent.__semaphore.Semaphore.acquire
Module gevent.__semaphore:128 in gevent.__semaphore.Semaphore.acquire
Module gevent.__abstract_linkable:192 in gevent.__abstract_linkable.AbstractLinkable._wait
Module gevent.__abstract_linkable:165 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__abstract_linkable:169 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:65 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:35 in gevent.__greenlet_primitives._greenlet_switch
error: cannot switch to a different thread

Module zc.intid.utility:87 in getObject
>>  return self.refs[id]
Module ZODB.Connection:791 in setstate
>>  p, serial = self._storage.load(oid)
Module zc.zlibstorage:59 in load
>>  data, serial = self.base.load(oid, version)
Module perfmetrics:127 in call_with_metric
>>  return f(*args, **kw)
Module relstorage.storage:562 in load
>>  state, tid_int = self.__load_using_method(self._cache.load, oid_int)
Module relstorage.storage:550 in __load_using_method
>>  return meth(cursor, argument)
Module relstorage.cache.storage_cache:535 in load
>>  response = cache(oid_int, cp0, tid2)
Module relstorage.cache.local_client:227 in __call__
>>  with self._lock:
Module gevent.__semaphore:141 in gevent.__semaphore.Semaphore.__enter__
Module gevent.__semaphore:142 in gevent.__semaphore.Semaphore.__enter__
Module gevent.__semaphore:100 in gevent.__semaphore.Semaphore.acquire
Module gevent.__semaphore:100 in gevent.__semaphore.Semaphore.acquire
Module gevent.__semaphore:128 in gevent.__semaphore.Semaphore.acquire
Module gevent.__abstract_linkable:192 in gevent.__abstract_linkable.AbstractLinkable._wait
Module gevent.__abstract_linkable:165 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__abstract_linkable:169 in gevent.__abstract_linkable.AbstractLinkable._wait_core
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:61 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:65 in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
Module gevent.__greenlet_primitives:35 in gevent.__greenlet_primitives._greenlet_switch
error: cannot switch to a different thread

[Kalethars]

I also get this error when I do not patch thread from monkey and call redis

[jamadden]

Trivial reproducer:

import threading
from gevent import lock

sem = lock.Semaphore(
    1,
    # Provide the hub of this thread. If we don't do this
    # now, it gets initialized lazily the first time it would have
    # to block, which, in the event of threads, would be from an arbitrary
    # thread.
    gevent.get_hub()
)
assert sem.hub is not None
# Make future acquires block
sem.acquire()


def thread_main():
    sem.acquire()

t = threading.Thread(target=thread_main)
t.start()
t.join()

Exception in thread Thread-1:
Traceback (most recent call last):
  File "src/gevent/_semaphore.py", line 131, in gevent.__semaphore.Semaphore.acquire
    def acquire(self, blocking=True, timeout=None):
  File "src/gevent/_semaphore.py", line 160, in gevent.__semaphore.Semaphore.acquire
    success = self._wait(timeout)
  File "src/gevent/_abstract_linkable.py", line 208, in gevent.__abstract_linkable.AbstractLinkable._wait
    gotit = self._wait_core(timeout)
  File "src/gevent/_abstract_linkable.py", line 178, in gevent.__abstract_linkable.AbstractLinkable._wait_core
    with Timeout._start_new_or_dummy(timeout) as timer:
  File "src/gevent/_abstract_linkable.py", line 196, in gevent.__abstract_linkable.AbstractLinkable._wait_core
    raise
  File "src/gevent/_abstract_linkable.py", line 182, in gevent.__abstract_linkable.AbstractLinkable._wait_core
    result = self.hub.switch()
  File "src/gevent/_greenlet_primitives.py", line 61, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
    def switch(self):
  File "src/gevent/_greenlet_primitives.py", line 61, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
    def switch(self):
  File "src/gevent/_greenlet_primitives.py", line 65, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
    return _greenlet_switch(self) # pylint:disable=undefined-variable
  File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
    return PyGreenlet_Switch(self, NULL, NULL)
error: cannot switch to a different thread

In other words, a greenlet from one thread tries to block on a lock held by a greenlet in another thread.

Now, obviously you're Not Supposed To Do That. One cannot mix gevent primitives with native threads like that; gevent objects generally have thread-affinity. (sockets are another example of this.) In such cases, perhaps we could at least provide a more informative error message.

In the tracebacks originally posted, though, the entire system was supposed to be monkey-patched, so there's not supposed to be more than one native thread running, so that's a bit puzzling.

Here's another recent example:

2020-05-07 01:05:15,947 DEBUG [...]                         [139795245541808:26704][MainThread] MSG
2020-05-07 01:05:15,947 DEBUG [relstorage.blobhelper.cached][139793671749296:26704][DummyThread-1] Blob cache size for ...: 4606.96 MB
2020-05-07 01:05:15,948 INFO  [relstorage.blobhelper.cached][139793671749296:26704][DummyThread-1] Traversed ... to compute size 4606.96 MB (<= 4608.00 MB); quitting.
2020-05-07 01:05:15,951 INFO  [relstorage.blobhelper.cached][139793671749296:26704][DummyThread-1] Finished checking ... (in 0.000s) with size of 4606.96 MB (max: 512
0.00 MB; target 4608.00 MB)
2020-05-07 01:05:15,953 INFO  [nti.zodb.activitylog]        [139795245541808:26704][MainThread] closedConnection=...
2020-05-07 01:05:15,953 ERROR [nti.appserver.standalone]    [139795245541808:26704][MainThread] Failed to create application
Traceback (most recent call last):
 F ile "/usr/lib64/python2.7/logging/__init__.py", line 1155, in debug
   self._log(DEBUG, msg, args, **kwargs)
 File "/usr/lib64/python2.7/logging/__init__.py", line 1286, in _log
   self.handle(record)
 File "/usr/lib64/python2.7/logging/__init__.py", line 1296, in handle
   self.callHandlers(record)
 File "/usr/lib64/python2.7/logging/__init__.py", line 1336, in callHandlers
   hdlr.handle(record)
 File "/usr/lib64/python2.7/logging/__init__.py", line 757, in handle
   self.acquire()
File "/usr/lib64/python2.7/logging/__init__.py", line 708, in acquire
   self.lock.acquire()
 File "/home/ntiuser/buildout/eggs/gevent-20.5.0-py2.7-linux-x86_64.egg/gevent/lock.py", line 261, in acquire
   rc = self._block.acquire(blocking, timeout)
 File "src/gevent/_semaphore.py", line 131, in gevent.__semaphore.Semaphore.acquire
 File "src/gevent/_semaphore.py", line 160, in gevent.__semaphore.Semaphore.acquire
 File "src/gevent/_abstract_linkable.py", line 208, in gevent.__abstract_linkable.AbstractLinkable._wait
 File "src/gevent/_abstract_linkable.py", line 178, in gevent.__abstract_linkable.AbstractLinkable._wait_core
 File "src/gevent/_abstract_linkable.py", line 196, in gevent.__abstract_linkable.AbstractLinkable._wait_core
 File "src/gevent/_abstract_linkable.py", line 182, in gevent.__abstract_linkable.AbstractLinkable._wait_core
 File "src/gevent/_greenlet_primitives.py", line 61, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
 File "src/gevent/_greenlet_primitives.py", line 61, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
 File "src/gevent/_greenlet_primitives.py", line 65, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
 File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
error: cannot switch to a different thread

Here, I happen to know that relstorage.blobhelper.cached log messages are coming from RelStorage 3.0.1, and I also know that from 3.0a7 that package is gevent-aware and runs that code using gevent's threadpool, so it should be running in a real native thread (though, why is it called DummyThread-1? Perhaps an artifact of how this application configures logging? I'm seeking additional information.) In that case, there's nothing the application developer is doing wrong. Just using logging from a threadpool function and the main greenlet is a time bomb. gevent should probably cope with such cases. The trick would be to limit the overhead, especially for uncontended/single-threaded locks.

[advance512]

I can confirm that this was fixed in 20.5.1.

I have a service which uses gevent, that serves data via an HTTP interface, and a pool which collects this data continuously from many external sources.
Collecting the data, though it was basically just using the requests module, caused blocking, which meant the HTTP interface was blocked and could not serve data. (Not sure why this happened, but that is the subject of a whole other post. Also, I believe a correct design here would have been to have two processes - one or more for serving and another for data collection, but the entire thing was develop under time constraints. Might refactor it in the future.)

Because of this blocking, I tried to move the data collection from a pool to a native threadpool, but then came errors with logging, LoopExit (had to following this to resolve), etc. Logging is very minimal, but I would still like to see errors when they occur, even if in another thread. Performance isn't critical here.

Upgrading to 20.6.2 (from 1.5.0) which contains PR #1617 meant that the solution from became feasible, which was great. So thanks for this!