runserver reloader masks exceptions

[Ivan Koval]

Migrating my project from 1.8.5 to 1.9b1 cause next traceback, when running server:

Traceback (most recent call last):
  File "/Users/.../manage.py", line 10, in <module>
    execute_from_command_line(sys.argv)
  File "/Users/.../env3/lib/python3.5/site-packages/django/core/management/__init__.py", line 350, in execute_from_command_line
    utility.execute()
  File "/Users/.../env3/lib/python3.5/site-packages/django/core/management/__init__.py", line 342, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/Users/.../env3/lib/python3.5/site-packages/django/core/management/__init__.py", line 176, in fetch_command
    commands = get_commands()
  File "/Users/.../env3/lib/python3.5/site-packages/django/core/management/__init__.py", line 71, in get_commands
    for app_config in reversed(list(apps.get_app_configs())):
  File "/Users/.../env3/lib/python3.5/site-packages/django/apps/registry.py", line 137, in get_app_configs
    self.check_apps_ready()
  File "/Users/.../env3/lib/python3.5/site-packages/django/apps/registry.py", line 124, in check_apps_ready
    raise AppRegistryNotReady("Apps aren't loaded yet.")
django.core.exceptions.AppRegistryNotReady: Apps aren't loaded yet.

Process finished with exit code 1

And my manage.py is pretty simple:

#!/usr/bin/env python
import os
import sys

if __name__ == "__main__":
    os.environ.setdefault("DJANGO_SETTINGS_MODULE", "settings.base")

    from django.core.management import execute_from_command_line

    execute_from_command_line(sys.argv)

[Tim Graham]

We'll need a sample project to reproduce the problem. It's not possible to help given what you provided so far. Thanks.

[Ivan Koval]

Traceback is poor on details, so i just back to 1.8.5.
Even if i could share project it won't work standalone.

[Tim Graham]

The only thing that comes to mind is #25477 but that doesn't look relevant here.

[Dheerendra Rathor]

I usually switch back and forth between 1.8.5 and 1.9b1 and never got this error. Is there any third party app you're using?

[Ivan Koval]

All my third part apps:

THIRD_PARTY_APPS = (
    'gunicorn',
    'opbeat.contrib.django',
    # Wagtail CMS
    'taggit',
    'compressor',
    'modelcluster',

    'wagtail.contrib.wagtailstyleguide',
    'wagtail.wagtailcore',
    'wagtail.wagtailadmin',
    'wagtail.wagtailsearch',
    'wagtail.wagtailimages',
    'wagtail.wagtaildocs',
    'wagtail.wagtailsnippets',
    'wagtail.wagtailusers',
    'wagtail.wagtailsites',
    'wagtail.wagtailembeds',
    'wagtail.wagtailredirects',
    'wagtail.wagtailforms',

    'wagtailforums',
    'wagtailmodeladmin',
)

[Ivan Koval]

It's specifically Wagtail CMS package problem.
Installing wagtail dev versions from github solved this error.

[Claude Paroz]

I've had this same error in one of my projects, and I'd like to reopen it because I think there is an exception swallowing which masks real errors. (was related to django-reversion in my case).
With runserver --noreload, I'm getting the proper traceback which reveals the real problem, but without the --noreload, I'm getting the useless traceback mentioned by the reporter.

The problem is with this exception catching:
​https://github.com/django/django/blob/stable/1.9.x/django/core/management/__init__.py#L315-L317

Frankly, I'd rather live with an autoreloader not restarting in case of syntax errors (#24704) than with exception swallowing.

[Collin Anderson]

We could maybe print the traceback yet still have the program continue (in case there's a more specific error message later).

[Villiers Strauss]

This is a real problem, as it seems to label other exceptions as django.core.exceptions.AppRegistryNotReady: Apps aren't loaded yet.

I had a working Django 1.9rc2 application yesterday, but this morning when I tried to run runserver, I got:

Traceback (most recent call last):
  File "./manage.py", line 9, in <module>
    execute_from_command_line(sys.argv)
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 350, in execute_from_command_line
    utility.execute()
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 342, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 176, in fetch_command
    commands = get_commands()
  File "/Users/phil/env/lib/python2.7/site-packages/django/utils/lru_cache.py", line 100, in wrapper
    result = user_function(*args, **kwds)
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 71, in get_commands
    for app_config in reversed(list(apps.get_app_configs())):
  File "/Users/phil/env/lib/python2.7/site-packages/django/apps/registry.py", line 137, in get_app_configs
    self.check_apps_ready()
  File "/Users/phil/env/lib/python2.7/site-packages/django/apps/registry.py", line 124, in check_apps_ready
    raise AppRegistryNotReady("Apps aren't loaded yet.")
django.core.exceptions.AppRegistryNotReady: Apps aren't loaded yet.

This was curious, as I hadn't changed any of the code or packages, so the AppRegistryNotReady didn't make any sense.

After a lot of troubleshooting and googling, I found claudep's suggestion of using --noreload to display the actual error and discovered that the error had nothing to do with apps not being ready. The exception it was masking was:

Traceback (most recent call last):
  File "./manage.py", line 9, in <module>
    execute_from_command_line(sys.argv)
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 350, in execute_from_command_line
    utility.execute()
  File "/Users/phil/env/lib/python2.7/site-packages/django/core/management/__init__.py", line 324, in execute
    django.setup()
  File "/Users/phil/env/lib/python2.7/site-packages/django/__init__.py", line 17, in setup
    configure_logging(settings.LOGGING_CONFIG, settings.LOGGING)
  File "/Users/phil/env/lib/python2.7/site-packages/django/utils/log.py", line 71, in configure_logging
    logging_config_func(logging_settings)
  File "/usr/local/Cellar/python/2.7.10_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/config.py", line 794, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/local/Cellar/python/2.7.10_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/config.py", line 576, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler u'app_log_file': [Errno 2] No such file or directory: u'/var/log/myapp/application.log'

Turns out an OS update removed my log directory, and it couldn't create the logfiles on startup, but it took me about an hour of troubleshooting to find this simple solution just because I was getting the wrong exception the whole time.

IMO this is a major problem, because firstly, the AppRegistryNotReady traceback is not helpful at all, because it doesn't tell you where the problem is, and secondly, it's not even the correct exception.

Seeing as most Django developers use runserver to develop, I would even consider labelling this as a release blocker.

[Aymeric Augustin]

Perhaps we could print the traceback here on Python 2:
​https://github.com/django/django/blob/9bc0c21b/django/core/management/__init__.py#L313

I believe this bug doesn't affect Python 3 thanks to exception chaining.

[Ivan Koval]

Replying to aaugustin:

I believe this bug doesn't affect Python 3 thanks to exception chaining.

It's weird, because my original exception was in Python 3.5

[Tino de Bruijn]

It happens to me in Python 3.4 as well.

It is also caused when trying to import something in an app's __init__.py, as some apps do. When that import fails, I see the django.core.exceptions.AppRegistryNotReady exception. Running the shell-management command (or runserver --noreload) allows me to see what is going on.

[Maxime Lorant]

Indeed, same behaviour, on Python 2.7.10 as well. A simple way to reproduce it is to install a third party app that use removed features of Django 1.9.

Tim said this wasn't a release block for the 1.9 (cf status of 1.9 on dev ML), but I tend to disagree, it makes the migration harder if you don't find this ticket and without knowing the --noreload option.

[Tim Graham]

The fix for #24704 was backported to 1.8 too. That's why I changed the version to 1.8 as I don't believe the issue is specific to 1.9, but I could be missing something.

[Tim Graham]

Upon further investigation, it looks like the fix for #25510 simply wasn't backported to the stable/1.9.x branch. I have done that in 24ebf17f04ee0ed157c430ff7d10ec0728abd48e.