ask/celery — Issue #603: Exception outside body: <class 'psycopg2.OperationalError'>: could not receive data from server: Bad file descriptor
Author: crucialfelix
Created: 2012-02-01 12:53:28+00:00
State: open

I'm getting DatabaseErrors using postgres when exceptions are thrown inside a task. I run the following task with concurrency 1 and it fails sometimes on the 2nd and at most the 6th time I call the task. There's some randomness involved as to when it fails and that's making debugging hellish.

UserWarning: Exception outside body: : could not receive data from server: Bad file descriptor

'/Users/crucial/Sites/eggs-cache/django_celery-2.4.2-py2.6.egg',
'/Users/crucial/Sites/eggs-cache/redis-2.4.11-py2.6.egg',
celery 2.4.6

REDIS_HOST = "localhost"
REDIS_PORT = 6379

BROKER_URL = "redis://%s:%s/0" % (REDIS_HOST,REDIS_PORT)
CELERY_RESULT_BACKEND = "database"
CELERY_IGNORE_RESULT = False
CELERY_REDIS_HOST = REDIS_HOST
CELERY_REDIS_PORT = REDIS_PORT
CELERY_REDIS_DB = 2
CELERY_STORE_ERRORS_EVEN_IF_IGNORED = True
CELERY_SEND_TASK_ERROR_EMAILS = True
CELERYD_CONCURRENCY = 1
#CELERY_REDIS_PASSWORD = ''
#CELERY_REDIS_MAX_CONNECTIONS
BROKER_TRANSPORT = "redis"
BROKER_HOST = REDIS_HOST
BROKER_PORT = REDIS_PORT
BROKER_VHOST = "3"

The following code works fine outside of celery and I have never seen this database error in hundreds of development hours on this setup.

class ContentPackStatus(models.Model):

import_key = models.CharField(blank=False, max_length=200)
validated = models.BooleanField(default=False)

class ContentPackImportError(models.Model):

message = models.CharField(blank=True, max_length=250)
content_pack_status = models.ForeignKey(ContentPackStatus,related_name="errors")

@task
def validate_content_pack(import_key):

status = ContentPackStatus.objects.get(import_key=import_key)
status.errors.all().delete()

try:
# an exception is raised
file = None
file.name

except Exception,e:
# and the event is logged
status.errors.create(message=str(e))
status.set_validated(False)
status.save()
return status.validated

This version also fails:

@task
def validate_content_pack(import_key):

with transaction.commit_on_success():
status = ContentPackStatus.objects.get(import_key=import_key)
status.errors.all().delete()

try:
file = None
file.name
except Exception,e:
with transaction.commit_on_success():
status.errors.create(message=str(e))
status.set_validated(False)
status.save()
return status.validated

after running this a few times and succesfully saving the error, it goes into a database connection error state:

[2012-02-01 13:17:23,394: DEBUG/MainProcess] Task accepted: hardwax.downloads.tasks.validate_content_pack[89bae45d-eace-4245-bde3-a73a52040d4f] pid:4740
[2012-02-01 13:17:23,431: WARNING/PoolWorker-1] /Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py:112: UserWarning: Exception outside body: : could not receive data from server: Bad file descriptor

Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 106, in execute_safe
return self.execute(*args, **kwargs)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 124, in execute
return super(WorkerTaskTrace, self).execute()
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/execute/trace.py", line 90, in execute
retval = self._trace()
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/execute/trace.py", line 104, in _trace
r = handler(trace.retval, trace.exc_type, trace.tb, trace.strtb)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 139, in handle_success
self.task.backend.mark_as_done(self.task_id, retval)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/backends/base.py", line 88, in mark_as_done
return self.store_result(task_id, result, status=states.SUCCESS)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/backends/base.py", line 225, in store_result
return self._store_result(task_id, result, status, traceback, **kwargs)
File "/Users/crucial/Sites/eggs-cache/django_celery-2.4.2-py2.6.egg/djcelery/backends/database.py", line 26, in _store_result
traceback=traceback)
File "/Users/crucial/Sites/eggs-cache/django_celery-2.4.2-py2.6.egg/djcelery/managers.py", line 49, in _inner
transaction.rollback_unless_managed()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/transaction.py", line 133, in rollback_unless_managed
connection.rollback_unless_managed()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/backends/__init__.py", line 193, in rollback_unless_managed
self._rollback()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/backends/__init__.py", line 50, in _rollback
return self.connection.rollback()
OperationalError: could not receive data from server: Bad file descriptor

map(str, (exc.__class__, exc, exc_info.traceback))))
[2012-02-01 13:17:23,433: ERROR/MainProcess] Task hardwax.downloads.tasks.validate_content_pack[89bae45d-eace-4245-bde3-a73a52040d4f] raised exception: OperationalError('could not receive data from server: Bad file descriptor\n',)
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 106, in execute_safe
return self.execute(*args, **kwargs)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 124, in execute
return super(WorkerTaskTrace, self).execute()
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/execute/trace.py", line 90, in execute
retval = self._trace()
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/execute/trace.py", line 104, in _trace
r = handler(trace.retval, trace.exc_type, trace.tb, trace.strtb)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/worker/job.py", line 139, in handle_success
self.task.backend.mark_as_done(self.task_id, retval)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/backends/base.py", line 88, in mark_as_done
return self.store_result(task_id, result, status=states.SUCCESS)
File "/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/site-packages/celery/backends/base.py", line 225, in store_result
return self._store_result(task_id, result, status, traceback, **kwargs)
File "/Users/crucial/Sites/eggs-cache/django_celery-2.4.2-py2.6.egg/djcelery/backends/database.py", line 26, in _store_result
traceback=traceback)
File "/Users/crucial/Sites/eggs-cache/django_celery-2.4.2-py2.6.egg/djcelery/managers.py", line 49, in _inner
transaction.rollback_unless_managed()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/transaction.py", line 133, in rollback_unless_managed
connection.rollback_unless_managed()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/backends/__init__.py", line 193, in rollback_unless_managed
self._rollback()
File "/Users/crucial/Sites/eggs-cache/Django-1.3.1-py2.6.egg/django/db/backends/__init__.py", line 50, in _rollback
return self.connection.rollback()
OperationalError: could not receive data from server: Bad file descriptor

I was also trying it before with storing results in redis. The same database error happened in my own code (saving the ContentPackImportError) but then the task never completed and would hang. Further tasks would get accepted but never processed as the last one never finishes. I was using celery on the command line and it needs to get kill 9, won't control-c.

Here's postgres log.
tl/dr: 2012-02-01 13:17:23 CETLOG: unexpected EOF on client connection

# here's the task logic doing the insert and update succesfully
2012-02-01 13:17:23 CETLOG: statement: SET DATESTYLE TO 'ISO'
2012-02-01 13:17:23 CETLOG: statement: SHOW client_encoding
2012-02-01 13:17:23 CETLOG: statement: SHOW default_transaction_isolation
2012-02-01 13:17:23 CETLOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2012-02-01 13:17:23 CETLOG: statement: SET TIME ZONE E'Europe/Berlin'
2012-02-01 13:17:23 CETLOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2012-02-01 13:17:23 CETLOG: statement: INSERT INTO "downloads_contentpackimporterror" ("content_pack_status_id", "error_time", "show_public", "message", "error_type") VALUES (330, E'2012-02-01 13:17:23.411329', true, E'''NoneType'' object has no attribute ''name''', 1)
2012-02-01 13:17:23 CETLOG: statement: SELECT CURRVAL(pg_get_serial_sequence('"downloads_contentpackimporterror"','id'))
2012-02-01 13:17:23 CETLOG: statement: SELECT (1) AS "a" FROM "downloads_contentpackstatus" WHERE "downloads_contentpackstatus"."id" = 330 LIMIT 1
2012-02-01 13:17:23 CETLOG: statement: UPDATE "downloads_contentpackstatus" SET "import_key" = E'hardwax/anstam/A-MS 002', "distributor_id" = 4, "licensor_id" = 7, "record_id" = NULL, "status" = 2, "created_on" = E'2012-01-31 17:35:12.252609', "last_updated" = E'2012-02-01 13:17:23.415617', "fatal_exception" = true, "validated" = false, "files_location" = 0 WHERE "downloads_contentpackstatus"."id" = 330
2012-02-01 13:17:23 CETLOG: statement: COMMIT

# here's celery encountering database failure
2012-02-01 13:17:23 CETLOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2012-02-01 13:17:23 CETLOG: statement: SELECT "celery_taskmeta"."id", "celery_taskmeta"."task_id", "celery_taskmeta"."status", "celery_taskmeta"."result", "celery_taskmeta"."date_done", "celery_taskmeta"."traceback" FROM "celery_taskmeta" WHERE "celery_taskmeta"."task_id" = E'89bae45d-eace-4245-bde3-a73a52040d4f'
2012-02-01 13:17:23 CETLOG: statement: SAVEPOINT s1597635264_x1
2012-02-01 13:17:23 CETLOG: unexpected EOF on client connection