populate isn't reentrant

[Deva P. Seetharam]

hello 

i am using mod_wsgi (version 3.3.4) with apache2.2.22 and django 1.7.3 on debian wheezy (amd64). i get the following error message:

[Wed Jan 14 17:58:09 2015] [info] [client 202.83.25.57] mod_wsgi (pid=3858, process='kutbill.com', application='www.mysite.com|'): Loading WSGI script '/var/www/mysite/scripts/wsgi.py'.

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57] mod_wsgi (pid=3858): Target WSGI script '/var/www/mysite/scripts/wsgi.py' cannot be loaded as Python module.

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57] mod_wsgi (pid=3858): Exception occurred processing WSGI script '/var/www/mysite/scripts/wsgi.py'.

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57] Traceback (most recent call last):

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]   File "/var/www/mysite/scripts/wsgi.py", line 14, in <module>

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]     application = get_wsgi_application()

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/core/wsgi.py", line 14, in get_wsgi_application

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]     django.setup()

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/__init__.py", line 21, in setup

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]     apps.populate(settings.INSTALLED_APPS)

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/apps/registry.py", line 78, in populate

[Wed Jan 14 17:58:09 2015] [error] [client 202.83.25.57]     raise RuntimeError("populate() isn't reentrant")

how to resolve this issue? kindly let me know. 

[Graham Dumpleton]

What is in the file:

/var/www/mysite/scripts/wsgi.py

You should only be calling get_wsgi_application() once at global scope in the file. You should not use any sort of WSGI application middleware that results in it being called more than once.

Are you only hosting the one Django application on this Apache server or are there others?

Graham

[Deva P. Seetharam]

wsgi.py contains the following (the default code created by Django):

import os

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "scripts.settings")

from django.core.wsgi import get_wsgi_application

application = get_wsgi_application()

there is only one project hosted on this apache server. but, it has two apps and the directory structure is as follows:

kutbill/

|-- datasink

|   |-- admin.py

|   |-- admin.pyc

|   |-- apps.py

|   |-- apps.pyc

|   |-- forms.py

|   |-- __init__.py

|   |-- __init__.pyc

|   |-- migrations

|   |   `-- __init__.py

|   |-- templates

|   |   `-- datasink

|   |       `-- index.html

|   |-- tests.py

|   |-- urls.py

|   `-- views.py

|-- dataviz

|   |-- admin.py

|   |-- admin.pyc

|   |-- forms.py

|   |-- __init__.py

|   |-- __init__.pyc

|   |-- migrations

|   |   `-- __init__.py

|   |-- models.py

|   |-- models.pyc

|   |-- templates

|   |   `-- dataviz

|   |       |-- index.html

|   |       `-- show_data.html

|   |-- tests.py

|   |-- urls.py

|   `-- views.py

|-- documents

|   |-- index.html

|   `-- main.html

|-- manage.py

`-- scripts

    |-- __init__.py

    |-- __init__.pyc

    |-- settings.py

    |-- settings.pyc

    |-- urls.py

    `-- wsgi.py

the installed_apps and middleware sections of settings.py are as follows:

# Application definition                                                                                                                                                                                          

INSTALLED_APPS = (

    'django.contrib.admin',

    'django.contrib.auth',

    'django.contrib.contenttypes',

    'django.contrib.sessions',

    'django.contrib.messages',

    'django.contrib.staticfiles',

    'dataviz',

    'datasink',

)

INSTALLED_APPS = ('django_cassandra_engine',) + INSTALLED_APPS

MIDDLEWARE_CLASSES = (

    'django.contrib.sessions.middleware.SessionMiddleware',

    'django.middleware.common.CommonMiddleware',

    'django.middleware.csrf.CsrfViewMiddleware',

    'django.contrib.auth.middleware.AuthenticationMiddleware',

    'django.contrib.auth.middleware.SessionAuthenticationMiddleware',

    'django.contrib.messages.middleware.MessageMiddleware',

    'django.middleware.clickjacking.XFrameOptionsMiddleware',

)

best regards 

Deva P. Seetharam 

[Graham Dumpleton]

Do you get this on every request and so the site isn't running at all?

I can only really think of one way this could be occurring but the traceback doesn't necessarily support that notion unfortunately.

Can you add into the wsgi.py file a debug print statement of:

    print 'IMPORTING', __name__, 'from', __file__

Try again and see if you see this debug message appear in the Apache error logs more than once with the name given for the module being different in each case even though the file path is the same.

Can you also show me the mod_wsgi configuration for this site. That is, any 'WSGI' directives from Apache configuration file.

Graham

--
You received this message because you are subscribed to the Google Groups "modwsgi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+u...@googlegroups.com.
To post to this group, send email to mod...@googlegroups.com.
Visit this group at http://groups.google.com/group/modwsgi.
For more options, visit https://groups.google.com/d/optout.

[Graham Dumpleton]

On 15/01/2015, at 2:14 PM, Graham Dumpleton <graham.d...@gmail.com> wrote:

Do you get this on every request and so the site isn't running at all?

I can only really think of one way this could be occurring but the traceback doesn't necessarily support that notion unfortunately.

Can you add into the wsgi.py file a debug print statement of:

    print 'IMPORTING', __name__, 'from', __file__

Sorry amend that to:

    import os

    print 'IMPORTING', __name__, 'from', __file__, 'in', os.getpid()

Graham

[Deva P. Seetharam]

this issue happens only when the machine is booted. if i restart the apache again, the site starts working.  

here is the wsgi config in the apache config file:

--------------

WSGIScriptAlias / /var/www/kutbill/scripts/wsgi.py

    # WSGIPythonPath /var/www/kutbill/                                                                                                                                                                            

    <Directory /var/www/kutbill/scripts>

        <Files wsgi.py>

            Order allow,deny

            Allow from all

        </Files>

    </Directory>

    WSGIDaemonProcess kutbill.com python-path=/var/www/kutbill/ processes=2 threads=20 display-name=%{GROUP}

    WSGIProcessGroup kutbill.com

-----------------

[Deva P. Seetharam]

the import message, you suggested, appears in the apache error log file as follows:

IMPORTING WSGI: _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 12993

IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 12994

IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 13058

interestingly, it does not appear at all after the machine is rebooted. 

after the machine is rebooted, i get the following error messages:

[Thu Jan 15 09:08:58 2015] [info] [client 202.83.25.57] mod_wsgi (pid=3830, process='kutbill.com', application='www.kutbill.com|'): Loading WSGI script '/var/www/kutbill/scripts/wsgi.py'.

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57] mod_wsgi (pid=3830): Target WSGI script '/var/www/kutbill/scripts/wsgi.py' cannot be loaded as Python module.

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57] mod_wsgi (pid=3830): Exception occurred processing WSGI script '/var/www/kutbill/scripts/wsgi.py'.

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57] Traceback (most recent call last):

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]   File "/var/www/kutbill/scripts/wsgi.py", line 15, in <module>

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]     application = get_wsgi_application()

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/core/wsgi.py", line 14, in get_wsgi_application

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]     django.setup()

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/__init__.py", line 21, in setup

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]     apps.populate(settings.INSTALLED_APPS)

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]   File "/usr/local/lib/python2.7/dist-packages/django/apps/registry.py", line 78, in populate

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57]     raise RuntimeError("populate() isn't reentrant")

[Thu Jan 15 09:08:58 2015] [error] [client 202.83.25.57] RuntimeError: populate() isn't reentrant

[Deva P. Seetharam]

after i manually restarted apache, i see the following error messages:

[Thu Jan 15 09:18:48 2015] [info] mod_wsgi (pid=4376): Create interpreter 'www.kutbill.com|'.

[Thu Jan 15 09:18:48 2015] [info] mod_wsgi (pid=4376): Adding '/var/www/kutbill/' to path.

[Thu Jan 15 09:18:48 2015] [info] [client 202.83.25.57] mod_wsgi (pid=4376, process='kutbill.com', application='www.kutbill.com|'): Loading WSGI script '/var/www/kutbill/scripts/wsgi.py'.

[Thu Jan 15 09:18:48 2015] [error] /usr/local/lib/python2.7/dist-packages/pytz/__init__.py:29: UserWarning: Module mod_wsgi was already imported from None, but /usr/local/lib/python2.7/dist-packages is being added to sys.path

[Thu Jan 15 09:18:48 2015] [error]   from pkg_resources import resource_stream

[Thu Jan 15 09:18:49 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4378

[Thu Jan 15 09:18:49 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4376

[Graham Dumpleton]

Have you ever done a 'pip install mod_wsgi'?

What do you get for 'pip freeze'?

Can you uninstall 'mod_wsgi' installed by pip if you have?

pip uninstall mod_wsgi

Removing that will not affect your main Apache/mod_wsgi and is separate unless you had worked out to load the mod_wsgi.so out of the Python installation, which is unlikely.

That you are seeing three separate processes is a bit odd. Do you happen to have a WSGIImportScript directive anywhere in your Apache configuration?

Also try changing debug to:

    import os

    import mod_wsgi
    print 'IMPORTING', __name__, 'from', __file__, 'in', os.getpid(), ":", mod_wsgi.process_group, ":", mod_wsgi.application_group

I think those variables exist in mod_wsgi 3.3, but they may not.

Graham

[Deva P. Seetharam]

yes, i had done a pip install mod_wsgi. however, i had already uninstalled it before i started getting this error.

pip freeze | grep -i wsgi yields the following:

mod-wsgi-metrics==1.1.0

wsgiref==0.1.2

after making the changes you suggested,  i see the following error messages:

[Thu Jan 15 09:41:54 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4296 : kutbill.com : www.kutbill.com|

[Thu Jan 15 09:41:54 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4295 : kutbill.com : www.kutbill.com|

[Graham Dumpleton]

For the warning:

[Thu Jan 15 09:18:48 2015] [error] /usr/local/lib/python2.7/dist-packages/pytz/__init__.py:29: UserWarning: Module mod_wsgi was already imported from None, but /usr/local/lib/python2.7/dist-packages is being added to sys.path

something might be a bit screwy with the Python installation. the issue is explained in:

    http://stackoverflow.com/questions/7239518/module-pytz-was-already-imported

Anyway, seems it can be ignored.

So the latest logging looks fine. Did you see the error in that case about not being reentrant?

Previously you also had:

IMPORTING WSGI: _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 12993
IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 12994
IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 13058

That is, showed 3 processes. Was that on initial Apache start? 

Graham

[Deva P. Seetharam]

thank you for the pointer to the python issue. seems like we can safely ignore it.

yes, "not reentrant" messages are still appearing when the machine is rebooted.

regarding the three error messages, i gathered those three messages appearing at three different instances in the log file. 

[Graham Dumpleton]

Okay, here is the reason this is likely happening. And a temporary workaround.

I am going to have to think about a bigger solution to the general problem and/or whether I have the Django folks make a change to the registry to cleanup after errors properly.

Anyway, what is happening is that when your server starts up and Apache/mod_wsgi therefore starts, when the first request comes into your Django application, that forces the loading of wsgi.py and so get_wsgi_application() is called.

Unlike before Django 1.7, this now has a side effect of loading up all your applications. This appears to occur within Registry.populate().

If the loading of one of the application experiences an error, it will raise an exception with the registry in a half built state. It will release the lock on the registry acquired by that thread, but the ready flag on the registry will be left as False.

When mod_wsgi sees that the WSGI script raised an exception when loading, it will throw away the module and return a 500 response error. What it doesn't do is throw away all the other modules that may have been loaded such as Django and its registry.

On the next request, it will load wsgi.py again and when it calls into Registry.populate(), if finds the ready flag still false, but app_configs, which it has the reentrant check on is half populated and so it raises an error for that now instead.

A few things to now sort out.

What was the transient error that loading of your application encounters on system boot. Is your application possibly trying to preload data from a database and the database server is on the same system and the database hasn't completely started up and so is failing? This would explain why it only happens on system boot.

If there was a transient error which caused an exception to be raised, the details should have appeared in the Apache error log. Make sure you check the main Apache error log and not just the VirtualHost error log.

Next, what can be done.

Ideally Django would in the case of seeing an exception while loading applications not leave the registry in an inconsistent state and cleanup so that application loading can be attempted again. I imagine though that they may be of the opinion that it is too hard to try and load applications more than once as they may have cached start which would cause reloading to be difficult.

The only solution therefore would be too kill the process so that mod_wsgi will recreate it automatically and so throw all the state away.

Thus, do the following:

    import sys

    import os

    import signal

    try:

        application = get_wsgi_application()

    except Exception:

        # Error loading applications.

        if 'mod_wsgi' in sys.modules:

            os.kill(os.getpid(), signal.SIGINT)

        

        raise

Worth pointing out is that this could happen with any WSGI server. With a WSGI server like gunicorn though, the initial error would cause gunicorn as a whole to exit and fail to start up. If gunicorn was under supervisord then it would automatically restart it and likely the next time if whatever resource wasn't ready the first time was then ready it would start okay.

I may be able to introduce a option configuration directive to say restart whole process on failed load of WSGI script. This has to be optional though and would also only apply to daemon mode. It can't be on by default because in a system with multiple WSGI applications in same process, you don't necessarily want to restart whole process if one fails.

Another issue is that if you do restart, if it fails to load again, then you end up in an endless loop of it continually restarting and due to how processes are managed by Apache, pretty well impossible to have a system which throttles back and stops restarting.

So try that workaround, but watch it carefully, because if the error isn't recoverable, it will loop, continually killing the process and restarting it.

Better that you work out what isn't ready such that the applications are loading so soon after system boot.

Does that all make sense?

Graham

[Graham Dumpleton]

As a throttle and to avoid a fork bomb of sorts, you could actually use:

    import sys
    import os
    import signal

    import time

    try:
        application = get_wsgi_application()

    except Exception:
        # Error loading applications.

        if 'mod_wsgi' in sys.modules:
            os.kill(os.getpid(), signal.SIGINT)

            time.sleep(2.5)
        
        raise

I use 2.5 seconds here, as it will be forcibly killed off after 5 seconds anyway if it blocked completely. So there is an upper limit, but just don't make it too small as new requests will cause it to all occur again in worst case where wasn't a transient issue.

Graham

[Deva P. Seetharam]

thank you for your detailed and prompt response. as per your advice, i have modified the wsgi.py as follows:

import os

import mod_wsgi

import time

import sys

import signal

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "scripts.settings")

from django.core.wsgi import get_wsgi_application

print 'IMPORTING WSGI: ', __name__, 'from', __file__, 'in', os.getpid(), ":", mod_wsgi.process_group, ":", mod_wsgi.application_group

try:

    application = get_wsgi_application()

    print 'WSGI without exception'

except Exception:

    print 'handling WSGI exception'

    # Error loading applications.                                                                                                                            

    if 'mod_wsgi' in sys.modules:

        os.kill(os.getpid(), signal.SIGINT)

        time.sleep(2.5)

    raise

as you guessed, the first import leads to exception and the subsequent one seems to work fine. pls. see the error messages in apache error.log:

[Thu Jan 15 11:47:33 2015] [info] [client 202.83.25.57] mod_wsgi (pid=4038, process='kutbill.com', application='www.kutbill.com|'): Loading WSGI script '/var/www/kutbill/scripts/wsgi.py'.

[Thu Jan 15 11:47:33 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4038 : kutbill.com : www.kutbill.com|

[Thu Jan 15 11:47:33 2015] [error] handling WSGI exception

[Thu Jan 15 11:47:33 2015] [error] IMPORTING WSGI:  _mod_wsgi_2331eb8e63d48eca49e254e1eadd5a47 from /var/www/kutbill/scripts/wsgi.py in 4195 : kutbill.com : www.kutbill.com|

[Thu Jan 15 11:47:34 2015] [error] WSGI without exception

[Thu Jan 15 11:47:35 2015] [info] mod_wsgi (pid=4038): Aborting process 'kutbill.com'.

[Thu Jan 15 11:47:35 2015] [error] [client 202.83.25.57] Premature end of script headers: wsgi.py

[Thu Jan 15 11:47:35 2015] [info] mod_wsgi (pid=4231): Attach interpreter ''.

[Thu Jan 15 11:47:35 2015] [info] mod_wsgi (pid=4231): Adding '/var/www/kutbill/' to path.

[Thu Jan 15 11:47:40 2015] [info] mod_wsgi (pid=4231): Create interpreter 'www.kutbill.com|'.

[Thu Jan 15 11:47:40 2015] [info] mod_wsgi (pid=4231): Adding '/var/www/kutbill/' to path.

[Thu Jan 15 11:47:40 2015] [info] [client 103.227.98.88] mod_wsgi (pid=4231, process='kutbill.com', application='www.kutbill.com|'): Loading WSGI script '/var/www/kutbill/scripts/wsgi.py'.

[Graham Dumpleton]

Looks like you are getting hit by an issue which have seen a few times before, but since rarely shown to me and haven't been able to duplicate, haven't worked out problem.

That is that the exception raised in WSGI script file when loaded isn't being logged.

Can you change it to:

import traceback

try:
    application = get_wsgi_application()
    print 'WSGI without exception'
except Exception:
    print 'handling WSGI exception'
    # Error loading applications.                                                                                                                            
    if 'mod_wsgi' in sys.modules:

        traceback.print_exc()
        os.kill(os.getpid(), signal.SIGINT)
        time.sleep(2.5)

That is, print the exception manually. Then can work out what it is.

Wonder if it is just the old mod_wsgi version you are using.

The problem with distros is that they leave stuff as old versions and so you could have various bugs in what you are using that distros will never fix.

Distros can be a curse.

Graham

[Graham Dumpleton]

Deva

Did you get to the bottom of why the transient issue was occurring?

I would really like to understand your case a bit better.

I am also still keen to work out why details of the exception may not be getting logged by mod_wsgi when the module isn't able to be imported. So if the traceback.print_exc() did actually print out the exception details and traceback, do please let me know.

I am working on a mechanism to allow mod_wsgi to be configured to deal with a case like this and force restart the process on a failed import of the WSGI script. Right now just trying to work out the best way of achieving that which will avoid a potential fork bomb if the problem isn't transient.

Graham

[Deva P. Seetharam]

hi Graham

sorry for not posting a followup. however, despite including the debug code (see below) you had suggested, only the following log messages appear in apache error.log:

[Fri Jan 16 23:47:39 2015] [error] handling WSGI exception

[Fri Jan 16 23:47:39 2015] [info] mod_wsgi (pid=32011): Shutdown requested 'kutbill.com'.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Stopping process 'kutbill.com'.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Destroying interpreters.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Destroy interpreter 'www.kutbill.com|'.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Cleanup interpreter ''.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Terminating Python.

[Fri Jan 16 23:47:40 2015] [info] mod_wsgi (pid=31986): Python has shutdown.

further more, this problem occurs only when the app is restarted. so finding the root cause seems a bit hard. pls. review and advise.

...

[Graham Dumpleton]

Try actually writing the error details out to a file:

 
import traceback

try:
    application = get_wsgi_application()
    print 'WSGI without exception'
except Exception:
    print 'handling WSGI exception'
    # Error loading applications.                                                                                                                            
    if 'mod_wsgi' in sys.modules:

        with open('/tmp/error.log', 'w') as fp:
            traceback.print_exc(file=fp)
        os.kill(os.getpid(), signal.SIGINT)
        time.sleep(2.5)

I don't understand why the message from traceback.print_exc() isn't coming out. One possibility is that what ever is being printed is failing to be converted by default encoding and so raising a new exception.

Try also setting the options:

    lang=en_US.UTF-8 locale=en_US.UTF-8

to WSGIDaemonProcess directive.

The default locale might be coming through as ASCII to cause that.

Graham