Incompatibilty with gunicorn.

We have a web app using django and gunicorn, I don't appreciate how gunicorn handles its workers but after the recent changes we're getting:

2013-10-08 12:28:31 [ERROR] gunicorn.error: Error handling request
Traceback (most recent call last):
  File "/home/ubuntu/venv/local/lib/python2.7/site-packages/gunicorn/workers/async.py", line 55, in handle
    self.handle_error(req, client, addr, e)
  File "/home/ubuntu/venv/local/lib/python2.7/site-packages/gunicorn/workers/base.py", line 177, in handle_error
    self.log.exception("Error handling request")
  File "/home/ubuntu/venv/local/lib/python2.7/site-packages/gunicorn/glogging.py", line 219, in exception
    self.error_log.exception(msg, *args)
  File "/usr/lib/python2.7/logging/__init__.py", line 1172, in exception
    self.error(msg, exc_info=1, *args)
  File "/usr/lib/python2.7/logging/__init__.py", line 1166, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1258, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1268, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1308, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 748, in handle
    self.emit(record)
  File "/home/ubuntu/venv/src/logentries/logentries/utils.py", line 122, in emit
    self._thread.start()
  File "/usr/lib/python2.7/threading.py", line 488, in start
    raise RuntimeError("threads can only be started once")
RuntimeError: threads can only be started once

If there's any further information I can provide that might help please let me know, also apologies if this is not an issue for le_python, however when we moved to commit 1726b2271b0fa6d9da4332e165f4ae394e4ffd47 it seems to have resolved the problem. We're using gunicorn 18.0, python 2.7, ubuntu, and we're monkey patching gunicorn. from gevent import monkey; monkey.patch_all(subprocess=False)

Hi Alexander, Sorry about that, I'll look into this as soon as I can. The strange thing is the recent change was to prevent the stacktrace that you pasted which was occurring to the user who made the pull request, whereby now it shouldn't reach the thread.start() more than once if the thread is already started. Thanks for the details about your stack. I'll keep you updated on here

No worries. This was the change that caused the problem, interesting that it should fix in one and break in another setup.

@Marklc

This commit has introduced a similar problem (it isn't gunicorn related, but we get the same RuntimeError: threads can only be started once exception) for us; @Marklc , do you have any opinion about "which way" is correct, with respect to how _started is defined/used? Undoing this change seems to fix the problem for us, but it may inadvertently reproduce it in the same place where the original user was experiencing it...

@AJamesPhillips

@AJamesPhillips , @Marklc , I just obtained some more information about our particular problem here: We use the Celery distributed task scheduler, and if we start our Celery workers with the option FORCE_EXECV=True, then we do not get this error. If we do not pass the option (the default is False), we get this error. Something about the Celery threading and Logentries threading doesn't play well together, evidently...

We are getting this error when running Celery + New Relic + Logentries.

» 14:18:57.838  {
    "name": "celery.redirected",
    "message": "LE: Starting Logentries Asynchronous Socket Appender",
    "asctime": "2014-12-11 14:18:57,767",
    "levelname": "WARNING",
    "pathname": "[...]/local/lib/python2.7/site-packages/celery/utils/log.py",
    "lineno": 278
}
» 14:18:57.881  {
    "name": "celery.worker",
    "message": "Unrecoverable error: RuntimeError('threads can only be started once',)",
    "asctime": "2014-12-11 14:18:57,768",
    "levelname": "ERROR",
    "pathname": "[...]/local/lib/python2.7/site-packages/celery/worker/__init__.py",
    "lineno": 210
}

Can you try the latest version ? https://pypi.python.org/pypi/Logentries

Error is reproducible when running workers using Celery.

  File "/usr/lib/python3.4/logging/__init__.py", line 1260, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python3.4/logging/__init__.py", line 1395, in _log
    self.handle(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 1405, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 1467, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 839, in handle
    self.emit(record)
  File "/vagrant/.env/lib/python3.4/site-packages/logentries/utils.py", line 184, in emit
    self._thread.start()
  File "/usr/lib/python3.4/threading.py", line 846, in start
    raise RuntimeError("threads can only be started once")
RuntimeError: threads can only be started once

Seeing the same issue with Logentries==0.7, Django==1.4.20, django-celery==3.1.10:

Traceback (most recent call last):
File "/home/fedora/deploy/master/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task
R = retval = fun(_args, *_kwargs)
File "/home/fedora/deploy/master/lib/python2.7/site-packages/celery/app/trace.py", line 437, in protected_call
return self.run(_args, *_kwargs)
File "/home/fedora/deploy/master/webapp/shopventoryapp/common/tasks.py", line 110, in run
result, exception = self.do_timed_work(_args, *_kwargs)
File "/home/fedora/deploy/master/webapp/shopventoryapp/common/tasks.py", line 132, in do_timed_work
kwargs))
File "/usr/lib64/python2.7/logging/init.py", line 1182, in exception
self.error(msg, _args, *_kwargs)
File "/usr/lib64/python2.7/logging/init.py", line 1175, in error
self._log(ERROR, msg, args, **kwargs)
File "/usr/lib64/python2.7/logging/init.py", line 1268, in _log
self.handle(record)
File "/usr/lib64/python2.7/logging/init.py", line 1278, in handle
self.callHandlers(record)
File "/usr/lib64/python2.7/logging/init.py", line 1318, in callHandlers
hdlr.handle(record)
File "/usr/lib64/python2.7/logging/init.py", line 749, in handle
self.emit(record)
File "/home/fedora/deploy/master/lib/python2.7/site-packages/logentries/utils.py", line 184, in emit
self._thread.start()
File "/usr/lib64/python2.7/threading.py", line 740, in start
raise RuntimeError("threads can only be started once")
RuntimeError: threads can only be started once

same issue with logentries 0.7 and flask

Same here with logentries 0.8 + aiohttp + gunicorn

To solve this issue I had to make a pass on the exception

             except RuntimeError: # It's already started.
-                if not self._thread.is_alive():
-                    raise
+                pass

Likewise here, just using multiprocessing in Python 2.7 and the logentries 0.15 Python client.

Same problem with multiple processes in python.

Does not happen if we don't use logging in the parent process.

We had the same issue using 0.15.

Problem was that we called:

import gevent
import gevent.monkey
gevent.monkey.patch_all()

after calling the Logentries handler.
This happened in a bastardized piece of code, that was a mix of several other projects.. and so this happened.

Interestingly, it didn't happen on the dev machine, but it did in a cloud env.

Not sure why.

Maybe the PR #46 solve this issue

Navigation Menu

Repository navigation

Incompatibilty with gunicorn. #3

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Incompatibilty with gunicorn. #3

Description

Activity

MarkLC-r7 commented on Oct 8, 2013

AJamesPhillips commented on Oct 8, 2013

bluebomber commented on Apr 4, 2014

bluebomber commented on Apr 4, 2014

akarl commented on Dec 11, 2014

StephenHynes7 commented on Feb 24, 2015

yrunts commented on Feb 27, 2015

rsaftoiu commented on Apr 9, 2015

hihell commented on Jun 22, 2015

drgarcia1986 commented on Aug 17, 2015

drgarcia1986 commented on Aug 18, 2015

chrisguidry commented on Aug 28, 2015

Sandeep4 commented on Sep 1, 2015

Sandeep4 commented on Sep 1, 2015

advance512 commented on Mar 6, 2016

drgarcia1986 commented on Apr 5, 2016

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions