Let's find a bug

Let's find a bug

I mentioned at the end of the last chapter that I have intentionally
introduced a bug in the application. Let me describe what the bug is,
then we will use it to see what happens to our application when it does
not work as expected.

The problem in the application is that there is no effort to keep the
nicknames of our users unique. The initial nickname of a user is chosen
automatically by the application. If the OpenID provider provides a
nickname for the user then we will just use it. If not we will use the
username part of the email address as nickname. If we get two users with
the same nickname then the second one will not be able to register. To
make matters worse, in the profile edit form we let users change their
nicknames to whatever they want, and again there is no effort to avoid
name collisions.

We will address these problems later, after we analyze how the
application behaves when an error occurs.

Flask debugging support

So let's see what happens when we trigger our bug.

Let's start by creating a brand new database. On Linux:

```
rm app.db
./db_create.py
```
or on Windows:

```
del app.db
flask/Scripts/python db_create.py
```
You need two OpenID accounts to reproduce this bug, ideally from
different providers, so that their cookies don't make this more
complicated. Follow these steps to create a nickname collision:

login with your first account
go to the edit profile page and change the nickname to 'dup'
logout
login with your second account
go to the edit profile page and change the nickname to 'dup'
Oops! We've got an exception from sqlalchemy. The text of the error
reads:

```
sqlalchemy.exc.IntegrityError
IntegrityError: (IntegrityError) column nickname is not unique u'UPDATE
user SET nickname=?, about_me=? WHERE user.id = ?' (u'dup', u'', 2)
```
What follows after the error is a stack trace of the error, and actually
it is a pretty nice one, where you can go to any frame and inspect
source code or even evaluate expressions right in the browser.

The error is pretty clear, we tried to insert a duplicated nickname in
the database. The database model had a unique constrain on the nickname
field, so this is an invalid operation.

In addition to the actual error, we have a secondary problem in our
hands. If a user inadvertently causes an error in our application (this
one or any other that causes an exception) it will be him or her that
gets the error with the revealing error message and the stack trace, not
us. While this is a fantastic feature while we are developing, it is
something we definitely do not want our users to ever see.

All this time we have been running our application in debug mode. The
debug mode is enabled when the application starts, by passing a debug =
True argument to the run method. This is how we coded our run.py start-
up script.

When we are developing the application this is convenient, but we need
to make sure it is turned off when we run our application in production
mode. Let's just create another starter script that runs with debugging
disabled (file runp.py):
```
#!flask/bin/python
from app import app
app.run(debug = False)
```
Now restart the application with:
```
./runp.py
```
And now try again to rename the nickname on the second account to 'dup'.

This time we did not get an error. Instead, we've got an HTTP error code
500, which is Internal Server Error. Not a great looking error, but at
least we are not exposing any details of our application to strangers.
The error 500 page is generated by Flask when debugging is off and an
unhandled exception occurs.

While this is better, we are now having two new issues. First a cosmetic
one: the default error 500 page is ugly. The second problem is much more
important. With things as they are we would never know when and if a
user experiences a failure in our application because now application
failures are silently dismissed. Luckily there are easy ways to address
both problems.
Custom HTTP error handlers

Custom HTTP error handlers

Flask provides a mechanism for an application to install its own error
pages. As an example, let's define custom error pages for the HTTP
errors 404 and 500, the two most common ones. Defining pages for other
errors works in the same way.

To declare a custom error handler the errorhandler decorator is used
(file app/views.py):
```
@app.errorhandler(404)
def internal_error(error):
    return render_template('404.html'), 404

@app.errorhandler(500)
def internal_error(error):
    db.session.rollback()
    return render_template('500.html'), 500
```
Not much to talk about for these, as they are almost self-explanatory.
The only interesting bit is the rollback statement in the error 500
handler. This is necessary because this function will be called as a
result of an exception. If the exception was triggered by a database
error then the database session is going to arrive in an invalid state,
so we have to roll it back in case a working session is needed for the
rendering of the template for the 500 error.

Here is the template for the 404 error:

```
<!-- extend base layout -->
{% extends "base.html" %}

{% block content %}
<h1>File Not Found</h1>
<p><a href="{{url_for('index')}}">Back</a></p>
{% endblock %}
```
And here is the one for the 500 error:

```
<!-- extend base layout -->
{% extends "base.html" %}

{% block content %}
<h1>An unexpected error has occurred</h1>
<p>The administrator has been notified. Sorry for the inconvenience!</p>
<p><a href="{{url_for('index')}}">Back</a></p>
{% endblock %}
```
Note that in both cases we continue to use our base.html layout, so that
the error page has the look and feel of the application.
Sending errors via email

Sending errors via email

To address our second problem we are going to configure two reporting
mechanisms for application errors. The first of them is to have the
application send us an email each time an error occurs.

Before we get into this let's configure an email server and an
administrator list in our application (file config.py):
```
# mail server settings
MAIL_SERVER = 'localhost'
MAIL_PORT = 25
MAIL_USERNAME = None
MAIL_PASSWORD = None

# administrator list
ADMINS = ['you@example.com']
```
Of course it will be up to you to change these to what makes sense.

Flask uses the regular Python logging module, so setting up an email
when there is an exception is pretty easy (file app/__init__.py):

```
from config import basedir, ADMINS, MAIL_SERVER, MAIL_PORT,
MAIL_USERNAME, MAIL_PASSWORD

if not app.debug:
    import logging
    from logging.handlers import SMTPHandler
    credentials = None
    if MAIL_USERNAME or MAIL_PASSWORD:
        credentials = (MAIL_USERNAME, MAIL_PASSWORD)
    mail_handler = SMTPHandler((MAIL_SERVER, MAIL_PORT), 'no-reply@' +
MAIL_SERVER, ADMINS, 'microblog failure', credentials)
    mail_handler.setLevel(logging.ERROR)
    app.logger.addHandler(mail_handler)
```
Note that we are only enabling the emails when we run without debugging.

Testing this on a development PC that does not have an email server is
easy, thanks to Python's SMTP debugging server. Just open a new console
window (command prompt for Windows users) and run the following to start
a fake email server:

```
python -m smtpd -n -c DebuggingServer localhost:25
```
When this is running, the emails sent by the application will be
received and displayed in the console window.
Logging to a file

Logging to a file

Receiving errors via email is nice, but sometimes this isn't enough.
There are some failure conditions that do not end in an exception and
aren't a major problem, yet we may want to keep track of them in a log
in case we need to do some debugging.

For this reason, we are also going to maintain a log file for the
application.

Enabling file logging is similar to the email logging (file
app/__init__.py):
```
if not app.debug:
    import logging
    from logging.handlers import RotatingFileHandler
    file_handler = RotatingFileHandler('tmp/microblog.log', 'a', 1 *
1024 * 1024, 10)
    file_handler.setFormatter(logging.Formatter('%(asctime)s
%(levelname)s: %(message)s [in %(pathname)s:%(lineno)d]'))
    app.logger.setLevel(logging.INFO)
    file_handler.setLevel(logging.INFO)
    app.logger.addHandler(file_handler)
    app.logger.info('microblog startup')
```
The log file will go to our tmp directory, with name microblog.log. We
are using the RotatingFileHandler so that there is a limit to the amount
of logs that are generated. In this case we are limiting the size of a
log file to one megabyte, and we will keep the last ten log files as
backups.

The logging.Formatter class provides custom formatting for the log
messages. Since these messages are going to a file, we want them to have
as much information as possible, so we write a timestamp, the logging
level and the file and line number where the message originated in
addition to the log message and the stack trace.

To make the logging more useful, we are lowering the logging level, both
in the app logger and the file logger handler, as this will give us the
opportunity to write useful messages to the log without having to call
them errors. As an example, we start by logging the application start up
as an informational level. From now on, each time you start the
application without debugging the log will record the event.

While we don't have a lot of need for a logger at this time, debugging a
web server that is online and in use is very difficult. Logging messages
to a file is an extremely useful tool in diagnosing and locating issues,
so we are now all ready to go should we need to use this feature.
The bug fix

The bug fix

Let's fix our nickname duplication bug.

As discussed earlier, there are two places that are currently not
handling duplicates. The first is in the after_login handler for Flask-
Login. This is called when a user successfully logs in to the system and
we need to create a new User instance. Here is the affected snippet of
code, with the fix in it (file app/views.py):
```
    if user is None:
        nickname = resp.nickname
        if nickname is None or nickname == "":
            nickname = resp.email.split('@')[0]
        nickname = User.make_unique_nickname(nickname)
        user = User(nickname = nickname, email = resp.email, role =
ROLE_USER)
        db.session.add(user)
        db.session.commit()
```
The way we solve the problem is by letting the User class pick a unique
name for us. This is what the new make_unique_nickname method does (file
app/models.py):
```

    class User(db.Model):
    # ...
    @staticmethod
    def make_unique_nickname(nickname):
        if User.query.filter_by(nickname = nickname).first() == None:
            return nickname
        version = 2
        while True:
            new_nickname = nickname + str(version)
            if User.query.filter_by(nickname = new_nickname).first() ==
None:
                break
            version += 1
        return new_nickname
    # ...
```
This method simply adds a counter to the requested nickname until a
unique name is found. For example, if the username "miguel" exists, the
method will suggest "miguel2", but if that also exists it will go to
"miguel3" and so on. Note that we coded the method as a static method,
since it this operation does not apply to any particular instance of the
class.

The second place where we have problems with duplicate nicknames is the
view function for the edit profile page. This one is a little tricker to
handle, because it is the user choosing the nickname. The correct thing
to do here is to not accept a duplicated nickname and let the user enter
another one. We will address this by adding custom validation to the
nickname form field. If the user enters an invalid nickname we'll just
fail the validation for the field, and that will send the user back to
the edit profile page. To add our validation we just override the form's
validate method (file app/forms.py):

```
class EditForm(Form):
    nickname = TextField('nickname', validators = [Required()])
    about_me = TextAreaField('about_me', validators = [Length(min = 0,
max = 140)])

    def __init__(self, original_nickname, *args, **kwargs):
        Form.__init__(self, *args, **kwargs)
        self.original_nickname = original_nickname

    def validate(self):
        if not Form.validate(self):
            return False
        if self.nickname.data == self.original_nickname:
            return True
        user = User.query.filter_by(nickname =
self.nickname.data).first()
        if user != None:
            self.nickname.errors.append('This nickname is already in
use. Please choose another one.')
            return False
        return True
```
The form constructor now takes a new argument original_nickname. The
validate method uses it to determine if the nickname has changed or not.
If it hasn't changed then it accepts it. If it has changed, then it
makes sure the new nickname does not exist in the database.

To complete this change we have to enable field errors to show in our
template for the form (file app/templates/edit.html):
```

        <td>Your nickname:</td>
        <td>
            {{form.nickname(size = 24)}}
            {% for error in form.errors.nickname %}
            <br><span style="color: red;">[{{error}}]</span>
            {% endfor %}
        </td>
```
Now the bug is fixed and duplicates will be prevented... except when
they are not. We still have a potential problem with concurrent access
to the database by two or more threads or processes, but this will be
the topic of a future article.

At this point you can try again to select a duplicated name to see how
the form nicely handles the error.
Unit testing framework

Unit testing framework

To close this session on testing, let's talk about automated testing a
bit.

As the application grows in size it gets more and more difficult to
ensure that code changes don't break existing functionality.

The traditional approach to prevent regressions is a very good one. You
write tests that exercise all the different features of the application.
Each test runs a focused part and verifies that the result obtained is
the expected one. The tests are executed periodically to make sure that
the application works as expected. When the test coverage is large you
can have confidence that modifications and additions do not affect the
application in a bad way just by running the tests.

We will now build a very simple testing framework using Python's
unittest module (file tests.py):
```
#!flask/bin/python
import unittest

from config import basedir
from app import app, db
from app.models import User

class TestCase(unittest.TestCase):
    def setUp(self):
        app.config['TESTING'] = True
        app.config['CSRF_ENABLED'] = False
        app.config['SQLALCHEMY_DATABASE_URI'] = 'sqlite:///' +
os.path.join(basedir, 'test.db')
        self.app = app.test_client()
        db.create_all()

    def tearDown(self):
        db.session.remove()
        db.drop_all()

    def test_avatar(self):
        u = User(nickname = 'john', email = 'john@example.com')
        avatar = u.avatar(128)
        expected =
'http://www.gravatar.com/avatar/d4c74594d841139328695756648b6bd6'
        assert avatar[0:len(expected)] == expected

    def test_make_unique_nickname(self):
        u = User(nickname = 'john', email = 'john@example.com')
        db.session.add(u)
        db.session.commit()
        nickname = User.make_unique_nickname('john')
        assert nickname != 'john'
        u = User(nickname = nickname, email = 'susan@example.com')
        db.session.add(u)
        db.session.commit()
        nickname2 = User.make_unique_nickname('john')
        assert nickname2 != 'john'
        assert nickname2 != nickname

if __name__ == '__main__':
    unittest.main()
```
Discussing the unittest module is outside the scope of this article.
Let's just say that class TestCase holds our tests. The setUp and
tearDown methods are special, these are run before and after each test
respectively. A more complex setup could include several groups of tests
each represented by a unittest.TestCase subclass, and each group then
would have independent setUp and tearDown methods.

These particular setUp and tearDown methods are pretty generic. In setUp
the configuration is edited a bit. For instance, we want the testing
database to be different that the main database. In tearDown we just
reset the database contents.

Tests are implemented as methods. A test is supposed to run some
function of the application that has a known outcome, and should assert
if the result is different than the expected one.

So far we have two tests in the testing framework. The first one
verifies that the Gravatar avatar URLs from the previous article are
generated correctly. Note how the expected avatar is hardcoded in the
test and checked against the one returned by the User class.

The second test verifies the make_unique_nickname method we just wrote,
also in the User class. This test is a bit more elaborate, it creates a
new user and writes it to the database, then ensures the same name is
not allowed as a unique name. It then creates a second user with the
suggested unique name and tries one more time to request the first
nickname. The expected result for this second part is to get a suggested
nickname that is different from the previous two.

To run the test suite you just run the tests.py script:

```
./tests.py
```
If there are any errors, you will get a report in the console.