Why is app engine project not calling unittest.TestCase.tearDown()?

Question

I'm trying to setup test for the App Engine python tutorial. It seems that the unittest.tearDown() is not being called because the print statement I put in the tearDown method is not displayed.

The unittest.TestCase.setUp() is being called, so why is the tearDown() not called?

import sys, os, subprocess, time, unittest, shlex     
sys.path.append("/usr/local/google_appengine")   
sys.path.append('/usr/local/google_appengine/lib/')     
sys.path.append("/usr/local/google_appengine/lib/yaml/lib")      
sys.path.append("/usr/local/google_appengine/lib/webapp2-2.5.2")      
sys.path.append("/usr/local/google_appengine/lib/django-1.5")      
sys.path.append("/usr/local/google_appengine/lib/cherrypy")      
sys.path.append("/usr/local/google_appengine/lib/concurrent")      
sys.path.append("/usr/local/google_appengine/lib/docker")      
sys.path.append("/usr/local/google_appengine/lib/requests")      
sys.path.append("/usr/local/google_appengine/lib/websocket")      
sys.path.append("/usr/local/google_appengine/lib/fancy_urllib")      
sys.path.append("/usr/local/google_appengine/lib/antlr3")      

from selenium import webdriver      
from selenium.webdriver.common.keys import Keys  

from google.appengine.api import memcache, apiproxy_stub, apiproxy_stub_map       
from google.appengine.ext import testbed      
from google.appengine.datastore import datastore_stub_util       
from google.appengine.tools.devappserver2 import devappserver2      
from guestbook import Author, Greeting    
from google.appengine.api import users  
from google.appengine.ext import ndb  


class NewVisitorTest(unittest.TestCase):      
    # enable the datastore stub  
    nosegae_datastore_v3 = True  
    nosegae_datastore_v3_kwargs = {  
        'datastore_file': '/tmp/nosegae.sqlite3',  
        'use_sqlite': True  
    }  

    def setUp(self):      
        self.testbed = testbed.Testbed()  
        self.testbed.setup_env(app_id='guestbook')      
        self.testbed.activate()        
        self.datastore_stub = apiproxy_stub_map.apiproxy.GetStub('datastore_v3')    
        ndb.get_context().clear_cache()    
        APP_CONFIGS = ['app.yaml']      

    def tearDown(self):   
        print("#####################functional_tests.teardown called")  
        self.testbed.deactivate()   
        # I put a print statement into testbed.deactivate and it's not showing up.     
        ndb.get_context().clear_cache()    

    def loginUser(self, email="elonMusk@example.com", id='888', is_admin=False):  
        self.testbed.setup_env(  
            user_email=email,  
            user_id=id,  
            user_is_admin='1' if is_admin else '0',  
            overwrite=True  
        )  
        self.testbed.init_user_stub()  

    def test_guest_can_submit_new_greeting_and_author(self):  

         #self.browser.get('http://localhost:8080')  
         self.loginUser()  
         greetings = Greeting.query(Greeting.author.email=='elonMusk@example.com').get()  
         pprint.pprint(greetings)  
         assert(Greeting.query(Greeting.author.email=='elonMusk@example.com').get()
self.assertEqual(1, len(Greeting.query().fetch(10)))  

    def test_entity_saves(self):  
         self.loginUser()              
         entity_key = Greeting(content="Test Value",   
                           author = Author(  
                                    identity=users.get_current_user().user_id(),  
                                    email=users.get_current_user().email())  
                           ).put()  
         print(entity_key)  
         self.assertIsNotNone(entity_key.id())    
         #self.assertNotNone(entity.key.id())  

Here is the output from the tests:

nosetests -v --with-gae

test_entity_saves (functional_tests.NewVisitorTest) ... ok  
test_guest_can_submit_new_greeting_and_author (functional_tests.NewVisitorTest) ... FAIL  

======================================================================  
FAIL: test_guest_can_submit_new_greeting_and_author (functional_tests.NewVisitorTest)  
----------------------------------------------------------------------  
Traceback (most recent call last):  
  File "/Users/Bryan/work/GoogleAppEngine/guestbook/functional_tests.py", line 124, in test_guest_can_submit_new_greeting_and_author  
    self.assertEqual(1, len(Greeting.query().fetch(10)))  
AssertionError: 1 != 10  
-------------------- >> begin captured stdout << ---------------------  
#*#**#*#*#*#*#*#*#*#*nosegae.py startTest   
Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))  

--------------------- >> end captured stdout << ----------------------  
-------------------- >> begin captured logging << --------------------  
root: DEBUG: all_pending: add <Future 106a2e690 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); pending>  
root: DEBUG: Clearing stale EventLoop instance...  
root: DEBUG:   current = deque([(<bound method AutoBatcher._finished_callback of AutoBatcher(_memcache_del_tasklet)>, (<Future 1069e9650 created by run_queue(context.py:185) for tasklet _memcache_del_tasklet(context.py:1131); result None>, [(<Future 1069e9590 created by add(context.py:211) for AutoBatcher(_memcache_del_tasklet).add(NDB9:ag1kZXZ-Z3Vlc3Rib29rcg8LEghHcmVldGluZxjhXQw, (0, '', None)); result 1>, 'NDB9:ag1kZXZ-Z3Vlc3Rib29rcg8LEghHcmVldGluZxjhXQw')]), {})])  
root: DEBUG: Cleared  
root: DEBUG: nowevent: _help_tasklet_along  
root: DEBUG: Sending None to initial generator _get_async(query.py:1247)  
root: DEBUG: all_pending: add <Future 106a2e850 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: initial generator _get_async(query.py:1247) yielded <Future 106a2e850 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: <Future 106a2e690 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247) suspended generator _get_async(query.py:1250); pending> is now blocked waiting for <Future 106a2e850 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: nowevent: _help_tasklet_along  
root: DEBUG: Sending None to initial generator _run_to_list(query.py:971)  
root: DEBUG: initial generator _run_to_list(query.py:971) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x106a2ed50>  
root: DEBUG: rpc: datastore_v3.RunQuery  
root: DEBUG: Sending <google.appengine.datastore.datastore_query.Batch object at 0x106a2ec50> to suspended generator _run_to_list(query.py:979)  
root: DEBUG: suspended generator _run_to_list(query.py:979) returned [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]  
root: DEBUG: all_pending: success: remove <Future 106a2e850 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); result [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]>  
root: DEBUG: nowevent: _on_future_completion  
root: DEBUG: <Future 106a2e690 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); pending> is no longer blocked waiting for <Future 106a2e850 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); result [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]>  
root: DEBUG: Sending [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))] to suspended generator _get_async(query.py:1250)  
root: DEBUG: suspended generator _get_async(query.py:1250) returned Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))  
root: DEBUG: all_pending: success: remove <Future 106a2e690 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); result Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))>  
root: DEBUG: all_pending: add <Future 1069e9ad0 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); pending>  
root: DEBUG: nowevent: _help_tasklet_along  
root: DEBUG: Sending None to initial generator _get_async(query.py:1247)  
root: DEBUG: all_pending: add <Future 106a2e650 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: initial generator _get_async(query.py:1247) yielded <Future 106a2e650 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: <Future 1069e9ad0 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247) suspended generator _get_async(query.py:1250); pending> is now blocked waiting for <Future 106a2e650 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: nowevent: _help_tasklet_along  
root: DEBUG: Sending None to initial generator _run_to_list(query.py:971)  
root: DEBUG: initial generator _run_to_list(query.py:971) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x106a2ee50>  
root: DEBUG: rpc: datastore_v3.RunQuery  
root: DEBUG: Sending <google.appengine.datastore.datastore_query.Batch object at 0x106a2ee10> to suspended generator _run_to_list(query.py:979)  
root: DEBUG: suspended generator _run_to_list(query.py:979) returned [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]  
root: DEBUG: all_pending: success: remove <Future 106a2e650 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); result [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]>  
root: DEBUG: nowevent: _on_future_completion  
root: DEBUG: <Future 1069e9ad0 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); pending> is no longer blocked waiting for <Future 106a2e650 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); result [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))]>  
root: DEBUG: Sending [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))] to suspended generator _get_async(query.py:1250)  
root: DEBUG: suspended generator _get_async(query.py:1250) returned Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))  
root: DEBUG: all_pending: success: remove <Future 1069e9ad0 created by get_async(query.py:1245) for tasklet _get_async(query.py:1247); result Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460))>  
root: DEBUG: all_pending: add <Future 1069cf8d0 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); pending>  
root: DEBUG: nowevent: _help_tasklet_along  
root: DEBUG: Sending None to initial generator _run_to_list(query.py:971)  
root: DEBUG: initial generator _run_to_list(query.py:971) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x106a2edd0>  
root: DEBUG: rpc: datastore_v3.RunQuery  
root: DEBUG: Sending <google.appengine.datastore.datastore_query.Batch object at 0x106a2ef10> to suspended generator _run_to_list(query.py:979)  
root: DEBUG: suspended generator _run_to_list(query.py:979) returned [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460)), Greeting(key=Key('Greeting', 1001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 43, 164283)), Greeting(key=Key('Greeting', 2001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 44, 59, 425351)), Greeting(key=Key('Greeting', 3001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 45, 39, 127541)), Greeting(key=Key('Greeting', 4001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 46, 40, 884853)), Greeting(key=Key('Greeting', 5001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 21, 10, 45, 14308)), Greeting(key=Key('Greeting', 6001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 21, 56, 12, 419565)), Greeting(key=Key('Greeting', 7001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 22, 0, 14, 800335)), Greeting(key=Key('Greeting', 8001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 22, 1, 7, 931768)), Greeting(key=Key('Greeting', 9001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 21, 13, 34, 43, 876008))]  
root: DEBUG: all_pending: success: remove <Future 1069cf8d0 created by fetch_async(query.py:1223) for tasklet _run_to_list(query.py:971); result [Greeting(key=Key('Greeting', 1), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 37, 659460)), Greeting(key=Key('Greeting', 1001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 39, 43, 164283)), Greeting(key=Key('Greeting', 2001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 44, 59, 425351)), Greeting(key=Key('Greeting', 3001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 45, 39, 127541)), Greeting(key=Key('Greeting', 4001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 20, 46, 40, 884853)), Greeting(key=Key('Greeting', 5001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 21, 10, 45, 14308)), Greeting(key=Key('Greeting', 6001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 21, 56, 12, 419565)), Greeting(key=Key('Greeting', 7001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 22, 0, 14, 800335)), Greeting(key=Key('Greeting', 8001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 18, 22, 1, 7, 931768)), Greeting(key=Key('Greeting', 9001), author=Author(email=u'elonMusk@example.com', identity=u'888'), content=u'Test Value', date=datetime.datetime(2016, 3, 21, 13, 34, 43, 876008))]>  
--------------------- >> end captured logging << ---------------------  

----------------------------------------------------------------------  
Ran 2 tests in 0.835s  

FAILED (failures=1)  

#

EDIT towards resolution:
The teardown() was being called, the output from the print was being swallowed by nosetests.
The --nocapture flag stops this behavior.

The persistence of the datastore entities in the failed tests stems from the fact that testbed.deactivate() seems to only flush the in-memory datastore and not data stored in a file on the hard drive.
I had defined 'datastore_file' with the path to a sqlite3 database which seems to maintain state despite testbed.deactivate()

Answer 1

Code present does not match with output. According to output, failed test is test_guest_can_submit_new_greeting_and_author, and failure is following:

Traceback (most recent call last):  
      File "/Users/Bryan/work/GoogleAppEngine/guestbook/functional_tests.py", line 124, in test_guest_can_submit_new_greeting_and_author  
        self.assertEqual(1, len(Greeting.query().fetch(10)))  
    AssertionError: 1 != 10 

But test_guest_can_submit_new_greeting_and_author doesn't contain shown assertion:

def test_guest_can_submit_new_greeting_and_author(self):  

     #self.browser.get('http://localhost:8080')  
     self.loginUser()  
     greetings = Greeting.query(Greeting.author.email=='elonMusk@example.com').get()  
     pprint.pprint(greetings)  
     assert(Greeting.query(Greeting.author.email=='elonMusk@example.com').get())  

Looks like you execute different version of file with tests.

Answer 2

The tearDown method is being called, but nosetests is swallowing the output.

Here's a minimal example.

import unittest


class MyTestCase(unittest.TestCase):

    def setUp(self):
        pass

    def tearDown(self):
        print 'Calling tearDown'

    def test_1(self):
        self.assertTrue(True)

    def test_2(self):
        self.assertTrue(False)

Called with the standard library unittest test runner, output from the print statement is shown for each test:

$ python -m unittest tests
Calling tearDown
.FCalling tearDown

======================================================================
FAIL: test_2 (tests.MyTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "tests.py", line 16, in test_2
    self.assertTrue(False)
AssertionError: False is not true

----------------------------------------------------------------------
Ran 2 tests in 0.000s

FAILED (failures=1)

Called with nosetests, the output is not shown:

$ nosetests -v  --with-gae --gae-lib-root=$APPENGINE
test_1 (tests.MyTestCase) ... ok
test_2 (tests.MyTestCase) ... FAIL

======================================================================
FAIL: test_2 (tests.MyTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/kev/python_projects/usr/local/bin/python2.7/tests.py", line 16, in test_2
    self.assertTrue(False)
AssertionError: False is not true

----------------------------------------------------------------------
Ran 2 tests in 0.268s

FAILED (failures=1)

If we pass the --nocapture flag to nosetests the output from the print statement is displayed:

$ nosetests -v --nocapture --with-gae --gae-lib-root=$APPENGINE
test_1 (tests.MyTestCase) ... Calling tearDown
ok
test_2 (tests.MyTestCase) ... FAIL
Calling tearDown

======================================================================
FAIL: test_2 (tests.MyTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/kev/python_projects/usr/local/bin/python2.7/tests.py", line 16, in test_2
    self.assertTrue(False)
AssertionError: False is not true

----------------------------------------------------------------------
Ran 2 tests in 0.265s

FAILED (failures=1)

The --nocapture option is described at http://nose.readthedocs.org/en/latest/plugins/capture.html