Opened 4 years ago

Closed 4 years ago

Last modified 2 years ago

#27543 closed Bug (needsinfo)

AttributeError: '_Frame' object has no attribute 'f_back' / Django and celery error logging gone wrong

Reported by: Simon Chenard Owned by:
Component: Error reporting Version: 1.10
Severity: Normal Keywords: celery logging traceback
Cc: Triage Stage: Unreviewed
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description (last modified by Simon Chenard)

When an error is raised inside a celery task, django crashes with the error described in the summary. This error is not raised anywhere else in the application, only in a celery task. Came across this situation trying to understand why I was not getting error emails for celery tasks. Triggered this exception by adding :

CELERY_WORKER_HIJACK_ROOT_LOGGER = False

Implying otherwise the error is not redirected to the AdminEmailHandler.

Django version : 1.10.2
Celery version : 4.0.0

(stacktrace is below)

The method "get_traceback_frame_variables" is the cause of this problem. By wrapping a try except around the code of the method and returning an empty array, I roughly get what I expect : an email describing the error with the adequate traceback.

My logging setup :

 LOGGING = { 
     'version': 1,
     'disable_existing_loggers': False,
     'filters': {
         'task_id': {
             '()': 'lib.logging.task_filter.TaskIDFilter'
         },
         'require_debug_false': {
             '()': 'django.utils.log.RequireDebugFalse'
         }
     },  
     'formatters' : { 
         'task': {
             'format': LOGGING_TASK_FORMAT
         },
     },  
     'handlers': {
         'mail_admins': {
             'level': 'ERROR',
             'class': 'django.utils.log.AdminEmailHandler',
             'include_html': True,
             'filters': ['require_debug_false'], # commented or not, the error happens with DEBUG = True or False
         },
     },
     'loggers': {
         '': {
             'handlers': ['console', 'mail_admins'],
             'level': 'INFO',
             'propagate': True
         },
     }
  }

Here is the stacktrace :

Traceback (most recent call last):
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/celery/app/trace.py", line 382, in trace_task
    I, R, state, retval = on_error(task_request, exc, uuid)
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/celery/app/trace.py", line 324, in on_error
    task, request, eager=eager, call_errbacks=call_errbacks,
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/celery/app/trace.py", line 158, in handle_error_state
    call_errbacks=call_errbacks)
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/celery/app/trace.py", line 212, in handle_failure
    self._log_error(task, req, einfo)
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/celery/app/trace.py", line 242, in _log_error
    extra={'data': context})
  File "/usr/lib/python3.4/logging/__init__.py", line 1341, in log
    self._log(level, msg, args, **kwargs)
  File "/usr/lib/python3.4/logging/__init__.py", line 1409, in _log
    self.handle(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 1419, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 1481, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 853, in handle
    self.emit(record)
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/django/utils/log.py", line 119, in emit
    message = "%s\n\n%s" % (self.format(no_exc_record), reporter.get_traceback_text())
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/django/views/debug.py", line 325, in get_traceback_text
    c = Context(self.get_traceback_data(), autoescape=False, use_l10n=False)
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/django/views/debug.py", line 264, in get_traceback_data
    frames = self.get_traceback_frames()
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/django/views/debug.py", line 420, in get_traceback_frames
    'vars': self.filter.get_traceback_frame_variables(self.request, tb.tb_frame),
  File "/home/simon/code/caravan/fibre/env-aws/lib/python3.4/site-packages/django/views/debug.py", line 191, in get_traceback_frame_variables
    current_frame = tb_frame.f_back
AttributeError: '_Frame' object has no attribute 'f_back'

Change History (6)

comment:1 Changed 4 years ago by Simon Chenard

Description: modified (diff)

comment:2 Changed 4 years ago by Simon Charette

That looks similar to #17699.

comment:3 Changed 4 years ago by Tim Graham

Can you provide a way to reproduce the issue without celery to confirm it's a Django bug and not something that should be fixed in celery?

comment:4 Changed 4 years ago by Tim Graham

Resolution: needsinfo
Status: newclosed

comment:5 Changed 4 years ago by Simon Chenard

In the end I couldn't completely understand the relationship between django and celery - but since it does only happens when celery is involved, it's most likely not a issue on Django's side.

But for the record, if anyone else stumble on a similar case, what I did end up doing is sub-classing the AdminEmailHandler and use python's own traceback library, if the exception described earlier is raised.

comment:6 Changed 2 years ago by David Black

The issue seems to be caused by celery using billiard's ExceptionInfo and it providing its own _Frame and Traceback classes. (Seemingly related -> https://github.com/celery/billiard/issues/6).

Note: See TracTickets for help on using tickets.
Back to Top