Chapter info |
|
shortname: |
chapter_server_side_debugging |
|
Warning
|
2017-03-13: Book upgraded to Python 3.6 and Django 1.11 beta. Before that, there was a big upgrade to Selenium 3 on 2017-01-30. More info on the blog. |
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.
They’re all very well for running the FTs locally, but how would they work against the staging server? Let’s try and 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 [email protected] [...]
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!
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:
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:applicationThat 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:
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 a:
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!
In the deployment chapter, 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:
[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 re-run 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, 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…
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':
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_serverThen 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:
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:
@@ -7,7 +7,7 @@ from selenium.webdriver.common.keys import Keys
from .base import FunctionalTest
-TEST_EMAIL = '[email protected]'
+
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 = '[email protected]'
+ else:
+ test_email = '[email protected]'
+
self.browser.get(self.live_server_url)And then modifications involving using that variable and calling our new helper function:
@@ -54,7 +54,7 @@ class LoginTest(FunctionalTest):
test_email = '[email protected]'
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. |
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.
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, (ie 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:
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_keyWe’ve taken the code for create_pre_authenticated_session code 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 [email protected] 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:
+++ b/superlists/settings.py
@@ -42,6 +42,7 @@ INSTALLED_APPS = [
'lists',
'accounts',
+ 'functional_tests',
]Now it works:
$ python manage.py create_session [email protected] 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.
|
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:
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:
from .server_tools import reset_database #(1)
[...]
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) #(1)-
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.
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:
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}'): #(1)
run(f'{manage_dot_py} flush --noinput') #(2)
def create_session_on_server(host, email):
manage_dot_py = _get_manage_dot_py(host)
with settings(host_string=f'elspeth@{host}'): #(1)
session_key = run(f'{manage_dot_py} create_session {email}') #(2)
return session_key.strip()-
Here’s the context manager that sets the host string, in the form 'user@server-address' (I’ve hard-coded 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.
Does that all make sense? Perhaps a little ascii-art diagram will help:
+-----------------------------------+ +-------------------------------------+ | MyListsTest | --> | .management.commands.create_session | | .create_pre_authenticated_session | | .create_pre_authenticated_session | | (locally) | | (locally) | +-----------------------------------+ +-------------------------------------+
+-----------------------------------+ +-------------------------------------+
| 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 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.
|
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 similar 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 [data-migrations-appendix]. LFMF.
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':
[...]
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:
## Systemd service
* see gunicorn-systemd.template.service
* replace SITENAME with, e.g., staging.my-domain.com
* replace SEKRIT with email password
[...]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 working 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.
- Fixtures also have to work remotely
-
LiveServerTestCasemakes 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.