Pretty Print Django POST Data in Python Logger

Due to customer requirements, I have a webpage with several forms, and dynamic formsets that are built on the client side using jquery formset. Kind of reminds me of the Simpsons episode where Homer designs a car. But here at ROI Technologies LLC, we are not girly men. We laugh in the face of complexity. And every once in a while complexity bites us in the ass.

Obviously, the best solution is to write extensive tests. Unless of course you include costs in your calculation of your “best” metric. An alternative to automatic testing is using the Python logger to gather the info you will need to quickly fix a bug if one is encountered. That’s what this post is about.

Back to my Homer page, as you can imagine, the POST data is extensive. To output it in a readable format in the logs, use json. Like this

try:
    is_valid = my_form.is_valid()
except:
    # Grab the data to fix the bug
    logger.exception('Got exception while validating form:')
    logger.debug('Here is the post data:\n %s', json.dumps(request.POST, indent=4, sort_keys=True))
    raise #  back to crashing

That first logger line in the exception handler, prints that message along with the traceback! The second logger line uses json to pretty print the Django POST data. Happy debugging.

Celery Debugging, Tricks, Etc…

I am not sure why, but Celery takes me forever to get working. Here are some notes for getting it working with Django.

Celery Troubleshooting

Lets say you have Supervisor daemonizing Celery. You can see the Celery processes are running with:

ps aux | grep celery

But things are not quite right yet. What to do? For troubleshooting, things will go a lot quicker if you do not run Celery as a daemon. Just cd to your manage.py dir and run:

celery worker -A <my_project> -E -l debug -B

This will give you lots of messages and is a lot easier to start and stop.

Restarting Supervisor

As you are debugging, you might discover errors in your Supervisor scripts. After you make changes to the Supervisor scripts, you need to restart supervisor:

service supervisor restart

Celery Beat

If you want to run periodic tasks, Celery beat is the answer. In the past, I started Celery using the -B flag in my command for starting Celery. But the docs say you should not use this in production. Instead of the -B flag, setup beat in production as shown here.

Celery Logging

In the Celery docs, they recommend setting up task logging like this:

from celery.utils.log import get_task_logger
logger = get_task_logger(__name__)

Easy enough. But where do those messages go? As is, you would think they would go to the root logger. If you did not setup the root logger, then they should go to Streamhandler, which should send them to stdout. I setup stdout in supervisor to write to a file, yet no celery logging appears there.

Others have suggested that Celery mucks with the logger tree. Maybe that’s true. In any case you can “kind of” solve it by creating a ‘celery’ logger handler. I say “kind of” because I still cannot figure out where Celery Beat tasks log to. In any case, the logger code is below.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'simple': {
            'format': '%(levelname)s %(message)s',
            'datefmt': '%y %b %d, %H:%M:%S',
            },
        },
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        }
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'celery': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': normpath(join(SITE_ROOT, 'celery.log')),
            'formatter': 'simple',
        }
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': True,
        },
        'celery': {
            'handlers': ['celery'],
            'level': 'DEBUG',
        }
    }
}

Celery Beat: Connection refused

In my case, this error was due to RabbitMQ being down. Running:

ps aux | grep rabbit

Showed only:

/usr/lib/erlang/erts-5.8.5/bin/epmd -daemon

To start RabbitMQ, run:

sudo rabbitmq-server -detached

Now you should see a bunch of new RabbitMQ processes.

Stopping Celery Worker Processes

If you use Supervisor to start and stop Celery, you will notice that you are accumulating worker processes. Evidently starting with supervisor creates workers, but stopping does not shut them down. I tried various settings in my supervisor config file, with no luck. I have googled it and not found an answer. So for now I am using a shell command to handle this:

ps auxww | grep 'celery worker' | awk '{print $2}' | xargs kill -9

This is from the Celery docs.

Django, PyCharm, Vagrant and Ansible

To provide maximum isolation between customers, I prefer to set each one up on its own VPS. One down-side to this approach is it is a pain to setup a new server. In the past, I used Fabric. But recently I read High Performance Django. In that book, they go out of their way to advise against using Fabric. They like Salt. After a little googling and a few coin tosses, I decided to give Ansible a try.

At first the going was a little rough, then I discovered this gem of a repo on Github: ansible-django-stack. It even uses Vagrant, another package I have wanted to try.

OMG

This repo is insanely helpful. It even comes with a fully functional Django project. This was incredibly helpful for figuring out how to get Pycharm working with the virtual machine created by Vagrant. Just follow the docs in repo and in a few minutes you will have a fully functioning Django site, running the components any serious Django project needs. This will change your life.

Installing the Exact Same Configuration on Digital Ocean

Getting it running on a local virtual machine is pretty cool. Its even more amazing how easy it is to get it running in a Digital Ocean droplet. In a previous post, I tried and failed to setup a droplet using Ansible. So I skipped that step and use the Ansible web interface to do that. Here are the steps for creating the droplet and installing the complete stack:

  1. Setup a Droplet using Ubuntu 12.04.5×64 because that is what the Vagrantfile specifies. If you want to setup a different OS, change your Vagrantfile.
  2. Get the IP address for your new droplet
  3. cd into the root dir of ansible-django-stack and type:

ansible-playbook -i ip_address, -v development.yml --ask-sudo-pass

Make sure to include the comma after the IP address. This tells Ansible to not look for an inventory file and to just run the playbook on that server. That’s it! Go to http://192.168.33.15/ and you will see a fully functioning Django site!

Bring the Charm

One powerful feature of Vagrant is it’s “Synced Folders” function. Actually this is a misnomer. A synced folder is a folder that is accessible on your host machine and the virtual machine. Thus there is no synching involved. They are the same physical location.

You can use this feature to edit project files “on” the virtual machine from the PyCharm installation on the host machine. To activate folder synching, do the following:

  1. git clone https://github.com/jcalazan/glucose-tracker.git   /home/me/glucose-tracker
  2. Add this line to the Vagrantfile in ansible-django-stack:
config.vm.synced_folder "/home/me/glucose-tracker", "/webapps/glucosetracker/glucose-tracker"

Now open this repo with PyCharm just like you would with any other project. If you change some of the code and restart the server on the virtual machine, you will see the changes when you reload the page.

Yeah But Can I Use the PyCharm Debugger?

The best feature of PyCharm is the debugger. But will it work with Vagrant? Of course it will. Those folks at Jet Brains have got you covered.

PyCharm (v4) fully supports Vagrant and can run the python interpreter on the virtual machine. To get started, just go to settings>tools>vagrant and do what comes naturally. Then go to Tools on the menu bar and select vagrant up.

Next, go to settings>Project>Project Interpreter. Click the gear icon and select Add Remote, then select Vagrant and set the instance folder to the folder that contains Vagrantfile. Next set the python interpreter to the virtualenv for this project (note how awesome having a working project is):

/webapps/glucosetracker/bin/python

Next go to Run>Edit Configurations to setup the PyCharm server. Here is what it looks like:

run_config

You will need to setup these environment vars:

env_vars

Finally, you need to setup the Path Mappings like this:

path_mappings

And ta da! You can now run the project in PyCharm complete with debugging.

Now you can add the power of Ansible and Vagrant without sacrificing any of the power of PyCharm!

Tip for Debugging “Internal Server Error” in Django

Usually I can debug “Internal Server Error” by looking at the server logs. But recently I ran into this error and it left no message in the logs, making it pretty difficult to debug. This command revealed the problem:

python manage.py shell --traceback

the problem was in the settings file. Too early in the chain of events to put a message in the logs.

Debugging a New Django Site on Webfaction

Your Django site works fine in dev. You put it on a server and get:

502 Bad Gateway

You look at the error log and the error does not trace back to any of your code. The traceback starts like this:

Traceback (most recent call last):
  File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/django/core/handlers/wsgi.py", line 255, in __call__
    response = self.get_response(request)
  File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/django/core/handlers/base.py", line 178, in get_response
    response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
  File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/django/core/handlers/base.py", line 224, in handle_uncaught_exception
    return callback(request, **param_dict)
  File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/django/utils/decorators.py", line 91, in _wrapped_view
    response = view_func(request, *args, **kwargs)
  File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/django/views/defaults.py", line 41, in server_error
    return http.HttpResponseServerError(template.render(Context({})))

In my case, I used django-compressor so the traceback ends with:

File "/home/my_site/.virtualenvs/my_env/lib/python2.7/site-packages/compressor/parser/lxml.py", line 20, in __init__
 raise ImproperlyConfigured("Error while importing lxml: %s" % err)
django.core.exceptions.ImproperlyConfigured: Error while importing lxml: No module named BeautifulSoup

To debug, I set DEBUG=True in my settings file. Suddenly the error went away.

In this case, I also had:

EMAIL_BACKEND = 'django.core.mail.backends.dummy.EmailBackend

If email was on, I would have gotten a message that resolved this problem.

So what’s the answer? The setting:

ALLOWED_HOSTS

was wrong.