Chapter 21. Server-Side Debugging

Popping a few layers off the stack of things we’re working on: we have nice wait-for helpers; what were we using them for? Oh yes, waiting to be logged in. And why was that? Ah yes, we had just built a way of pre-authenticating a user.

The Proof Is in the Pudding: Using Staging to Catch Final Bugs

They’re all very well for running the FTs locally, but how would they work against the staging server? Let’s try to deploy our site. Along the way we’ll catch an unexpected bug (that’s what staging is for!), and then we’ll have to figure out a way of managing the database on the test server:

$ cd deploy_tools
$ fab deploy --host=elspeth@superlists-staging.ottg.eu
[...]

And restart Gunicorn…

elspeth@server:$ sudo systemctl daemon-reload
elspeth@server:$ sudo systemctl restart gunicorn-superlists-staging.ottg.eu

Here’s what happens when we run the functional tests:

$ STAGING_SERVER=superlists-staging.ottg.eu python manage.py test functional_tests

======================================================================
ERROR: test_can_get_email_link_to_log_in
(functional_tests.test_login.LoginTest)
 ---------------------------------------------------------------------
Traceback (most recent call last):
  File "/.../functional_tests/test_login.py", line 22, in
  test_can_get_email_link_to_log_in
    self.assertIn('Check your email', body.text)
AssertionError: 'Check your email' not found in 'Server Error (500)'


======================================================================
ERROR: test_logged_in_users_lists_are_saved_as_my_lists
(functional_tests.test_my_lists.MyListsTest)
 ---------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/harry/.../book-example/functional_tests/test_my_lists.py",
  line 34, in test_logged_in_users_lists_are_saved_as_my_lists
    self.wait_to_be_logged_in(email)
  File "/worskpace/functional_tests/base.py", line 42, in wait_to_be_logged_in
    self.browser.find_element_by_link_text('Log out')
    [...]
selenium.common.exceptions.NoSuchElementException: Message: Unable to locate
element: {"method":"link text","selector":"Log out"}
Stacktrace:
[...]

 ---------------------------------------------------------------------
Ran 8 tests in 27.933s

FAILED (errors=2)

We can’t log in—either with the real email system or with our pre-authenticated session. Looks like our nice new authentication system is crashing the server.

Let’s practice a bit of server-side debugging!

Setting Up Logging

In order to track this problem down, we have to set up Gunicorn to do some logging. Adjust the Gunicorn config on the server, using vi or nano:

server: /etc/systemd/system/gunicorn-superlists-staging.ottg.eu.service

ExecStart=/home/elspeth/sites/superlists-staging.ottg.eu/virtualenv/bin/gunicorn \
    --bind unix:/tmp/superlists-staging.ottg.eu.socket \
    --capture-output \
    --access-logfile ../access.log \
    --error-logfile ../error.log \
    superlists.wsgi:application

That will put an access log and error log into the ~/sites/$SITENAME folder.

You should also make sure your settings.py still contains the LOGGING settings which will actually send stuff to the console:

superlists/settings.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
        },
    },
    'root': {'level': 'INFO'},
}

We restart Gunicorn again, and then either rerun the FT, or just try to log in manually. While that happens, we can watch the logs on the server with:

elspeth@server:$ sudo systemctl daemon-reload
elspeth@server:$ sudo systemctl restart gunicorn-superlists-staging.ottg.eu
elspeth@server:$ tail -f error.log  # assumes we are in ~/sites/$SITENAME folder

You should see an error like this:

Internal Server Error: /accounts/send_login_email
Traceback (most recent call last):
  File "/home/elspeth/sites/superlists-staging.ottg.eu/virtualenv/lib/python3.6/[...]
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File
"/home/elspeth/sites/superlists-staging.ottg.eu/source/accounts/views.py", line
20, in send_login_email
    [email]
[...]
    self.connection.sendmail(from_email, recipients, message.as_bytes(linesep=\r\n))
  File "/usr/lib/python3.6/smtplib.py", line 862, in sendmail
    raise SMTPSenderRefused(code, resp, from_addr)
smtplib.SMTPSenderRefused: (530, b'5.5.1 Authentication Required. Learn more
at\n5.5.1  https://support.google.com/mail/?p=WantAuthError [...]
- gsmtp', noreply@superlists)

Hm, Gmail is refusing to send our emails, is it? Now why might that be? Ah yes, we haven’t told the server what our password is!

Setting Secret Environment Variables on the Server

In Chapter 11, we’ve seen one way of setting secret values on the server, which we use to populate the Django SECRET_KEY setting—creating one-off Python files on the server filesystem, and importing them.

In these chapters we’ve been using environment variables in our shells to store our email password, so let’s replicate that on the server. We can set the environment variable in the Systemd config file:

server: /etc/systemd/system/gunicorn-superlists-staging.ottg.eu.service

[Service]
User=elspeth
Environment=EMAIL_PASSWORD=yoursekritpasswordhere
WorkingDirectory=/home/elspeth/sites/superlists-staging.ottg.eu/source
[...]

Note

One arguable security advantage to using this config file is we can restrict its permissions to only be readable by root, something we can’t do for our app’s Python source files.

Saving that file, and doing the usual daemon-reload and restart gunicorn dance, we can rerun our FTs, and…

$ STAGING_SERVER=superlists-staging.ottg.eu python manage.py test functional_tests

[...]
Traceback (most recent call last):
  File "/.../superlists/functional_tests/test_login.py", line 25, in
  test_can_get_email_link_to_log_in
    email = mail.outbox[0]
IndexError: list index out of range

[...]

selenium.common.exceptions.NoSuchElementException: Message: Unable to locate
element: {"method":"link text","selector":"Log out"}

The my_lists failure is still the same, but we have more information in our login test: the FT gets further, and the site now looks like it’s sending emails correctly (and the server log shows no errors), but we can’t check the email in the mail.outbox…

Adapting Our FT to Be Able to Test Real Emails via POP3

Ah. That explains it. Now that we’re running against a real server rather than the LiveServerTestCase, we can no longer inspect the local django.mail.outbox to see sent emails.

First, we’ll need to know, in our FTs, whether we’re running against the staging server or not. Let’s save the staging_server variable on self in base.py:

functional_tests/base.py (ch18l009)

    def setUp(self):
        self.browser = webdriver.Firefox()
        self.staging_server = os.environ.get('STAGING_SERVER')
        if self.staging_server:
            self.live_server_url = 'http://' + self.staging_server

Then we build a helper function that can retrieve a real email from a real POP3 email server, using the horrifically tortuous Python standard library POP3 client:

functional_tests/test_login.py (ch18l010)

import os
import poplib
import re
import time
[...]

    def wait_for_email(self, test_email, subject):
        if not self.staging_server:
            email = mail.outbox[0]
            self.assertIn(test_email, email.to)
            self.assertEqual(email.subject, subject)
            return email.body

        email_id = None
        start = time.time()
        inbox = poplib.POP3_SSL('pop.mail.yahoo.com')
        try:
            inbox.user(test_email)
            inbox.pass_(os.environ['YAHOO_PASSWORD'])
            while time.time() - start < 60:
                # get 10 newest messages
                count, _ = inbox.stat()
                for i in reversed(range(max(1, count - 10), count + 1)):
                    print('getting msg', i)
                    _, lines, __ = inbox.retr(i)
                    lines = [l.decode('utf8') for l in lines]
                    print(lines)
                    if f'Subject: {subject}' in lines:
                        email_id = i
                        body = '\n'.join(lines)
                        return body
                time.sleep(5)
        finally:
            if email_id:
                inbox.dele(email_id)
            inbox.quit()

Note

I’m using a Yahoo account for testing, but you can use any email service you like, as long as it offers POP3 access. You will need to set the YAHOO_PASSWORD environment variable in the console that’s running the FT.

And then we feed through the rest of the changes to the FT that are required as a result. Firstly, populating a test_email variable, differently for local and staging tests:

functional_tests/test_login.py (ch18l011-1)

@@ -7,7 +7,7 @@ from selenium.webdriver.common.keys import Keys

 from .base import FunctionalTest

-TEST_EMAIL = 'edith@example.com'
+
 SUBJECT = 'Your login link for Superlists'


@@ -33,7 +33,6 @@ class LoginTest(FunctionalTest):
                     print('getting msg', i)
                     _, lines, __ = inbox.retr(i)
                     lines = [l.decode('utf8') for l in lines]
-                    print(lines)
                     if f'Subject: {subject}' in lines:
                         email_id = i
                         body = '\n'.join(lines)
@@ -49,6 +48,11 @@ class LoginTest(FunctionalTest):
         # Edith goes to the awesome superlists site
         # and notices a "Log in" section in the navbar for the first time
         # It's telling her to enter her email address, so she does
+        if self.staging_server:
+            test_email = 'edith.testuser@yahoo.com'
+        else:
+            test_email = 'edith@example.com'
+
         self.browser.get(self.live_server_url)

And then modifications involving using that variable and calling our new helper function:

functional_tests/test_login.py (ch18l011-2)

@@ -54,7 +54,7 @@ class LoginTest(FunctionalTest):
             test_email = 'edith@example.com'

         self.browser.get(self.live_server_url)
-        self.browser.find_element_by_name('email').send_keys(TEST_EMAIL)
+        self.browser.find_element_by_name('email').send_keys(test_email)
         self.browser.find_element_by_name('email').send_keys(Keys.ENTER)

         # A message appears telling her an email has been sent
@@ -64,15 +64,13 @@ class LoginTest(FunctionalTest):
         ))

         # She checks her email and finds a message
-        email = mail.outbox[0]
-        self.assertIn(TEST_EMAIL, email.to)
-        self.assertEqual(email.subject, SUBJECT)
+        body = self.wait_for_email(test_email, SUBJECT)

         # It has a url link in it
-        self.assertIn('Use this link to log in', email.body)
-        url_search = re.search(r'http://.+/.+$', email.body)
+        self.assertIn('Use this link to log in', body)
+        url_search = re.search(r'http://.+/.+$', body)
         if not url_search:
-            self.fail(f'Could not find url in email body:\n{email.body}')
+            self.fail(f'Could not find url in email body:\n{body}')
         url = url_search.group(0)
         self.assertIn(self.live_server_url, url)

@@ -80,11 +78,11 @@ class LoginTest(FunctionalTest):
         self.browser.get(url)

         # she is logged in!
-        self.wait_to_be_logged_in(email=TEST_EMAIL)
+        self.wait_to_be_logged_in(email=test_email)

         # Now she logs out
         self.browser.find_element_by_link_text('Log out').click()

         # She is logged out
-        self.wait_to_be_logged_out(email=TEST_EMAIL)
+        self.wait_to_be_logged_out(email=test_email)

And, believe it or not, that’ll actually work, and give us an FT that can actually check for logins that work, involving real emails!

Tip

I’ve just hacked this email-checking code together, and it’s currently pretty ugly and brittle (one common problem is picking up the wrong email from a previous test run). With some cleanup and a few more retry loops it could grow into something more reliable. Alternatively, services like mailinator.com will give you throwaway email addresses and an API to check them, for a small fee.

Managing the Test Database on Staging

Now we can rerun our FTs and get to the next failure: our attempt to create pre-authenticated sessions doesn’t work, so the “My Lists” test fails:

$ STAGING_SERVER=superlists-staging.ottg.eu python manage.py test functional_tests

ERROR: test_logged_in_users_lists_are_saved_as_my_lists
(functional_tests.test_my_lists.MyListsTest)
[...]
selenium.common.exceptions.TimeoutException: Message: Could not find element
with id id_logout. Page text was:
Superlists
Sign in
Start a new To-Do list

Ran 8 tests in 72.742s

FAILED (errors=1)

It’s because our test utility function create_pre_authenticated_session only acts on the local database. Let’s find out how our tests can manage the database on the server.

A Django Management Command to Create Sessions

To do things on the server, we’ll need to build a self-contained script that can be run from the command line on the server, most probably via Fabric.

When trying to build a standalone script that works with Django (i.e., can talk to the database and so on), there are some fiddly issues you need to get right, like setting the DJANGO_SETTINGS_MODULE environment variable, and getting sys.path correctly.

Instead of messing about with all that, Django lets you create your own “management commands” (commands you can run with python manage.py), which will do all that path mangling for you. They live in a folder called management/commands inside your apps:

$ mkdir -p functional_tests/management/commands
$ touch functional_tests/management/__init__.py
$ touch functional_tests/management/commands/__init__.py

The boilerplate in a management command is a class that inherits from django.core.management.BaseCommand, and that defines a method called handle:

functional_tests/management/commands/create_session.py

from django.conf import settings
from django.contrib.auth import BACKEND_SESSION_KEY, SESSION_KEY, get_user_model
User = get_user_model()
from django.contrib.sessions.backends.db import SessionStore
from django.core.management.base import BaseCommand


class Command(BaseCommand):

    def add_arguments(self, parser):
        parser.add_argument('email')

    def handle(self, *args, **options):
        session_key = create_pre_authenticated_session(options['email'])
        self.stdout.write(session_key)


def create_pre_authenticated_session(email):
    user = User.objects.create(email=email)
    session = SessionStore()
    session[SESSION_KEY] = user.pk
    session[BACKEND_SESSION_KEY] = settings.AUTHENTICATION_BACKENDS[0]
    session.save()
    return session.session_key

We’ve taken the code for create_pre_authenticated_session from test_my_lists.py. handle will pick up an email address from the parser, and then return the session key that we’ll want to add to our browser cookies, and the management command prints it out at the command line. Try it out:

$ python manage.py create_session a@b.com
Unknown command: 'create_session'

One more step: we need to add functional_tests to our settings.py for it to recognise it as a real app that might have management commands as well as tests:

superlists/settings.py

+++ b/superlists/settings.py
@@ -42,6 +42,7 @@ INSTALLED_APPS = [
     'lists',
     'accounts',
+    'functional_tests',
 ]

Now it works:

$ python manage.py create_session a@b.com
qnslckvp2aga7tm6xuivyb0ob1akzzwl

Note

If you see an error saying the auth_user table is missing, you may need to run manage.py migrate. In case that doesn’t work, delete the db.sqlite3 file and run migrate again, to get a clean slate.

Getting the FT to Run the Management Command on the Server

Next we need to adjust test_my_lists so that it runs the local function when we’re on the local server, and make it run the management command on the staging server if we’re on that:

functional_tests/test_my_lists.py (ch18l016)

from django.conf import settings
from .base import FunctionalTest
from .server_tools import create_session_on_server
from .management.commands.create_session import create_pre_authenticated_session

class MyListsTest(FunctionalTest):

    def create_pre_authenticated_session(self, email):
        if self.staging_server:
            session_key = create_session_on_server(self.staging_server, email)
        else:
            session_key = create_pre_authenticated_session(email)
        ## to set a cookie we need to first visit the domain.
        ## 404 pages load the quickest!
        self.browser.get(self.live_server_url + "/404_no_such_url/")
        self.browser.add_cookie(dict(
            name=settings.SESSION_COOKIE_NAME,
            value=session_key,
            path='/',
        ))

    [...]

Let’s also tweak base.py, to gather a bit more information when we populate self.against_staging:

functional_tests/base.py (ch18l017)

from .server_tools import reset_database  
[...]

class FunctionalTest(StaticLiveServerTestCase):

    def setUp(self):
        self.browser = webdriver.Firefox()
        self.staging_server = os.environ.get('STAGING_SERVER')
        if self.staging_server:
            self.live_server_url = 'http://' + self.staging_server
            reset_database(self.staging_server)  

This will be our function to reset the server database in between each test. I’ll explain the logic of the session-creation code, which should also explain how this works.

Using Fabric Directly from Python

Rather than using the fab command, Fabric provides an API that lets you run Fabric server commands directly inline in your Python code. You just need to let it know the “host string” you’re connecting to:

functional_tests/server_tools.py

from fabric.api import run
from fabric.context_managers import settings


def _get_manage_dot_py(host):
    return f'~/sites/{host}/virtualenv/bin/python ~/sites/{host}/source/manage.py'


def reset_database(host):
    manage_dot_py = _get_manage_dot_py(host)
    with settings(host_string=f'elspeth@{host}'):  
        run(f'{manage_dot_py} flush --noinput')  


def create_session_on_server(host, email):
    manage_dot_py = _get_manage_dot_py(host)
    with settings(host_string=f'elspeth@{host}'):  
        session_key = run(f'{manage_dot_py} create_session {email}')  
        return session_key.strip()

Here’s the context manager that sets the host string, in the form user@server-address (I’ve hardcoded my server username, elspeth, so adjust as necessary).

Then, once we’re inside the context manager, we can just call Fabric commands as if we’re in a fabfile.

Recap: Creating Sessions Locally Versus Staging

Does that all make sense? Perhaps a little ascii-art diagram will help:

Locally:

+-----------------------------------+       +-------------------------------------+
| MyListsTest                       |  -->  | .management.commands.create_session |
| .create_pre_authenticated_session |       |  .create_pre_authenticated_session  |
|            (locally)              |       |             (locally)               |
+-----------------------------------+       +-------------------------------------+

Against staging:

+-----------------------------------+       +-------------------------------------+
| MyListsTest                       |       | .management.commands.create_session |
| .create_pre_authenticated_session |       |  .create_pre_authenticated_session  |
|            (locally)              |       |            (on server)              |
+-----------------------------------+       +-------------------------------------+
            |                                                   ^
            v                                                   |
+----------------------------+     +--------+      +------------------------------+
| server_tools               | --> | fabric | -->  | ./manage.py create_session   |
| .create_session_on_server  |     |  "run" |      |       (on server)            |
|        (locally)           |     +--------+      +------------------------------+
+----------------------------+

In any case, let’s see if it works. First, locally, to check that we didn’t break anything:

$ python manage.py test functional_tests.test_my_lists
[...]
OK

Next, against the server. We push our code up first:

$ git push  # you'll need to commit changes first.
$ cd deploy_tools
$ fab deploy --host=superlists-staging.ottg.eu

And now we run the test:

$ STAGING_SERVER=superlists-staging.ottg.eu python manage.py test \
 functional_tests.test_my_lists
[...]
[superlists-staging.ottg.eu] Executing task 'reset_database'
~/sites/superlists-staging.ottg.eu/source/manage.py flush --noinput
[superlists-staging.ottg.eu] out: Syncing...
[superlists-staging.ottg.eu] out: Creating tables ...
[...]
.
 ---------------------------------------------------------------------
Ran 1 test in 25.701s

OK

Looking good! We can rerun all the tests to make sure…

$ STAGING_SERVER=superlists-staging.ottg.eu python manage.py test \
 functional_tests
[...]
[superlists-staging.ottg.eu] Executing task 'reset_database'
[...]
Ran 8 tests in 89.494s

OK

Hooray!

Note

I’ve shown one way of managing the test database, but you could experiment with others—for example, if you were using MySQL or Postgres, you could open up an SSH tunnel to the server, and use port forwarding to talk to the database directly. You could then amend settings.DATABASES during FTs to talk to the tunnelled port.

Warning: Be Careful Not to Run Test Code Against the Live Server

We’re into dangerous territory, now that we have code that can directly affect a database on the server. You want to be very, very careful that you don’t accidentally blow away your production database by running FTs against the wrong host.

You might consider putting some safeguards in place at this point. For example, you could put staging and production on different servers, and make it so they use different keypairs for authentication, with different passphrases.

This is similarly dangerous territory to running tests against clones of production data. I have a little story about accidentally sending thousands of duplicate invoices to clients in Appendix D. LFMF.

Baking In Our Logging Code

Before we finish, let’s “bake in” our logging setup. It would be useful to keep our new logging code in there, under source control, so that we can debug any future login problems. They may indicate someone is up to no good, after all…

Let’s start by saving the Gunicorn config to our template file in deploy_tools:

deploy_tools/gunicorn-systemd.template.service (ch18l020)

[...]
Environment=EMAIL_PASSWORD=SEKRIT
ExecStart=/home/elspeth/sites/SITENAME/virtualenv/bin/gunicorn \
    --bind unix:/tmp/SITENAME.socket \
    --access-logfile ../access.log \
    --error-logfile ../error.log \
    superlists.wsgi:application
[...]

And a little reminder in our provisioning notes about needing to set the email password environment variable via that Gunicorn config file:

deploy_tools/provisioning_notes.md (ch18l021)

## Systemd service

* see gunicorn-systemd.template.service
* replace SITENAME with, e.g., staging.my-domain.com
* replace SEKRIT with email password
[...]

Wrap-Up

Actually getting your new code up and running on a server always tends to flush out some last-minute bugs and unexpected issues. We had to do a bit of work to get through them, but we’ve ended up with several useful things as a result.

We now have a lovely generic wait decorator which will be a nice Pythonic helper for our FTs from now on. We have test fixtures that work both locally and on the server, including the ability to test “real” email integration. And we’ve got some more robust logging configuration.

But before we can deploy our actual live site, we’d better actually give the users what they wanted—the next chapter describes how to give them the ability to save their lists on a “My Lists” page.

Lessons Learned Catching Bugs in Staging

Fixtures also have to work remotely

LiveServerTestCase makes it easy to interact with the test database using the Django ORM for tests running locally. Interacting with the database on the staging server is not so straightforward. One solution is Fabric and Django management commands, as I’ve shown, but you should explore what works for you—SSH tunnels, for example.

Be very careful when resetting data on your servers

A command that can remotely wipe the entire database on one of your servers is a dangerous weapon, and you want to be really, really sure it’s never accidentally going to hit your production data.

Logging is critical to debugging issues on the server

At the very least, you’ll want to be able to see any error messages that are being generated by the server. For thornier bugs, you’ll also want to be able to do the occasional “debug print”, and see it end up in a file somewhere.